[GH-ISSUE #3490] Slow initial connection with selfhosted netbird #7355

Closed
opened 2026-08-05 01:12:37 -04:00 by saavagebueno · 6 comments
Owner

Originally created by @marcportabellaclotet-mt on GitHub (Mar 12, 2025).
Original GitHub issue: https://github.com/netbirdio/netbird/issues/3490

Describe the problem

Randomly the netbird client takes more than usual to do the initial connection. When this happens there is always a 30 seconds delay where the client is waiting for signal stream to be ready

To Reproduce

Steps to reproduce the behavior:

netbird up

Expected behavior

As this is random, I should expect that this not happens any time.

NetBird version

0.38.0

Is any other VPN software installed?

no
Debug output

2025-03-12T21:18:30+01:00 DEBG client/internal/dns/systemd_linux.go:78: got dbus Link interface: /org/freedesktop/resolve1/link/_3131 from net interface wt0 and index 131
2025-03-12T21:18:30+01:00 DEBG signal/client/grpc.go:128: signal connection state READY
2025-03-12T21:19:00+01:00 INFO signal/client/grpc.go:149: connected to the Signal Service stream

As you can see in the above logs when this happens there is always the same 30 seconds delay, betweeen the signal connection state READY and the connected to the Signal Service stream steps

Have you tried these troubleshooting steps?

  • Checked for newer NetBird versions
  • Searched for similar issues on GitHub (including closed ones)
  • Restarted the NetBird client
  • Disabled other VPN software
  • Checked firewall settings
Originally created by @marcportabellaclotet-mt on GitHub (Mar 12, 2025). Original GitHub issue: https://github.com/netbirdio/netbird/issues/3490 **Describe the problem** Randomly the netbird client takes more than usual to do the initial connection. When this happens there is always a 30 seconds delay where the client is waiting for signal stream to be ready **To Reproduce** Steps to reproduce the behavior: netbird up **Expected behavior** As this is random, I should expect that this not happens any time. **NetBird version** `0.38.0` **Is any other VPN software installed?** no **Debug output** ``` 2025-03-12T21:18:30+01:00 DEBG client/internal/dns/systemd_linux.go:78: got dbus Link interface: /org/freedesktop/resolve1/link/_3131 from net interface wt0 and index 131 2025-03-12T21:18:30+01:00 DEBG signal/client/grpc.go:128: signal connection state READY 2025-03-12T21:19:00+01:00 INFO signal/client/grpc.go:149: connected to the Signal Service stream ``` As you can see in the above logs when this happens there is always the same 30 seconds delay, betweeen the signal connection state READY and the connected to the Signal Service stream steps **Have you tried these troubleshooting steps?** - [x] Checked for newer NetBird versions - [x] Searched for similar issues on GitHub (including closed ones) - [x] Restarted the NetBird client - [x] Disabled other VPN software - [x] Checked firewall settings
saavagebueno added the triage-neededself-hosting labels 2026-08-05 01:12:37 -04:00
Author
Owner

@marcportabellaclotet-mt commented on GitHub (Mar 13, 2025):

Same thing today.. The exact 30 seconds delay

2025-03-13T08:54:19+01:00 DEBG client/internal/dns/systemd_linux.go:78: got dbus Link interface: /org/freedesktop/resolve1/link/_3151 from net interface wt0 and index 151
2025-03-13T08:54:19+01:00 DEBG signal/client/grpc.go:128: signal connection state READY
2025-03-13T08:54:49+01:00 DEBG client/internal/engine.go:845: connecting to Management Service updates stream
2025-03-13T08:54:49+01:00 INFO client/internal/engine.go:1610: Network monitor is disabled, not starting
2025-03-13T08:54:49+01:00 INFO client/internal/connect.go:281: Netbird engine started, the IP is: 100.127.59.119/16
2025-03-13T08:54:49+01:00 DEBG management/client/grpc.go:115: management connection state READY
2025-03-13T08:54:49+01:00 INFO signal/client/grpc.go:149: connected to the Signal Service stream

<!-- gh-comment-id:2720290385 --> @marcportabellaclotet-mt commented on GitHub (Mar 13, 2025): Same thing today.. The exact 30 seconds delay ``` 2025-03-13T08:54:19+01:00 DEBG client/internal/dns/systemd_linux.go:78: got dbus Link interface: /org/freedesktop/resolve1/link/_3151 from net interface wt0 and index 151 2025-03-13T08:54:19+01:00 DEBG signal/client/grpc.go:128: signal connection state READY 2025-03-13T08:54:49+01:00 DEBG client/internal/engine.go:845: connecting to Management Service updates stream 2025-03-13T08:54:49+01:00 INFO client/internal/engine.go:1610: Network monitor is disabled, not starting 2025-03-13T08:54:49+01:00 INFO client/internal/connect.go:281: Netbird engine started, the IP is: 100.127.59.119/16 2025-03-13T08:54:49+01:00 DEBG management/client/grpc.go:115: management connection state READY 2025-03-13T08:54:49+01:00 INFO signal/client/grpc.go:149: connected to the Signal Service stream ```
Author
Owner

@marcportabellaclotet-mt commented on GitHub (Apr 8, 2025):

logs in signal server:

2025-04-08T13:19:44Z DEBG signal/peer/peer.go:88: peer registered [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=]
2025-04-08T13:19:44Z DEBG signal/server/signal.go:99: peer connected [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] [streamID 1744118384472104846]
2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [azWzxsXppGhAjQs22hFfJI9ewhKoMELLba7AZSV2pwk=]
2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [aRcNFzer3LIVttzPmTbNCPJUgs9ntDt4ncGZJj741kg=]
2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [RzJRfFYKKS5wVRFC1DB7H5VhKu13xUSyXUVPPySqRz8=]
2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [zPYrKD5tPpKz8Baei2dUBXSxGkkMNIo1ySBdBwOzmh4=]
2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o=]
2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [eLfK4fvgXmEb1EtkHQITo5U63AthC0+BQslU2DPKtBw=]
2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [clmK4hrzipeOuRPA0Hm3lxBIkog6cnhNAXcZ4GSj9GQ=]
2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ=]
2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [X4tGuLM5YHYbiCCE3bOivTLBvzAoxc1N+m9K8nEBtTE=]
2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [lR0IJP6877b7EYJoM4CupjYA27cLMier/OYAmazmF34=]

