Skip to content

session log: remove two-writer race and synchronous file I/O on the logging hot path #918

Description

@Aaronontheweb

Background

PR #916 introduced a session-scoped session.log that consolidates session output audit lines and session-scoped MEL diagnostics into a single canonical per-session file. The current implementation works for the MVP but carries a few structural problems we want to address before they bite under load.

Problems

1. Two writers to the same file, coordinated by a leaking dictionary

Two independent code paths call SessionLogFile.AppendLine(sessionId, basePath, line):

  • SessionLogActor — receives SendUserMessage and SessionOutput from the session pipeline and writes audit lines.
  • RollingFileLoggerProvider.TryWriteSessionLog — invoked from RollingFileLogger.Log<TState> whenever a MEL log call fires under a populated SessionDiagnosticsContext.

To prevent torn writes from concurrent threads, SessionLogFile keeps a ConcurrentDictionary<string, Lock> FileLocks keyed by log path and locks per file inside AppendLine. The dictionary has no eviction tied to session lifecycle, so each unique session path the daemon ever serves accumulates a Lock instance for the lifetime of the process.

Net: the lock dictionary is a slow leak (small magnitude, but unbounded), and its existence is purely a workaround for the fact that we have two writers.

2. Synchronous file I/O on the MEL log hot path

RollingFileLoggerProvider.Enqueue writes the daemon-global log line via a background BlockingCollection<string> queue (cheap, non-blocking on the caller). For session-scoped lines it delegates to TryWriteSessionLog, which performs File.Open + per-path lock + WriteLine + Flush + Dispose synchronously on the caller's thread.

Daemon log path: async. Session log path: sync. This is inconsistent and bad under load. During a streaming-token burst on a session-owned thread with debug logging enabled, every diagnostic emit is a blocking file operation on the LLM streaming continuation thread.

3. No chronological ordering guarantee across writers

Even with the per-path lock, audit and diagnostic lines for the same session can interleave at write time depending on which thread acquires the lock first. The lock prevents corruption but does not preserve the wall-clock order of producer-side events when two writers race on the same line.

Redesign: actor as single writer

Make SessionLogActor the only thing that ever calls SessionLogFile.AppendLine for a given session. Diagnostic lines route to it through Akka instead of being written from the MEL provider's caller thread.

Components

  • SessionLogDispatcher — root actor, registered via Akka.Hosting. Receives SessionLogAudit(sessionId, payload) and SessionLogDiagnostic(sessionId, line). Routes each message to a child SessionLogActor named by sanitized session id, lazy-creating the child on first use.
  • SessionLogActor — child of the dispatcher. Receives both audit and diagnostic messages, writes via SessionLogFile.AppendLine. Configurable ReceiveTimeout evicts the child on idle (default ~10 minutes).
  • RollingFileLoggerProvider — takes IRequiredActor<SessionLogDispatcher>. The daemon-log path is unchanged. The session-scoped branch reads SessionDiagnosticsContext.SessionId synchronously at log-emit time, snapshots it into a SessionLogDiagnostic message, and Tells the dispatcher.
  • LlmSessionActor — stops creating SessionLogActor directly; sends SessionLogAudit to the dispatcher.

What this fixes

Problem Resolution
Two-writer coordination One actor, one mailbox per session = single writer per file.
Lock dictionary leak Deleted entirely. Akka's child registry replaces it; eviction is ReceiveTimeout-driven and lifecycle-managed.
Sync file I/O on log hot path Replaced with Tell (non-blocking). File write happens on the actor's dispatched thread.
Chronological ordering Single mailbox per session = wall-clock-faithful timeline by construction.

Why AsyncLocal is sufficient (and why we do not need structured-logging belt-and-suspenders)

Session-owned LLM calls happen inside actor message handlers. Each handler is one continuous async flow:

  1. Handler enters, executes using var scope = SessionDiagnosticsContext.Push(sessionId.Value).
  2. Handler awaits the chat client. All internal awaits inside the chat client (HTTP send, SSE read loop, response parsing) are continuations of that one flow.
  3. ExecutionContext flows through every await, so SessionDiagnosticsContext.SessionId is correct on every continuation thread.
  4. MEL log calls inside the chat client run synchronously on the current continuation thread. The provider reads SessionDiagnosticsContext.SessionId at log-emit time and snapshots it into the message it sends to the dispatcher.
  5. Handler returns; scope disposes; AsyncLocal cleared. Next message handler starts on a clean slate (actors are serial per mailbox).

Issue #915 will add a Roslyn analyzer that ensures the Push(sessionId) scope is in place at every session-owned IChatClient call site. That single contract — combined with standard await/ExecutionContext flow — is enough. We do not need BeginScope("SessionId") or {SessionId} template parameters in every log line.

Pre-resolution buffering

RollingFileLoggerProvider is constructed before the ActorSystem. It uses the Task<IActorRef>-shaped accessor on IRequiredActor<SessionLogDispatcher> and a small bounded ConcurrentQueue to handle the boot window. In practice this is academic — SessionDiagnosticsContext only gets populated from inside actor handlers, which by definition run after the system is up — but the queue exists to make the contract robust against any theoretical race during startup.

Out of scope (separate issues)

  • No size cap on session.log. The daemon log rolls at 10 MB; session.log does not. A noisy session can fill disk over time. Tracked separately.
  • Sidecar paths bypass SessionDiagnosticsContext. Compaction, title generation, sub-agent invocations, and other session-owned but non-SessionLlmInvoker paths do not currently set the diagnostics scope. Tracked in analyzer: flag session-owned chat client calls outside session diagnostics context #915 (analyzer scope) and a separate cleanup pass.

Acceptance criteria

  • SessionLogFile.FileLocks and the lock block in AppendLine are deleted.
  • RollingFileLoggerProvider no longer performs synchronous file I/O on the session-scoped branch.
  • SessionLogActor receives both audit and diagnostic messages and is the only caller of SessionLogFile.AppendLine.
  • Existing session log tests still pass; new tests cover routing, cross-session isolation, idle eviction + recreation, and pre-resolution buffer-and-drain.
  • No new Slopwatch violations.

Reference

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions