diff --git a/management/internals/shared/grpc/sync_fast_path.go b/management/internals/shared/grpc/sync_fast_path.go index 28fde2f11..171c3b447 100644 --- a/management/internals/shared/grpc/sync_fast_path.go +++ b/management/internals/shared/grpc/sync_fast_path.go @@ -106,15 +106,18 @@ func buildFastPathResponse( nbConfig := toNetbirdConfig(cfg, turnToken, relayToken, extraSettings) var peerGroups []string + start := time.Now() if fetchGroups != nil { if ids, err := fetchGroups(ctx, peer.AccountID, peer.ID); err != nil { log.WithContext(ctx).Debugf("fast path: get peer group ids: %v", err) } else { peerGroups = ids } + log.WithContext(ctx).Debugf("fast path: get peer group took %s", time.Since(start)) } - + start = time.Now() nbConfig = integrationsConfig.ExtendNetBirdConfig(peer.ID, peerGroups, nbConfig, extraSettings) + log.WithContext(ctx).Debugf("fast path: ExtendNetBirdConfig took %s", time.Since(start)) return &proto.SyncResponse{NetbirdConfig: nbConfig} } @@ -155,9 +158,12 @@ func (s *Server) tryFastPathSync( cached, hit := s.peerSerialCache.Get(peerKey.String()) if !shouldSkipNetworkMap(peerMeta.GoOS, hit, cached, network.CurrentSerial(), peerMetaHash) { + log.WithContext(ctx).Tracef("fast path: checking for fast path eligibility for peer took %s", time.Since(reqStart)) return false, nil } + log.WithContext(ctx).Tracef("fast path: checking for fast path eligibility for peer took %s", time.Since(reqStart)) + peer, updates, committed := s.commitFastPath(ctx, accountID, peerKey, realIP, syncStart, network.CurrentSerial()) if !committed { return false, nil @@ -180,28 +186,39 @@ func (s *Server) commitFastPath( syncStart time.Time, expectedSerial uint64, ) (*nbpeer.Peer, chan *network_map.UpdateMessage, bool) { + defer log.WithContext(ctx).Tracef("fast path: commitFastPath took %s", time.Since(syncStart)) + if err := s.accountManager.MarkPeerConnected(ctx, peerKey.String(), true, realIP, accountID, syncStart); err != nil { log.WithContext(ctx).Warnf("fast path: mark connected for peer %s: %v", peerKey.String(), err) } + log.WithContext(ctx).Tracef("fast path: mark peer connected took %s", time.Since(syncStart)) + peer, err := s.accountManager.GetStore().GetPeerByPeerPubKey(ctx, store.LockingStrengthNone, peerKey.String()) if err != nil { log.WithContext(ctx).Debugf("fast path: lookup peer %s: %v", peerKey.String(), err) return nil, nil, false } + log.WithContext(ctx).Tracef("fast path: get peer took %s", time.Since(syncStart)) + updates, err := s.networkMapController.OnPeerConnected(ctx, accountID, peer.ID) if err != nil { log.WithContext(ctx).Debugf("fast path: notify peer connected for %s: %v", peerKey.String(), err) return nil, nil, false } + log.WithContext(ctx).Tracef("fast path: on peer connected took %s", time.Since(syncStart)) + network, err := s.accountManager.GetStore().GetAccountNetwork(ctx, store.LockingStrengthNone, accountID) if err != nil { log.WithContext(ctx).Debugf("fast path: re-check account network: %v", err) s.cancelPeerRoutinesWithoutLock(ctx, accountID, peer, syncStart) return nil, nil, false } + + log.WithContext(ctx).Tracef("fast path: get network took %s", time.Since(syncStart)) + if network.CurrentSerial() != expectedSerial { log.WithContext(ctx).Debugf("fast path: serial advanced from %d to %d after subscribe, falling back to slow path for peer %s", expectedSerial, network.CurrentSerial(), peerKey.String()) s.cancelPeerRoutinesWithoutLock(ctx, accountID, peer, syncStart) @@ -234,6 +251,8 @@ func (s *Server) runFastPathSync( return err } + log.WithContext(ctx).Tracef("fast path: mark peer connected took %s", time.Since(syncStart)) + s.secretsManager.SetupRefresh(ctx, accountID, peer.ID) if unlock != nil && *unlock != nil { @@ -244,6 +263,7 @@ func (s *Server) runFastPathSync( if s.appMetrics != nil { s.appMetrics.GRPCMetrics().CountSyncRequestDuration(time.Since(reqStart), accountID) } + log.WithContext(ctx).Tracef("fast path: sync took %s", time.Since(syncStart)) log.WithContext(ctx).Debugf("Sync (fast path) took %s", time.Since(reqStart)) s.syncSem.Add(-1)