<!-- gh-comment-id:2786435903 --> @marcportabellaclotet-mt commented on GitHub (Apr 8, 2025): logs in signal server: ``` 2025-04-08T13:19:44Z DEBG signal/peer/peer.go:88: peer registered [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] 2025-04-08T13:19:44Z DEBG signal/server/signal.go:99: peer connected [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] [streamID 1744118384472104846] 2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [azWzxsXppGhAjQs22hFfJI9ewhKoMELLba7AZSV2pwk=] 2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [aRcNFzer3LIVttzPmTbNCPJUgs9ntDt4ncGZJj741kg=] 2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [RzJRfFYKKS5wVRFC1DB7H5VhKu13xUSyXUVPPySqRz8=] 2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [zPYrKD5tPpKz8Baei2dUBXSxGkkMNIo1ySBdBwOzmh4=] 2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o=] 2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [eLfK4fvgXmEb1EtkHQITo5U63AthC0+BQslU2DPKtBw=] 2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [clmK4hrzipeOuRPA0Hm3lxBIkog6cnhNAXcZ4GSj9GQ=] 2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ=] 2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [X4tGuLM5YHYbiCCE3bOivTLBvzAoxc1N+m9K8nEBtTE=] 2025-04-08T13:20:14Z DEBG signal/server/signal.go:72: received a new message to send from peer [8xAuBQ2cYvj4DKjw66Mo44qaO2TlobXZ/no6Nz7JomQ=] to peer [lR0IJP6877b7EYJoM4CupjYA27cLMier/OYAmazmF34=] ```
Author
Owner

@marcportabellaclotet-mt commented on GitHub (Apr 9, 2025):

Adding client log in debug mode

