From bfca332fe1c01b6b86b444e7ddc8ffc10f7564d8 Mon Sep 17 00:00:00 2001 From: pascal Date: Tue, 30 Dec 2025 21:42:04 +0100 Subject: [PATCH 1/9] remove lock + add context timeout to transactions --- management/server/group.go | 6 +++++- management/server/store/sql_store.go | 6 +++++- 2 files changed, 10 insertions(+), 2 deletions(-) diff --git a/management/server/group.go b/management/server/group.go index 84e641f264b..9fc8db1209e 100644 --- a/management/server/group.go +++ b/management/server/group.go @@ -427,7 +427,7 @@ func (am *DefaultAccountManager) DeleteGroups(ctx context.Context, accountID, us err = am.Store.ExecuteInTransaction(ctx, func(transaction store.Store) error { for _, groupID := range groupIDs { - group, err := transaction.GetGroupByID(ctx, store.LockingStrengthUpdate, accountID, groupID) + group, err := transaction.GetGroupByID(ctx, store.LockingStrengthNone, accountID, groupID) if err != nil { allErrors = errors.Join(allErrors, err) continue @@ -442,6 +442,10 @@ func (am *DefaultAccountManager) DeleteGroups(ctx context.Context, accountID, us deletedGroups = append(deletedGroups, group) } + if len(groupIDsToDelete) == 0 { + return allErrors + } + if err = transaction.DeleteGroups(ctx, accountID, groupIDsToDelete); err != nil { return err } diff --git a/management/server/store/sql_store.go b/management/server/store/sql_store.go index 73565a46277..aca09a62c5f 100644 --- a/management/server/store/sql_store.go +++ b/management/server/store/sql_store.go @@ -37,6 +37,7 @@ import ( "github.com/netbirdio/netbird/management/server/util" "github.com/netbirdio/netbird/route" "github.com/netbirdio/netbird/shared/management/status" + "github.com/netbirdio/netbird/shared/sshauth" ) const ( @@ -2897,8 +2898,11 @@ func (s *SqlStore) IncrementNetworkSerial(ctx context.Context, accountId string) } func (s *SqlStore) ExecuteInTransaction(ctx context.Context, operation func(store Store) error) error { + timeoutCtx, cancel := context.WithTimeout(context.Background(), 5*time.Minute) + defer cancel() + startTime := time.Now() - tx := s.db.Begin() + tx := s.db.WithContext(timeoutCtx).Begin() if tx.Error != nil { return tx.Error } From 9c11fbb6f1a646c866a76dcb231776f5dcadde0b Mon Sep 17 00:00:00 2001 From: pascal Date: Tue, 30 Dec 2025 21:49:09 +0100 Subject: [PATCH 2/9] bring back took logs --- management/internals/shared/grpc/server.go | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/management/internals/shared/grpc/server.go b/management/internals/shared/grpc/server.go index 0b9326fbc07..4b2c87a30ca 100644 --- a/management/internals/shared/grpc/server.go +++ b/management/internals/shared/grpc/server.go @@ -227,6 +227,10 @@ func (s *Server) Sync(req *proto.EncryptedMessage, srv proto.ManagementService_S // nolint:staticcheck ctx = context.WithValue(ctx, nbContext.AccountIDKey, accountID) + defer func() { + log.WithContext(ctx).Debugf("Sync took %s", time.Since(reqStart)) + }() + start := time.Now() unlock := s.acquirePeerLockByUID(ctx, peerKey.String()) defer func() { @@ -565,6 +569,7 @@ func (s *Server) Login(ctx context.Context, req *proto.EncryptedMessage) (*proto if s.appMetrics != nil { s.appMetrics.GRPCMetrics().CountLoginRequestDuration(time.Since(reqStart), accountID) } + log.WithContext(ctx).Debugf("Login took %s", time.Since(reqStart)) }() if loginReq.GetMeta() == nil { From c60b1098a56244b8d9f4a425591b2802d7a6fcde Mon Sep 17 00:00:00 2001 From: pascal Date: Tue, 30 Dec 2025 21:59:44 +0100 Subject: [PATCH 3/9] add context exceeded logging with caller stack --- management/server/store/sql_store.go | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/management/server/store/sql_store.go b/management/server/store/sql_store.go index aca09a62c5f..faa1a42462f 100644 --- a/management/server/store/sql_store.go +++ b/management/server/store/sql_store.go @@ -2937,6 +2937,9 @@ func (s *SqlStore) ExecuteInTransaction(ctx context.Context, operation func(stor err := operation(repo) if err != nil { tx.Rollback() + if errors.Is(err, context.DeadlineExceeded) || errors.Is(timeoutCtx.Err(), context.DeadlineExceeded) { + log.WithContext(ctx).Warnf("transaction exceeded 5 minute timeout after %v, stack: %s", time.Since(startTime), debug.Stack()) + } return err } @@ -2949,13 +2952,19 @@ func (s *SqlStore) ExecuteInTransaction(ctx context.Context, operation func(stor } err = tx.Commit().Error + if err != nil { + if errors.Is(err, context.DeadlineExceeded) || errors.Is(timeoutCtx.Err(), context.DeadlineExceeded) { + log.WithContext(ctx).Warnf("transaction commit exceeded 5 minute timeout after %v, stack: %s", time.Since(startTime), debug.Stack()) + } + return err + } log.WithContext(ctx).Tracef("transaction took %v", time.Since(startTime)) if s.metrics != nil { s.metrics.StoreMetrics().CountTransactionDuration(time.Since(startTime)) } - return err + return nil } func (s *SqlStore) withTx(tx *gorm.DB) Store { From 751b2f9e3744a71e08988f762ee48c37db536222 Mon Sep 17 00:00:00 2001 From: pascal Date: Tue, 30 Dec 2025 22:08:58 +0100 Subject: [PATCH 4/9] make transaction timeout configurable --- management/server/store/sql_store.go | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/management/server/store/sql_store.go b/management/server/store/sql_store.go index faa1a42462f..33ba7f991fa 100644 --- a/management/server/store/sql_store.go +++ b/management/server/store/sql_store.go @@ -37,7 +37,6 @@ import ( "github.com/netbirdio/netbird/management/server/util" "github.com/netbirdio/netbird/route" "github.com/netbirdio/netbird/shared/management/status" - "github.com/netbirdio/netbird/shared/sshauth" ) const ( @@ -64,6 +63,8 @@ type SqlStore struct { installationPK int storeEngine types.Engine pool *pgxpool.Pool + + transactionTimeout time.Duration } type installation struct { @@ -85,6 +86,14 @@ func NewSqlStore(ctx context.Context, db *gorm.DB, storeEngine types.Engine, met conns = runtime.NumCPU() } + transactionTimeout := 5 * time.Minute + if v := os.Getenv("NB_STORE_TRANSACTION_TIMEOUT"); v != "" { + if parsed, err := time.ParseDuration(v); err == nil { + transactionTimeout = parsed + } + } + log.WithContext(ctx).Infof("Setting transaction timeout to %v", transactionTimeout) + if storeEngine == types.SqliteStoreEngine { if err == nil { log.WithContext(ctx).Warnf("setting NB_SQL_MAX_OPEN_CONNS is not supported for sqlite, using default value 1") @@ -102,7 +111,7 @@ func NewSqlStore(ctx context.Context, db *gorm.DB, storeEngine types.Engine, met if skipMigration { log.WithContext(ctx).Infof("skipping migration") - return &SqlStore{db: db, storeEngine: storeEngine, metrics: metrics, installationPK: 1}, nil + return &SqlStore{db: db, storeEngine: storeEngine, metrics: metrics, installationPK: 1, transactionTimeout: transactionTimeout}, nil } if err := migratePreAuto(ctx, db); err != nil { @@ -121,7 +130,7 @@ func NewSqlStore(ctx context.Context, db *gorm.DB, storeEngine types.Engine, met return nil, fmt.Errorf("migratePostAuto: %w", err) } - return &SqlStore{db: db, storeEngine: storeEngine, metrics: metrics, installationPK: 1}, nil + return &SqlStore{db: db, storeEngine: storeEngine, metrics: metrics, installationPK: 1, transactionTimeout: transactionTimeout}, nil } func GetKeyQueryCondition(s *SqlStore) string { From 072a134b709dd4d937d9e3afa7e17e4b4d25ff77 Mon Sep 17 00:00:00 2001 From: pascal Date: Tue, 30 Dec 2025 22:17:12 +0100 Subject: [PATCH 5/9] test --- management/server/store/sql_store.go | 2 +- management/server/store/sql_store_test.go | 28 +++++++++++++++++++++++ 2 files changed, 29 insertions(+), 1 deletion(-) diff --git a/management/server/store/sql_store.go b/management/server/store/sql_store.go index 33ba7f991fa..567b238d1dc 100644 --- a/management/server/store/sql_store.go +++ b/management/server/store/sql_store.go @@ -2907,7 +2907,7 @@ func (s *SqlStore) IncrementNetworkSerial(ctx context.Context, accountId string) } func (s *SqlStore) ExecuteInTransaction(ctx context.Context, operation func(store Store) error) error { - timeoutCtx, cancel := context.WithTimeout(context.Background(), 5*time.Minute) + timeoutCtx, cancel := context.WithTimeout(context.Background(), s.transactionTimeout) defer cancel() startTime := time.Now() diff --git a/management/server/store/sql_store_test.go b/management/server/store/sql_store_test.go index d63d624deb3..d7e8e4aeb1c 100644 --- a/management/server/store/sql_store_test.go +++ b/management/server/store/sql_store_test.go @@ -5,6 +5,7 @@ import ( "crypto/sha256" b64 "encoding/base64" "encoding/binary" + "errors" "fmt" "math/rand" "net" @@ -3857,3 +3858,30 @@ func TestSqlStore_ApproveAccountPeers(t *testing.T) { }) }) } + +func TestSqlStore_ExecuteInTransaction_Timeout(t *testing.T) { + if runtime.GOOS == "windows" { + t.Skip("The SQLite store is not properly supported by Windows yet") + } + + t.Setenv("NB_STORE_TRANSACTION_TIMEOUT", "1s") + + store, cleanup, err := NewTestStoreFromSQL(context.Background(), "", t.TempDir()) + require.NoError(t, err) + t.Cleanup(cleanup) + + sqlStore, ok := store.(*SqlStore) + require.True(t, ok) + assert.Equal(t, 1*time.Second, sqlStore.transactionTimeout) + + ctx := context.Background() + err = sqlStore.ExecuteInTransaction(ctx, func(transaction Store) error { + // Sleep for 2 seconds to exceed the 1 second timeout + time.Sleep(2 * time.Second) + return nil + }) + + // The error should be a deadline exceeded error + require.Error(t, err) + assert.True(t, errors.Is(err, context.DeadlineExceeded), "expected context.DeadlineExceeded error, got: %v", err) +} From 0e327083d801ad56cd3afeb62568465d8590039a Mon Sep 17 00:00:00 2001 From: pascal Date: Tue, 30 Dec 2025 22:22:11 +0100 Subject: [PATCH 6/9] use dynamic log message --- management/server/store/sql_store.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/management/server/store/sql_store.go b/management/server/store/sql_store.go index 567b238d1dc..08d19f0d31b 100644 --- a/management/server/store/sql_store.go +++ b/management/server/store/sql_store.go @@ -2947,7 +2947,7 @@ func (s *SqlStore) ExecuteInTransaction(ctx context.Context, operation func(stor if err != nil { tx.Rollback() if errors.Is(err, context.DeadlineExceeded) || errors.Is(timeoutCtx.Err(), context.DeadlineExceeded) { - log.WithContext(ctx).Warnf("transaction exceeded 5 minute timeout after %v, stack: %s", time.Since(startTime), debug.Stack()) + log.WithContext(ctx).Warnf("transaction exceeded %s timeout after %v, stack: %s", s.transactionTimeout, time.Since(startTime), debug.Stack()) } return err } @@ -2963,7 +2963,7 @@ func (s *SqlStore) ExecuteInTransaction(ctx context.Context, operation func(stor err = tx.Commit().Error if err != nil { if errors.Is(err, context.DeadlineExceeded) || errors.Is(timeoutCtx.Err(), context.DeadlineExceeded) { - log.WithContext(ctx).Warnf("transaction commit exceeded 5 minute timeout after %v, stack: %s", time.Since(startTime), debug.Stack()) + log.WithContext(ctx).Warnf("transaction commit exceeded %s timeout after %v, stack: %s", s.transactionTimeout, time.Since(startTime), debug.Stack()) } return err } From 9736fa9269ae905119d9e2dbc02f096c004ad067 Mon Sep 17 00:00:00 2001 From: pascal Date: Tue, 30 Dec 2025 22:31:50 +0100 Subject: [PATCH 7/9] fix test --- management/server/store/sql_store_test.go | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/management/server/store/sql_store_test.go b/management/server/store/sql_store_test.go index d7e8e4aeb1c..f32256fa74e 100644 --- a/management/server/store/sql_store_test.go +++ b/management/server/store/sql_store_test.go @@ -5,7 +5,6 @@ import ( "crypto/sha256" b64 "encoding/base64" "encoding/binary" - "errors" "fmt" "math/rand" "net" @@ -3881,7 +3880,7 @@ func TestSqlStore_ExecuteInTransaction_Timeout(t *testing.T) { return nil }) - // The error should be a deadline exceeded error + // The transaction should fail with an error (either timeout or already rolled back) require.Error(t, err) - assert.True(t, errors.Is(err, context.DeadlineExceeded), "expected context.DeadlineExceeded error, got: %v", err) + assert.Contains(t, err.Error(), "transaction has already been committed or rolled back", "expected transaction rolled back error, got: %v", err) } From 2e02a5aca064d496a5073727a80fd3f0fc59a8d0 Mon Sep 17 00:00:00 2001 From: pascal Date: Tue, 30 Dec 2025 22:44:23 +0100 Subject: [PATCH 8/9] skip test on mysql --- management/server/store/sql_store_test.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/management/server/store/sql_store_test.go b/management/server/store/sql_store_test.go index f32256fa74e..714927a5a90 100644 --- a/management/server/store/sql_store_test.go +++ b/management/server/store/sql_store_test.go @@ -3859,8 +3859,8 @@ func TestSqlStore_ApproveAccountPeers(t *testing.T) { } func TestSqlStore_ExecuteInTransaction_Timeout(t *testing.T) { - if runtime.GOOS == "windows" { - t.Skip("The SQLite store is not properly supported by Windows yet") + if os.Getenv("NETBIRD_STORE_ENGINE") == "mysql" { + t.Skip("Skipping timeout test for MySQL") } t.Setenv("NB_STORE_TRANSACTION_TIMEOUT", "1s") From 08f1bf32277cbed7752600617843ffae4c1b77da Mon Sep 17 00:00:00 2001 From: pascal Date: Wed, 31 Dec 2025 09:56:39 +0100 Subject: [PATCH 9/9] fix sync log --- management/internals/shared/grpc/server.go | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/management/internals/shared/grpc/server.go b/management/internals/shared/grpc/server.go index 4b2c87a30ca..063dda7e492 100644 --- a/management/internals/shared/grpc/server.go +++ b/management/internals/shared/grpc/server.go @@ -227,10 +227,6 @@ func (s *Server) Sync(req *proto.EncryptedMessage, srv proto.ManagementService_S // nolint:staticcheck ctx = context.WithValue(ctx, nbContext.AccountIDKey, accountID) - defer func() { - log.WithContext(ctx).Debugf("Sync took %s", time.Since(reqStart)) - }() - start := time.Now() unlock := s.acquirePeerLockByUID(ctx, peerKey.String()) defer func() { @@ -280,6 +276,8 @@ func (s *Server) Sync(req *proto.EncryptedMessage, srv proto.ManagementService_S unlock() unlock = nil + log.WithContext(ctx).Debugf("Sync took %s", time.Since(reqStart)) + s.syncSem.Add(-1) return s.handleUpdates(ctx, accountID, peerKey, peer, updates, srv)