add method timing logs

management/server/account.go

@@ -386,6 +386,12 @@ func (a *Account) GetGroup(groupID string) *nbgroup.Group {
 
 // GetPeerNetworkMap returns a group by ID if exists, nil otherwise
 func (a *Account) GetPeerNetworkMap(peerID, dnsDomain string, validatedPeersMap map[string]struct{}) *NetworkMap {
+	startTime := time.Now()
+	defer func() {
+		duration := time.Since(startTime)
+		log.Debugf("GetPeerNetworkMap took %s", duration)
+	}()
+
 	peer := a.Peers[peerID]
 	if peer == nil {
 		return &NetworkMap{

management/server/grpcserver.go

@@ -121,6 +121,12 @@ func getRealIP(ctx context.Context) net.IP {
 // Sync validates the existence of a connecting peer, sends an initial state (all available for the connecting peers) and
 // notifies the connected peer of any updates (e.g. new peers under the same account)
 func (s *GRPCServer) Sync(req *proto.EncryptedMessage, srv proto.ManagementService_SyncServer) error {
+	startTime := time.Now()
+	defer func() {
+		duration := time.Since(startTime)
+		log.Debugf("Sync took %s", duration)
+	}()
+
 	reqStart := time.Now()
 	if s.appMetrics != nil {
 		s.appMetrics.GRPCMetrics().CountSyncRequest()
@@ -523,6 +529,12 @@ func (s *GRPCServer) IsHealthy(ctx context.Context, req *proto.Empty) (*proto.Em
 
 // sendInitialSync sends initial proto.SyncResponse to the peer requesting synchronization
 func (s *GRPCServer) sendInitialSync(peerKey wgtypes.Key, peer *nbpeer.Peer, networkMap *NetworkMap, srv proto.ManagementService_SyncServer) error {
+	startTime := time.Now()
+	defer func() {
+		duration := time.Since(startTime)
+		log.Debugf("sendInitialSync took %s", duration)
+	}()
+
 	// make secret time based TURN credentials optional
 	var turnCredentials *TURNCredentials
 	if s.config.TURNConfig.TimeBasedCredentials {

management/server/integrated_validator.go

@@ -2,6 +2,7 @@ package server
 
 import (
 	"errors"
+	"time"
 
 	"github.com/google/martian/v3/log"
 
@@ -76,5 +77,11 @@ func (am *DefaultAccountManager) GroupValidation(accountId string, groups []stri
 }
 
 func (am *DefaultAccountManager) GetValidatedPeers(account *Account) (map[string]struct{}, error) {
+	startTime := time.Now()
+	defer func() {
+		duration := time.Since(startTime)
+		log.Debugf("GetValidatedPeers took %s", duration)
+	}()
+
 	return am.integratedPeerValidator.GetValidatedPeers(account.Id, account.Groups, account.Peers, account.Settings.Extra)
 }

management/server/peer.go

@@ -89,6 +89,12 @@ func (am *DefaultAccountManager) GetPeers(accountID, userID string) ([]*nbpeer.P
 
 // MarkPeerConnected marks peer as connected (true) or disconnected (false)
 func (am *DefaultAccountManager) MarkPeerConnected(peerPubKey string, connected bool, realIP net.IP) error {
+	startTime := time.Now()
+	defer func() {
+		duration := time.Since(startTime)
+		log.Debugf("MarkPeerConnected took %s", duration)
+	}()
+
 	account, err := am.Store.GetAccountByPeerPubKey(peerPubKey)
 	if err != nil {
 		return err
@@ -519,6 +525,12 @@ func (am *DefaultAccountManager) AddPeer(setupKey, userID string, peer *nbpeer.P
 
 // SyncPeer checks whether peer is eligible for receiving NetworkMap (authenticated) and returns its NetworkMap if eligible
 func (am *DefaultAccountManager) SyncPeer(sync PeerSync) (*nbpeer.Peer, *NetworkMap, error) {
+	startTime := time.Now()
+	defer func() {
+		duration := time.Since(startTime)
+		log.Debugf("SyncPeer took %s", duration)
+	}()
+
 	account, err := am.Store.GetAccountByPeerPubKey(sync.WireGuardPubKey)
 	if err != nil {
 		if errStatus, ok := status.FromError(err); ok && errStatus.Type() == status.NotFound {
@@ -684,6 +696,12 @@ func (am *DefaultAccountManager) LoginPeer(login PeerLogin) (*nbpeer.Peer, *Netw
 }
 
 func checkIfPeerOwnerIsBlocked(peer *nbpeer.Peer, account *Account) error {
+	startTime := time.Now()
+	defer func() {
+		duration := time.Since(startTime)
+		log.Debugf("checkIfPeerOwnerIsBlocked took %s", duration)
+	}()
+
 	if peer.AddedWithSSOLogin() {
 		user, err := account.FindUser(peer.UserID)
 		if err != nil {
@@ -857,6 +875,12 @@ func updatePeerMeta(peer *nbpeer.Peer, meta nbpeer.PeerSystemMeta, account *Acco
 // updateAccountPeers updates all peers that belong to an account.
 // Should be called when changes have to be synced to peers.
 func (am *DefaultAccountManager) updateAccountPeers(account *Account) {
+	startTime := time.Now()
+	defer func() {
+		duration := time.Since(startTime)
+		log.Debugf("updateAccountPeers took %s", duration)
+	}()
+
 	peers := account.GetPeers()
 
 	approvedPeersMap, err := am.GetValidatedPeers(account)

management/server/peer/peer.go

@@ -5,6 +5,8 @@ import (
 	"net"
 	"net/netip"
 	"time"
+
+	log "github.com/sirupsen/logrus"
 )
 
 // Peer represents a machine connected to the network.
@@ -173,6 +175,8 @@ func (p *Peer) UpdateMetaIfNew(meta PeerSystemMeta) bool {
 		meta.UIVersion = p.Meta.UIVersion
 	}
 
+	log.Infof("Check if meta is equal: %v", p.Meta.isEqual(meta))
+
 	if p.Meta.isEqual(meta) {
 		return false
 	}

management/server/sqlite_store.go

@@ -263,36 +263,27 @@ func (s *SqliteStore) GetInstallationID() string {
 }
 
 func (s *SqliteStore) SavePeerStatus(accountID, peerID string, peerStatus nbpeer.PeerStatus) error {
-	var peer nbpeer.Peer
+	startTime := time.Now()
+	defer func() {
+		duration := time.Since(startTime)
+		log.Debugf("SavePeerStatus took %s", duration)
+	}()
 
-	result := s.db.First(&peer, "account_id = ? and id = ?", accountID, peerID)
-	if result.Error != nil {
-		if errors.Is(result.Error, gorm.ErrRecordNotFound) {
-			return status.Errorf(status.NotFound, "peer %s not found", peerID)
-		}
-		log.Errorf("error when getting peer from the store: %s", result.Error)
-		return status.Errorf(status.Internal, "issue getting peer from store")
-	}
-
-	peer.Status = &peerStatus
-
-	return s.db.Save(peer).Error
+	log.Infof("saving peer status")
+	s.db.Where("account_id = ? and id = ?", accountID, peerID).Update("status", peerStatus)
+	return nil
 }
 
 func (s *SqliteStore) SavePeerLocation(accountID string, peerWithLocation *nbpeer.Peer) error {
-	var peer nbpeer.Peer
-	result := s.db.First(&peer, "account_id = ? and id = ?", accountID, peerWithLocation.ID)
-	if result.Error != nil {
-		if errors.Is(result.Error, gorm.ErrRecordNotFound) {
-			return status.Errorf(status.NotFound, "peer %s not found", peer.ID)
-		}
-		log.Errorf("error when getting peer from the store: %s", result.Error)
-		return status.Errorf(status.Internal, "issue getting peer from store")
-	}
+	startTime := time.Now()
+	defer func() {
+		duration := time.Since(startTime)
+		log.Debugf("SavePeerLocation took %s", duration)
+	}()
 
-	peer.Location = peerWithLocation.Location
-
-	return s.db.Save(peer).Error
+	log.Info("saving peer location")
+	s.db.Where("account_id = ? and id = ?", accountID, peerWithLocation.ID).Update("location", peerWithLocation.Location)
+	return nil
 }
 
 // DeleteHashedPAT2TokenIDIndex is noop in Sqlite
@@ -400,6 +391,12 @@ func (s *SqliteStore) GetAllAccounts() (all []*Account) {
 }
 
 func (s *SqliteStore) GetAccount(accountID string) (*Account, error) {
+	startTime := time.Now()
+	defer func() {
+		duration := time.Since(startTime)
+		log.Debugf("GetAccount took %s", duration)
+	}()
+
 	var account Account
 	result := s.db.Model(&account).
 		Preload("UsersG.PATsG"). // have to be specifies as this is nester reference