Skip to content

Quiet recoverable server-error logs#1148

Merged
mtmk merged 2 commits into
mainfrom
auth-expiry-log-level
May 27, 2026
Merged

Quiet recoverable server-error logs#1148
mtmk merged 2 commits into
mainfrom
auth-expiry-log-level

Conversation

@mtmk

@mtmk mtmk commented May 18, 2026

Copy link
Copy Markdown
Member

Server-initiated graceful disconnects (User/Account Authentication Expired, Authentication Revoked, Stale Connection) are expected and recovered by the client's normal reconnect flow. Logging them at Error every 15 minutes (common with auth-callout JWTs) creates noise in monitoring without indicating an actual problem. They now log at Debug; other -ERR kinds (Permissions Violation, Maximum Connections, etc.) continue to log at Error. The ServerError event still fires for every kind, so callers wanting visibility can subscribe. Matches the nats.go behaviour of not surfacing these as errors and routing them through a callback instead.

The unobserved-exception part of the same issue was already fixed by #1051; the new test pins both behaviours.

The new test also exposed a pre-existing bug in -ERR parsing: when PONG and -ERR arrived in the same TCP read, buffer.GetOffset(position.Value) on the post-PONG slice returned the segment-internal index instead of the offset relative to the slice start, so Slice(0, GetOffset - 1) threw ArgumentOutOfRangeException and the server error was never logged or signalled. Switched to SequencePosition-based slicing.

Fixes #847

@synadia-claude-reviewer

synadia-claude-reviewer Bot commented May 18, 2026

Copy link
Copy Markdown
Contributor

Claude finished @mtmk's task in 1m 37s —— View job


PR Review: Quiet recoverable server-error logs

  • Gather context (CLAUDE.md, PR diff)
  • Review NatsReadProtocolProcessor.cs changes
  • Review AuthErrorTest.cs changes
  • Check for correctness, security, and performance issues
  • Post inline comments where needed
  • Post final review summary

Review Summary

The change is correct and well-scoped. The three operations that were duplicated across two call sites (log, fire event, signal TCS) are consolidated into HandleServerError, and the log-level selection is cleanly driven from NatsServerErrorEventArgs.Kind — reusing the parse logic already committed to NatsEventArgs.cs rather than re-matching strings.

Correctness

  • All three side effects are preserved in HandleServerError: _logger.Log, PushEvent, and TrySetObservedException. Order is unchanged.
  • _waitForPongOrErrorSignal.TrySetObservedException is still called for every error kind (including now-Debug ones). For mid-session errors where the signal was already resolved, Try* is a no-op — correct.
  • The ServerError event still fires for all kinds, preserving the documented API contract that subscribers can observe every error.
  • NatsServerErrorEventArgs is constructed once and shared between the level switch and PushEvent, eliminating the extra allocation that existed in the original duplicated code.

Error kind coverage

AuthorizationViolation ("Authorization Violation") is not listed in the quiet set, so it falls through to _ => LogLevel.Error. That's the right call — wrong-credential errors during a reconnect cycle need to stay visible. The PR description doesn't enumerate it explicitly; worth a brief call-out in the commit message or description, but not blocking.

Test

  • The Theory covers all four quiet kinds and one loud kind (PermissionsViolation). The mock server closes the socket unconditionally after the first PING in all cases, so the reconnect path is exercised for every variant.
  • InMemoryTestLoggerFactory is initialized at LogLevel.Trace, so Debug messages are captured — Assert.NotEmpty(serverErrorLogs) genuinely verifies the log was emitted, not just that nothing crashed.
  • The GC.Collect / GC.WaitForPendingFinalizers pattern for catching unobserved exceptions is non-deterministic but is the established pattern in this file and across the test suite — not introduced here.
  • One minor nit: TaskScheduler.UnobservedTaskException is a process-wide hook; concurrent tests in the same process could cause spurious counts. The finally cleanup mitigates this, and it mirrors the existing Auth_err_then_connection_recreation_does_not_cause_unobserved_exception test, so this is consistent.

No issues requiring changes. The PR is ready to merge.

@github-actions

github-actions Bot commented May 18, 2026

Copy link
Copy Markdown

