Skip to content

[client] Diagnostic logs #6681

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
riccardomanfrin wants to merge 6 commits into
base: main
Choose a base branch
from
Open

[client] Diagnostic logs #6681

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
8012294
Add logs for Rosenpass to check for lost key
riccardomanfrin Jul 6, 2026
0860660
Adds logs for 6626
riccardomanfrin Jul 6, 2026
bf9de56
Route diagnostics
riccardomanfrin Jul 6, 2026
2f3bf5b
[client] diag: log remote rosenpass key presence + RP negotiation start
riccardomanfrin Jul 7, 2026
dd20a40
Revert "[client] Fix race between WG watcher initial handshake read a…
riccardomanfrin Jul 7, 2026
e24ae10
Revert V4 mapped to V6 not working on Darwin/Freebsd for V6 netbird
riccardomanfrin Jul 7, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions client/internal/peer/conn.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -932,18 +932,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
Expand Down
6 changes: 6 additions & 0 deletions client/internal/peer/endpoint.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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()

Expand All @@ -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)
}
Expand Down
14 changes: 11 additions & 3 deletions client/internal/peer/wg_watcher.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -66,6 +66,7 @@ func (w *WGWatcher) PrepareInitialHandshake() (ok bool) {

handshake, _ := w.wgState()
w.initialHandshake = handshake
w.log.Warnf("PSK-DIAG: watcher baseline handshake=%v (zero=%v)", handshake, handshake.IsZero())
return true
}

Expand All @@ -92,6 +93,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()
Expand All @@ -101,11 +103,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 {
// #6626 race check: a superseded/cancelled watcher must not tear
// down a now-healthy connection. Log which branch we take so a
// bundle shows whether teardowns fire on live vs cancelled ctx.
if ctx.Err() != nil {
w.log.Warnf("WGW-DIAG: check failed but ctx cancelled -> standing down, NO teardown id=%d", enabledTime.UnixNano())
return
}
w.log.Warnf("WGW-DIAG: check failed, ctx live -> firing onDisconnected (TEARDOWN) id=%d", enabledTime.UnixNano())
onDisconnectedFn()
return
}
Expand All @@ -123,15 +131,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
}
}
Expand Down
1 change: 1 addition & 0 deletions client/internal/rosenpass/netbird_handler.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
12 changes: 8 additions & 4 deletions client/internal/routemanager/client/client.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Comment on lines +234 to +242

@coderabbitai coderabbitai Bot Jul 6, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🎯 Functional Correctness | 🟡 Minor | ⚡ Quick win

Format the candidate list as a string.

peers is a []string, so %s will not render the troubleshooting snapshot correctly here. Use %v or strings.Join(peers, ", ") to avoid malformed log output.

🐛 Proposed fix 
-		log.Warnf("ROUTE-DIAG: network [%v] no routing peer available yet (all candidates connecting/absent); candidates: %s", w.handler, peers)
+		log.Warnf("ROUTE-DIAG: network [%v] no routing peer available yet (all candidates connecting/absent); candidates: %v", w.handler, peers)
📝 Committable suggestion

‼️ IMPORTANT
Carefully review the code before committing. Ensure that it accurately replaces the highlighted code, contains no missing lines, and has no issues with indentation. Thoroughly test & benchmark the code to ensure it meets the requirements.

Suggested change
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)
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.Warnf("ROUTE-DIAG: network [%v] no routing peer available yet (all candidates connecting/absent); candidates: %v", w.handler, peers)
🤖 Prompt for AI Agents 
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@client/internal/routemanager/client/client.go` around lines 234 - 242, The
troubleshooting log in the route manager is formatting the candidate list
incorrectly because peers is a []string but the warning in the route-diagnostics
block uses a string formatter. Update the log call in the ROUTE-DIAG path inside
the loop over w.routes so the candidates are rendered with a slice-aware format
like %v or by joining peers into a single string before logging. Keep the rest
of the snapshot construction in place using routePeerStatuses, st, and
w.handler.

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 {
Expand All @@ -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
Expand Down
Loading