Merge branch 'debug-slow-conn' into fix/missed-offers-and-debug

- do not miss ICE offers when relay worker busy
- close p2p connection before recreate agent

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/handshaker.go

@@ -43,13 +43,6 @@ type OfferAnswer struct {
 	SessionID *ICESessionID
 }
 
-func (oa *OfferAnswer) SessionIDString() string {
-	if oa.SessionID == nil {
-		return "unknown"
-	}
-	return oa.SessionID.String()
-}
-
 type Handshaker struct {
 	mu                  sync.Mutex
 	log                 *log.Entry
@@ -57,7 +50,7 @@ type Handshaker struct {
 	signaler            *Signaler
 	ice                 *WorkerICE
 	relay               *WorkerRelay
-	onNewOfferListeners []func(*OfferAnswer)
+	onNewOfferListeners []*OfferListener
 
 	// remoteOffersCh is a channel used to wait for remote credentials to proceed with the connection
 	remoteOffersCh chan OfferAnswer
@@ -78,7 +71,8 @@ func NewHandshaker(log *log.Entry, config ConnConfig, signaler *Signaler, ice *W
 }
 
 func (h *Handshaker) AddOnNewOfferListener(offer func(remoteOfferAnswer *OfferAnswer)) {
-	h.onNewOfferListeners = append(h.onNewOfferListeners, offer)
+	l := NewOfferListener(offer)
+	h.onNewOfferListeners = append(h.onNewOfferListeners, l)
 }
 
 func (h *Handshaker) Listen(ctx context.Context) {
@@ -91,13 +85,13 @@ func (h *Handshaker) Listen(ctx context.Context) {
 				continue
 			}
 			for _, listener := range h.onNewOfferListeners {
-				listener(&remoteOfferAnswer)
+				listener.Notify(&remoteOfferAnswer)
 			}
 			h.log.Infof("received offer, running version %s, remote WireGuard listen port %d, session id: %s", remoteOfferAnswer.Version, remoteOfferAnswer.WgListenPort, remoteOfferAnswer.SessionIDString())
 		case remoteOfferAnswer := <-h.remoteAnswerCh:
 			h.log.Infof("received answer, running version %s, remote WireGuard listen port %d, session id: %s", remoteOfferAnswer.Version, remoteOfferAnswer.WgListenPort, remoteOfferAnswer.SessionIDString())
 			for _, listener := range h.onNewOfferListeners {
-				listener(&remoteOfferAnswer)
+				listener.Notify(&remoteOfferAnswer)
 			}
 		case <-ctx.Done():
 			h.log.Infof("stop listening for remote offers and answers")

client/internal/peer/handshaker_listener.go

@@ -0,0 +1,62 @@
+package peer
+
+import (
+	"sync"
+)
+
+type callbackFunc func(remoteOfferAnswer *OfferAnswer)
+
+func (oa *OfferAnswer) SessionIDString() string {
+	if oa.SessionID == nil {
+		return "unknown"
+	}
+	return oa.SessionID.String()
+}
+
+type OfferListener struct {
+	fn      callbackFunc
+	running bool
+	latest  *OfferAnswer
+	mu      sync.Mutex
+}
+
+func NewOfferListener(fn callbackFunc) *OfferListener {
+	return &OfferListener{
+		fn: fn,
+	}
+}
+
+func (o *OfferListener) Notify(remoteOfferAnswer *OfferAnswer) {
+	o.mu.Lock()
+	defer o.mu.Unlock()
+
+	// Store the latest offer
+	o.latest = remoteOfferAnswer
+
+	// If already running, the running goroutine will pick up this latest value
+	if o.running {
+		return
+	}
+
+	// Start processing
+	o.running = true
+
+	// Process in a goroutine to avoid blocking the caller
+	go func(remoteOfferAnswer *OfferAnswer) {
+		for {
+			o.fn(remoteOfferAnswer)
+
+			o.mu.Lock()
+			if o.latest == nil {
+				// No more work to do
+				o.running = false
+				o.mu.Unlock()
+				return
+			}
+			remoteOfferAnswer = o.latest
+			// Clear the latest to mark it as being processed
+			o.latest = nil
+			o.mu.Unlock()
+		}
+	}(remoteOfferAnswer)
+}

client/internal/peer/handshaker_listener_test.go

@@ -0,0 +1,39 @@
+package peer
+
+import (
+	"testing"
+	"time"
+)
+
+func Test_newOfferListener(t *testing.T) {
+	dummyOfferAnswer := &OfferAnswer{}
+	runChan := make(chan struct{}, 10)
+
+	longRunningFn := func(remoteOfferAnswer *OfferAnswer) {
+		time.Sleep(1 * time.Second)
+		runChan <- struct{}{}
+	}
+
+	hl := NewOfferListener(longRunningFn)
+
+	hl.Notify(dummyOfferAnswer)
+	hl.Notify(dummyOfferAnswer)
+	hl.Notify(dummyOfferAnswer)
+
+	// Wait for exactly 2 callbacks
+	for i := 0; i < 2; i++ {
+		select {
+		case <-runChan:
+		case <-time.After(3 * time.Second):
+			t.Fatal("Timeout waiting for callback")
+		}
+	}
+
+	// Verify no additional callbacks happen
+	select {
+	case <-runChan:
+		t.Fatal("Unexpected additional callback")
+	case <-time.After(100 * time.Millisecond):
+		t.Log("Correctly received exactly 2 callbacks")
+	}
+}

client/internal/peer/wg_watcher.go

@@ -101,6 +101,10 @@ func (w *WGWatcher) periodicHandshakeCheck(ctx context.Context, ctxCancel contex
 				onDisconnectedFn()
 				return
 			}
+			if lastHandshake.IsZero() {
+				w.log.Infof("first wg handshake detected at: %s", handshake)
+			}
+
 			lastHandshake = *handshake
 
 			resetTime := time.Until(handshake.Add(checkPeriod))

client/internal/peer/worker_ice.go

@@ -122,7 +122,6 @@ func (w *WorkerICE) OnNewOffer(remoteOfferAnswer *OfferAnswer) {
 			w.log.Warnf("failed to close ICE agent: %s", err)
 		}
 		w.agent = nil
-		// todo consider to switch to Relay connection while establishing a new ICE connection
 	}
 
 	var preferredCandidateTypes []ice.CandidateType
@@ -410,7 +409,10 @@ func (w *WorkerICE) onConnectionStateChange(agent *icemaker.ThreadSafeAgent, dia
 		case ice.ConnectionStateConnected:
 			w.lastKnownState = ice.ConnectionStateConnected
 			return
-		case ice.ConnectionStateFailed, ice.ConnectionStateDisconnected:
+		case ice.ConnectionStateFailed, ice.ConnectionStateDisconnected, ice.ConnectionStateClosed:
+			// ice.ConnectionStateClosed happens when we recreate the agent. For the P2P to TURN switch important to
+			// notify the conn.onICEStateDisconnected changes to update the current used priority
+
 			if w.lastKnownState == ice.ConnectionStateConnected {
 				w.lastKnownState = ice.ConnectionStateDisconnected
 				w.conn.onICEStateDisconnected()

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"
@@ -180,6 +181,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()...)
@@ -189,10 +191,12 @@ 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
 }