From 3e6eede1523f5073cd3d35f068c771b6d88ba397 Mon Sep 17 00:00:00 2001 From: Zoltan Papp Date: Sat, 12 Jul 2025 11:10:45 +0200 Subject: [PATCH] [client] Fix elapsed time calculation when machine is in sleep mode (#4140) --- client/iface/bind/activity.go | 24 ++++++++++--------- client/iface/bind/activity_test.go | 8 +++---- client/iface/configurer/kernel_unix.go | 4 +++- client/iface/configurer/usp.go | 3 ++- client/iface/device/interface.go | 3 ++- client/iface/iface.go | 3 ++- client/internal/conn_mgr.go | 1 - client/internal/engine_test.go | 5 ++-- client/internal/iface_common.go | 3 ++- client/internal/lazyconn/activity/listener.go | 7 +++--- .../internal/lazyconn/inactivity/manager.go | 9 ++++--- .../lazyconn/inactivity/manager_test.go | 13 +++++----- client/internal/lazyconn/manager/manager.go | 7 +++--- client/internal/lazyconn/wgiface.go | 4 +++- monotime/time.go | 10 ++++++-- 15 files changed, 62 insertions(+), 42 deletions(-) diff --git a/client/iface/bind/activity.go b/client/iface/bind/activity.go index d3b406bcd..57862e3d1 100644 --- a/client/iface/bind/activity.go +++ b/client/iface/bind/activity.go @@ -34,14 +34,14 @@ func NewActivityRecorder() *ActivityRecorder { } // GetLastActivities returns a snapshot of peer last activity -func (r *ActivityRecorder) GetLastActivities() map[string]time.Time { +func (r *ActivityRecorder) GetLastActivities() map[string]monotime.Time { r.mu.RLock() defer r.mu.RUnlock() - activities := make(map[string]time.Time, len(r.peers)) + activities := make(map[string]monotime.Time, len(r.peers)) for key, record := range r.peers { - unixNano := record.LastActivity.Load() - activities[key] = time.Unix(0, unixNano) + monoTime := record.LastActivity.Load() + activities[key] = monotime.Time(monoTime) } return activities } @@ -51,18 +51,20 @@ func (r *ActivityRecorder) UpsertAddress(publicKey string, address netip.AddrPor r.mu.Lock() defer r.mu.Unlock() - if pr, exists := r.peers[publicKey]; exists { - delete(r.addrToPeer, pr.Address) - pr.Address = address + var record *PeerRecord + record, exists := r.peers[publicKey] + if exists { + delete(r.addrToPeer, record.Address) + record.Address = address } else { - record := &PeerRecord{ + record = &PeerRecord{ Address: address, } - record.LastActivity.Store(monotime.Now()) + record.LastActivity.Store(int64(monotime.Now())) r.peers[publicKey] = record } - r.addrToPeer[address] = r.peers[publicKey] + r.addrToPeer[address] = record } func (r *ActivityRecorder) Remove(publicKey string) { @@ -84,7 +86,7 @@ func (r *ActivityRecorder) record(address netip.AddrPort) { return } - now := monotime.Now() + now := int64(monotime.Now()) last := record.LastActivity.Load() if now-last < saveFrequency { return diff --git a/client/iface/bind/activity_test.go b/client/iface/bind/activity_test.go index 598607b95..bdd0dca29 100644 --- a/client/iface/bind/activity_test.go +++ b/client/iface/bind/activity_test.go @@ -4,6 +4,8 @@ import ( "net/netip" "testing" "time" + + "github.com/netbirdio/netbird/monotime" ) func TestActivityRecorder_GetLastActivities(t *testing.T) { @@ -17,11 +19,7 @@ func TestActivityRecorder_GetLastActivities(t *testing.T) { t.Fatalf("Expected activity for peer %s, but got none", peer) } - if p.IsZero() { - t.Fatalf("Expected activity for peer %s, but got zero", peer) - } - - if p.Before(time.Now().Add(-2 * time.Minute)) { + if monotime.Since(p) > 5*time.Second { t.Fatalf("Expected activity for peer %s to be recent, but got %v", peer, p) } } diff --git a/client/iface/configurer/kernel_unix.go b/client/iface/configurer/kernel_unix.go index e2ea19144..84afc38f5 100644 --- a/client/iface/configurer/kernel_unix.go +++ b/client/iface/configurer/kernel_unix.go @@ -11,6 +11,8 @@ import ( log "github.com/sirupsen/logrus" "golang.zx2c4.com/wireguard/wgctrl" "golang.zx2c4.com/wireguard/wgctrl/wgtypes" + + "github.com/netbirdio/netbird/monotime" ) var zeroKey wgtypes.Key @@ -277,6 +279,6 @@ func (c *KernelConfigurer) GetStats() (map[string]WGStats, error) { return stats, nil } -func (c *KernelConfigurer) LastActivities() map[string]time.Time { +func (c *KernelConfigurer) LastActivities() map[string]monotime.Time { return nil } diff --git a/client/iface/configurer/usp.go b/client/iface/configurer/usp.go index 6ead716f1..1ff4d839c 100644 --- a/client/iface/configurer/usp.go +++ b/client/iface/configurer/usp.go @@ -17,6 +17,7 @@ import ( "golang.zx2c4.com/wireguard/wgctrl/wgtypes" "github.com/netbirdio/netbird/client/iface/bind" + "github.com/netbirdio/netbird/monotime" nbnet "github.com/netbirdio/netbird/util/net" ) @@ -223,7 +224,7 @@ func (c *WGUSPConfigurer) FullStats() (*Stats, error) { return parseStatus(c.deviceName, ipcStr) } -func (c *WGUSPConfigurer) LastActivities() map[string]time.Time { +func (c *WGUSPConfigurer) LastActivities() map[string]monotime.Time { return c.activityRecorder.GetLastActivities() } diff --git a/client/iface/device/interface.go b/client/iface/device/interface.go index d68e6bf90..1f40b0d46 100644 --- a/client/iface/device/interface.go +++ b/client/iface/device/interface.go @@ -8,6 +8,7 @@ import ( "golang.zx2c4.com/wireguard/wgctrl/wgtypes" "github.com/netbirdio/netbird/client/iface/configurer" + "github.com/netbirdio/netbird/monotime" ) type WGConfigurer interface { @@ -19,5 +20,5 @@ type WGConfigurer interface { Close() GetStats() (map[string]configurer.WGStats, error) FullStats() (*configurer.Stats, error) - LastActivities() map[string]time.Time + LastActivities() map[string]monotime.Time } diff --git a/client/iface/iface.go b/client/iface/iface.go index e90c3536b..0e41f8e64 100644 --- a/client/iface/iface.go +++ b/client/iface/iface.go @@ -21,6 +21,7 @@ import ( "github.com/netbirdio/netbird/client/iface/device" "github.com/netbirdio/netbird/client/iface/wgaddr" "github.com/netbirdio/netbird/client/iface/wgproxy" + "github.com/netbirdio/netbird/monotime" ) const ( @@ -237,7 +238,7 @@ func (w *WGIface) GetStats() (map[string]configurer.WGStats, error) { return w.configurer.GetStats() } -func (w *WGIface) LastActivities() map[string]time.Time { +func (w *WGIface) LastActivities() map[string]monotime.Time { w.mu.Lock() defer w.mu.Unlock() diff --git a/client/internal/conn_mgr.go b/client/internal/conn_mgr.go index c76b0a99f..112559132 100644 --- a/client/internal/conn_mgr.go +++ b/client/internal/conn_mgr.go @@ -226,7 +226,6 @@ func (e *ConnMgr) ActivatePeer(ctx context.Context, conn *peer.Conn) { } if found := e.lazyConnMgr.ActivatePeer(conn.GetKey()); found { - conn.Log.Infof("activated peer from inactive state") if err := conn.Open(ctx); err != nil { conn.Log.Errorf("failed to open connection: %v", err) } diff --git a/client/internal/engine_test.go b/client/internal/engine_test.go index f4ed8f1c0..4b7a2d600 100644 --- a/client/internal/engine_test.go +++ b/client/internal/engine_test.go @@ -52,6 +52,7 @@ import ( "github.com/netbirdio/netbird/management/server/store" "github.com/netbirdio/netbird/management/server/telemetry" "github.com/netbirdio/netbird/management/server/types" + "github.com/netbirdio/netbird/monotime" relayClient "github.com/netbirdio/netbird/relay/client" "github.com/netbirdio/netbird/route" signal "github.com/netbirdio/netbird/signal/client" @@ -96,7 +97,7 @@ type MockWGIface struct { GetInterfaceGUIDStringFunc func() (string, error) GetProxyFunc func() wgproxy.Proxy GetNetFunc func() *netstack.Net - LastActivitiesFunc func() map[string]time.Time + LastActivitiesFunc func() map[string]monotime.Time } func (m *MockWGIface) FullStats() (*configurer.Stats, error) { @@ -187,7 +188,7 @@ func (m *MockWGIface) GetNet() *netstack.Net { return m.GetNetFunc() } -func (m *MockWGIface) LastActivities() map[string]time.Time { +func (m *MockWGIface) LastActivities() map[string]monotime.Time { if m.LastActivitiesFunc != nil { return m.LastActivitiesFunc() } diff --git a/client/internal/iface_common.go b/client/internal/iface_common.go index 38fb3561e..bf96153ea 100644 --- a/client/internal/iface_common.go +++ b/client/internal/iface_common.go @@ -14,6 +14,7 @@ import ( "github.com/netbirdio/netbird/client/iface/device" "github.com/netbirdio/netbird/client/iface/wgaddr" "github.com/netbirdio/netbird/client/iface/wgproxy" + "github.com/netbirdio/netbird/monotime" ) type wgIfaceBase interface { @@ -38,5 +39,5 @@ type wgIfaceBase interface { GetStats() (map[string]configurer.WGStats, error) GetNet() *netstack.Net FullStats() (*configurer.Stats, error) - LastActivities() map[string]time.Time + LastActivities() map[string]monotime.Time } diff --git a/client/internal/lazyconn/activity/listener.go b/client/internal/lazyconn/activity/listener.go index 81b5da17b..817ff00c3 100644 --- a/client/internal/lazyconn/activity/listener.go +++ b/client/internal/lazyconn/activity/listener.go @@ -48,7 +48,7 @@ func (d *Listener) ReadPackets() { n, remoteAddr, err := d.conn.ReadFromUDP(make([]byte, 1)) if err != nil { if d.isClosed.Load() { - d.peerCfg.Log.Debugf("exit from activity listener") + d.peerCfg.Log.Infof("exit from activity listener") } else { d.peerCfg.Log.Errorf("failed to read from activity listener: %s", err) } @@ -59,9 +59,11 @@ func (d *Listener) ReadPackets() { d.peerCfg.Log.Warnf("received %d bytes from %s, too short", n, remoteAddr) continue } + d.peerCfg.Log.Infof("activity detected") break } + d.peerCfg.Log.Debugf("removing lazy endpoint: %s", d.endpoint.String()) if err := d.removeEndpoint(); err != nil { d.peerCfg.Log.Errorf("failed to remove endpoint: %s", err) } @@ -71,7 +73,7 @@ func (d *Listener) ReadPackets() { } func (d *Listener) Close() { - d.peerCfg.Log.Infof("closing listener: %s", d.conn.LocalAddr().String()) + d.peerCfg.Log.Infof("closing activity listener: %s", d.conn.LocalAddr().String()) d.isClosed.Store(true) if err := d.conn.Close(); err != nil { @@ -81,7 +83,6 @@ func (d *Listener) Close() { } func (d *Listener) removeEndpoint() error { - d.peerCfg.Log.Debugf("removing lazy endpoint: %s", d.endpoint.String()) return d.wgIface.RemovePeer(d.peerCfg.PublicKey) } diff --git a/client/internal/lazyconn/inactivity/manager.go b/client/internal/lazyconn/inactivity/manager.go index 854951729..0120f4430 100644 --- a/client/internal/lazyconn/inactivity/manager.go +++ b/client/internal/lazyconn/inactivity/manager.go @@ -8,6 +8,7 @@ import ( log "github.com/sirupsen/logrus" "github.com/netbirdio/netbird/client/internal/lazyconn" + "github.com/netbirdio/netbird/monotime" ) const ( @@ -18,7 +19,7 @@ const ( ) type WgInterface interface { - LastActivities() map[string]time.Time + LastActivities() map[string]monotime.Time } type Manager struct { @@ -124,6 +125,7 @@ func (m *Manager) checkStats() (map[string]struct{}, error) { idlePeers := make(map[string]struct{}) + checkTime := time.Now() for peerID, peerCfg := range m.interestedPeers { lastActive, ok := lastActivities[peerID] if !ok { @@ -132,8 +134,9 @@ func (m *Manager) checkStats() (map[string]struct{}, error) { continue } - if time.Since(lastActive) > m.inactivityThreshold { - peerCfg.Log.Infof("peer is inactive since: %v", lastActive) + since := monotime.Since(lastActive) + if since > m.inactivityThreshold { + peerCfg.Log.Infof("peer is inactive since time: %s", checkTime.Add(-since).String()) idlePeers[peerID] = struct{}{} } } diff --git a/client/internal/lazyconn/inactivity/manager_test.go b/client/internal/lazyconn/inactivity/manager_test.go index d012b41a2..10b4ef1eb 100644 --- a/client/internal/lazyconn/inactivity/manager_test.go +++ b/client/internal/lazyconn/inactivity/manager_test.go @@ -9,13 +9,14 @@ import ( "github.com/stretchr/testify/assert" "github.com/netbirdio/netbird/client/internal/lazyconn" + "github.com/netbirdio/netbird/monotime" ) type mockWgInterface struct { - lastActivities map[string]time.Time + lastActivities map[string]monotime.Time } -func (m *mockWgInterface) LastActivities() map[string]time.Time { +func (m *mockWgInterface) LastActivities() map[string]monotime.Time { return m.lastActivities } @@ -23,8 +24,8 @@ func TestPeerTriggersInactivity(t *testing.T) { peerID := "peer1" wgMock := &mockWgInterface{ - lastActivities: map[string]time.Time{ - peerID: time.Now().Add(-20 * time.Minute), + lastActivities: map[string]monotime.Time{ + peerID: monotime.Time(int64(monotime.Now()) - int64(20*time.Minute)), }, } @@ -64,8 +65,8 @@ func TestPeerTriggersActivity(t *testing.T) { peerID := "peer1" wgMock := &mockWgInterface{ - lastActivities: map[string]time.Time{ - peerID: time.Now().Add(-5 * time.Minute), + lastActivities: map[string]monotime.Time{ + peerID: monotime.Time(int64(monotime.Now()) - int64(5*time.Minute)), }, } diff --git a/client/internal/lazyconn/manager/manager.go b/client/internal/lazyconn/manager/manager.go index 416e4e7e7..b6b3c6091 100644 --- a/client/internal/lazyconn/manager/manager.go +++ b/client/internal/lazyconn/manager/manager.go @@ -258,12 +258,13 @@ func (m *Manager) ActivatePeer(peerID string) (found bool) { return false } + cfg.Log.Infof("activate peer from inactive state by remote signal message") + if !m.activateSinglePeer(cfg, mp) { return false } m.activateHAGroupPeers(cfg) - return true } @@ -571,12 +572,12 @@ func (m *Manager) onPeerInactivityTimedOut(peerIDs map[string]struct{}) { // this is blocking operation, potentially can be optimized m.peerStore.PeerConnIdle(mp.peerCfg.PublicKey) - mp.peerCfg.Log.Infof("start activity monitor") - mp.expectedWatcher = watcherActivity m.inactivityManager.RemovePeer(mp.peerCfg.PublicKey) + mp.peerCfg.Log.Infof("start activity monitor") + if err := m.activityManager.MonitorPeerActivity(*mp.peerCfg); err != nil { mp.peerCfg.Log.Errorf("failed to create activity monitor: %v", err) continue diff --git a/client/internal/lazyconn/wgiface.go b/client/internal/lazyconn/wgiface.go index d55ff9670..0351904f7 100644 --- a/client/internal/lazyconn/wgiface.go +++ b/client/internal/lazyconn/wgiface.go @@ -6,11 +6,13 @@ import ( "time" "golang.zx2c4.com/wireguard/wgctrl/wgtypes" + + "github.com/netbirdio/netbird/monotime" ) type WGIface interface { RemovePeer(peerKey string) error UpdatePeer(peerKey string, allowedIps []netip.Prefix, keepAlive time.Duration, endpoint *net.UDPAddr, preSharedKey *wgtypes.Key) error IsUserspaceBind() bool - LastActivities() map[string]time.Time + LastActivities() map[string]monotime.Time } diff --git a/monotime/time.go b/monotime/time.go index 6032fb60b..ba45b6659 100644 --- a/monotime/time.go +++ b/monotime/time.go @@ -9,6 +9,8 @@ var ( baseWallNano int64 ) +type Time int64 + func init() { baseWallTime = time.Now() baseWallNano = baseWallTime.UnixNano() @@ -23,7 +25,11 @@ func init() { // and using time.Since() for elapsed calculation, this avoids repeated // time.Now() calls and leverages Go's internal monotonic clock for // efficient duration measurement. -func Now() int64 { +func Now() Time { elapsed := time.Since(baseWallTime) - return baseWallNano + int64(elapsed) + return Time(baseWallNano + int64(elapsed)) +} + +func Since(t Time) time.Duration { + return time.Duration(Now() - t) }