2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [Channel #10 SubChannel #11]Subchannel created
2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [Channel #10]Channel Connectivity change to CONNECTING
2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [Channel #10]Channel exiting idle mode
2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [Channel #10 SubChannel #11]Subchannel Connectivity change to CONNECTING
2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [Channel #10 SubChannel #11]Subchannel picks a new address "netbird.example.tools:443" to connect
2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [pick-first-lb 0xc000a3fbf0] Received SubConn state update: 0xc00068a4b0, {ConnectivityState:CONNECTING ConnectionError:<nil>}
2025-04-09T09:56:07+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:07 INFO: [core] [Channel #10 SubChannel #11]Subchannel Connectivity change to READY
2025-04-09T09:56:07+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:07 INFO: [core] [pick-first-lb 0xc000a3fbf0] Received SubConn state update: 0xc00068a4b0, {ConnectivityState:READY ConnectionError:<nil>}
2025-04-09T09:56:07+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:07 INFO: [core] [Channel #10]Channel Connectivity change to READY
2025-04-09T09:56:07+02:00 INFO client/iface/wgproxy/ebpf/proxy.go:91: local wg proxy listening on: 3128
2025-04-09T09:56:07+02:00 INFO client/iface/wgproxy/factory_kernel.go:29: WireGuard Proxy Factory will produce eBPF proxy
2025-04-09T09:56:07+02:00 INFO client/internal/routemanager/manager.go:193: Routing setup complete
2025-04-09T09:56:07+02:00 INFO client/firewall/create_linux.go:73: creating an nftables firewall manager
2025-04-09T09:56:07+02:00 INFO client/internal/dns/host_unix.go:54: System DNS manager discovered: systemd
2025-04-09T09:56:37+02:00 INFO signal/client/grpc.go:149: connected to the Signal Service stream
2025-04-09T09:56:37+02:00 INFO client/internal/engine.go:1672: Network monitor is disabled, not starting
2025-04-09T09:56:37+02:00 INFO client/internal/connect.go:281: Netbird engine started, the IP is: 100.127.215.95/16
2025-04-09T09:56:37+02:00 INFO management/client/grpc.go:156: connected to the Management Service stream
2025-04-09T09:56:37+02:00 INFO relay/client/manager.go:223: update relay server URLs: []
2025-04-09T09:56:37+02:00 WARN client/internal/engine.go:785: running SSH server is not permitted
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.120.0.0/16] has not been assigned a routing peer as no peers from the list [Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ= DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o=] are currently connected
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.30.0.0/16] has not been assigned a routing peer as no peers from the list [DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o= Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ=] are currently connected
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.110.0.0/16] has not been assigned a routing peer as no peers from the list [Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ= DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o=] are currently connected
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [172.31.0.0/16] has not been assigned a routing peer as no peers from the list [DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o= Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ=] are currently connected
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.10.0.0/16] has not been assigned a routing peer as no peers from the list [Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ= DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o=] are currently connected
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.160.0.0/16] has not been assigned a routing peer as no peers from the list [X4tGuLM5YHYbiCCE3bOivTLBvzAoxc1N+m9K8nEBtTE= aRcNFzer3LIVttzPmTbNCPJUgs9ntDt4ncGZJj741kg=] are currently connected
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.250.0.0/16] has not been assigned a routing peer as no peers from the list [lR0IJP6877b7EYJoM4CupjYA27cLMier/OYAmazmF34=] are currently connected
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.200.0.0/16] has not been assigned a routing peer as no peers from the list [DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o= Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ=] are currently connected
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.170.0.0/16] has not been assigned a routing peer as no peers from the list [zPYrKD5tPpKz8Baei2dUBXSxGkkMNIo1ySBdBwOzmh4= clmK4hrzipeOuRPA0Hm3lxBIkog6cnhNAXcZ4GSj9GQ=] are currently connected
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.0.0.0/16] has not been assigned a routing peer as no peers from the list [Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ= DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o=] are currently connected
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.150.0.0/16] has not been assigned a routing peer as no peers from the list [azWzxsXppGhAjQs22hFfJI9ewhKoMELLba7AZSV2pwk=] are currently connected
2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.180.0.0/16] has not been assigned a routing peer as no peers from the list [eLfK4fvgXmEb1EtkHQITo5U63AthC0+BQslU2DPKtBw=] are currently connected
2025-04-09T09:56:37+02:00 INFO client/internal/acl/manager.go:66: ACL rules processed in: 27.578247ms, total rules count: 1
2025-04-09T09:56:37+02:00 INFO [peer: X4tGuLM5YHYbiCCE3bOivTLBvzAoxc1N+m9K8nEBtTE=] client/internal/peer/handshaker.go:79: wait for 

Full client log:

netbird.log

