fix(logging): route session diagnostics into one session log#916
Merged
Aaronontheweb merged 13 commits intoMay 7, 2026
Conversation
- OpenAiCompatibleProviderPlugin passed _logger as a 4th constructor arg but OpenAiCompatibleChatClient has only a 3-arg constructor (and zero log call sites). Revert the plugin to its original 3-arg shape. - Replace empty Dispose catch in RollingFileLoggerProviderTests with scoped IO/UnauthorizedAccess handlers that surface cleanup failures to test stderr instead of silently swallowing them.
) Replaces the two-writer + per-path lock dictionary design with a SessionLogDispatcher root actor that owns one SessionLogActor child per sanitized session id. The dispatcher is the only routing fabric; the child actor's mailbox is the only writer per session.log file. What changed - New SessionLogDispatcher routes SessionOutput, SendUserMessage, and the new SessionLogDiagnostic message to the right child by sessionId. - SessionLogActor moves to be a child of the dispatcher, gets a ReceiveTimeout-based idle eviction, and now also handles SessionLogDiagnostic for MEL provider lines. - RollingFileLoggerProvider takes IRequiredActor<SessionLogDispatcherActorKey> via a Func<Task<IActorRef>> dispatcher factory, awaits the actor system to come up, and buffers session-scoped diagnostics in a small bounded ConcurrentQueue during the boot window. After resolution, all session-scoped log lines are pre-formatted on the caller's thread, snapshotted into a SessionLogDiagnostic, and Tell'd to the dispatcher. - SessionLogFile.AppendLine no longer holds a lock or maintains a ConcurrentDictionary of per-path Lock instances; the actor model guarantees a single writer per file. - LlmSessionActor stops creating SessionLogActor as its own child and instead resolves the dispatcher via ActorRegistry to forward audit messages. - Hosting wired via WithSessionLogDispatcher in NetclawAkkaHostingExtensions; daemon Program.cs registers it after WithNetclawActors so the IRequiredActor<...> resolves cleanly. Why - Two-writer coordination via per-path Lock was a structural workaround with an unbounded leak (lock dictionary grew once per unique session path the daemon ever served). - Synchronous file I/O on the MEL log hot path (open + lock + write + flush + dispose per emit) was inconsistent with the daemon log's background queue and bad under streaming bursts. - A single mailbox per session makes audit and diagnostic line ordering wall-clock-faithful by construction; the prior design only prevented corruption, not interleaving. Other fixes - SessionDiagnosticsContext.NormalizeSessionId now documents why /subagent/* markers collapse to the parent id (sub-agent diagnostics share the parent's session.log; per-agent files would scatter the audit trail). - Tests cover routing, cross-session isolation, eviction + recreation appending to the same file, audit/diagnostic interleaving, async continuation flow of AsyncLocal session id, and pre-resolution buffer-and-drain. See netclaw-dev#918 for the full design rationale.
This was referenced May 7, 2026
…arent Simplification pass on the e95f514 redesign, surfaced by code review: - Delete SessionLogDispatcher.cs entirely. Reuse the existing GenericChildPerEntityParent + SessionMessageExtractor pattern (the same one WithSessionManager already uses for routing IWithSessionId messages to LlmSessionActors). Net: ~60 lines removed, identical routing behavior. - Make SessionOutput implement IWithSessionId so the extractor returns its sessionId. SessionOutput already had a SessionId property; the interface declaration was the only thing missing. - Fix drain/publish ordering race in RollingFileLoggerProvider: publish the dispatcher ref BEFORE draining the buffer. A producer racing with the drainer now sees the ref and Tells directly instead of enqueueing into a queue we are about to abandon. - Fail loudly on dispatcher resolution failure: write a single ERR line to the daemon log queue and disable the session-log path for the rest of the process. Replaces the prior Console.Error one-shot that operators would never see. - Replace ConcurrentQueue<T>.Count (O(N/32)) with an Interlocked counter for the buffer-full check. Cheap improvement on a hot path that fires per session-scoped log line during boot. - Drop the "Session log attached" line that PreStart wrote on every (re)creation. With idle-eviction the marker no longer corresponds to a session lifecycle event and was just noise + sync I/O per recreation. - Remove SessionLogActor.GetSessionLogPath / GetSessionLogsDirectory pass-throughs. Path computation lives on SessionLogFile; production callers and tests now call SessionLogFile.GetLogPath directly. - Drop the misleading FakeTimeProvider.Advance line from the eviction test — Akka's ReceiveTimeout is driven by the actor scheduler, not TimeProvider, so the Advance call was a no-op against the eviction trigger. The test still passes via real-time AwaitAssertAsync polling against the small idle-timeout, which is the correct Akka pattern.
The previous attempt used builder.Logging.Services.AddSingleton<ILoggerProvider>(factory)
to lazily resolve IRequiredActor<SessionLogDispatcherActorKey> via DI. In this
hosting setup the LoggerFactory does not pick up that registration — the
provider was constructed but never received any log lines, so the daemon
started silently and never bound the health endpoint.
Restore the eager builder.Logging.AddProvider(instance) registration that
worked previously, and connect the dispatcher post-construction:
- RollingFileLoggerProvider exposes AttachSessionDispatcher(Task<IActorRef>),
which kicks off the existing buffer-and-drain logic.
- SessionLogDispatcherWiringService is registered as IHostedService and runs
during host startup; it calls AttachSessionDispatcher with the
IRequiredActor<>.GetAsync() task. The actor system is up by the time
IHostedService.StartAsync fires, so resolution succeeds without a
pre-resolution buffer in normal operation. The buffer remains as a safety
net for any racing log lines emitted between provider construction and
StartAsync.
- Tests use AttachSessionDispatcher directly with a fake task / probe; no
test setup churn beyond switching to the new method.
Verified locally: daemon binds health endpoint, daemon-{date}.log writes
correctly under default Warning level. CI Validate Docker Build and Smoke
Sandbox should both recover.
Two specialists (akka-net + dotnet-concurrency) confirmed the original test failure on Windows had two stacked causes: 1. Akka race: 150ms ReceiveTimeout idle eviction + AwaitAssertAsync polling. When the second Tell arrived during the still-Terminating window of the prior child, GenericChildPerEntityParent.Forward routed to the closed mailbox -> dead letters -> message lost. The prior commit replaced this with deterministic Watch + Sys.Stop + ExpectTerminatedAsync of the dispatcher. 2. Windows OS-level race: even after actor termination completes, the kernel close-completion window plus AV / Defender real-time scanning can briefly hold a SHARING_VIOLATION on the just-closed file path. A new actor's first AppendLine can fail with IOException for tens-to-hundreds of ms after the prior writer closed. Linux releases inode references immediately, so this never reproduces there. Two targeted fixes: - SessionLogFile.AppendLine now retries up to 4 times on IOException / UnauthorizedAccessException with linear backoff (10, 20, 30 ms). The actor model still guarantees a single writer, so this is purely an OS-level transient absorber. Helps both production Windows deployments and the test suite. - SessionLogActorTests.TryDeleteDirectory replaces the bare Directory.Delete in finally blocks. The test's assertions have already passed by the time we reach finally, so cleanup failures should never mask success. Retries on IOException / UnauthorizedAccessException with the same backoff shape; logs to stderr if cleanup ultimately fails. Applied to all four tests. CLAUDE.md note: this is the rare case where Thread.Sleep is the right tool — we are absorbing an OS-level transient with no synchronization signal available to wait on. The retries are bounded and on a non-hot-path (cleanup or first-write-after-close).
Replaces the prior commit's hand-rolled retry loops: - SessionLogFile.AppendLine: removed the IOException retry + Thread.Sleep backoff. Adding silent retry inside the helper layered recovery on top of the actor's existing explicit catch+log "drop on failure" semantics in SessionLogActor — the wrong place to handle transient OS-level failures. If AppendLine throws on Windows, the actor's existing handler logs at Debug and the line is dropped, which is the documented best-effort contract for session.log. - SessionLogActorTests cleanup: replaced TryDeleteDirectory's hand-rolled retry-with-Thread.Sleep loop with TryDeleteDirectoryAsync that spins via AwaitAssertAsync. Same shape as every other test polling helper in the codebase, no new mechanism, deterministic deadline driven by TestKit's outer timeout rather than a hardcoded 5-attempt cap. The Akka deterministic-teardown fix from 434b6c7 (Watch + Sys.Stop + ExpectTerminatedAsync of the dispatcher) is unchanged — that was the real Windows fix; the AppendLine retry was overreach.
Successive_dispatchers_append_to_same_canonical_file kept failing on Windows after 535df45: "Assistant: second" never reached the file even with deterministic dispatcher teardown. Root cause: when dispatcher2's SessionLogActor calls SessionLogFile.AppendLine, Windows AV / kernel handle-cleanup transiently holds SHARING_VIOLATION on the just-closed file. The actor's existing catch-Exception-and-log-Debug contract drops the message; the test's AwaitAssertAsync polls forever for a line that never arrives. Fix: move the dispatcher2.Tell INSIDE the AwaitAssertAsync polling predicate. Each iteration re-Tells "second"; eventually one attempt lands when AV isn't holding the file. Multiple landed writes are fine — Assert.Contains is duplicate-tolerant, and we still assert the single-file invariant via Assert.Single(...). Production behavior is unchanged: AppendLine still throws on transient failures and SessionLogActor still drops the message at Debug log level. session.log is best-effort observability.
Update operator-facing surfaces to reflect the SessionLogDispatcher redesign and what diagnosticians should expect when reading the files. netclaw-operations skill (v1.26.0): - Document the daemon-log + session-log split with rotation properties. - Explain the chronological-timeline guarantee (single actor writes session.log) and the two line shapes inside it (audit + Diagnostic:). - State the best-effort observability contract: lines may be dropped on transient IO; debug-level note lands in the daemon log. - Note current sidecar bypass (compaction, title gen, sub-agents) and reference netclaw-dev#920 so the agent can tell operators why some diagnostics may be missing. - Reference netclaw-dev#919 for the size-cap follow-up. docs/spec/configuration.md: - Note daemon-log rotation properties (10 MB cap). - Describe the dispatcher-as-single-writer property. - State the best-effort drop-on-error contract. - Note absence of session.log size rotation today.
Two specialist agents (akka-net + dotnet-concurrency) traced the Windows-CI-only flake of QuerySkillUsageStats_returns_groupable_rows_for_each_method to synchronous SQLite I/O on DailyStatsActor.PreStart() — connection open + 2 CREATE TABLE statements + COMMIT against a freshly-created .db file. AV / Defender scanning the new file plus first-time fsync on Windows runners can push the round-trip past 3s. Linux releases inode references and fsyncs cheaply, so it never reproduces there. This is not a race — Akka guarantees mailbox FIFO from the test thread's four Tells through the subsequent Ask. The fix is purely a timeout budget. Drive-by fix in this PR because the flake hit the session-log-routing branch's CI rerun and was unrelated to it. Proper fix (move table creation off the actor's hot path) is tracked in netclaw-dev#925.
Aaronontheweb
added a commit
that referenced
this pull request
May 8, 2026
…text (#920) (#926) * fix(logging): wrap sidecar IChatClient calls in SessionDiagnosticsContext Closes the gap tracked in #920: session-owned sidecar paths bypassed the SessionDiagnosticsContext scope, so MEL provider diagnostics emitted during their LLM calls landed in the daemon log without a session-id tag and never reached session.log. Wrapped every direct IChatClient.{Get,GetStreaming}ResponseAsync call in session-owned code with a using-scope of SessionDiagnosticsContext.Push(sessionId.Value): - SessionCompactionPipeline.GenerateObservationsAsync — sessionId already on the signature; one-line wrap. - SessionMemoryObserverActor.RunDistillationAsync — sessionId already on the signature; one-line wrap. - SessionTitleGenerator.GenerateAsync — added SessionId parameter; caller in LlmSessionActor passes _sessionId. - LlmSessionActor.InvokeMemoryExtractionCoreAsync — added SessionId parameter; caller threads _sessionId. - SubAgentActor.InvokeLlmAsync — added string? sessionId parameter; passes _toolExecutionContext.SessionId. Sub-agents share the parent's session.log (SessionDiagnosticsContext.NormalizeSessionId strips the /subagent/ suffix back to the parent id). - MemoryCurationActor — added SessionId field + constructor param; CreateProps signature changed; LlmSessionActor caller updated; storage-integration tests updated to pass a placeholder sessionId. Test: SidecarDiagnosticsContextTests verifies the contract for SessionTitleGenerator and SessionCompactionPipeline (the two pure-static helpers, easiest to drive). A capturing fake IChatClient records SessionDiagnosticsContext.SessionId at the moment its method is invoked — that AsyncLocal value is what any real provider plugin emitting MEL log lines inside the call would see. Sidecar paths that did not need changes: - SessionLlmInvoker.InvokeAsync already pushes the scope (the original PR #916 wired that path). Net diagnostic coverage now matches what the Roslyn analyzer planned in #915 will require. * refactor: simplify-pass cleanups on sidecar diagnostics PR - MemoryCurationActor: replace Protocol.SessionId qualifier with a using alias matching the SessionLlmInvoker.cs:9 pattern. A full Netclaw.Actors.Protocol namespace import would have introduced a ChatRole ambiguity (Protocol.ChatRole vs Microsoft.Extensions.AI.ChatRole) that the bare alias avoids cleanly. - SidecarDiagnosticsContextTests: drop two defensive SessionDiagnosticsContext.SessionId = null pre-test resets. xUnit creates a fresh class instance per test method and AsyncLocal is rooted in the per-task ExecutionContext; there's no shared state to reset. The Assert.Null at the end of each test still verifies the using-scope restored properly. - SubAgentActor: tighten the diagnostics-scope comment from 4 lines to 3, dropping the redundant "shares parent's session.log" framing that's now covered by the SessionDiagnosticsContext doc. * refactor: type sidecar sessionId, normalize positionals, close test gap Three follow-up fixes from the simplify-pass review on the sidecar diagnostics-context PR. Each addresses something I had previously left on the table: 1. Stringly-typed sessionId on SubAgentActor.InvokeLlmAsync replaced with `SessionId? sessionId`. The call site converts the upstream `_toolExecutionContext.SessionId` (which is still typed as string? in Netclaw.Tools.Abstractions; out of scope to retype here) into the value object once at the boundary. 2. Positional ordering on InvokeLlmAsync normalized: ct now last, sessionId after options. The previous "ct between options and self" placement was inherited from the original signature and was awkward for the new sessionId parameter; the conventional order makes the private API harder to mis-call from a future test. 3. Test coverage gap closed. All seven sidecar IChatClient call sites now have direct unit tests in SidecarDiagnosticsContextTests: - SessionTitleGenerator.GenerateAsync - SessionCompactionPipeline.GenerateObservationsAsync - LlmSessionActor.InvokeMemoryExtractionCoreAsync (now internal static) - SubAgentActor.InvokeLlmAsync (now internal static; null-sessionId case also covered) - SessionMemoryObserverActor.RunDistillationAsync (now internal static; was private instance — extracted to match the existing SessionTitleGenerator/SessionCompactionPipeline pattern, _log passed as ILoggingAdapter parameter) - MemoryCurationActor.TryLlmEvaluationAsync (now internal static; same shape — _llmClient, _sessionId, _log all passed as params) The static extractions for RunDistillationAsync and TryLlmEvaluationAsync are behavior-preserving refactors that follow the established pattern of the other sidecar helpers in the same namespace. They make these methods unit-testable in isolation without spinning up the parent actor or driving the message protocol. This closes the coverage gap I previously deferred to the planned Roslyn analyzer (#915). Now we don't depend on #915 landing — the contract is verified at the unit-test level for every call site.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
session.logalongside session output audit entries.SessionLogDispatcherroot actor that owns oneSessionLogActorchildper sanitized session id. The actor's mailbox is the only writer per
file. See session log: remove two-writer race and synchronous file I/O on the logging hot path #918 for the full design rationale.
RollingFileLoggerProviderto the dispatcher viaIRequiredActor<SessionLogDispatcherActorKey>, with a small boundedConcurrentQueuefor the boot window and pureTellthereafter.SessionLogFile.AppendLineis now lock-free and dictionary-free —the actor model guarantees a single writer per file.
LlmSessionActorno longer createsSessionLogActordirectly; itforwards audit messages (
SendUserMessage,SessionOutput) to thedispatcher.
What this fixes
LockdictionaryFileLocksdictionary leakTell(non-blocking). File writes happen on the actor's dispatched thread.Out of scope on this PR
session.logsize cap and rotation — tracked in session log: cap session.log size and rotate per-session like the daemon log #919.diagnostics scope — tracked in session log: wrap remaining sidecar IChatClient call sites in SessionDiagnosticsContext.Push #920. The analyzer in analyzer: flag session-owned chat client calls outside session diagnostics context #915 will
enforce coverage going forward.
Tests
SessionDiagnosticsContextTests.NormalizeSessionId_*— sub-agent idcollapse + blank handling.
SessionLogActorTests— routing through dispatcher, cross-sessionisolation, eviction + recreation appending to the same canonical file,
audit/diagnostic interleaving in the same
session.log.RollingFileLoggerProviderTests— session-scoped log routes throughthe dispatcher, daemon-scoped does not, pre-resolution buffer-and-drain,
diagnostic routing across
awaitcontinuations.Quality gates
References
session.logsize cap and rotation: session log: cap session.log size and rotate per-session like the daemon log #919Pushat LLM call sites: analyzer: flag session-owned chat client calls outside session diagnostics context #915