search

netbirdio / netbird

Connect your devices into a secure WireGuard®-based overlay network with SSO, MFA and granular access controls.
https://netbird.io
BSD 3-Clause "New" or "Revised" License
11.38k stars 521 forks source link

Rosenpass Preshared key is not being updated #2973

Open cdestefano opened 2 days ago

cdestefano commented 2 days ago

Describe the problem

When RosenpassEnabled is on, the psk is not being rotated.

To Reproduce

Steps to reproduce the behavior: Used the most basic case two peers (One is up, other joins. Both Debian 12 amd64 - VPS)

  1. Start the first peer with: netbird up --enable-rosenpass --setup-key=GUID
  2. Start the second peer with the same command: netbird up --enable-rosenpass --setup-key=GUID
  3. Start watch -n 0.1 wg show wt0 preshared-keys in another session
  4. Observe the original key will not update.
  5. Can even try bringing down and bring back up. Waiting long enough for the key to clear, bringing the peer back up will use the previous psk.

Probably not relevant, but my config has: "PreSharedKey": "",

Expected behavior

Following the detailed implementation guide, I believe the key should be set intiially to a common key, and every two minutes it should be rotated. Running watch -n 0.1 wg show wt0 preshared-keys it is the same key throughout the entire time. (cXJVNjRCYndEak90ejdVTWhlQ0JibDF3cnVPeEdudW4=)

After using the rust library of rosenpass, I believe this should be rotated every two minutes and all peers should see the key changed while watching that command.

Are you using NetBird Cloud?

Both. I found this on my self hosted instance, but I stopped the service, deleted my config, restarted the service pointing to the cloud and see the same thing. It seems like it should have gotten to a mostly clean slate pointing to the cloud instance.

NetBird version

v0.33.0

Additional context

Ran a couple traces, and do occasionally see: failed to add rosenpass peer: failed to resolve peer endpoint address: lookup 100.175.197.197/32: no such host, but that seems unrelated as the log below doesn't error and I still see the same PSK.

This is two VPSs and the firewall has an allow of 100.75.0.0/16 for all udp packets.

Result of running netbird debug for 3m -AS (should be long enough for initial key exchange and 2 minute update)

2024-12-01T08:37:37-05:00 INFO client/internal/statemanager/manager.go:281: client was not shut down properly, cleaning up dns_state
2024-12-01T08:37:37-05:00 WARN client/server/server.go:567: failed to restore residual state: 1 error occurred:
    * perform cleanup: 1 error occurred:
    * cleanup state for dns_state: restore unclean shutdown dns: restoring dns for interface wt0: removing resolvconf configuration for wt0 interface: exit status 99
2024-12-01T08:37:37-05:00 INFO client/internal/connect.go:111: starting NetBird client version 0.33.0 on linux/amd64
2024-12-01T08:37:38-05:00 INFO client/internal/connect.go:242: connecting to the Relay service(s): rels://relay.netbird.io:443
2024-12-01T08:37:38-05:00 INFO relay/client/picker.go:66: try to connecting to relay server: rels://relay.netbird.io:443
2024-12-01T08:37:38-05:00 INFO [relay: rels://relay.netbird.io:443] relay/client/client.go:165: create new relay connection: local peerID: heCBbl1wruOxGnun6fpplP2P4Qnf1Hj+Wt6p+ZPb7gc=, local peer hashedID: sha-/mJ/2jan7aZe44Jiw+gPXxjQOTeq5NbNh5TVJAWbGvI=
2024-12-01T08:37:38-05:00 INFO [relay: rels://relay.netbird.io:443] relay/client/client.go:171: connecting to relay server
2024-12-01T08:37:38-05:00 INFO [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:188: relay connection established
2024-12-01T08:37:38-05:00 INFO relay/client/picker.go:84: connected to Relay server: rels://relay.netbird.io:443
2024-12-01T08:37:38-05:00 INFO relay/client/picker.go:58: chosen home Relay server: rels://relay.netbird.io:443
2024-12-01T08:37:38-05:00 INFO client/iface/wgproxy/ebpf/proxy.go:91: local wg proxy listening on: 3128
2024-12-01T08:37:38-05:00 INFO client/iface/wgproxy/factory_kernel.go:29: WireGuard Proxy Factory will produce eBPF proxy
2024-12-01T08:37:38-05:00 INFO client/internal/engine.go:327: rosenpass is enabled
2024-12-01T08:37:38-05:00 INFO client/internal/engine.go:331: running rosenpass in strict mode
2024-12-01T08:37:39-05:00 INFO client/internal/rosenpass/manager.go:158: starting rosenpass server on port 39981
2024-12-01T08:37:39-05:00 INFO client/internal/routemanager/manager.go:144: Routing setup complete
2024-12-01T08:37:39-05:00 INFO client/firewall/create_linux.go:72: creating an nftables firewall manager
2024-12-01T08:37:39-05:00 INFO client/internal/dns/host_unix.go:54: System DNS manager discovered: resolvconf
2024-12-01T08:37:39-05:00 INFO client/internal/peer/guard/sr_watcher.go:106: reconnected to Signal or Relay server
2024-12-01T08:37:39-05:00 INFO signal/client/grpc.go:149: connected to the Signal Service stream
2024-12-01T08:37:39-05:00 INFO client/internal/engine.go:1419: Network monitor is disabled, not starting
2024-12-01T08:37:39-05:00 INFO client/internal/connect.go:270: Netbird engine started, the IP is: 100.75.197.197/16
2024-12-01T08:37:39-05:00 INFO management/client/grpc.go:155: connected to the Management Service stream
2024-12-01T08:37:39-05:00 WARN client/internal/engine.go:597: running SSH server is not permitted
2024-12-01T08:37:39-05:00 INFO client/internal/acl/manager.go:61: ACL rules processed in: 1.852855ms, total rules count: 2
2024-12-01T08:37:39-05:00 ERRO client/internal/dns/server.go:322: apply config: applying resolvconf configuration for wt0 interface: exit status 99
2024-12-01T08:37:40-05:00 INFO [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/guard/guard.go:138: start listen for reconnect events...
2024-12-01T08:37:41-05:00 ERRO [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:433: peer not found: sha-brMfdPjCp7U2FG0haITs30DcW0bYZU60avWnjqF9cL0=
2024-12-01T08:37:41-05:00 INFO [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:217: open connection to peer: sha-brMfdPjCp7U2FG0haITs30DcW0bYZU60avWnjqF9cL0=
2024-12-01T08:37:41-05:00 INFO client/iface/wgproxy/ebpf/proxy.go:102: turn conn added to wg proxy store: rels://streamline-us-nyc1-2.relay.netbird.io:443, endpoint port: :1
2024-12-01T08:37:41-05:00 INFO [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:441: created new wgProxy for relay connection: 127.0.0.1:1
2024-12-01T08:37:41-05:00 INFO [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:470: start to communicate with peer via relay
2024-12-01T08:37:41-05:00 INFO [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:325: set ICE to active connection
2024-12-01T08:37:49-05:00 INFO client/server/debug.go:312: Log level set to trace
2024-12-01T08:37:49-05:00 INFO client/internal/engine.go:261: Network monitor: stopped
2024-12-01T08:37:49-05:00 INFO [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:536: closing all peer connections
2024-12-01T08:37:49-05:00 INFO [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:345: start to Relay read loop exit
2024-12-01T08:37:49-05:00 DEBG client/iface/wgproxy/ebpf/proxy.go:192: remove turn conn from store by port: 1
2024-12-01T08:37:49-05:00 INFO [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:544: waiting for read loop to close
2024-12-01T08:37:49-05:00 INFO [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:546: relay connection closed
2024-12-01T08:37:49-05:00 WARN [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:531: relay connection was already marked as not running
2024-12-01T08:37:49-05:00 TRAC [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/handshaker.go:84: stop handshaker
2024-12-01T08:37:49-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/guard/guard.go:156: context is done, stop reconnect loop
2024-12-01T08:37:49-05:00 DEBG signal/client/grpc.go:392: stream canceled (usually indicates shutdown)
2024-12-01T08:37:49-05:00 DEBG signal/client/grpc.go:155: signal connection context has been canceled, this usually indicates shutdown
2024-12-01T08:37:49-05:00 DEBG management/client/grpc.go:248: disconnected from Management Service sync stream: rpc error: code = Canceled desc = context canceled
2024-12-01T08:37:49-05:00 DEBG management/client/grpc.go:166: management connection context has been canceled, this usually indicates shutdown
2024-12-01T08:37:49-05:00 DEBG client/internal/engine.go:695: stopped receiving updates from Management Service
2024-12-01T08:37:49-05:00 ERRO client/internal/dns/server.go:194: failed to restore host DNS settings: removing resolvconf configuration for wt0 interface: exit status 99
2024-12-01T08:37:49-05:00 DEBG client/internal/routemanager/sysctl/sysctl_linux.go:87: Set sysctl net.ipv4.conf.all.src_valid_mark from 1 to 0
2024-12-01T08:37:49-05:00 INFO client/internal/routemanager/manager.go:179: Routing cleanup complete
2024-12-01T08:37:49-05:00 DEBG client/internal/engine.go:485: removing all peer connections
2024-12-01T08:37:49-05:00 DEBG client/internal/engine.go:497: removing peer from engine qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=
2024-12-01T08:37:49-05:00 INFO [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:212: close peer connection
2024-12-01T08:37:49-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_relay.go:129: disable WireGuard watcher
2024-12-01T08:37:49-05:00 WARN [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_relay.go:155: failed to close relay connection: use of closed network connection
2024-12-01T08:37:49-05:00 DEBG client/iface/iface.go:125: Removing peer qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM= from interface wt0 
2024-12-01T08:37:49-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:219: ICE ConnectionState has changed to Closed
2024-12-01T08:37:49-05:00 DEBG client/internal/engine.go:1159: removing Netbird interface wt0
2024-12-01T08:37:49-05:00 DEBG client/iface/wgproxy/ebpf/proxy.go:113: free up ebpf wg proxy
2024-12-01T08:37:49-05:00 DEBG client/internal/ebpf/ebpf/wg_proxy_linux.go:39: free ebpf WG proxy
2024-12-01T08:37:49-05:00 DEBG client/internal/ebpf/ebpf/manager_linux.go:107: detach ebpf program 
2024-12-01T08:37:49-05:00 ERRO client/iface/bind/udp_mux_universal.go:93: error while reading packet: shared socked stopped
2024-12-01T08:37:49-05:00 DEBG client/iface/bind/udp_mux_universal.go:88: stopped reading from the UDPConn due to finished context
2024-12-01T08:37:49-05:00 INFO client/iface/iface.go:220: interface wt0 has been removed
2024-12-01T08:37:50-05:00 INFO client/internal/engine.go:292: stopped Netbird Engine
2024-12-01T08:37:50-05:00 DEBG client/internal/statemanager/manager.go:205: persisted shutdown states: [nftables_state], took 240.925µs
2024-12-01T08:37:50-05:00 INFO client/server/server.go:645: service is down
2024-12-01T08:37:50-05:00 INFO client/internal/connect.go:293: stopped NetBird client
2024-12-01T08:37:50-05:00 TRAC client/server/server.go:221: client connection exited
2024-12-01T08:37:50-05:00 TRAC client/server/server.go:229: retry canceled
2024-12-01T08:37:51-05:00 DEBG client/internal/statemanager/manager.go:254: loaded state: dns_state
2024-12-01T08:37:51-05:00 INFO client/internal/statemanager/manager.go:281: client was not shut down properly, cleaning up dns_state
2024-12-01T08:37:51-05:00 WARN client/server/server.go:567: failed to restore residual state: 1 error occurred:
    * perform cleanup: 1 error occurred:
    * cleanup state for dns_state: restore unclean shutdown dns: restoring dns for interface wt0: removing resolvconf configuration for wt0 interface: exit status 99
2024-12-01T08:37:51-05:00 TRAC client/server/server.go:197: running client connection
2024-12-01T08:37:51-05:00 INFO client/internal/connect.go:111: starting NetBird client version 0.33.0 on linux/amd64
2024-12-01T08:37:51-05:00 DEBG client/internal/connect.go:166: connecting to the Management service api.netbird.io:443
2024-12-01T08:37:51-05:00 DEBG util/grpc/dialer.go:40: Using nbnet.NewDialer()
2024-12-01T08:37:51-05:00 DEBG util/net/dialer_nonios.go:52: Dialing tcp api.netbird.io:443
2024-12-01T08:37:51-05:00 DEBG client/internal/connect.go:174: connected to the Management service api.netbird.io:443
2024-12-01T08:37:51-05:00 DEBG util/grpc/dialer.go:40: Using nbnet.NewDialer()
2024-12-01T08:37:51-05:00 DEBG util/net/dialer_nonios.go:52: Dialing tcp signal.netbird.io:443
2024-12-01T08:37:51-05:00 DEBG signal/client/grpc.go:83: connected to Signal Service: signal.netbird.io:443
2024-12-01T08:37:51-05:00 INFO client/internal/connect.go:242: connecting to the Relay service(s): rels://relay.netbird.io:443
2024-12-01T08:37:51-05:00 DEBG relay/client/manager.go:95: starting relay client manager with [rels://relay.netbird.io:443] relay servers
2024-12-01T08:37:51-05:00 INFO relay/client/picker.go:66: try to connecting to relay server: rels://relay.netbird.io:443
2024-12-01T08:37:51-05:00 INFO [relay: rels://relay.netbird.io:443] relay/client/client.go:165: create new relay connection: local peerID: heCBbl1wruOxGnun6fpplP2P4Qnf1Hj+Wt6p+ZPb7gc=, local peer hashedID: sha-/mJ/2jan7aZe44Jiw+gPXxjQOTeq5NbNh5TVJAWbGvI=
2024-12-01T08:37:51-05:00 INFO [relay: rels://relay.netbird.io:443] relay/client/client.go:171: connecting to relay server
2024-12-01T08:37:51-05:00 DEBG util/net/dialer_nonios.go:52: Dialing tcp relay.netbird.io:443
2024-12-01T08:37:51-05:00 INFO [relay: rels://streamline-us-nyc1-1.relay.netbird.io:443] relay/client/client.go:188: relay connection established
2024-12-01T08:37:51-05:00 INFO relay/client/picker.go:84: connected to Relay server: rels://relay.netbird.io:443
2024-12-01T08:37:51-05:00 INFO relay/client/picker.go:58: chosen home Relay server: rels://relay.netbird.io:443
2024-12-01T08:37:51-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface br-3ac6c2b00a2b - it is not allowed
2024-12-01T08:37:51-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface docker0 - it is not allowed
2024-12-01T08:37:51-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface br-e08f87324274 - it is not allowed
2024-12-01T08:37:51-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface veth555967d - it is not allowed
2024-12-01T08:37:51-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface vethc9a3b26 - it is not allowed
2024-12-01T08:37:51-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface veth3ef8570 - it is not allowed
2024-12-01T08:37:51-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface vethe3a775c - it is not allowed
2024-12-01T08:37:51-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface vetha4895f0 - it is not allowed
2024-12-01T08:37:51-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface veth47739c8 - it is not allowed
2024-12-01T08:37:51-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface vetha0c7f1b - it is not allowed
2024-12-01T08:37:51-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface veth2390b5c - it is not allowed
2024-12-01T08:37:51-05:00 DEBG client/iface/wgproxy/ebpf/proxy.go:47: instantiate ebpf proxy
2024-12-01T08:37:51-05:00 DEBG client/internal/ebpf/ebpf/wg_proxy_linux.go:11: load ebpf WG proxy
2024-12-01T08:37:51-05:00 INFO client/iface/wgproxy/ebpf/proxy.go:91: local wg proxy listening on: 3128
2024-12-01T08:37:51-05:00 INFO client/iface/wgproxy/factory_kernel.go:29: WireGuard Proxy Factory will produce eBPF proxy
2024-12-01T08:37:51-05:00 INFO client/internal/engine.go:327: rosenpass is enabled
2024-12-01T08:37:51-05:00 INFO client/internal/engine.go:331: running rosenpass in strict mode
2024-12-01T08:37:51-05:00 DEBG client/internal/rosenpass/manager.go:47: generated new rosenpass key pair with public key 7ddd986959cdca4acf953f35553da7689be8d4da5efb3f6fdba1e6221ea3c830
2024-12-01T08:37:51-05:00 INFO client/internal/rosenpass/manager.go:158: starting rosenpass server on port 54446
2024-12-01T08:37:51-05:00 DEBG client/internal/routemanager/sysctl/sysctl_linux.go:87: Set sysctl net.ipv4.conf.all.src_valid_mark from 0 to 1
2024-12-01T08:37:51-05:00 INFO client/internal/routemanager/manager.go:144: Routing setup complete
2024-12-01T08:37:51-05:00 DEBG client/iface/device/wg_link_linux.go:63: adding device: wt0
2024-12-01T08:37:51-05:00 DEBG client/iface/device/wg_link_linux.go:113: adding address 100.75.197.197/16 to interface: wt0
2024-12-01T08:37:51-05:00 DEBG client/iface/device/device_kernel_unix.go:65: setting MTU: 1280 interface: wt0
2024-12-01T08:37:51-05:00 DEBG client/iface/configurer/kernel_unix.go:26: adding Wireguard private key
2024-12-01T08:37:51-05:00 INFO client/firewall/create_linux.go:72: creating an nftables firewall manager
2024-12-01T08:37:51-05:00 DEBG client/firewall/nftables/router_linux.go:702: added iptables rule: [-i wt0 -j ACCEPT]
2024-12-01T08:37:51-05:00 DEBG client/firewall/nftables/router_linux.go:702: added iptables rule: [-o wt0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
2024-12-01T08:37:51-05:00 DEBG client/firewall/nftables/router_linux.go:680: Used iptables to add accept forward rules
2024-12-01T08:37:51-05:00 DEBG client/iface/device/device_kernel_unix.go:89: bringing up interface: wt0
2024-12-01T08:37:51-05:00 DEBG client/internal/statemanager/manager.go:205: persisted shutdown states: [nftables_state], took 180.682µs
2024-12-01T08:37:51-05:00 DEBG client/iface/device/device_kernel_unix.go:111: device is ready to use: wt0
2024-12-01T08:37:51-05:00 TRAC client/internal/dns/dbus_unix.go:28: error calling dbus: The name org.freedesktop.resolve1 was not provided by any .service files
2024-12-01T08:37:51-05:00 INFO client/internal/dns/host_unix.go:54: System DNS manager discovered: resolvconf
2024-12-01T08:37:51-05:00 DEBG signal/client/grpc.go:128: signal connection state READY
2024-12-01T08:37:51-05:00 INFO client/internal/peer/guard/sr_watcher.go:106: reconnected to Signal or Relay server
2024-12-01T08:37:51-05:00 INFO signal/client/grpc.go:149: connected to the Signal Service stream
2024-12-01T08:37:51-05:00 DEBG client/internal/engine.go:697: connecting to Management Service updates stream
2024-12-01T08:37:51-05:00 INFO client/internal/engine.go:1419: Network monitor is disabled, not starting
2024-12-01T08:37:51-05:00 INFO client/internal/connect.go:270: Netbird engine started, the IP is: 100.75.197.197/16
2024-12-01T08:37:51-05:00 DEBG management/client/grpc.go:114: management connection state READY
2024-12-01T08:37:52-05:00 INFO management/client/grpc.go:155: connected to the Management Service stream
2024-12-01T08:37:52-05:00 DEBG management/client/grpc.go:252: got an update message from Management Service
2024-12-01T08:37:52-05:00 DEBG client/internal/engine.go:723: got TURNs update from Management Service, updating
2024-12-01T08:37:52-05:00 DEBG client/internal/engine.go:705: got STUNs update from Management Service, updating
2024-12-01T08:37:52-05:00 WARN client/internal/engine.go:597: running SSH server is not permitted
2024-12-01T08:37:52-05:00 INFO client/internal/acl/manager.go:61: ACL rules processed in: 2.376838ms, total rules count: 2
2024-12-01T08:37:52-05:00 DEBG client/internal/engine.go:773: got peers update from Management Service, total peers to connect to = 1
2024-12-01T08:37:52-05:00 DEBG client/internal/engine.go:958: creating peer connection qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=
2024-12-01T08:37:52-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:174: open connection to peer
2024-12-01T08:37:52-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/handshaker.go:79: wait for remote offer confirmation
2024-12-01T08:37:52-05:00 DEBG client/internal/dns/service_listener.go:69: starting dns on 100.75.197.197:53
2024-12-01T08:37:52-05:00 ERRO client/internal/dns/server.go:322: apply config: applying resolvconf configuration for wt0 interface: exit status 99
2024-12-01T08:37:52-05:00 DEBG client/internal/statemanager/manager.go:205: persisted shutdown states: [dns_state], took 192.463µs
2024-12-01T08:37:52-05:00 TRAC signal/client/grpc.go:403: received a new message from Peer [fingerprint: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=]
2024-12-01T08:37:52-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:283: OnRemoteOffer, on status ICE: Disconnected, status Relay: Disconnected
2024-12-01T08:37:52-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/handshaker.go:171: sending answer
2024-12-01T08:37:53-05:00 INFO [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/guard/guard.go:138: start listen for reconnect events...
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/handshaker.go:91: received connection confirmation, running version 0.33.0 and with remote WireGuard listen port 51820
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/handshaker.go:79: wait for remote offer confirmation
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:87: OnNewOffer for ICE
2024-12-01T08:37:53-05:00 DEBG relay/client/manager.go:137: open peer connection via foreign server: rels://streamline-us-nyc1-2.relay.netbird.io:443
2024-12-01T08:37:53-05:00 INFO [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:165: create new relay connection: local peerID: heCBbl1wruOxGnun6fpplP2P4Qnf1Hj+Wt6p+ZPb7gc=, local peer hashedID: sha-/mJ/2jan7aZe44Jiw+gPXxjQOTeq5NbNh5TVJAWbGvI=
2024-12-01T08:37:53-05:00 INFO [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:171: connecting to relay server
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:105: recreate ICE agent
2024-12-01T08:37:53-05:00 DEBG util/net/dialer_nonios.go:52: Dialing tcp streamline-us-nyc1-2.relay.netbird.io:443
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface br-3ac6c2b00a2b - it is not allowed
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface docker0 - it is not allowed
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface br-e08f87324274 - it is not allowed
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface veth555967d - it is not allowed
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface vethc9a3b26 - it is not allowed
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface veth3ef8570 - it is not allowed
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface vethe3a775c - it is not allowed
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface vetha4895f0 - it is not allowed
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface veth47739c8 - it is not allowed
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface vetha0c7f1b - it is not allowed
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface veth2390b5c - it is not allowed
2024-12-01T08:37:53-05:00 TRAC client/internal/stdnet/filter.go:24: ignoring interface wt0 - it is not allowed
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:116: gather candidates
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:126: turn agent dial
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:219: ICE ConnectionState has changed to Checking
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:297: discovered local candidate udp4 host 198.51.100.0:51820
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:297: discovered local candidate udp4 srflx 198.51.100.0:51820 related 0.0.0.0:51820
2024-12-01T08:37:53-05:00 INFO [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:188: relay connection established
2024-12-01T08:37:53-05:00 INFO [relay: rels://streamline-us-nyc1-2.relay.netbird.io:443] relay/client/client.go:217: open connection to peer: sha-brMfdPjCp7U2FG0haITs30DcW0bYZU60avWnjqF9cL0=
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_relay.go:97: peer conn opened via Relay: rels://streamline-us-nyc1-2.relay.netbird.io:443
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:433: Relay connection has been established, setup the WireGuard
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:693: setup proxied WireGuard connection
2024-12-01T08:37:53-05:00 INFO client/iface/wgproxy/ebpf/proxy.go:102: turn conn added to wg proxy store: rels://streamline-us-nyc1-2.relay.netbird.io:443, endpoint port: :1
2024-12-01T08:37:53-05:00 INFO [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:441: created new wgProxy for relay connection: 127.0.0.1:1
2024-12-01T08:37:53-05:00 DEBG client/iface/iface.go:116: updating interface wt0 peer qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=, endpoint 127.0.0.1:1
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_relay.go:106: enable WireGuard watcher
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_relay.go:161: WireGuard watcher started
2024-12-01T08:37:53-05:00 INFO [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:470: start to communicate with peer via relay
2024-12-01T08:37:53-05:00 DEBG client/internal/rosenpass/manager.go:186: received remote rosenpass key 9deda0666f38fcb9f85a3f1ed45296b925b6d0c085c8b66c79c2e70d51adacba, my key 7ddd986959cdca4acf953f35553da7689be8d4da5efb3f6fdba1e6221ea3c830
2024-12-01T08:37:53-05:00 TRAC signal/client/grpc.go:403: received a new message from Peer [fingerprint: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=]
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:256: OnRemoteAnswer, status ICE: Disconnected, status relay: Connected
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/handshaker.go:91: received connection confirmation, running version 0.33.0 and with remote WireGuard listen port 51820
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/handshaker.go:79: wait for remote offer confirmation
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:87: OnNewOffer for ICE
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:91: agent already exists, skipping the offer
2024-12-01T08:37:53-05:00 DEBG relay/client/manager.go:137: open peer connection via foreign server: rels://streamline-us-nyc1-2.relay.netbird.io:443
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_relay.go:79: handled offer by reusing existing relay connection
2024-12-01T08:37:53-05:00 TRAC signal/client/grpc.go:403: received a new message from Peer [fingerprint: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=]
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:169: OnRemoteCandidate from peer qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM= -> udp4 host 198.51.100.4:51820
2024-12-01T08:37:53-05:00 DEBG client/iface/bind/udp_mux.go:346: ICE: registered 198.51.100.4:51820 for YuhUXzfQOKjFSSdA
2024-12-01T08:37:53-05:00 DEBG client/iface/bind/udp_mux.go:346: ICE: registered 198.51.100.4:51820 for YuhUXzfQOKjFSSdAturns:turn.netbird.io:443?transport=tcp
2024-12-01T08:37:53-05:00 TRAC signal/client/grpc.go:403: received a new message from Peer [fingerprint: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=]
2024-12-01T08:37:53-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:169: OnRemoteCandidate from peer qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM= -> udp4 srflx 198.51.100.4:51820 related 0.0.0.0:51820
2024-12-01T08:37:54-05:00 TRAC signal/client/grpc.go:403: received a new message from Peer [fingerprint: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=]
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:283: OnRemoteOffer, on status ICE: Disconnected, status Relay: Connected
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/handshaker.go:171: sending answer
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/handshaker.go:91: received connection confirmation, running version 0.33.0 and with remote WireGuard listen port 51820
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/handshaker.go:79: wait for remote offer confirmation
2024-12-01T08:37:54-05:00 DEBG relay/client/manager.go:137: open peer connection via foreign server: rels://streamline-us-nyc1-2.relay.netbird.io:443
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_relay.go:79: handled offer by reusing existing relay connection
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:87: OnNewOffer for ICE
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:91: agent already exists, skipping the offer
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:132: agent dial succeeded
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:161: on ICE conn read to use ready
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:219: ICE ConnectionState has changed to Connected
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:317: ICE connection is ready
2024-12-01T08:37:54-05:00 INFO [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/conn.go:325: set ICE to active connection
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_relay.go:129: disable WireGuard watcher
2024-12-01T08:37:54-05:00 TRAC client/iface/wgproxy/ebpf/wrapper.go:66: pause proxy reading from: rels://streamline-us-nyc1-2.relay.netbird.io:443
2024-12-01T08:37:54-05:00 DEBG client/iface/iface.go:116: updating interface wt0 peer qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=, endpoint 198.51.100.4:51820
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_ice.go:327: selected candidate pair [local <-> remote] -> [udp4 host 198.51.100.0:51820 <-> udp4 host 198.51.100.4:51820], peer qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=
2024-12-01T08:37:54-05:00 DEBG [peer: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=] client/internal/peer/worker_relay.go:198: WireGuard watcher stopped
2024-12-01T08:37:54-05:00 DEBG client/internal/rosenpass/manager.go:186: received remote rosenpass key 9deda0666f38fcb9f85a3f1ed45296b925b6d0c085c8b66c79c2e70d51adacba, my key 7ddd986959cdca4acf953f35553da7689be8d4da5efb3f6fdba1e6221ea3c830
2024-12-01T08:37:55-05:00 DEBG client/internal/engine.go:1350: received management probe request, healthy: true
2024-12-01T08:37:55-05:00 DEBG client/internal/engine.go:1342: received signal probe request, healthy: true
2024-12-01T08:37:55-05:00 DEBG util/net/dialer_nonios.go:52: Dialing udp stun.netbird.io:5555
2024-12-01T08:37:55-05:00 DEBG client/internal/relay/relay.go:66: stun probe received address from stun:stun.netbird.io:5555: 198.51.100.0:58204
2024-12-01T08:37:55-05:00 DEBG util/net/dialer_nonios.go:52: Dialing tcp turn.netbird.io:443
2024-12-01T08:37:55-05:00 DEBG client/internal/relay/relay.go:158: turn probe relay address from turns:turn.netbird.io:443?transport=tcp: 198.51.100.7:62776
2024-12-01T08:37:55-05:00 DEBG client/internal/engine.go:1370: received relay probe request, healthy: true
2024-12-01T08:37:55-05:00 DEBG client/internal/engine.go:1377: received wg probe request
2024-12-01T08:40:55-05:00 DEBG client/internal/engine.go:1350: received management probe request, healthy: true
2024-12-01T08:40:55-05:00 DEBG client/internal/engine.go:1342: received signal probe request, healthy: true
2024-12-01T08:40:55-05:00 DEBG util/net/dialer_nonios.go:52: Dialing udp stun.netbird.io:5555
2024-12-01T08:40:55-05:00 DEBG client/internal/relay/relay.go:66: stun probe received address from stun:stun.netbird.io:5555: 198.51.100.0:55088
2024-12-01T08:40:55-05:00 DEBG util/net/dialer_nonios.go:52: Dialing tcp turn.netbird.io:443
2024-12-01T08:40:55-05:00 DEBG client/internal/relay/relay.go:158: turn probe relay address from turns:turn.netbird.io:443?transport=tcp: 198.51.100.5:27961
2024-12-01T08:40:55-05:00 DEBG client/internal/engine.go:1370: received relay probe request, healthy: true
2024-12-01T08:40:55-05:00 DEBG client/internal/engine.go:1377: received wg probe request

Status

----- Netbird post-up - Timestamp: 2024-12-01T08:37:54-05:00
Peers detail:
 c1.netbird.cloud:
  NetBird IP: 100.75.221.194
  Public key: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=
  Status: Connected
  -- detail --
  Connection type: P2P
  ICE candidate (Local/Remote): host/host
  ICE candidate endpoints (Local/Remote): 198.51.100.0:51820/198.51.100.1:51820
  Relay server address: rels://streamline-us-nyc1-2.relay.netbird.io:443
  Last connection update: Now
  Last WireGuard handshake: 2 seconds ago
  Transfer status (received/sent) 92 B/180 B
  Quantum resistance: true
  Routes: -
  Latency: 509.244µs

OS: linux/amd64
Daemon version: 0.33.0
CLI version: 0.33.0
Management: Connected to https://api.netbird.io:443
Signal: Connected to https://signal.netbird.io:443
Relays: 
  [stun:stun.netbird.io:5555] is Available
  [turns:turn.netbird.io:443?transport=tcp] is Available
  [rels://streamline-us-nyc1-1.relay.netbird.io:443] is Available
Nameservers: 
  [9.9.9.9:53, 149.112.112.112:53] for [.] is Available
FQDN: c2.netbird.cloud
NetBird IP: 100.75.197.197/16
Interface type: Kernel
Quantum resistance: true
Routes: -
Peers count: 1/1 Connected

----- Netbird pre-down - Timestamp: 2024-12-01T08:40:55-05:00 - Duration: 3m0s
Peers detail:
 c1.netbird.cloud:
  NetBird IP: 100.75.221.194
  Public key: qrU64BbwDjOtz7UMLK1SuGjn1UJSl+i63pJcrc3hsCM=
  Status: Connected
  -- detail --
  Connection type: P2P
  ICE candidate (Local/Remote): host/host
  ICE candidate endpoints (Local/Remote): 198.51.100.0:51820/198.51.100.1:51820
  Relay server address: rels://streamline-us-nyc1-2.relay.netbird.io:443
  Last connection update: 3 minutes ago
  Last WireGuard handshake: 48 seconds ago
  Transfer status (received/sent) 184 B/552 BResult of running `netbird debug for 3m -AS` (should be long enough for initial key exchange and 2 minute update)
  Quantum resistance: true
  Routes: -
  Latency: 642.976µs

OS: linux/amd64
Daemon version: 0.33.0
CLI version: 0.33.0
Management: Connected to https://api.netbird.io:443
Signal: Connected to https://signal.netbird.io:443
Relays: 
  [stun:stun.netbird.io:5555] is Available
  [turns:turn.netbird.io:443?transport=tcp] is Available
  [rels://streamline-us-nyc1-1.relay.netbird.io:443] is Available
Nameservers: 
  [9.9.9.9:53, 149.112.112.112:53] for [.] is Available
FQDN: c2.netbird.cloud
NetBird IP: 100.75.197.197/16
Interface type: Kernel
Quantum resistance: true
Routes: -
Peers count: 1/1 Connected

Hopefully I'm just missing something, but I'm scrating my head. Thanks for the amazing project!

mgarces commented 1 day ago

hello @cdestefano we believe we found an issue with Rosepass implementation and we will work on a fix. Thanks for reporting this.