buffer.GetOffset(position.Value) returns the segment-internal index
instead of the offset relative to buffer.Start when the sequence comes
from SeqeunceBuilder's multi-segment constructor and the buffer has
been sliced (e.g. after a PONG was consumed from the same read).
That made buffer.Slice(0, GetOffset - 1) throw ArgumentOutOfRange,
so the -ERR was never logged. Use SequencePosition-based slicing,
which honours the sliced view.
@mtmk mtmk self-assigned this May 18, 2026
@mtmk mtmk added the bug fix label May 18, 2026
@mtmk

mtmk commented May 18, 2026

Copy link
Copy Markdown
Member Author

@claude can you review 4cfe182?

@synadia-claude-reviewer

synadia-claude-reviewer Bot commented May 18, 2026

Copy link
Copy Markdown
Contributor

Claude finished @mtmk's task in 1m 50s —— View job


Review of commit 4cfe182 — Fix -ERR parsing on sliced ReadOnlySequence

  • Gather commit details
  • Read changed files (NatsReadProtocolProcessor.cs, netstandard.cs)
  • Review for correctness, edge cases, and issues
  • Post findings

The fix is correct. Here's the analysis:

Root cause

GetOffset (defined in netstandard.cs:204) walks segments to compute the offset relative to the sequence's start:

return currentSegment.RunningIndex + positionIndex;

RunningIndex is set when the original sequence is built and is absolute from the sequence root. When the buffer has been sliced (e.g. after consuming a PONG from the same TCP read), the new slice's Start sits partway into a segment, but RunningIndex of that segment still reflects its absolute position in the original sequence — it is never adjusted for the slice offset. So GetOffset returns a value relative to the original sequence root, not to the sliced view.

Concretely: if the sliced buffer starts at byte 90 of a segment and position lands at byte 94, GetOffset returns 94 instead of 4. Then buffer.Slice(0, 94 - 1) attempts to slice 93 bytes from a 5-byte window → ArgumentOutOfRangeException.

The fix

// Before
var error = ParseError(buffer.Slice(0, buffer.GetOffset(position.Value) - 1));

// After
var lineWithCR = buffer.Slice(0, position.Value);         // up to '\n' (exclusive), via SequencePosition
var error = ParseError(lineWithCR.Slice(0, lineWithCR.Length - 1));  // strip '\r'

ReadOnlySequence<T>.Slice(SequencePosition) is purely position-based and correctly handles sliced views. lineWithCR.Length reports the logical length of that slice, so stripping the \r via Length - 1 is always accurate regardless of segment layout.

Coverage of both branches

  • else branch (fast path, \n already in buffer): This is where the bug actually triggers — the buffer was sliced after PONG, making GetOffset return a wrong offset. Fixed correctly.
  • null branch (slow path, ReadUntilReceiveNewLineAsync): ReadUntilReceiveNewLineAsync likely returns a fresh single-segment sequence where GetOffset would have been correct, so this wasn't a live bug. Making both branches consistent is the right call — it avoids a latent risk if that method's internals ever change, and the two branches are now symmetric.

The GetOffset definition is no longer called at all

After this commit, GetOffset has no remaining callers in NatsReadProtocolProcessor.cs. The only definition is in netstandard.cs:204 (a polyfill extension method). If no other file calls it, it's dead code — not a bug, just a cleanup opportunity.

One minor nit

newPosition!.Value appears twice in the null branch (lines 427 and 430 of the file). The ! is correct (the method guarantees a \n is present), but the second use on the return line is redundant: newPosition was already dereferenced on the line above without throwing, so the nullability state is already narrowed. Not a problem in practice — just slightly noisy.

No correctness issues. The fix is minimal, accurate, and well-described in the commit message.

@mtmk
mtmk requested a review from scottf May 18, 2026 08:38
NatsServerErrorKind.StaleConnection => LogLevel.Debug,
_ => LogLevel.Error,
};
_logger.Log(level, NatsLogEvents.Protocol, "Server error {Error}", error);

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since it's not an error, maybe change the message? Also, doesn't the user already have a way to monitor connections state and do their own logging?

@scottf scottf left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@mtmk
mtmk merged commit 187639d into main May 27, 2026
32 of 33 checks passed
@mtmk
mtmk deleted the auth-expiry-log-level branch May 27, 2026 09:33
This was referenced May 27, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Exceptions thrown during auth expiry despite successful reconnect

2 participants