[management] cleanup logs

management/internals/shared/grpc/server.go

@@ -134,10 +134,6 @@ func (s *Server) GetServerKey(ctx context.Context, req *proto.Empty) (*proto.Ser
 	}
 
 	log.WithContext(ctx).Tracef("GetServerKey request from %s", ip)
-	start := time.Now()
-	defer func() {
-		log.WithContext(ctx).Tracef("GetServerKey from %s took %v", ip, time.Since(start))
-	}()
 
 	// todo introduce something more meaningful with the key expiration/rotation
 	if s.appMetrics != nil {
@@ -222,8 +218,6 @@ func (s *Server) Sync(req *proto.EncryptedMessage, srv proto.ManagementService_S
 		return err
 	}
 
-	log.WithContext(ctx).Debugf("Sync: GetAccountIDForPeerKey since start %v", time.Since(reqStart))
-
 	// nolint:staticcheck
 	ctx = context.WithValue(ctx, nbContext.AccountIDKey, accountID)
 
@@ -235,7 +229,6 @@ func (s *Server) Sync(req *proto.EncryptedMessage, srv proto.ManagementService_S
 		}
 	}()
 	log.WithContext(ctx).Tracef("acquired peer lock for peer %s took %v", peerKey.String(), time.Since(start))
-	log.WithContext(ctx).Debugf("Sync: acquirePeerLockByUID since start %v", time.Since(reqStart))
 
 	log.WithContext(ctx).Debugf("Sync request from peer [%s] [%s]", req.WgPubKey, sRealIP)
 
