From 0314cd8e22398c9f9e87d7ea8f3055e63e37f611 Mon Sep 17 00:00:00 2001 From: Dzianis Vashchuk Date: Mon, 1 Jun 2026 14:16:02 +0000 Subject: [PATCH 1/3] fix(nodeauth): downgrade context-cancel errors to WARN in node JWT authenticator When IsNodePubKeyTrusted returns context.Canceled or context.DeadlineExceeded, log at WARN instead of ERROR. These are expected transient conditions (caller-initiated cancellation or slow upstream) and should not fire alerts. Adds tests for both Canceled and DeadlineExceeded paths, and a well-behaved captureHandler for slog assertions. Ticket: SHARED-2644 --- pkg/nodeauth/jwt/node_jwt_authenticator.go | 16 ++- .../jwt/node_jwt_authenticator_test.go | 117 ++++++++++++++++++ 2 files changed, 129 insertions(+), 4 deletions(-) diff --git a/pkg/nodeauth/jwt/node_jwt_authenticator.go b/pkg/nodeauth/jwt/node_jwt_authenticator.go index 24bcbd5ac8..5a3fa79ba2 100644 --- a/pkg/nodeauth/jwt/node_jwt_authenticator.go +++ b/pkg/nodeauth/jwt/node_jwt_authenticator.go @@ -78,10 +78,18 @@ func (v *NodeJWTAuthenticator) AuthenticateJWT(ctx context.Context, tokenString // Public Key Validation: Verify node's CSA pubkey against the whitelisted registry via NodeAuthProvider. isValid, err := v.nodeAuthProvider.IsNodePubKeyTrusted(ctx, publicKey) if err != nil { - v.logger.Error("Node validation failed", - "csaPubKey", hex.EncodeToString(publicKey), - "error", err, - ) + if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) { + v.logger.Warn("Node validation skipped: context canceled or deadline exceeded", + "csaPubKey", hex.EncodeToString(publicKey), + "error", err, + "contextErr", ctx.Err(), + ) + } else { + v.logger.Error("Node validation failed", + "csaPubKey", hex.EncodeToString(publicKey), + "error", err, + ) + } return false, claims, fmt.Errorf("node validation failed: %w", err) } diff --git a/pkg/nodeauth/jwt/node_jwt_authenticator_test.go b/pkg/nodeauth/jwt/node_jwt_authenticator_test.go index 9986d268aa..539abc919f 100644 --- a/pkg/nodeauth/jwt/node_jwt_authenticator_test.go +++ b/pkg/nodeauth/jwt/node_jwt_authenticator_test.go @@ -5,8 +5,10 @@ import ( "crypto/ed25519" "crypto/rand" "encoding/hex" + "errors" "io" "log/slog" + "sync" "testing" "time" @@ -450,3 +452,118 @@ func TestNewNodeJWTAuthenticator_WithAndWithoutLeeway(t *testing.T) { assert.NotNil(t, authenticator.parser) }) } + +// captureHandler is a minimal slog.Handler that captures log records for test assertions. +// It satisfies the full slog.Handler contract: WithAttrs and WithGroup return a new +// handler so that logger.With(...) / logger.WithGroup(...) calls don't silently discard +// attributes. +type captureHandler struct { + mu sync.Mutex + records []slog.Record + attrs []slog.Attr + groups []string +} + +func (h *captureHandler) Enabled(_ context.Context, _ slog.Level) bool { return true } +func (h *captureHandler) Handle(_ context.Context, r slog.Record) error { + // Prepend any inherited attrs so they appear in captured records. + if len(h.attrs) > 0 { + r2 := slog.NewRecord(r.Time, r.Level, r.Message, r.PC) + r2.AddAttrs(h.attrs...) + r.Attrs(func(a slog.Attr) bool { r2.AddAttrs(a); return true }) + r = r2 + } + h.mu.Lock() + defer h.mu.Unlock() + h.records = append(h.records, r.Clone()) + return nil +} +func (h *captureHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + h.mu.Lock() + defer h.mu.Unlock() + merged := make([]slog.Attr, len(h.attrs)+len(attrs)) + copy(merged, h.attrs) + copy(merged[len(h.attrs):], attrs) + return &captureHandler{records: h.records, attrs: merged, groups: h.groups} +} +func (h *captureHandler) WithGroup(name string) slog.Handler { + h.mu.Lock() + defer h.mu.Unlock() + groups := append(append([]string{}, h.groups...), name) + return &captureHandler{records: h.records, attrs: h.attrs, groups: groups} +} + +func TestNodeJWTAuthenticator_AuthenticateJWT_ProviderNonContextError(t *testing.T) { + // Non-context provider errors must be logged at ERROR level. + privateKey, csaPubKey := createValidatorTestKeys() + providerErr := errors.New("database unavailable") + mockProvider := &mocks.NodeAuthProvider{} + mockProvider.On("IsNodePubKeyTrusted", mock.Anything, csaPubKey).Return(false, providerErr) + + h := &captureHandler{} + authenticator := NewNodeJWTAuthenticator(mockProvider, slog.New(h)) + + testRequest := testRequest{Field: "test-request"} + valid, claims, err := authenticator.AuthenticateJWT(context.Background(), createValidJWT(privateKey, csaPubKey), testRequest) + + require.Error(t, err) + assert.False(t, valid) + assert.NotNil(t, claims) + assert.Contains(t, err.Error(), "node validation failed") + + require.Len(t, h.records, 1) + assert.Equal(t, slog.LevelError, h.records[0].Level, "non-context provider errors should log at ERROR") + mockProvider.AssertExpectations(t) +} + +func TestNodeJWTAuthenticator_AuthenticateJWT_ProviderContextCancelledError(t *testing.T) { + // Context-cancellation errors from the provider must be logged at WARN, not ERROR, + // because they are caused by the caller cancelling the request — not a system fault. + privateKey, csaPubKey := createValidatorTestKeys() + mockProvider := &mocks.NodeAuthProvider{} + mockProvider.On("IsNodePubKeyTrusted", mock.Anything, csaPubKey).Return(false, context.Canceled) + + h := &captureHandler{} + authenticator := NewNodeJWTAuthenticator(mockProvider, slog.New(h)) + + ctx, cancel := context.WithCancel(context.Background()) + cancel() // already cancelled + + testRequest := testRequest{Field: "test-request"} + valid, claims, err := authenticator.AuthenticateJWT(ctx, createValidJWT(privateKey, csaPubKey), testRequest) + + require.Error(t, err) + assert.False(t, valid) + assert.NotNil(t, claims) + assert.ErrorIs(t, err, context.Canceled) + + require.Len(t, h.records, 1) + assert.Equal(t, slog.LevelWarn, h.records[0].Level, "context cancellation from provider should log at WARN not ERROR") + mockProvider.AssertExpectations(t) +} + +func TestNodeJWTAuthenticator_AuthenticateJWT_ProviderDeadlineExceededError(t *testing.T) { + // context.DeadlineExceeded from the provider must also be logged at WARN, not ERROR, + // because it is an expected transient condition (e.g. slow upstream), not a system fault. + privateKey, csaPubKey := createValidatorTestKeys() + mockProvider := &mocks.NodeAuthProvider{} + mockProvider.On("IsNodePubKeyTrusted", mock.Anything, csaPubKey).Return(false, context.DeadlineExceeded) + + h := &captureHandler{} + authenticator := NewNodeJWTAuthenticator(mockProvider, slog.New(h)) + + ctx, cancel := context.WithTimeout(context.Background(), 0) // immediately expired + defer cancel() + + testRequest := testRequest{Field: "test-request"} + valid, claims, err := authenticator.AuthenticateJWT(ctx, createValidJWT(privateKey, csaPubKey), testRequest) + + require.Error(t, err) + assert.False(t, valid) + assert.NotNil(t, claims) + assert.ErrorIs(t, err, context.DeadlineExceeded) + + require.Len(t, h.records, 1) + assert.Equal(t, slog.LevelWarn, h.records[0].Level, "deadline exceeded from provider should log at WARN not ERROR") + mockProvider.AssertExpectations(t) +} From 6da70557ac6007fb91089acf274b0e0d35d045e3 Mon Sep 17 00:00:00 2001 From: Dzianis Vashchuk Date: Tue, 2 Jun 2026 08:59:11 +0000 Subject: [PATCH 2/3] ci: retrigger CI to refresh SonarQube coverage analysis From 712f553f5e0eaf7945a89518075c66ec6c101b56 Mon Sep 17 00:00:00 2001 From: Dzianis Vashchuk Date: Tue, 2 Jun 2026 16:27:50 +0000 Subject: [PATCH 3/3] fix(nodeauth): use real slog handler in tests --- pkg/nodeauth/jwt/node_jwt_authenticator.go | 9 ++- .../jwt/node_jwt_authenticator_test.go | 80 +++++++------------ 2 files changed, 33 insertions(+), 56 deletions(-) diff --git a/pkg/nodeauth/jwt/node_jwt_authenticator.go b/pkg/nodeauth/jwt/node_jwt_authenticator.go index 5a3fa79ba2..bb5c836101 100644 --- a/pkg/nodeauth/jwt/node_jwt_authenticator.go +++ b/pkg/nodeauth/jwt/node_jwt_authenticator.go @@ -79,11 +79,14 @@ func (v *NodeJWTAuthenticator) AuthenticateJWT(ctx context.Context, tokenString isValid, err := v.nodeAuthProvider.IsNodePubKeyTrusted(ctx, publicKey) if err != nil { if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) { - v.logger.Warn("Node validation skipped: context canceled or deadline exceeded", + attrs := []any{ "csaPubKey", hex.EncodeToString(publicKey), "error", err, - "contextErr", ctx.Err(), - ) + } + if ctxErr := ctx.Err(); ctxErr != nil { + attrs = append(attrs, "contextErr", ctxErr) + } + v.logger.Warn("Node validation skipped: context canceled or deadline exceeded", attrs...) } else { v.logger.Error("Node validation failed", "csaPubKey", hex.EncodeToString(publicKey), diff --git a/pkg/nodeauth/jwt/node_jwt_authenticator_test.go b/pkg/nodeauth/jwt/node_jwt_authenticator_test.go index 539abc919f..81c8154902 100644 --- a/pkg/nodeauth/jwt/node_jwt_authenticator_test.go +++ b/pkg/nodeauth/jwt/node_jwt_authenticator_test.go @@ -1,14 +1,15 @@ package jwt import ( + "bytes" "context" "crypto/ed25519" "crypto/rand" "encoding/hex" + "encoding/json" "errors" "io" "log/slog" - "sync" "testing" "time" @@ -453,46 +454,6 @@ func TestNewNodeJWTAuthenticator_WithAndWithoutLeeway(t *testing.T) { }) } -// captureHandler is a minimal slog.Handler that captures log records for test assertions. -// It satisfies the full slog.Handler contract: WithAttrs and WithGroup return a new -// handler so that logger.With(...) / logger.WithGroup(...) calls don't silently discard -// attributes. -type captureHandler struct { - mu sync.Mutex - records []slog.Record - attrs []slog.Attr - groups []string -} - -func (h *captureHandler) Enabled(_ context.Context, _ slog.Level) bool { return true } -func (h *captureHandler) Handle(_ context.Context, r slog.Record) error { - // Prepend any inherited attrs so they appear in captured records. - if len(h.attrs) > 0 { - r2 := slog.NewRecord(r.Time, r.Level, r.Message, r.PC) - r2.AddAttrs(h.attrs...) - r.Attrs(func(a slog.Attr) bool { r2.AddAttrs(a); return true }) - r = r2 - } - h.mu.Lock() - defer h.mu.Unlock() - h.records = append(h.records, r.Clone()) - return nil -} -func (h *captureHandler) WithAttrs(attrs []slog.Attr) slog.Handler { - h.mu.Lock() - defer h.mu.Unlock() - merged := make([]slog.Attr, len(h.attrs)+len(attrs)) - copy(merged, h.attrs) - copy(merged[len(h.attrs):], attrs) - return &captureHandler{records: h.records, attrs: merged, groups: h.groups} -} -func (h *captureHandler) WithGroup(name string) slog.Handler { - h.mu.Lock() - defer h.mu.Unlock() - groups := append(append([]string{}, h.groups...), name) - return &captureHandler{records: h.records, attrs: h.attrs, groups: groups} -} - func TestNodeJWTAuthenticator_AuthenticateJWT_ProviderNonContextError(t *testing.T) { // Non-context provider errors must be logged at ERROR level. privateKey, csaPubKey := createValidatorTestKeys() @@ -500,8 +461,8 @@ func TestNodeJWTAuthenticator_AuthenticateJWT_ProviderNonContextError(t *testing mockProvider := &mocks.NodeAuthProvider{} mockProvider.On("IsNodePubKeyTrusted", mock.Anything, csaPubKey).Return(false, providerErr) - h := &captureHandler{} - authenticator := NewNodeJWTAuthenticator(mockProvider, slog.New(h)) + logger, buf := newCaptureLogger() + authenticator := NewNodeJWTAuthenticator(mockProvider, logger) testRequest := testRequest{Field: "test-request"} valid, claims, err := authenticator.AuthenticateJWT(context.Background(), createValidJWT(privateKey, csaPubKey), testRequest) @@ -511,8 +472,8 @@ func TestNodeJWTAuthenticator_AuthenticateJWT_ProviderNonContextError(t *testing assert.NotNil(t, claims) assert.Contains(t, err.Error(), "node validation failed") - require.Len(t, h.records, 1) - assert.Equal(t, slog.LevelError, h.records[0].Level, "non-context provider errors should log at ERROR") + entry := readLogEntry(t, buf) + assert.Equal(t, "ERROR", entry["level"], "non-context provider errors should log at ERROR") mockProvider.AssertExpectations(t) } @@ -523,8 +484,8 @@ func TestNodeJWTAuthenticator_AuthenticateJWT_ProviderContextCancelledError(t *t mockProvider := &mocks.NodeAuthProvider{} mockProvider.On("IsNodePubKeyTrusted", mock.Anything, csaPubKey).Return(false, context.Canceled) - h := &captureHandler{} - authenticator := NewNodeJWTAuthenticator(mockProvider, slog.New(h)) + logger, buf := newCaptureLogger() + authenticator := NewNodeJWTAuthenticator(mockProvider, logger) ctx, cancel := context.WithCancel(context.Background()) cancel() // already cancelled @@ -537,8 +498,8 @@ func TestNodeJWTAuthenticator_AuthenticateJWT_ProviderContextCancelledError(t *t assert.NotNil(t, claims) assert.ErrorIs(t, err, context.Canceled) - require.Len(t, h.records, 1) - assert.Equal(t, slog.LevelWarn, h.records[0].Level, "context cancellation from provider should log at WARN not ERROR") + entry := readLogEntry(t, buf) + assert.Equal(t, "WARN", entry["level"], "context cancellation from provider should log at WARN not ERROR") mockProvider.AssertExpectations(t) } @@ -549,8 +510,8 @@ func TestNodeJWTAuthenticator_AuthenticateJWT_ProviderDeadlineExceededError(t *t mockProvider := &mocks.NodeAuthProvider{} mockProvider.On("IsNodePubKeyTrusted", mock.Anything, csaPubKey).Return(false, context.DeadlineExceeded) - h := &captureHandler{} - authenticator := NewNodeJWTAuthenticator(mockProvider, slog.New(h)) + logger, buf := newCaptureLogger() + authenticator := NewNodeJWTAuthenticator(mockProvider, logger) ctx, cancel := context.WithTimeout(context.Background(), 0) // immediately expired defer cancel() @@ -563,7 +524,20 @@ func TestNodeJWTAuthenticator_AuthenticateJWT_ProviderDeadlineExceededError(t *t assert.NotNil(t, claims) assert.ErrorIs(t, err, context.DeadlineExceeded) - require.Len(t, h.records, 1) - assert.Equal(t, slog.LevelWarn, h.records[0].Level, "deadline exceeded from provider should log at WARN not ERROR") + entry := readLogEntry(t, buf) + assert.Equal(t, "WARN", entry["level"], "deadline exceeded from provider should log at WARN not ERROR") mockProvider.AssertExpectations(t) } + +func newCaptureLogger() (*slog.Logger, *bytes.Buffer) { + var buf bytes.Buffer + return slog.New(slog.NewJSONHandler(&buf, nil)), &buf +} + +func readLogEntry(t *testing.T, buf *bytes.Buffer) map[string]any { + t.Helper() + + var entry map[string]any + require.NoError(t, json.Unmarshal(buf.Bytes(), &entry)) + return entry +}