<!-- gh-comment-id:2788841413 --> @marcportabellaclotet-mt commented on GitHub (Apr 9, 2025): Adding client log in debug mode ``` 2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [Channel #10 SubChannel #11]Subchannel created 2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [Channel #10]Channel Connectivity change to CONNECTING 2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [Channel #10]Channel exiting idle mode 2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [Channel #10 SubChannel #11]Subchannel Connectivity change to CONNECTING 2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [Channel #10 SubChannel #11]Subchannel picks a new address "netbird.example.tools:443" to connect 2025-04-09T09:56:06+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:06 INFO: [core] [pick-first-lb 0xc000a3fbf0] Received SubConn state update: 0xc00068a4b0, {ConnectivityState:CONNECTING ConnectionError:<nil>} 2025-04-09T09:56:07+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:07 INFO: [core] [Channel #10 SubChannel #11]Subchannel Connectivity change to READY 2025-04-09T09:56:07+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:07 INFO: [core] [pick-first-lb 0xc000a3fbf0] Received SubConn state update: 0xc00068a4b0, {ConnectivityState:READY ConnectionError:<nil>} 2025-04-09T09:56:07+02:00 INFO ./caller_not_available:0: 2025/04/09 09:56:07 INFO: [core] [Channel #10]Channel Connectivity change to READY 2025-04-09T09:56:07+02:00 INFO client/iface/wgproxy/ebpf/proxy.go:91: local wg proxy listening on: 3128 2025-04-09T09:56:07+02:00 INFO client/iface/wgproxy/factory_kernel.go:29: WireGuard Proxy Factory will produce eBPF proxy 2025-04-09T09:56:07+02:00 INFO client/internal/routemanager/manager.go:193: Routing setup complete 2025-04-09T09:56:07+02:00 INFO client/firewall/create_linux.go:73: creating an nftables firewall manager 2025-04-09T09:56:07+02:00 INFO client/internal/dns/host_unix.go:54: System DNS manager discovered: systemd 2025-04-09T09:56:37+02:00 INFO signal/client/grpc.go:149: connected to the Signal Service stream 2025-04-09T09:56:37+02:00 INFO client/internal/engine.go:1672: Network monitor is disabled, not starting 2025-04-09T09:56:37+02:00 INFO client/internal/connect.go:281: Netbird engine started, the IP is: 100.127.215.95/16 2025-04-09T09:56:37+02:00 INFO management/client/grpc.go:156: connected to the Management Service stream 2025-04-09T09:56:37+02:00 INFO relay/client/manager.go:223: update relay server URLs: [] 2025-04-09T09:56:37+02:00 WARN client/internal/engine.go:785: running SSH server is not permitted 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.120.0.0/16] has not been assigned a routing peer as no peers from the list [Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ= DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o=] are currently connected 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.30.0.0/16] has not been assigned a routing peer as no peers from the list [DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o= Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ=] are currently connected 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.110.0.0/16] has not been assigned a routing peer as no peers from the list [Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ= DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o=] are currently connected 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [172.31.0.0/16] has not been assigned a routing peer as no peers from the list [DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o= Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ=] are currently connected 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.10.0.0/16] has not been assigned a routing peer as no peers from the list [Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ= DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o=] are currently connected 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.160.0.0/16] has not been assigned a routing peer as no peers from the list [X4tGuLM5YHYbiCCE3bOivTLBvzAoxc1N+m9K8nEBtTE= aRcNFzer3LIVttzPmTbNCPJUgs9ntDt4ncGZJj741kg=] are currently connected 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.250.0.0/16] has not been assigned a routing peer as no peers from the list [lR0IJP6877b7EYJoM4CupjYA27cLMier/OYAmazmF34=] are currently connected 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.200.0.0/16] has not been assigned a routing peer as no peers from the list [DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o= Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ=] are currently connected 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.170.0.0/16] has not been assigned a routing peer as no peers from the list [zPYrKD5tPpKz8Baei2dUBXSxGkkMNIo1ySBdBwOzmh4= clmK4hrzipeOuRPA0Hm3lxBIkog6cnhNAXcZ4GSj9GQ=] are currently connected 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.0.0.0/16] has not been assigned a routing peer as no peers from the list [Y86ay9tcUViChlWaU03JEXXqvOPAkUlpdqGdFMFPyRQ= DDfTMvJcTT6S1Nc5MNcWOgUqJGKY2DBuDc8UYhbtD1o=] are currently connected 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.150.0.0/16] has not been assigned a routing peer as no peers from the list [azWzxsXppGhAjQs22hFfJI9ewhKoMELLba7AZSV2pwk=] are currently connected 2025-04-09T09:56:37+02:00 WARN client/internal/routemanager/client.go:209: The network [10.180.0.0/16] has not been assigned a routing peer as no peers from the list [eLfK4fvgXmEb1EtkHQITo5U63AthC0+BQslU2DPKtBw=] are currently connected 2025-04-09T09:56:37+02:00 INFO client/internal/acl/manager.go:66: ACL rules processed in: 27.578247ms, total rules count: 1 2025-04-09T09:56:37+02:00 INFO [peer: X4tGuLM5YHYbiCCE3bOivTLBvzAoxc1N+m9K8nEBtTE=] client/internal/peer/handshaker.go:79: wait for ``` Full client log: [netbird.log](https://github.com/user-attachments/files/19663659/netbird.log)
Author
Owner

@marcportabellaclotet-mt commented on GitHub (Apr 23, 2025):

I tried a new connection with setup keys, for a peers with no rules and no groups, and I have the same issue, 30 seconds of delay.

sudo GRPC_GO_LOG_VERBOSITY_LEVEL=99 GRPC_GO_LOG_SEVERITY_LEVEL=debug PIONS_LOG_DEBUG=all NB_LOG_LEVEL=debug  netbird up -F -m https://netbird.example.tools --setup-key xxxxxxxxxxxx
2025-04-23T08:49:18+02:00 INFO client/internal/config.go:261: new Management URL provided, updated to "https://netbird.example.tools" (old value "https://netbird.example.tools:443")
2025-04-23T08:49:18+02:00 DEBG client/internal/login.go:94: connecting to the Management service https://netbird.example.tools:443
2025-04-23T08:49:18+02:00 DEBG util/net/dialer_dial.go:52: Dialing tcp netbird.example.tools:443
2025-04-23T08:49:18+02:00 DEBG client/internal/login.go:64: connected to the Management service https://netbird.example.tools:443
2025-04-23T08:49:18+02:00 DEBG client/internal/login.go:94: connecting to the Management service https://netbird.example.tools:443
2025-04-23T08:49:18+02:00 DEBG util/net/dialer_dial.go:52: Dialing tcp netbird.example.tools:443
2025-04-23T08:49:19+02:00 DEBG client/internal/login.go:64: connected to the Management service https://netbird.example.tools:443
2025-04-23T08:49:19+02:00 INFO client/internal/connect.go:122: starting NetBird client version 0.41.3 on linux/amd64
2025-04-23T08:49:19+02:00 DEBG util/net/dialer_dial.go:52: Dialing udp 127.0.0.1:9
2025-04-23T08:49:19+02:00 INFO util/net/env_linux.go:70: system supports advanced routing
2025-04-23T08:49:19+02:00 DEBG client/internal/connect.go:178: connecting to the Management service netbird.example.tools:443
2025-04-23T08:49:19+02:00 DEBG util/net/dialer_dial.go:52: Dialing tcp netbird.example.tools:443
2025-04-23T08:49:19+02:00 DEBG client/internal/connect.go:186: connected to the Management service netbird.example.tools:443
2025-04-23T08:49:19+02:00 DEBG util/net/dialer_dial.go:52: Dialing tcp netbird.example.tools:443
2025-04-23T08:49:20+02:00 DEBG signal/client/grpc.go:83: connected to Signal Service: netbird.example.tools:443
2025-04-23T08:49:20+02:00 DEBG client/iface/wgproxy/ebpf/proxy.go:47: instantiate ebpf proxy
2025-04-23T08:49:20+02:00 DEBG client/internal/ebpf/ebpf/wg_proxy_linux.go:11: load ebpf WG proxy
2025-04-23T08:49:20+02:00 INFO client/iface/wgproxy/ebpf/proxy.go:91: local wg proxy listening on: 3128
2025-04-23T08:49:20+02:00 INFO client/iface/wgproxy/factory_kernel.go:29: WireGuard Proxy Factory will produce eBPF proxy
2025-04-23T08:49:20+02:00 DEBG client/internal/dns/service_listener.go:108: registering dns handler for pattern: .
2025-04-23T08:49:20+02:00 DEBG client/internal/statemanager/manager.go:378: loaded state: routeselector_state
2025-04-23T08:49:20+02:00 DEBG client/internal/routemanager/sysctl/sysctl_linux.go:87: Set sysctl net.ipv4.conf.all.src_valid_mark from 0 to 1
2025-04-23T08:49:20+02:00 INFO client/internal/routemanager/manager.go:193: Routing setup complete
2025-04-23T08:49:20+02:00 DEBG client/iface/device/wg_link_linux.go:65: adding device: wt0
2025-04-23T08:49:20+02:00 DEBG client/iface/device/wg_link_linux.go:115: adding address 100.127.126.127/16 to interface: wt0
2025-04-23T08:49:20+02:00 DEBG client/iface/device/device_kernel_unix.go:66: setting MTU: 1280 interface: wt0
2025-04-23T08:49:20+02:00 DEBG client/iface/configurer/kernel_unix.go:26: adding Wireguard private key
2025-04-23T08:49:20+02:00 INFO client/firewall/create_linux.go:73: creating an nftables firewall manager
2025-04-23T08:49:20+02:00 DEBG client/firewall/nftables/router_linux.go:846: added iptables rule: [-i wt0 -j ACCEPT]
2025-04-23T08:49:20+02:00 DEBG client/firewall/nftables/router_linux.go:846: added iptables rule: [-o wt0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
2025-04-23T08:49:20+02:00 DEBG client/firewall/nftables/router_linux.go:824: Used iptables to add accept forward rules
2025-04-23T08:49:20+02:00 DEBG client/iface/device/device_kernel_unix.go:90: bringing up interface: wt0
2025-04-23T08:49:20+02:00 DEBG client/internal/statemanager/manager.go:286: persisted states: [nftables_state], took 214.088µs
ice WARNING: 2025/04/23 08:49:20 UDPMuxDefault should not listening on unspecified address, use NewMultiUDPMuxFromPort instead
2025-04-23T08:49:20+02:00 DEBG client/iface/device/device_kernel_unix.go:113: device is ready to use: wt0
2025-04-23T08:49:20+02:00 INFO client/internal/dns/host_unix.go:54: System DNS manager discovered: systemd
2025-04-23T08:49:20+02:00 DEBG client/internal/dns/systemd_linux.go:76: got dbus Link interface: /org/freedesktop/resolve1/link/_381 from net interface wt0 and index 81
2025-04-23T08:49:20+02:00 DEBG signal/client/grpc.go:128: signal connection state READY
2025-04-23T08:49:50+02:00 INFO signal/client/grpc.go:149: connected to the Signal Service stream
2025-04-23T08:49:50+02:00 DEBG client/internal/engine.go:899: connecting to Management Service updates stream
2025-04-23T08:49:50+02:00 INFO client/internal/engine.go:1655: Network monitor is disabled, not starting
2025-04-23T08:49:50+02:00 INFO client/internal/connect.go:281: Netbird engine started, the IP is: 100.127.126.127/16
2025-04-23T08:49:50+02:00 DEBG management/client/grpc.go:115: management connection state READY
2025-04-23T08:49:50+02:00 INFO management/client/grpc.go:156: connected to the Management Service stream
2025-04-23T08:49:50+02:00 DEBG management/client/grpc.go:253: got an update message from Management Service
2025-04-23T08:49:50+02:00 DEBG client/internal/engine.go:907: got STUNs update from Management Service, updating
2025-04-23T08:49:50+02:00 INFO relay/client/manager.go:223: update relay server URLs: []
2025-04-23T08:49:50+02:00 WARN client/internal/engine.go:785: running SSH server is not permitted
2025-04-23T08:49:50+02:00 INFO client/internal/acl/manager.go:66: ACL rules processed in: 126.948µs, total rules count: 0
2025-04-23T08:49:50+02:00 DEBG client/internal/engine.go:983: got peers update from Management Service, total peers to connect to = 0
2025-04-23T08:49:50+02:00 DEBG client/internal/engine.go:606: removing all peer connections
2025-04-23T08:49:50+02:00 DEBG client/internal/dns.go:110: added reverse DNS zone: 127.100.in-addr.arpa. with 108 records
2025-04-23T08:49:50+02:00 DEBG client/internal/dns/service_listener.go:69: starting dns on 100.127.126.127:53
2025-04-23T08:49:50+02:00 DEBG client/internal/dns/server.go:213: registering handler local resolver [0 records] with priority 50
2025-04-23T08:49:50+02:00 DEBG client/internal/dns/handler_chain.go:86: adding handler pattern: domain=netbird.selfhosted. original: domain=netbird.selfhosted. wildcard=false match_subdomain=true priority=50
2025-04-23T08:49:50+02:00 DEBG client/internal/dns/server.go:213: registering handler local resolver [0 records] with priority 50
2025-04-23T08:49:50+02:00 DEBG client/internal/dns/handler_chain.go:86: adding handler pattern: domain=127.100.in-addr.arpa. original: domain=127.100.in-addr.arpa. wildcard=false match_subdomain=true priority=50
2025-04-23T08:49:50+02:00 DEBG client/internal/dns/server.go:494: extra match domains: map[]
2025-04-23T08:49:50+02:00 INFO client/internal/dns/systemd_linux.go:148: adding 1 search domains and 1 match domains. Search list: [netbird.selfhosted.] , Match list: [127.100.in-addr.arpa.]
2025-04-23T08:49:50+02:00 DEBG client/internal/peer/status.go:981: event published: id:"a84210cf-185c-4846-8d3a-cf4fd1e7b3f8"  category:SYSTEM  message:"Network map updated"  timestamp:{seconds:1745390990  nanos:461962509}
2025-04-23T08:49:50+02:00 DEBG client/internal/statemanager/manager.go:286: persisted states: [dns_state], took 164.07µs
<!-- gh-comment-id:2823256722 --> @marcportabellaclotet-mt commented on GitHub (Apr 23, 2025): I tried a new connection with setup keys, for a peers with no rules and no groups, and I have the same issue, 30 seconds of delay. ``` sudo GRPC_GO_LOG_VERBOSITY_LEVEL=99 GRPC_GO_LOG_SEVERITY_LEVEL=debug PIONS_LOG_DEBUG=all NB_LOG_LEVEL=debug netbird up -F -m https://netbird.example.tools --setup-key xxxxxxxxxxxx 2025-04-23T08:49:18+02:00 INFO client/internal/config.go:261: new Management URL provided, updated to "https://netbird.example.tools" (old value "https://netbird.example.tools:443") 2025-04-23T08:49:18+02:00 DEBG client/internal/login.go:94: connecting to the Management service https://netbird.example.tools:443 2025-04-23T08:49:18+02:00 DEBG util/net/dialer_dial.go:52: Dialing tcp netbird.example.tools:443 2025-04-23T08:49:18+02:00 DEBG client/internal/login.go:64: connected to the Management service https://netbird.example.tools:443 2025-04-23T08:49:18+02:00 DEBG client/internal/login.go:94: connecting to the Management service https://netbird.example.tools:443 2025-04-23T08:49:18+02:00 DEBG util/net/dialer_dial.go:52: Dialing tcp netbird.example.tools:443 2025-04-23T08:49:19+02:00 DEBG client/internal/login.go:64: connected to the Management service https://netbird.example.tools:443 2025-04-23T08:49:19+02:00 INFO client/internal/connect.go:122: starting NetBird client version 0.41.3 on linux/amd64 2025-04-23T08:49:19+02:00 DEBG util/net/dialer_dial.go:52: Dialing udp 127.0.0.1:9 2025-04-23T08:49:19+02:00 INFO util/net/env_linux.go:70: system supports advanced routing 2025-04-23T08:49:19+02:00 DEBG client/internal/connect.go:178: connecting to the Management service netbird.example.tools:443 2025-04-23T08:49:19+02:00 DEBG util/net/dialer_dial.go:52: Dialing tcp netbird.example.tools:443 2025-04-23T08:49:19+02:00 DEBG client/internal/connect.go:186: connected to the Management service netbird.example.tools:443 2025-04-23T08:49:19+02:00 DEBG util/net/dialer_dial.go:52: Dialing tcp netbird.example.tools:443 2025-04-23T08:49:20+02:00 DEBG signal/client/grpc.go:83: connected to Signal Service: netbird.example.tools:443 2025-04-23T08:49:20+02:00 DEBG client/iface/wgproxy/ebpf/proxy.go:47: instantiate ebpf proxy 2025-04-23T08:49:20+02:00 DEBG client/internal/ebpf/ebpf/wg_proxy_linux.go:11: load ebpf WG proxy 2025-04-23T08:49:20+02:00 INFO client/iface/wgproxy/ebpf/proxy.go:91: local wg proxy listening on: 3128 2025-04-23T08:49:20+02:00 INFO client/iface/wgproxy/factory_kernel.go:29: WireGuard Proxy Factory will produce eBPF proxy 2025-04-23T08:49:20+02:00 DEBG client/internal/dns/service_listener.go:108: registering dns handler for pattern: . 2025-04-23T08:49:20+02:00 DEBG client/internal/statemanager/manager.go:378: loaded state: routeselector_state 2025-04-23T08:49:20+02:00 DEBG client/internal/routemanager/sysctl/sysctl_linux.go:87: Set sysctl net.ipv4.conf.all.src_valid_mark from 0 to 1 2025-04-23T08:49:20+02:00 INFO client/internal/routemanager/manager.go:193: Routing setup complete 2025-04-23T08:49:20+02:00 DEBG client/iface/device/wg_link_linux.go:65: adding device: wt0 2025-04-23T08:49:20+02:00 DEBG client/iface/device/wg_link_linux.go:115: adding address 100.127.126.127/16 to interface: wt0 2025-04-23T08:49:20+02:00 DEBG client/iface/device/device_kernel_unix.go:66: setting MTU: 1280 interface: wt0 2025-04-23T08:49:20+02:00 DEBG client/iface/configurer/kernel_unix.go:26: adding Wireguard private key 2025-04-23T08:49:20+02:00 INFO client/firewall/create_linux.go:73: creating an nftables firewall manager 2025-04-23T08:49:20+02:00 DEBG client/firewall/nftables/router_linux.go:846: added iptables rule: [-i wt0 -j ACCEPT] 2025-04-23T08:49:20+02:00 DEBG client/firewall/nftables/router_linux.go:846: added iptables rule: [-o wt0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT] 2025-04-23T08:49:20+02:00 DEBG client/firewall/nftables/router_linux.go:824: Used iptables to add accept forward rules 2025-04-23T08:49:20+02:00 DEBG client/iface/device/device_kernel_unix.go:90: bringing up interface: wt0 2025-04-23T08:49:20+02:00 DEBG client/internal/statemanager/manager.go:286: persisted states: [nftables_state], took 214.088µs ice WARNING: 2025/04/23 08:49:20 UDPMuxDefault should not listening on unspecified address, use NewMultiUDPMuxFromPort instead 2025-04-23T08:49:20+02:00 DEBG client/iface/device/device_kernel_unix.go:113: device is ready to use: wt0 2025-04-23T08:49:20+02:00 INFO client/internal/dns/host_unix.go:54: System DNS manager discovered: systemd 2025-04-23T08:49:20+02:00 DEBG client/internal/dns/systemd_linux.go:76: got dbus Link interface: /org/freedesktop/resolve1/link/_381 from net interface wt0 and index 81 2025-04-23T08:49:20+02:00 DEBG signal/client/grpc.go:128: signal connection state READY 2025-04-23T08:49:50+02:00 INFO signal/client/grpc.go:149: connected to the Signal Service stream 2025-04-23T08:49:50+02:00 DEBG client/internal/engine.go:899: connecting to Management Service updates stream 2025-04-23T08:49:50+02:00 INFO client/internal/engine.go:1655: Network monitor is disabled, not starting 2025-04-23T08:49:50+02:00 INFO client/internal/connect.go:281: Netbird engine started, the IP is: 100.127.126.127/16 2025-04-23T08:49:50+02:00 DEBG management/client/grpc.go:115: management connection state READY 2025-04-23T08:49:50+02:00 INFO management/client/grpc.go:156: connected to the Management Service stream 2025-04-23T08:49:50+02:00 DEBG management/client/grpc.go:253: got an update message from Management Service 2025-04-23T08:49:50+02:00 DEBG client/internal/engine.go:907: got STUNs update from Management Service, updating 2025-04-23T08:49:50+02:00 INFO relay/client/manager.go:223: update relay server URLs: [] 2025-04-23T08:49:50+02:00 WARN client/internal/engine.go:785: running SSH server is not permitted 2025-04-23T08:49:50+02:00 INFO client/internal/acl/manager.go:66: ACL rules processed in: 126.948µs, total rules count: 0 2025-04-23T08:49:50+02:00 DEBG client/internal/engine.go:983: got peers update from Management Service, total peers to connect to = 0 2025-04-23T08:49:50+02:00 DEBG client/internal/engine.go:606: removing all peer connections 2025-04-23T08:49:50+02:00 DEBG client/internal/dns.go:110: added reverse DNS zone: 127.100.in-addr.arpa. with 108 records 2025-04-23T08:49:50+02:00 DEBG client/internal/dns/service_listener.go:69: starting dns on 100.127.126.127:53 2025-04-23T08:49:50+02:00 DEBG client/internal/dns/server.go:213: registering handler local resolver [0 records] with priority 50 2025-04-23T08:49:50+02:00 DEBG client/internal/dns/handler_chain.go:86: adding handler pattern: domain=netbird.selfhosted. original: domain=netbird.selfhosted. wildcard=false match_subdomain=true priority=50 2025-04-23T08:49:50+02:00 DEBG client/internal/dns/server.go:213: registering handler local resolver [0 records] with priority 50 2025-04-23T08:49:50+02:00 DEBG client/internal/dns/handler_chain.go:86: adding handler pattern: domain=127.100.in-addr.arpa. original: domain=127.100.in-addr.arpa. wildcard=false match_subdomain=true priority=50 2025-04-23T08:49:50+02:00 DEBG client/internal/dns/server.go:494: extra match domains: map[] 2025-04-23T08:49:50+02:00 INFO client/internal/dns/systemd_linux.go:148: adding 1 search domains and 1 match domains. Search list: [netbird.selfhosted.] , Match list: [127.100.in-addr.arpa.] 2025-04-23T08:49:50+02:00 DEBG client/internal/peer/status.go:981: event published: id:"a84210cf-185c-4846-8d3a-cf4fd1e7b3f8" category:SYSTEM message:"Network map updated" timestamp:{seconds:1745390990 nanos:461962509} 2025-04-23T08:49:50+02:00 DEBG client/internal/statemanager/manager.go:286: persisted states: [dns_state], took 164.07µs ```
Author
Owner

@marcportabellaclotet-mt commented on GitHub (Apr 23, 2025):

After adding some custom logs in the client, it seems that if waits 30 seconds when requesting the header

header, err := c.stream.Header()
<!-- gh-comment-id:2823372078 --> @marcportabellaclotet-mt commented on GitHub (Apr 23, 2025): After adding some custom logs in the client, it seems that if waits 30 seconds when requesting the [header](https://github.com/netbirdio/netbird/blob/main/signal/client/grpc.go#L220) ``` header, err := c.stream.Header() ```
Author
Owner

@marcportabellaclotet-mt commented on GitHub (Apr 28, 2025):

The issue seems to be solved after netbird client v0.43.0. Probably related to this fix, which makes sense with my findings.

Closing the issue

<!-- gh-comment-id:2834232010 --> @marcportabellaclotet-mt commented on GitHub (Apr 28, 2025): The issue seems to be solved after netbird client v0.43.0. Probably related to this [fix](https://github.com/netbirdio/netbird/pull/3727), which makes sense with my findings. Closing the issue
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: DYNR/netbird#7355