[client] Debug information for connection (#4439)

Improve logging

Print the exact time when the first WireGuard handshake occurs
Print the steps for gathering system information

Author: pappz

client/iface/configurer/usp.go

@@ -394,6 +394,13 @@ func toLastHandshake(stringVar string) (time.Time, error) {
 	if err != nil {
 		return time.Time{}, fmt.Errorf("parse handshake sec: %w", err)
 	}
+
+	// If sec is 0 (Unix epoch), return zero time instead
+	// This indicates no handshake has occurred
+	if sec == 0 {
+		return time.Time{}, nil
+	}
+
 	return time.Unix(sec, 0), nil
 }
 

client/internal/engine.go

@@ -949,7 +949,6 @@ func (e *Engine) receiveManagementEvents() {
 			e.config.LazyConnectionEnabled,
 		)
 
-		// err = e.mgmClient.Sync(info, e.handleSync)
 		err = e.mgmClient.Sync(e.ctx, info, e.handleSync)
 		if err != nil {
 			// happens if management is unavailable for a long time.
@@ -960,7 +959,7 @@ func (e *Engine) receiveManagementEvents() {
 		}
 		log.Debugf("stopped receiving updates from Management Service")
 	}()
-	log.Debugf("connecting to Management Service updates stream")
+	log.Infof("connecting to Management Service updates stream")
 }
 
 func (e *Engine) updateSTUNs(stuns []*mgmProto.HostConfig) error {

client/internal/peer/wg_watcher.go

@@ -30,9 +30,10 @@ type WGWatcher struct {
 	peerKey       string
 	stateDump     *stateDump
 
-	ctx       context.Context
-	ctxCancel context.CancelFunc
-	ctxLock   sync.Mutex
+	ctx         context.Context
+	ctxCancel   context.CancelFunc
+	ctxLock     sync.Mutex
+	enabledTime time.Time
 }
 
 func NewWGWatcher(log *log.Entry, wgIfaceStater WGInterfaceStater, peerKey string, stateDump *stateDump) *WGWatcher {
@@ -48,6 +49,7 @@ func NewWGWatcher(log *log.Entry, wgIfaceStater WGInterfaceStater, peerKey strin
 func (w *WGWatcher) EnableWgWatcher(parentCtx context.Context, onDisconnectedFn func()) {
 	w.log.Debugf("enable WireGuard watcher")
 	w.ctxLock.Lock()
+	w.enabledTime = time.Now()
 
 	if w.ctx != nil && w.ctx.Err() == nil {
 		w.log.Errorf("WireGuard watcher already enabled")
@@ -101,6 +103,11 @@ func (w *WGWatcher) periodicHandshakeCheck(ctx context.Context, ctxCancel contex
 				onDisconnectedFn()
 				return
 			}
+			if lastHandshake.IsZero() {
+				elapsed := handshake.Sub(w.enabledTime).Seconds()
+				w.log.Infof("first wg handshake detected within: %.2fsec, (%s)", elapsed, handshake)
+			}
+
 			lastHandshake = *handshake
 
 			resetTime := time.Until(handshake.Add(checkPeriod))

client/system/info.go

@@ -6,6 +6,7 @@ import (
 	"net/netip"
 	"strings"
 
+	log "github.com/sirupsen/logrus"
 	"google.golang.org/grpc/metadata"
 
 	"github.com/netbirdio/netbird/shared/management/proto"
@@ -172,6 +173,7 @@ func isDuplicated(addresses []NetworkAddress, addr NetworkAddress) bool {
 
 // GetInfoWithChecks retrieves and parses the system information with applied checks.
 func GetInfoWithChecks(ctx context.Context, checks []*proto.Checks) (*Info, error) {
+	log.Debugf("gathering system information with checks: %d", len(checks))
 	processCheckPaths := make([]string, 0)
 	for _, check := range checks {
 		processCheckPaths = append(processCheckPaths, check.GetFiles()...)
@@ -181,9 +183,11 @@ func GetInfoWithChecks(ctx context.Context, checks []*proto.Checks) (*Info, erro
 	if err != nil {
 		return nil, err
 	}
+	log.Debugf("gathering process check information completed")
 
 	info := GetInfo(ctx)
 	info.Files = files
 
+	log.Debugf("all system information gathered successfully")
 	return info, nil
 }

client/system/info_windows.go

@@ -48,6 +48,5 @@ func GetInfo(ctx context.Context) *Info {
 	gio.Hostname = extractDeviceName(ctx, systemHostname)
 	gio.NetbirdVersion = version.NetbirdVersion()
 	gio.UIVersion = extractUserAgent(ctx)
-
 	return gio
 }