Skip to content

fix(logging): route session diagnostics into one session log#916

Merged
Aaronontheweb merged 13 commits into
netclaw-dev:devfrom
Aaronontheweb:fix/session-log-routing
May 7, 2026
Merged

fix(logging): route session diagnostics into one session log#916
Aaronontheweb merged 13 commits into
netclaw-dev:devfrom
Aaronontheweb:fix/session-log-routing

Conversation

@Aaronontheweb

@Aaronontheweb Aaronontheweb commented May 7, 2026

Copy link
Copy Markdown
Collaborator

Summary

  • Route session-scoped provider diagnostics into the canonical per-session
    session.log alongside session output audit entries.
  • Replace the two-writer + per-path-lock-dictionary design with a
    SessionLogDispatcher root actor that owns one SessionLogActor child
    per 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.
  • Wire RollingFileLoggerProvider to the dispatcher via
    IRequiredActor<SessionLogDispatcherActorKey>, with a small bounded
    ConcurrentQueue for the boot window and pure Tell thereafter.
  • SessionLogFile.AppendLine is now lock-free and dictionary-free —
    the actor model guarantees a single writer per file.
  • LlmSessionActor no longer creates SessionLogActor directly; it
    forwards audit messages (SendUserMessage, SessionOutput) to the
    dispatcher.

What this fixes

Concern Resolution
Two-writer coordination via per-path Lock dictionary Deleted. One actor, one mailbox per session.
Unbounded FileLocks dictionary leak Dictionary gone; Akka's child registry replaces it.
Synchronous file I/O on the MEL log hot path Replaced with Tell (non-blocking). File writes happen on the actor's dispatched thread.
Audit/diagnostic ordering races Single mailbox per session = wall-clock-faithful timeline by construction.

Out of scope on this PR

Tests

  • SessionDiagnosticsContextTests.NormalizeSessionId_* — sub-agent id
    collapse + blank handling.
  • SessionLogActorTests — routing through dispatcher, cross-session
    isolation, eviction + recreation appending to the same canonical file,
    audit/diagnostic interleaving in the same session.log.
  • RollingFileLoggerProviderTests — session-scoped log routes through
    the dispatcher, daemon-scoped does not, pre-resolution buffer-and-drain,
    diagnostic routing across await continuations.

Quality gates

  • Full solution build clean.
  • 1468 (Actors) + 504 (Daemon) + 6 (Configuration) tests passing.
  • Slopwatch zero issues.
  • All copyright headers present.

References

@Aaronontheweb Aaronontheweb added the stats Stats, metrics, and telemetry label May 7, 2026
@Aaronontheweb Aaronontheweb added observability and removed stats Stats, metrics, and telemetry labels May 7, 2026
- 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.
…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
Aaronontheweb merged commit 5e8d052 into netclaw-dev:dev May 7, 2026
6 checks passed
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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant