diff --git a/client/internal/peer/conn.go b/client/internal/peer/conn.go index fb468696f83..7dcb537707a 100644 --- a/client/internal/peer/conn.go +++ b/client/internal/peer/conn.go @@ -803,17 +803,15 @@ func (conn *Conn) isConnectedOnAllWay() (status guard.ConnStatus) { } func (conn *Conn) enableWgWatcherIfNeeded(enabledTime time.Time) { - if !conn.wgWatcher.PrepareInitialHandshake() { - return + if !conn.wgWatcher.IsEnabled() { + wgWatcherCtx, wgWatcherCancel := context.WithCancel(conn.ctx) + conn.wgWatcherCancel = wgWatcherCancel + conn.wgWatcherWg.Add(1) + go func() { + defer conn.wgWatcherWg.Done() + conn.wgWatcher.EnableWgWatcher(wgWatcherCtx, enabledTime, conn.onWGDisconnected, conn.onWGHandshakeSuccess) + }() } - - wgWatcherCtx, wgWatcherCancel := context.WithCancel(conn.ctx) - conn.wgWatcherCancel = wgWatcherCancel - conn.wgWatcherWg.Add(1) - go func() { - defer conn.wgWatcherWg.Done() - conn.wgWatcher.EnableWgWatcher(wgWatcherCtx, enabledTime, conn.onWGDisconnected, conn.onWGHandshakeSuccess) - }() } func (conn *Conn) disableWgWatcherIfNeeded() { @@ -932,18 +930,22 @@ func (conn *Conn) AgentVersionString() string { func (conn *Conn) presharedKey(remoteRosenpassKey []byte) *wgtypes.Key { if conn.config.RosenpassConfig.PubKey == nil { + conn.Log.Warnf("PSK-DIAG: rosenpass off -> static PSK (present=%v)", conn.config.WgConfig.PreSharedKey != nil) return conn.config.WgConfig.PreSharedKey } if remoteRosenpassKey == nil && conn.config.RosenpassConfig.PermissiveMode { + conn.Log.Warnf("PSK-DIAG: rosenpass permissive + no remote RP key -> static PSK bridge (present=%v)", conn.config.WgConfig.PreSharedKey != nil) return conn.config.WgConfig.PreSharedKey } // If Rosenpass has already set a PSK for this peer, return nil to prevent // UpdatePeer from overwriting the Rosenpass-managed key. if conn.rosenpassInitializedPresharedKeyValidator != nil && conn.rosenpassInitializedPresharedKeyValidator(conn.config.Key) { + conn.Log.Warnf("PSK-DIAG: rosenpass initialized -> returning nil (keep existing on-wire PSK; NOT re-set)") return nil } + conn.Log.Warnf("PSK-DIAG: rosenpass strict, not yet initialized -> seeding PSK (staticPresent=%v)", conn.config.WgConfig.PreSharedKey != nil) // Use NetBird PSK as the seed for Rosenpass. This same PSK is passed to // Rosenpass as PeerConfig.PresharedKey, ensuring the derived post-quantum diff --git a/client/internal/peer/endpoint.go b/client/internal/peer/endpoint.go index 9ba1efb6eb3..302ac01dc7b 100644 --- a/client/internal/peer/endpoint.go +++ b/client/internal/peer/endpoint.go @@ -38,6 +38,8 @@ func (e *EndpointUpdater) ConfigureWGEndpoint(addr *net.UDPAddr, presharedKey *w e.mu.Lock() defer e.mu.Unlock() + e.log.Warnf("PSK-DIAG: ConfigureWGEndpoint endpoint=%s psk_present=%v", addr, presharedKey != nil) + if e.initiator { e.log.Debugf("configure up WireGuard as initiator") return e.configureAsInitiator(addr, presharedKey) @@ -51,6 +53,8 @@ func (e *EndpointUpdater) SwitchWGEndpoint(addr *net.UDPAddr, presharedKey *wgty e.mu.Lock() defer e.mu.Unlock() + e.log.Warnf("PSK-DIAG: SwitchWGEndpoint endpoint=%s psk_present=%v", addr, presharedKey != nil) + // prevent to run new update while cancel the previous update e.waitForCloseTheDelayedUpdate() @@ -69,6 +73,8 @@ func (e *EndpointUpdater) RemoveEndpointAddress() error { e.mu.Lock() defer e.mu.Unlock() + e.log.Warnf("PSK-DIAG: RemoveEndpointAddress -> peer re-added with only PublicKey+AllowedIPs; on-wire PSK is dropped") + e.waitForCloseTheDelayedUpdate() return e.wgConfig.WgInterface.RemoveEndpointAddress(e.wgConfig.RemoteKey) } diff --git a/client/internal/peer/wg_watcher.go b/client/internal/peer/wg_watcher.go index 4fc883d1761..e40ab85bfc8 100644 --- a/client/internal/peer/wg_watcher.go +++ b/client/internal/peer/wg_watcher.go @@ -31,9 +31,7 @@ type WGWatcher struct { stateDump *stateDump enabled bool - muEnabled sync.Mutex - // initialHandshake is not thread-safe; never call PrepareInitialHandshake and EnableWgWatcher concurrently. - initialHandshake time.Time + muEnabled sync.RWMutex resetCh chan struct{} } @@ -48,38 +46,40 @@ func NewWGWatcher(log *log.Entry, wgIfaceStater WGInterfaceStater, peerKey strin } } -// PrepareInitialHandshake reserves the watcher and reads the peer's current WireGuard -// handshake time. It must be called before the peer is (re)configured on the WireGuard -// interface, so the captured baseline reflects the state prior to this connection attempt -// instead of racing with that configuration. Returns ok=false if the watcher is already -// running, in which case EnableWgWatcher must not be called. -func (w *WGWatcher) PrepareInitialHandshake() (ok bool) { +// EnableWgWatcher starts the WireGuard watcher. If it is already enabled, it will return immediately and do nothing. +// The watcher runs until ctx is cancelled. Caller is responsible for context lifecycle management. +// NOTE: reverted to the pre-#6626 shape for bisecting the NHN issue. +func (w *WGWatcher) EnableWgWatcher(ctx context.Context, enabledTime time.Time, onDisconnectedFn func(), onHandshakeSuccessFn func(when time.Time)) { w.muEnabled.Lock() if w.enabled { w.muEnabled.Unlock() - return false + return } w.log.Debugf("enable WireGuard watcher") w.enabled = true w.muEnabled.Unlock() - handshake, _ := w.wgState() - w.initialHandshake = handshake - return true -} + initialHandshake, err := w.wgState() + if err != nil { + w.log.Warnf("failed to read initial wg stats: %v", err) + } + w.log.Warnf("PSK-DIAG: watcher baseline handshake=%v (zero=%v) [pre-6626 revert]", initialHandshake, initialHandshake.IsZero()) -// EnableWgWatcher runs the WireGuard watcher loop using the handshake baseline captured by -// PrepareInitialHandshake. The watcher runs until ctx is cancelled. Caller is responsible -// for context lifecycle management. -func (w *WGWatcher) EnableWgWatcher(ctx context.Context, enabledTime time.Time, onDisconnectedFn func(), onHandshakeSuccessFn func(when time.Time)) { - w.periodicHandshakeCheck(ctx, onDisconnectedFn, onHandshakeSuccessFn, enabledTime, w.initialHandshake) + w.periodicHandshakeCheck(ctx, onDisconnectedFn, onHandshakeSuccessFn, enabledTime, initialHandshake) w.muEnabled.Lock() w.enabled = false w.muEnabled.Unlock() } +// IsEnabled returns true if the WireGuard watcher is currently enabled +func (w *WGWatcher) IsEnabled() bool { + w.muEnabled.RLock() + defer w.muEnabled.RUnlock() + return w.enabled +} + // Reset signals the watcher that the WireGuard peer has been reset and a new // handshake is expected. This restarts the handshake timeout from scratch. func (w *WGWatcher) Reset() { @@ -92,6 +92,7 @@ func (w *WGWatcher) Reset() { // wgStateCheck help to check the state of the WireGuard handshake and relay connection func (w *WGWatcher) periodicHandshakeCheck(ctx context.Context, onDisconnectedFn func(), onHandshakeSuccessFn func(when time.Time), enabledTime time.Time, initialHandshake time.Time) { w.log.Infof("WireGuard watcher started") + w.log.Warnf("WGW-DIAG: watcher started id=%d baseline=%v (zero=%v) firstCheckIn=%v", enabledTime.UnixNano(), initialHandshake, initialHandshake.IsZero(), wgHandshakeOvertime) timer := time.NewTimer(wgHandshakeOvertime) defer timer.Stop() @@ -101,18 +102,17 @@ func (w *WGWatcher) periodicHandshakeCheck(ctx context.Context, onDisconnectedFn for { select { case <-timer.C: + w.log.Warnf("WGW-DIAG: check fire id=%d lastHandshake=%v", enabledTime.UnixNano(), lastHandshake) handshake, ok := w.handshakeCheck(lastHandshake) if !ok { - if ctx.Err() != nil { - return - } + w.log.Warnf("WGW-DIAG: check failed -> firing onDisconnected (TEARDOWN, pre-6626 no ctx-recheck) id=%d", enabledTime.UnixNano()) onDisconnectedFn() return } if lastHandshake.IsZero() { elapsed := calcElapsed(enabledTime, *handshake) w.log.Infof("first wg handshake detected within: %.2fsec, (%s)", elapsed, handshake) - if onHandshakeSuccessFn != nil && ctx.Err() == nil { + if onHandshakeSuccessFn != nil { onHandshakeSuccessFn(*handshake) } } @@ -123,15 +123,15 @@ func (w *WGWatcher) periodicHandshakeCheck(ctx context.Context, onDisconnectedFn timer.Reset(resetTime) w.stateDump.WGcheckSuccess() - w.log.Debugf("WireGuard watcher reset timer: %v", resetTime) + w.log.Warnf("WGW-DIAG: check ok id=%d handshake=%v nextCheckIn=%v", enabledTime.UnixNano(), handshake, resetTime) case <-w.resetCh: - w.log.Infof("WireGuard watcher received peer reset, restarting handshake timeout") + w.log.Warnf("WGW-DIAG: peer reset received, restarting timeout id=%d", enabledTime.UnixNano()) lastHandshake = time.Time{} enabledTime = time.Now() timer.Stop() timer.Reset(wgHandshakeOvertime) case <-ctx.Done(): - w.log.Infof("WireGuard watcher stopped") + w.log.Warnf("WGW-DIAG: watcher stopped (ctx done) id=%d", enabledTime.UnixNano()) return } } diff --git a/client/internal/peer/wg_watcher_test.go b/client/internal/peer/wg_watcher_test.go index 634d7974fbf..3ce91cd466e 100644 --- a/client/internal/peer/wg_watcher_test.go +++ b/client/internal/peer/wg_watcher_test.go @@ -7,7 +7,6 @@ import ( "time" log "github.com/sirupsen/logrus" - "github.com/stretchr/testify/require" "github.com/netbirdio/netbird/client/iface/configurer" ) @@ -35,9 +34,6 @@ func TestWGWatcher_EnableWgWatcher(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() - ok := watcher.PrepareInitialHandshake() - require.True(t, ok, "watcher should not be enabled yet") - onDisconnected := make(chan struct{}, 1) go watcher.EnableWgWatcher(ctx, time.Now(), func() { mlog.Infof("onDisconnectedFn") @@ -66,9 +62,6 @@ func TestWGWatcher_ReEnable(t *testing.T) { watcher := NewWGWatcher(mlog, mocWgIface, "", newStateDump("peer", mlog, &Status{})) ctx, cancel := context.WithCancel(context.Background()) - ok := watcher.PrepareInitialHandshake() - require.True(t, ok, "watcher should not be enabled yet") - wg := &sync.WaitGroup{} wg.Add(1) go func() { @@ -83,9 +76,6 @@ func TestWGWatcher_ReEnable(t *testing.T) { ctx, cancel = context.WithCancel(context.Background()) defer cancel() - ok = watcher.PrepareInitialHandshake() - require.True(t, ok, "watcher should be re-enabled after the previous run stopped") - onDisconnected := make(chan struct{}, 1) go watcher.EnableWgWatcher(ctx, time.Now(), func() { onDisconnected <- struct{}{} diff --git a/client/internal/rosenpass/manager.go b/client/internal/rosenpass/manager.go index 90375375337..6e33e75727a 100644 --- a/client/internal/rosenpass/manager.go +++ b/client/internal/rosenpass/manager.go @@ -82,9 +82,15 @@ func (m *Manager) GetPubKey() []byte { return m.spk } -// GetAddress returns the address of the Rosenpass server +// GetAddress returns the address of the Rosenpass server. +// +// The server binds v4-only (0.0.0.0). Rosenpass reaches peers over their +// WireGuard overlay IP, which is always IPv4, so a v4 socket suffices. This +// avoids the AF_INET6 -> IPv4 send rejection (EDESTADDRREQ) that a [::] +// (dual-stack) socket hits on macOS/BSD when sending to a 4-byte IPv4 +// destination. func (m *Manager) GetAddress() *net.UDPAddr { - return &net.UDPAddr{Port: m.port} + return &net.UDPAddr{IP: net.IPv4zero, Port: m.port} } // addPeer adds a new peer to the Rosenpass server @@ -109,20 +115,14 @@ func (m *Manager) addPeer(rosenpassPubKey []byte, rosenpassAddr string, wireGuar if err != nil { return fmt.Errorf("failed to parse rosenpass address: %w", err) } + // Resolve as udp4: our Rosenpass server binds v4-only (see GetAddress) + // and the peer WireGuard overlay IP is always IPv4. This keeps the + // destination a 4-byte IPv4 address that matches our v4 listening + // socket, avoiding the AF_INET6 -> IPv4 send rejection on macOS/BSD. peerAddr := net.JoinHostPort(wireGuardIP, strPort) - if pcfg.Endpoint, err = net.ResolveUDPAddr("udp", peerAddr); err != nil { + if pcfg.Endpoint, err = net.ResolveUDPAddr("udp4", peerAddr); err != nil { return fmt.Errorf("failed to resolve peer endpoint address: %w", err) } - // Our local Rosenpass UDP server binds on the IPv6 wildcard ([::]) — see - // GetAddress(). The remote peer's endpoint (pcfg.Endpoint) is the destination - // our server will sendto when initiating handshakes. ResolveUDPAddr returns a - // 4-byte IPv4 for IPv4 hosts, which the kernel rejects (EDESTADDRREQ) when - // sent from an AF_INET6 socket. Normalize the remote endpoint to IPv4-mapped - // IPv6 so its address family matches our listening socket. - // TODO: maybe bind the Rosenpass UDP server to the peer wg IP addr - if v4 := pcfg.Endpoint.IP.To4(); v4 != nil { - pcfg.Endpoint.IP = v4.To16() - } } peerID, err := m.server.AddPeer(pcfg) if err != nil { @@ -280,13 +280,15 @@ func (m *Manager) OnConnected(remoteWireGuardKey string, remoteRosenpassPubKey [ } rpKeyHash := hashRosenpassKey(remoteRosenpassPubKey) - log.Debugf("received remote rosenpass key %s, my key %s", rpKeyHash, m.rpKeyHash) + initiator := bytes.Compare(m.spk, remoteRosenpassPubKey) == 1 + log.Warnf("PSK-DIAG: remote peer %s advertises rosenpass (key %s, addr %s); starting RP negotiation as initiator=%v", remoteWireGuardKey, rpKeyHash, remoteRosenpassAddr, initiator) err := m.addPeer(remoteRosenpassPubKey, remoteRosenpassAddr, wireGuardIP, remoteWireGuardKey) if err != nil { log.Errorf("failed to add rosenpass peer: %s", err) return } + log.Warnf("PSK-DIAG: rosenpass peer added for %s (RP negotiation started; watch for 'set PSK on WG' to confirm completion)", remoteWireGuardKey) } // IsPresharedKeyInitialized returns true if Rosenpass has completed a handshake diff --git a/client/internal/rosenpass/netbird_handler.go b/client/internal/rosenpass/netbird_handler.go index 9de2409ef93..8fa4a50571d 100644 --- a/client/internal/rosenpass/netbird_handler.go +++ b/client/internal/rosenpass/netbird_handler.go @@ -100,6 +100,7 @@ func (h *NetbirdHandler) outputKey(_ rp.KeyOutputReason, pid rp.PeerID, psk rp.K log.Errorf("Failed to apply rosenpass key: %v", err) return } + log.Warnf("PSK-DIAG: rosenpass set PSK on WG for peer %s (updateOnly=%v)", peerKey, isInitialized) // Mark peer as isInitialized after the successful first rotation if !isInitialized { diff --git a/client/internal/routemanager/client/client.go b/client/internal/routemanager/client/client.go index c691c54f8a7..fea97a3d491 100644 --- a/client/internal/routemanager/client/client.go +++ b/client/internal/routemanager/client/client.go @@ -231,11 +231,15 @@ func (w *Watcher) getBestRouteFromStatuses(routePeerStatuses map[route.ID]router switch { case chosen == "": var peers []string - for _, r := range w.routes { - peers = append(peers, r.Peer) + for id, r := range w.routes { + st := "unknown(no status)" + if ps, ok := routePeerStatuses[id]; ok { + st = fmt.Sprintf("%s relayed=%v lat=%v", ps.status, ps.relayed, ps.latency) + } + peers = append(peers, fmt.Sprintf("%s{%s}", r.Peer, st)) } - log.Infof("network [%v] has not been assigned a routing peer as no peers from the list %s are currently available", w.handler, peers) + log.Warnf("ROUTE-DIAG: network [%v] no routing peer available yet (all candidates connecting/absent); candidates: %s", w.handler, peers) case chosen != currID: // we compare the current score + 10ms to the chosen score to avoid flapping between routes if currScore != 0 && currScore+0.01 > chosenScore { @@ -247,7 +251,7 @@ func (w *Watcher) getBestRouteFromStatuses(routePeerStatuses map[route.ID]router if rt := w.routes[chosen]; rt != nil { p = rt.Peer } - log.Infof("New chosen route is %s with peer %s with score %f for network [%v]", chosen, p, chosenScore, w.handler) + log.Warnf("ROUTE-DIAG: new chosen route %s peer %s score %f for network [%v] (routing peer now usable)", chosen, p, chosenScore, w.handler) } return chosen, chosenStatus