@@ -352,7 +345,7 @@ func (s *Server) cancelPeerRoutines(ctx context.Context, accountID string, peer
 	s.networkMapController.OnPeerDisconnected(ctx, accountID, peer.ID)
 	s.secretsManager.CancelRefresh(peer.ID)
 
-	log.WithContext(ctx).Tracef("peer %s has been disconnected", peer.Key)
+	log.WithContext(ctx).Debugf("peer %s has been disconnected", peer.Key)
 }
 
 func (s *Server) validateToken(ctx context.Context, jwtToken string) (string, error) {
@@ -561,16 +554,10 @@ func (s *Server) Login(ctx context.Context, req *proto.EncryptedMessage) (*proto
 	//nolint
 	ctx = context.WithValue(ctx, nbContext.AccountIDKey, accountID)
 
-	log.WithContext(ctx).Debugf("Login: GetAccountIDForPeerKey since start %v", time.Since(reqStart))
-
 	defer func() {
 		if s.appMetrics != nil {
 			s.appMetrics.GRPCMetrics().CountLoginRequestDuration(time.Since(reqStart), accountID)
 		}
-		took := time.Since(reqStart)
-		if took > 7*time.Second {
-			log.WithContext(ctx).Debugf("Login: took %v", time.Since(reqStart))
-		}
 	}()
 
 	if loginReq.GetMeta() == nil {
@@ -604,16 +591,12 @@ func (s *Server) Login(ctx context.Context, req *proto.EncryptedMessage) (*proto
 		return nil, mapError(ctx, err)
 	}
 
-	log.WithContext(ctx).Debugf("Login: LoginPeer since start %v", time.Since(reqStart))
-
 	loginResp, err := s.prepareLoginResponse(ctx, peer, netMap, postureChecks)
 	if err != nil {
 		log.WithContext(ctx).Warnf("failed preparing login response for peer %s: %s", peerKey, err)
 		return nil, status.Errorf(codes.Internal, "failed logging in peer")
 	}
 
-	log.WithContext(ctx).Debugf("Login: prepareLoginResponse since start %v", time.Since(reqStart))
-
 	key, err := s.secretsManager.GetWGKey()
 	if err != nil {
 		log.WithContext(ctx).Warnf("failed getting server's WireGuard private key: %s", err)
@@ -730,12 +713,10 @@ func (s *Server) sendInitialSync(ctx context.Context, peerKey wgtypes.Key, peer
 		return status.Errorf(codes.Internal, "error handling request")
 	}
 
-	sendStart := time.Now()
 	err = srv.Send(&proto.EncryptedMessage{
 		WgPubKey: key.PublicKey().String(),
 		Body:     encryptedResp,
 	})
-	log.WithContext(ctx).Debugf("sendInitialSync: sending response took %s", time.Since(sendStart))
 
 	if err != nil {
 		log.WithContext(ctx).Errorf("failed sending SyncResponse %v", err)
@@ -750,10 +731,6 @@ func (s *Server) sendInitialSync(ctx context.Context, peerKey wgtypes.Key, peer
 // which will be used by our clients to Login
 func (s *Server) GetDeviceAuthorizationFlow(ctx context.Context, req *proto.EncryptedMessage) (*proto.EncryptedMessage, error) {
 	log.WithContext(ctx).Tracef("GetDeviceAuthorizationFlow request for pubKey: %s", req.WgPubKey)
-	start := time.Now()
-	defer func() {
-		log.WithContext(ctx).Tracef("GetDeviceAuthorizationFlow for pubKey: %s took %v", req.WgPubKey, time.Since(start))
-	}()
 
 	peerKey, err := wgtypes.ParseKey(req.GetWgPubKey())
 	if err != nil {
@@ -813,10 +790,6 @@ func (s *Server) GetDeviceAuthorizationFlow(ctx context.Context, req *proto.Encr
 // which will be used by our clients to Login
 func (s *Server) GetPKCEAuthorizationFlow(ctx context.Context, req *proto.EncryptedMessage) (*proto.EncryptedMessage, error) {
 	log.WithContext(ctx).Tracef("GetPKCEAuthorizationFlow request for pubKey: %s", req.WgPubKey)
-	start := time.Now()
-	defer func() {
-		log.WithContext(ctx).Tracef("GetPKCEAuthorizationFlow for pubKey %s took %v", req.WgPubKey, time.Since(start))
-	}()
 
 	peerKey, err := wgtypes.ParseKey(req.GetWgPubKey())
 	if err != nil {

management/internals/shared/grpc/token_mgr.go

@@ -167,7 +167,7 @@ func (m *TimeBasedAuthSecretsManager) SetupRefresh(ctx context.Context, accountI
 		relayCancel := make(chan struct{}, 1)
 		m.relayCancelMap[peerID] = relayCancel
 		go m.refreshRelayTokens(ctx, accountID, peerID, relayCancel)
-		log.WithContext(ctx).Debugf("starting relay refresh for %s", peerID)
+		log.WithContext(ctx).Tracef("starting relay refresh for %s", peerID)
 	}
 }
 
@@ -178,7 +178,7 @@ func (m *TimeBasedAuthSecretsManager) refreshTURNTokens(ctx context.Context, acc
 	for {
 		select {
 		case <-cancel:
-			log.WithContext(ctx).Debugf("stopping TURN refresh for %s", peerID)
+			log.WithContext(ctx).Tracef("stopping TURN refresh for %s", peerID)
 			return
 		case <-ticker.C:
 			m.pushNewTURNAndRelayTokens(ctx, accountID, peerID)
@@ -193,7 +193,7 @@ func (m *TimeBasedAuthSecretsManager) refreshRelayTokens(ctx context.Context, ac
 	for {
 		select {
 		case <-cancel:
-			log.WithContext(ctx).Debugf("stopping relay refresh for %s", peerID)
+			log.WithContext(ctx).Tracef("stopping relay refresh for %s", peerID)
 			return
 		case <-ticker.C:
 			m.pushNewRelayTokens(ctx, accountID, peerID)

management/server/http/middleware/auth_middleware.go

@@ -141,7 +141,7 @@ func (m *AuthMiddleware) checkJWTFromRequest(r *http.Request, authHeaderParts []
 	}
 
 	if userAuth.AccountId != accountId {
-		log.WithContext(ctx).Debugf("Auth middleware sets accountId from ensure, before %s, now %s", userAuth.AccountId, accountId)
+		log.WithContext(ctx).Tracef("Auth middleware sets accountId from ensure, before %s, now %s", userAuth.AccountId, accountId)
 		userAuth.AccountId = accountId
 	}
 

management/server/peer.go

@@ -172,7 +172,7 @@ func updatePeerStatusAndLocation(ctx context.Context, geo geolocation.Geolocatio
 		}
 	}
 
-	log.WithContext(ctx).Tracef("saving peer status for peer %s is connected: %t", peer.ID, connected)
+	log.WithContext(ctx).Debugf("saving peer status for peer %s is connected: %t", peer.ID, connected)
 
 	err := transaction.SavePeerStatus(ctx, accountID, peer.ID, *newStatus)
 	if err != nil {
@@ -783,7 +783,6 @@ func (am *DefaultAccountManager) LoginPeer(ctx context.Context, login types.Peer
 		return nil, nil, nil, err
 	}
 
-	startTransaction := time.Now()
 	err = am.Store.ExecuteInTransaction(ctx, func(transaction store.Store) error {
 		peer, err = transaction.GetPeerByPeerPubKey(ctx, store.LockingStrengthUpdate, login.WireGuardPubKey)
 		if err != nil {
@@ -853,8 +852,6 @@ func (am *DefaultAccountManager) LoginPeer(ctx context.Context, login types.Peer
 		return nil, nil, nil, err
 	}
 
-	log.WithContext(ctx).Debugf("LoginPeer: transaction took %v", time.Since(startTransaction))
-
 	if updateRemotePeers || isStatusChanged || (isPeerUpdated && len(postureChecks) > 0) {
 		err = am.networkMapController.OnPeersUpdated(ctx, accountID, []string{peer.ID})
 		if err != nil {

management/server/posture/os_version.go

@@ -82,7 +82,7 @@ func (c *OSVersionCheck) Validate() error {
 
 func checkMinVersion(ctx context.Context, peerGoOS, peerVersion string, check *MinVersionCheck) (bool, error) {
 	if check == nil {
-		log.WithContext(ctx).Debugf("peer %s OS is not allowed in the check", peerGoOS)
+		log.WithContext(ctx).Tracef("peer %s OS is not allowed in the check", peerGoOS)
 		return false, nil
 	}
 
@@ -107,7 +107,7 @@ func checkMinVersion(ctx context.Context, peerGoOS, peerVersion string, check *M
 
 func checkMinKernelVersion(ctx context.Context, peerGoOS, peerVersion string, check *MinKernelVersionCheck) (bool, error) {
 	if check == nil {
-		log.WithContext(ctx).Debugf("peer %s OS is not allowed in the check", peerGoOS)
+		log.WithContext(ctx).Tracef("peer %s OS is not allowed in the check", peerGoOS)
 		return false, nil
 	}
 

management/server/settings/manager.go

@@ -5,9 +5,6 @@ package settings
 import (
 	"context"
 	"fmt"
-	"time"
-
-	log "github.com/sirupsen/logrus"
 
 	"github.com/netbirdio/netbird/management/server/activity"
 	"github.com/netbirdio/netbird/management/server/integrations/extra_settings"
@@ -48,11 +45,6 @@ func (m *managerImpl) GetExtraSettingsManager() extra_settings.Manager {
 }
 
 func (m *managerImpl) GetSettings(ctx context.Context, accountID, userID string) (*types.Settings, error) {
-	start := time.Now()
-	defer func() {
-		log.WithContext(ctx).Debugf("GetSettings took %s", time.Since(start))
-	}()
-
 	if userID != activity.SystemInitiator {
 		ok, err := m.permissionsManager.ValidateUserPermissions(ctx, accountID, userID, modules.Settings, operations.Read)
 		if err != nil {

management/server/store/sql_store.go

@@ -27,7 +27,6 @@ import (
 	"gorm.io/gorm/logger"
 
 	nbdns "github.com/netbirdio/netbird/dns"
-	nbcontext "github.com/netbirdio/netbird/management/server/context"
 	resourceTypes "github.com/netbirdio/netbird/management/server/networks/resources/types"
 	routerTypes "github.com/netbirdio/netbird/management/server/networks/routers/types"
 	networkTypes "github.com/netbirdio/netbird/management/server/networks/types"
@@ -288,7 +287,7 @@ func (s *SqlStore) DeleteAccount(ctx context.Context, account *types.Account) er
 	if s.metrics != nil {
 		s.metrics.StoreMetrics().CountPersistenceDuration(took)
 	}
-	log.WithContext(ctx).Debugf("took %d ms to delete an account to the store", took.Milliseconds())
+	log.WithContext(ctx).Tracef("took %d ms to delete an account to the store", took.Milliseconds())
 
 	return err
 }
@@ -583,9 +582,6 @@ func (s *SqlStore) GetUserByPATID(ctx context.Context, lockStrength LockingStren
 }
 
 func (s *SqlStore) GetUserByUserID(ctx context.Context, lockStrength LockingStrength, userID string) (*types.User, error) {
-	ctx, cancel := getDebuggingCtx(ctx)
-	defer cancel()
-
 	tx := s.db
 	if lockStrength != LockingStrengthNone {
 		tx = tx.Clauses(clause.Locking{Strength: string(lockStrength)})
@@ -2152,9 +2148,6 @@ func (s *SqlStore) GetPeerLabelsInAccount(ctx context.Context, lockStrength Lock
 }
 
 func (s *SqlStore) GetAccountNetwork(ctx context.Context, lockStrength LockingStrength, accountID string) (*types.Network, error) {
-	ctx, cancel := getDebuggingCtx(ctx)
-	defer cancel()
-
 	tx := s.db
 	if lockStrength != LockingStrengthNone {
 		tx = tx.Clauses(clause.Locking{Strength: string(lockStrength)})
@@ -2171,9 +2164,6 @@ func (s *SqlStore) GetAccountNetwork(ctx context.Context, lockStrength LockingSt
 }
 
 func (s *SqlStore) GetPeerByPeerPubKey(ctx context.Context, lockStrength LockingStrength, peerKey string) (*nbpeer.Peer, error) {
-	ctx, cancel := getDebuggingCtx(ctx)
-	defer cancel()
-
 	tx := s.db
 	if lockStrength != LockingStrengthNone {
 		tx = tx.Clauses(clause.Locking{Strength: string(lockStrength)})
@@ -2229,9 +2219,6 @@ func (s *SqlStore) GetAccountCreatedBy(ctx context.Context, lockStrength Locking
 
 // SaveUserLastLogin stores the last login time for a user in DB.
 func (s *SqlStore) SaveUserLastLogin(ctx context.Context, accountID, userID string, lastLogin time.Time) error {
-	ctx, cancel := getDebuggingCtx(ctx)
-	defer cancel()
-
 	var user types.User
 	result := s.db.WithContext(ctx).Take(&user, accountAndIDQueryCondition, accountID, userID)
 	if result.Error != nil {
@@ -2491,9 +2478,6 @@ func NewMysqlStoreFromSqlStore(ctx context.Context, sqliteStore *SqlStore, dsn s
 }
 
 func (s *SqlStore) GetSetupKeyBySecret(ctx context.Context, lockStrength LockingStrength, key string) (*types.SetupKey, error) {
-	ctx, cancel := getDebuggingCtx(ctx)
-	defer cancel()
-
 	tx := s.db
 	if lockStrength != LockingStrengthNone {
 		tx = tx.Clauses(clause.Locking{Strength: string(lockStrength)})
@@ -2514,9 +2498,6 @@ func (s *SqlStore) GetSetupKeyBySecret(ctx context.Context, lockStrength Locking
 }
 
 func (s *SqlStore) IncrementSetupKeyUsage(ctx context.Context, setupKeyID string) error {
-	ctx, cancel := getDebuggingCtx(ctx)
-	defer cancel()
-
 	result := s.db.WithContext(ctx).Model(&types.SetupKey{}).
 		Where(idQueryCondition, setupKeyID).
 		Updates(map[string]interface{}{
@@ -2537,9 +2518,6 @@ func (s *SqlStore) IncrementSetupKeyUsage(ctx context.Context, setupKeyID string
 
 // AddPeerToAllGroup adds a peer to the 'All' group. Method always needs to run in a transaction
 func (s *SqlStore) AddPeerToAllGroup(ctx context.Context, accountID string, peerID string) error {
-	ctx, cancel := getDebuggingCtx(ctx)
-	defer cancel()
-
 	var groupID string
 	_ = s.db.WithContext(ctx).Model(types.Group{}).
 		Select("id").
@@ -2569,9 +2547,6 @@ func (s *SqlStore) AddPeerToAllGroup(ctx context.Context, accountID string, peer
 
 // AddPeerToGroup adds a peer to a group
 func (s *SqlStore) AddPeerToGroup(ctx context.Context, accountID, peerID, groupID string) error {
-	ctx, cancel := getDebuggingCtx(ctx)
-	defer cancel()
-
 	peer := &types.GroupPeer{
 		AccountID: accountID,
 		GroupID:   groupID,
@@ -2768,9 +2743,6 @@ func (s *SqlStore) GetUserPeers(ctx context.Context, lockStrength LockingStrengt
 }
 
 func (s *SqlStore) AddPeerToAccount(ctx context.Context, peer *nbpeer.Peer) error {
-	ctx, cancel := getDebuggingCtx(ctx)
-	defer cancel()
-
 	if err := s.db.WithContext(ctx).Create(peer).Error; err != nil {
 		return status.Errorf(status.Internal, "issue adding peer to account: %s", err)
 	}
@@ -2897,9 +2869,6 @@ func (s *SqlStore) DeletePeer(ctx context.Context, accountID string, peerID stri
 }
 
 func (s *SqlStore) IncrementNetworkSerial(ctx context.Context, accountId string) error {
-	ctx, cancel := getDebuggingCtx(ctx)
-	defer cancel()
-
 	result := s.db.WithContext(ctx).Model(&types.Account{}).Where(idQueryCondition, accountId).Update("network_serial", gorm.Expr("network_serial + 1"))
 	if result.Error != nil {
 		log.WithContext(ctx).Errorf("failed to increment network serial count in store: %v", result.Error)
@@ -4022,36 +3991,6 @@ func (s *SqlStore) GetAccountGroupPeers(ctx context.Context, lockStrength Lockin
 	return groupPeers, nil
 }
 
-func getDebuggingCtx(grpcCtx context.Context) (context.Context, context.CancelFunc) {
-	ctx, cancel := context.WithTimeout(context.Background(), time.Minute)
-	userID, ok := grpcCtx.Value(nbcontext.UserIDKey).(string)
-	if ok {
-		//nolint
-		ctx = context.WithValue(ctx, nbcontext.UserIDKey, userID)
-	}
-
-	requestID, ok := grpcCtx.Value(nbcontext.RequestIDKey).(string)
-	if ok {
-		//nolint
-		ctx = context.WithValue(ctx, nbcontext.RequestIDKey, requestID)
-	}
-
-	accountID, ok := grpcCtx.Value(nbcontext.AccountIDKey).(string)
-	if ok {
-		//nolint
-		ctx = context.WithValue(ctx, nbcontext.AccountIDKey, accountID)
-	}
-
-	go func() {
-		select {
-		case <-ctx.Done():
-		case <-grpcCtx.Done():
-			log.WithContext(grpcCtx).Warnf("grpc context ended early, error: %v", grpcCtx.Err())
-		}
-	}()
-	return ctx, cancel
-}
-
 func (s *SqlStore) IsPrimaryAccount(ctx context.Context, accountID string) (bool, string, error) {
 	var info types.PrimaryAccountInfo
 	result := s.db.Model(&types.Account{}).