Skip to content

refactor(logging): partition the log stream by session — session.log per session, daemon.log sparse, OTEL the union (#1472)#1499

Merged
Aaronontheweb merged 30 commits into
devfrom
refactor/unify-session-logging
Jul 1, 2026
Merged

refactor(logging): partition the log stream by session — session.log per session, daemon.log sparse, OTEL the union (#1472)#1499
Aaronontheweb merged 30 commits into
devfrom
refactor/unify-session-logging

Conversation

@Aaronontheweb

@Aaronontheweb Aaronontheweb commented Jun 25, 2026

Copy link
Copy Markdown
Collaborator

What & why

Part of #1472. Unify session logging into one stream, partitioned locally by session.

Session-relevant output — the conversation transcript and operational diagnostics (sub-agent spawn lifecycle, LLM-pipeline activity, retries, provider failover) — was scattered and inconsistently routed, gated by a fragile SessionDiagnosticsContext AsyncLocal that was lost across Akka actor boundaries. This PR replaces all of that with a single partitioning rule.

The model

There is one log stream. Locally it is partitioned by session id; globally it is exported whole to OTEL.

  • A log line that carries a session id — an actor's WithContext("SessionId", …), a {SessionId} message field, or a SessionId logging scope (the chat-client decorators) — is written to that session's session.log and not to daemon.log. Nothing is duplicated locally.
  • daemon.log holds only sessionless, daemon-wide lines: startup/config, session start/stop, and operational alerts (e.g. the provider.unreachable alert when an inference provider goes down — surfaced here and to webhooks by the notification sink).
  • The full stream (daemon + session) is exported to OTEL/Seq with SessionId as an attribute; the OTEL receiver does the global slicing/distilling.

Net: daemon.log is sparse, session.log is the session's full local slice (transcript + every session-scoped operational line, wall-clock interleaved), OTEL is the union.

How

  • RollingFileLoggerProvider implements ISupportExternalScope and owns the local partition. Per line it resolves the session id from the event's structured state (the Akka→MEL bridge, AddLoggerFactory, surfaces WithContext/{SessionId}) or the active scopes; session-tagged → Tell the SessionLogDispatcher a SessionLogDiagnostic; otherwise → daemon.log. The dispatcher is a single volatile reference resolved in the background via IRequiredActor.GetAsync()no buffer, no lock (a line logged before it resolves falls back to daemon.log).
  • Feedback guard: the SessionLogActor's own lines (identified by its Akka LogSource/ActorPath) are forced to daemon.log so a write-failure log can never recurse into the file that just failed.
  • SessionLogActor — the single writer per session.log — switches from per-line AutoFlush to a batched/idle flush (~1s or 256 lines), since it now carries the session's whole stream.
  • Chat-client decorators carry the session id via SessionScopedChatOptions + a SessionId scope (ChatClientSessionScope) — a typed property, not AdditionalProperties (which providers forward onto the wire and would leak the id into the LLM request). This is now what routes LLM timing/retry/failover lines to the session file.
  • Centralized the SessionId/SubSessionId log-attribute keys in NetclawLogProperties.
  • Deleted the SessionDiagnosticsContext AsyncLocal and the interim EmitSessionLogLine side-channel.

Evolution (see commit history)

This PR first tried explicit-publish — an Action<string> EmitSessionLogLine hand-driven alongside each log call — and, before that, a sink that routed any SessionId-tagged line to session.log (reverted as a transcript flood). The final design routes by session-id presence and embraces the full per-session slice (with OTEL distilling globally), which removed the per-call-site coupling entirely — the original routed-skill gap that motivated step 6 is now structurally impossible.

Verification

  • RollingFileLoggerPartitionTests — routing by message-field and by scope, sessionless → daemon.log, the feedback carve-out, pre-resolution daemon.log fallback, and the resolution-failure beacon.
  • SessionLogPartitionIntegrationTests — end-to-end through the real Akka→MEL bridge: a real actor's WithContext("SessionId").Info(...) lands in its session.log file and not daemon.log.
  • SubAgentSpawnObservabilityTests (breadcrumbs log under a SessionId scope) + chat-client correlation tests (wire-leak guard proving the id never reaches the LLM request body, decorator scope, composed pipeline).
  • Suites green (Daemon config + Actors session/sub-agent); slopwatch clean; copyright headers present. An xhigh multi-agent review pass was applied — its concurrency findings were resolved by deleting the buffer/lock outright.

Operational notes for reviewers

  • daemon.log is now sparse; session.log is effectively a per-session debug log (hence the batched flush) and interleaves the clean transcript with operational lines. Debugging one session → read its session.log; a daemon-wide problem → daemon.log + the operational-alert/webhook path.
  • One dormant, documented gap: if Netclaw ever issues a non-streaming LLM request, that retry path opens no SessionId scope (it relies on LoggingChatClient's streaming scope) and would route to daemon.log — caveated at RetryingChatClient.BackoffAsync.

…syncLocal (#1472 step 6)

Actor ILoggingAdapter lifecycle lines now reach per-session session.log reliably, and
the SessionDiagnosticsContext AsyncLocal threading is gone.

The session.log sink (RollingFileLoggerProvider) reads the session id off each log
event's structured state instead of an ambient AsyncLocal. The Akka->MEL bridge passes
the event's properties as the MEL state (AkkaLogState, carrying the actor's
WithContext("SessionId", ...) tag), and MEL's own structured logging passes
FormattedLogValues (a {SessionId} field). RollingFileLogger.Log reads "SessionId" from
either and Enqueue(message, sessionId) routes to the existing per-session writer
(SessionLogDiagnostic -> SessionLogDispatcher -> SessionLogActor). Because the id rides
on the line, routing no longer depends on thread/async context — a line logged after an
await still routes, which the AsyncLocal could not.

Deleted (the context-threading workaround):
- SessionDiagnosticsContext (the AsyncLocal) + its 9 Push() scope sites.
- SessionLoggingScope (the MEL BeginScope helper) + its 3 chat-client call sites.
- Obsolete tests/helpers: SidecarDiagnosticsContextTests, ScopeCapturingLogger, the
  SessionDiagnosticsContext test. NormalizeSessionId relocated to SubAgentSessionScope.

Kept session-routed by carrying the id on the line:
- The #1468 spawn breadcrumbs (SubAgentSpawner/SpawnAgentTool) now include a {SessionId}
  field, so the sink routes them without a scope.

Behavior change: chat-client / LLM-pipeline INTERNAL diagnostics (retry, failover,
request/response internals) were only ever session-tagged via the AsyncLocal — already
lost after the first await — so they settle into daemon.log only. Each actor's own
lifecycle log still reaches session.log via the sink, and OTLP/Seq correlation for actor
logs is unaffected (it rides the same WithContext tag).

Net -350 LOC. The bridge behavior (AkkaLogState carrying the WithContext properties) was
verified by decompiling Akka.Hosting 1.5.69; provider-level + async-continuation tests
cover the read path. Skill diagnostics guidance updated (netclaw-operations 2.19.0).
Part of #1472.
Comment thread src/Netclaw.Daemon/Configuration/RollingFileLoggerProvider.cs Fixed
Comment thread src/Netclaw.Daemon/Configuration/RollingFileLoggerProvider.cs Fixed
…the real bridge (#1472 step 6)

A hand-built host (AddLogging(AddProvider) + AddAkka(ConfigureLoggers(AddLoggerFactory)) —
production wiring) drives an actor's WithContext("SessionId", ...) log through the real
Akka->MEL bridge into RollingFileLoggerProvider and asserts a SessionLogDiagnostic is routed
for that session. Proves the essential goal through the live bridge, not a mocked state.

Not Akka.Hosting.TestKit on purpose: its bridge (TestKitLoggerFactoryLogger : the production
LoggerFactoryLogger) is hardwired to the TestKit's own xUnit test-output ILoggerFactory, so a
TestKit-based test cannot observe the bridged log arriving at our provider.

Relates to #1499, #1472.
… in the sink

A max-effort review showed the previous step-6 approach (the file sink reading a
"SessionId" property off each log event and routing it to session.log) was wrong:
"{SessionId}" is a descriptive message-template placeholder in 86 places across the
codebase (binding actors, gateway, webhooks, session catalog/registry, drain/recovery),
each of which produces a structured "SessionId" property — so the sink would flood
session.log with operational noise and create a self-feedback loop in SessionLogActor's
write-failure path. SessionId is a correlation field, not a routing field.

Replace sink-side routing with explicit publish through the existing actor-message
contract (the same one that already carries the transcript):

- RollingFileLoggerProvider reverts to a daemon.log-only writer — no ExtractSessionId,
  no dispatcher attach, no buffer. (Deletes the collision, the feedback loop, the
  per-line boxing, the dead branch, and the TOCTOU buffer race the review found.)
- ToolExecutionContext.EmitSessionLogLine: LlmSessionActor wires it to
  _logActor.Tell(new SessionLogDiagnostic(parentSessionId, line)); the tool pipeline
  threads it to the spawn breadcrumbs, which publish their lifecycle explicitly. Using
  the parent id also fixes the composite-id normalization gap.
- SessionId stays a pure Seq/OTLP correlation field on those lines, doing one job.
- Removed the dead sessionId param on SubAgentActor.InvokeLlmAsync; fixed the stale
  LoggingChatClient doc; skill diagnostics guidance updated to the explicit-publish model.

session.log scope = transcript + explicitly-published spawn lifecycle. Chat-client and
sidecar internals are daemon.log-only (filter by the SessionId field). Sidecar diagnostic
restore is a follow-up.

Relates to #1499, #1472.
@Aaronontheweb Aaronontheweb changed the title refactor(logging): route session logs off the log event, delete the AsyncLocal (#1472 step 6) refactor(logging): publish session logs explicitly, delete the AsyncLocal gate (#1472 step 6) Jun 26, 2026
…on.log (#1472 step 6)

The routed-skill spawn path (LlmSessionActor.ExecuteRoutedSkillAsync) built
its own ToolExecutionContext and wired SpawnChildActor + OnSubAgentActivity
but never set EmitSessionLogLine, so skill-routed sub-agent spawns — and
critically their failure breadcrumbs — were invisible in session.log. That
is the original #1467 gap still present on one of the three spawn paths.

Wire EmitSessionLogLine to the session-log dispatcher, mirroring the
tool-execution dispatch path, and fix the stale SessionLogDiagnostic doc
comment that still described the deleted MEL-sink-routing model.

Test: Routed_slash_command_publishes_spawn_lifecycle_to_session_log
(verified failing without the fix).
…explicit ChatOptions

Deleting the SessionDiagnosticsContext AsyncLocal (#1472 step 6) removed the
only way the session-agnostic chat-client decorators (logging / retry /
routing) knew which session a call belonged to. LLM timing, retries, and —
most importantly — provider failover/outage events lost all session
correlation: gone from session.log (intentional) and carrying no SessionId
field in Seq either.

Restore the Seq/OTLP correlation explicitly, without resurrecting ambient
state that does not flow across the actor mailbox boundary:

- SessionScopedChatOptions carries the owning session id on the call's
  ChatOptions as a typed property — NOT in AdditionalProperties, which the
  self-hosted provider forwards verbatim onto the wire (a dictionary entry
  would leak the id into the LLM request body). LlmSessionActor and
  SubAgentActor (parent id) set it on every model call; sidecar calls stay
  session-agnostic.
- ChatClientSessionScope re-opens the SessionId logging scope in all three
  decorators, sourced from the options. IncludeScopes surfaces it as a
  filterable Seq field; session.log stays narrow (no re-flood).

Tests: decorator scope attach + negatives, a wire-leak guard proving the id
never reaches the provider request body, and builder-side coverage that the
session and sub-agent actors emit the carrier with the right id. Updates the
netclaw-operations diagnostics skill (2.20.0) to state precisely where each
line type is filterable (inline grep vs Seq scope).
…ation

Follow-up to the two preceding commits, from a multi-agent review pass:

- Dedupe the explicit session-log emitter: the routed-skill path and the
  tool-execution dispatch path built the identical
  logActor?.Tell(SessionLogDiagnostic(...)) closure. Collapse both onto one
  private CreateSessionLogEmitter() so their timestamp format and routing
  cannot drift.
- Drop a now-dead null-conditional (options?.Tools) — options is
  unconditionally non-null since it became the SessionScopedChatOptions carrier.
- Cover the production (streaming) path: the chat-client scope tests only
  exercised the non-streaming GetResponseAsync branch, but StreamingResponseReader
  only ever calls GetStreamingResponseAsync. Add streaming retry-backoff and
  provider-failover scope tests, plus a composed-pipeline test proving the
  SessionScopedChatOptions subclass survives Logging->Retry by reference (guards
  the correlation against a future cloning decorator).
- Correct the diagnostics skill: session id is reliably filterable in Seq for
  both actor and decorator lines; daemon.log *text* grep only catches lines that
  template the id inline. The prior wording over-claimed inline greppability for
  context-enriched actor logs.
…ibute keys

The structured-logging key "SessionId" was hardcoded as a raw literal at ~9
WithContext sites across the actor system and every channel adapter, plus two
private SessionIdKey consts in the chat-client scope helper and its test double.
A rename to align OTLP attributes would have had to find every copy, and the
producer could silently drift from the test assertion.

Introduce Netclaw.Actors.Protocol.NetclawLogProperties (SessionId, SubSessionId)
— Netclaw.Actors is already referenced by every consumer (Daemon, all Channels.*,
Daemon.Tests), so no new project references — and route all logging-key usages
through it. Type references, proto field names, DTO/JSON keys, and doc-comment
prose are untouched; only WithContext/BeginScope keys changed.
Code-review follow-up. In the composed pipeline RetryingChatClient always runs
inside LoggingChatClient's streaming scope (guarded by Compose_puts_Logging_
outermost), which stays open for the whole enumeration that drives the retry
loop — so BackoffAsync re-opening an identical SessionId scope was pure
duplication. Drop it and document the inherited-scope contract; only
RoutingChatClient, which logs outside any LoggingChatClient scope, keeps its own.

Move the retry-warning correlation coverage from two isolated-decorator tests
(which asserted the now-removed self-scope) to one composed-pipeline test that
fires a real retry and asserts, at the message level, that the warning line is
emitted while the SessionId scope is active — i.e. it tests the production wiring
(LoggingChatClient enclosing Retry) rather than a decorator in isolation.
@Aaronontheweb Aaronontheweb added cleanup Code quality improvements and tech debt reduction observability labels Jun 26, 2026
…t emitter

Every spawn-lifecycle breadcrumb hand-drove two sinks at the call site — a
structured _logger call for daemon.log/Seq and a parallel EmitSessionLogLine
string for the session.log transcript — with two message strings to keep in
sync. The sinks are genuinely different artifacts (operational diagnostics vs
the per-session audit transcript; unifying them at the sink was tried and
reverted), but that seam belongs behind one emit point, not duplicated at every
site.

Add SubAgentSpawnBreadcrumbs: one method per lifecycle event that fans out to
both sinks from a single source of truth. SubAgentSpawner (7 sites) and
SpawnAgentTool (2 refusal sites) now state each event once; the two renderings
live together and can't drift. Message text is byte-for-byte preserved, so the
existing SubAgentSpawnObservabilityTests and the routed-slash session-log test
cover it unchanged.
…t-publish

Replace the bolted-on EmitSessionLogLine side-channel with a single partitioning
logging sink. The routing rule is now simply "does this line carry a session id?":

- RollingFileLoggerProvider implements ISupportExternalScope and, per line,
  resolves the session id from the event's structured state (an actor's
  WithContext("SessionId", ...) bridged by Akka->MEL, or a {SessionId} message
  field) or from the active scopes (the chat-client decorators' BeginScope). A
  session-tagged line is Tell'd to the SessionLogDispatcher as a SessionLogDiagnostic
  and is NOT written to daemon.log; everything else goes to daemon.log. The full
  stream still exports to OTEL with SessionId as an attribute — the receiver does
  the global slicing.
- The session-log writer's own lines (identified by its Akka LogSource/ActorPath)
  are forced to daemon.log so a write-failure log can never recurse into the file
  that just failed.
- session.log is now the session's full local slice (transcript + every
  session-scoped operational line), so SessionLogActor switches from per-line
  AutoFlush to a batched/idle flush (~1s or 256 writes). FlushTick is
  INotInfluenceReceiveTimeout so the cadence doesn't keep an idle session alive.

Deletes ToolExecutionContext.EmitSessionLogLine, LlmSessionActor.CreateSessionLogEmitter,
and the pipeline threading. SubAgentSpawnBreadcrumbs now logs each event under a
SessionId scope (one call, no fan-out); because routing is no longer per-path-wired,
the original routed-skill gap (commit 9551067) is structurally impossible. Retains
the chat-client SessionId-scope work, which is now what routes LLM-pipeline lines.

Restores the SessionLogDispatcherWiringService IHostedService to attach the dispatcher
post-start. Tests: RollingFileLoggerPartitionTests (routing, scope, feedback carve-out,
pre-attach buffering); SubAgentSpawnObservabilityTests reworked to assert the SessionId
scope; diagnostics skill updated to 2.21.0.
…bridge

The unit tests simulate the log-event state shape; this drives the real thing. A
test actor tags its logger with WithContext("SessionId", ...) and logs; the line
flows through ConfigureLoggers(AddLoggerFactory) -> the host ILoggerFactory ->
RollingFileLoggerProvider, which extracts the id from the live AkkaLogState and
routes it to the real SessionLogDispatcher/SessionLogActor. Asserts the line lands
in that session's session.log file and NOT in daemon.log — confirming the bridge
produces the structured state the provider's ScanState reads.
xhigh review fixes on the partition rework:

- Concurrency in RollingFileLoggerProvider's pre-resolution buffer had a
  null-deref (NRE thrown into a logging call) and a lost-line race against
  dispatcher resolution. Replaced the Interlocked/ConcurrentQueue dance with a
  lock-guarded slow path; the steady state (dispatcher resolved) stays lock-free
  via a Volatile read. On resolution FAILURE the buffered lines now drain to
  daemon.log instead of being dropped, and the one-shot failure beacon has a
  stderr fallback if the daemon queue is saturated.
- SessionLogActor flush failure: Flush() now resets _unflushedWrites and
  rate-limits the warning to onset+recovery, so a persistent disk error no longer
  floods daemon.log every tick. Its own self-logs use a {Session} key (not
  {SessionId}) so they can't arm routing back into the file that just failed —
  defense-in-depth on the feedback carve-out.
- FindSessionIdInScopes: static lambda + StrongBox state to drop the per-line
  closure allocation on the chat-client hot path.
- Docs: fixed the LoggingChatClient comment (its lines DO route to session.log
  now) and the diagnostics runbook (a daemon-wide provider outage surfaces as the
  sessionless provider.unreachable alert in daemon.log; per-call failover detail
  is in each session's session.log).

Test: Dispatcher_resolution_failure_drains_buffer_and_beacons_to_daemon_log.
… gap

RetryingChatClient inherits its SessionId scope from the enclosing LoggingChatClient,
which instruments only the streaming path. The non-streaming GetResponseAsync retry
path therefore opens no scope — dormant today (Netclaw issues only streaming
requests), but if a non-streaming path is ever added the retry warnings would lose
session correlation and route to daemon.log. Leave a caveat at BackoffAsync pointing
the future fix at ChatClientSessionScope.Begin / LoggingChatClient.GetResponseAsync.
…le dispatcher ref

The pre-resolution buffer (and the lock guarding it, where the review found a
null-deref and a lost-line race) only existed to route session-tagged lines
emitted in the window between AttachSessionDispatcher and the dispatcher
resolving. But the things that log with a SessionId — session actors, chat-client
calls — don't exist until a session starts processing a turn, well after startup,
so that window carries no session traffic.

Collapse it to one volatile _sessionDispatcher reference that
IRequiredActor.GetAsync resolves in the background; a line that finds it still null
(startup window or resolution failure) falls back to daemon.log, which is already
the documented routing-off behavior. Removes _pendingDiagnostics, the _routeGate
lock, _routingFailed, _sessionRoutingEnabled, and the whole concurrency surface the
review flagged (~60 lines). Resolution stays in the background — not a blocking
await in the wiring service's StartAsync, which runs before Akka and would deadlock.

Tests updated: a pre-resolution session line now falls back to daemon.log rather
than buffer-and-drain.
…into refactor/unify-session-logging

# Conflicts:
#	feeds/skills/.system/files/netclaw-operations/SKILL.md
@Aaronontheweb Aaronontheweb changed the title refactor(logging): publish session logs explicitly, delete the AsyncLocal gate (#1472 step 6) refactor(logging): partition the log stream by session — session.log per session, daemon.log sparse, OTEL the union (#1472) Jun 30, 2026
Comment thread src/Netclaw.Daemon.Tests/Configuration/LoggingChatClientTests.cs Fixed
Comment thread src/Netclaw.Daemon.Tests/Configuration/RoutingChatClientTests.cs Fixed
Comment on lines +123 to +125
foreach (var kv in kvps)
if (kv.Key == NetclawLogProperties.SessionId && kv.Value is string s)
return s;
Comment thread src/Netclaw.Daemon/Configuration/RollingFileLoggerProvider.cs Fixed
Comment on lines +144 to +146
foreach (var kv in kvps)
if (kv.Key == Netclaw.Actors.Protocol.NetclawLogProperties.SessionId && kv.Value is string s)
return s;
… run-id refactor

The merged SubAgentRunId/SubAgentScopeId refactor changed SubAgentSpawner's runId from
a string to a SubAgentRunId value object, but the spawn breadcrumb emitters still took
`string runId` — a CI compile failure (CS1503). Take SubAgentRunId and log runId.Value.
…SubSessionId

Per the design call: a parent investigating a sub-agent reviews that run's own log,
and the parent's session.log stays clean (transcript + spawn breadcrumbs only).

- RollingFileLoggerProvider reads SubSessionId (from log state or scope) and partitions
  the LOCAL file by SubSessionId when present, else SessionId. The line still carries the
  parent SessionId, so OTEL groups sub-agent lines under the parent AND slices by SubSessionId.
- SessionScopedChatOptions gains SubSessionId; ChatClientSessionScope emits it in the scope;
  SubAgentActor sets it (its scopeId {parent}/subagent/{name}/{runId}) on the LLM-call options.
  The sub-agent's own actor logs already carried both ids.
- Spawn breadcrumbs stay in the PARENT's log (parent context, no SubSessionId) as the pointer.

Tests: provider routes a state- or scope-carried SubSessionId line to the sub-run file (not
the parent's). diagnostics skill updated (2.22.0).
…-review)

The AsyncLocal removal stripped SessionDiagnosticsContext from five session-owned sidecar
chat calls but never gave them the replacement SessionScopedChatOptions carrier, so their
chat-client diagnostics (timing, retries, provider failover) silently regressed to
daemon.log uncorrelated — and the #920 guard test was deleted in the same commit. Restore
correlation by threading SessionScopedChatOptions through all five (each already had the
session id in scope): SessionTitleGenerator, SessionCompactionPipeline observer,
SessionMemoryObserverActor distillation, MemoryCurationActor, and LlmSessionActor
memory-extraction. Replace the deleted guard with SidecarSessionCorrelationTests (one case
per sidecar, asserting the carrier). The diagnostics doc's claim that session.log holds the
session's LLM-pipeline/memory lines is now true rather than aspirational.

Also from the review:
- Harden RollingFileLoggerProvider.Route: only consult scopes when there is no state session
  id, so an ambient SubSessionId scope cannot hijack an actor line's routing.
- SessionLogActor.Flush: keep retrying on the 1s tick while failing, so buffered audit bytes
  are not stranded through an idle period after the disk recovers.
- Correct SubAgentSessionScope doc: it claimed sub-agents reuse the parent's log and were the
  "only place" the /subagent/ split happens — both now false (own file; ToolApprovalActor too).
…cs batched

Per the durability decision: SessionLogActor has two inputs — the audit transcript
(user/assistant/tool/usage via SendUserMessage/SessionOutput, low volume, durability-
critical) and the high-volume diagnostic lines (SessionLogDiagnostic). The audit handlers
now WriteDurable (write + immediate flush) so a hard process death (SIGKILL/OOM) cannot drop
the audit record's tail, while diagnostics stay on the batched Write() path (an fsync per
line would dominate now that the whole per-session stream lands here). An audit line also
flushes any diagnostics buffered before it, so audit lines are natural flush points.
…nt/ split (code-review)

Two minor code-review follow-ups:

- daemon.log writer no longer fsyncs per line. It flushes when the queue drains (so sparse
  daemon.log lines — startup, config, lifecycle, alerts — stay immediately durable) or after a
  256-line burst cap, matching the cadence the sibling SessionLogActor already uses. The tail
  is flushed by Dispose() when the writer thread exits.
- ToolApprovalActor's approval-inheritance walk now calls SubAgentSessionScope.NormalizeSessionId
  instead of re-implementing the "/subagent/" split inline, so there is a single owner of that
  parse (behavior preserved — IndexOf-first already walked leaf -> root parent). Doc updated.
… the tool-denial line

Code-review follow-ups (clear-cut findings):
- SessionLogActor.PostStop: guard _writer.Dispose() in try/catch. On a disk-full stop the
  explicit Flush() already reports via its rate-limited warning; the Dispose flush could throw
  IOException out of PostStop and bury the real cause under Akka's PostStop-failed noise.
- diagnostics skill: the flush description claimed session.log is uniformly batched (~1s lag).
  It now documents the split — the conversation audit is flushed immediately (durable), only
  the diagnostics batch. (skill 2.23.0; System Skills Sync Rule.)
- SubAgentSpawner tool-denial line: route via SubAgentSpawnBreadcrumbs.ToolDenied (a SessionId
  scope) instead of a hand-rolled "(session={SessionId})" message field, so it can't drift from
  the centralized NetclawLogProperties key like every other breadcrumb.
…p-accurate roll

Code-review #1 (the dominant finding) + #3, per the daemon.log decision.

The field-based router diverted ANY line carrying a {SessionId} into that session's session.log
— including daemon-infrastructure errors that merely NAME a session (gateway "failed to mark
session X active", drain "failed to drain session X before shutdown", restart-recovery). Those
are daemon functionality, and the class contract promises them in daemon.log. On dev they went
there because the old AsyncLocal was only set inside session-serving code.

Restore that structurally: a state SessionId routes only when it rode in on an Akka actor context
(the bridge's AkkaLogState carries a LogSource) or a BeginScope (chat-client decorators, spawn
breadcrumbs). A bare {SessionId} message field on a plain daemon-service ILogger<T> has no
LogSource → stays in daemon.log. No hand-maintained category list. Swept all {SessionId} message
templates: only daemon/channel/infra lines lack an actor context (consistent with dev); the one
session-serving exception (tool-denial) was already moved to a scope.

Also: daemon.log size-roll flushes within a batch of the 10MB cap so AutoFlush=off buffered bytes
can't overshoot it (#3). Tests updated to model actor-context vs message-field lines, plus a new
case locking in the daemon-service → daemon.log behavior. Skill bumped once for the PR (2.22.0).
…op comments)

GitHub code-quality (Copilot) review follow-ups on this PR's test files:
- Path.Combine -> Path.Join in the logging test temp-path helpers: the CodeQL "may drop earlier
  arguments" rule can't prove the second segment is non-rooted; Join is the correct idiom for
  plain concatenation and clears the recurring finding (identical result for these inputs).
- Intent comments on the empty `await foreach (var _ in stream) { }` drain loops in the
  chat-client tests, so the enumerate-and-discard reads as intentional (it drives the pipeline's
  scope/retry/logging side effects, which the test then asserts).

Declined the "use .Where()" suggestions: on the provider hot path (FindScopeIds) a LINQ Where
allocates a per-line iterator/closure that the manual loop + static lambda deliberately avoids
(documented); the mirroring test helpers stay foreach for consistency with it.
Comment on lines +372 to +376
else if (key == "ActorPath")
{
if (IsSessionLogActorSource(value.ToString()))
fromSessionLogActor = true;
}
{
var (dir, daemonPath) = TempPaths();
var pending = new TaskCompletionSource<Akka.Actor.IActorRef>();
var provider = new RollingFileLoggerProvider(daemonPath, new FakeTimeProvider(FixedNow));
Comment on lines +115 to +118
catch (Exception ex)
{
_log.Warning(ex, "Failed to close session.log for {Session}", _sessionId.Value);
}
Comment on lines +159 to +170
catch (Exception ex)
{
// Reset the write-batch counter so writes don't trigger a per-line flush storm during a
// persistent failure (full disk, locked file); _flushFailing stays set, so the 1s tick
// keeps retrying until recovery. Warn once on onset, once on recovery.
_unflushedWrites = 0;
if (!_flushFailing)
{
_flushFailing = true;
_log.Warning(ex, "Failed to flush session.log for {Session}; further flush failures suppressed until recovery", _sessionId.Value);
}
}

@Aaronontheweb Aaronontheweb left a comment

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

LGTM

captor, sessionId, history: [], self: CreateTestProbe().Ref,
log: NoLogger.Instance, timeout: TimeSpan.FromSeconds(5));

AssertScopedTo(sessionId, captor);

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

LGTM

// Walk to the parent session so a sub-agent inherits its parent's approvals.
// SubAgentSessionScope.NormalizeSessionId owns the "/subagent/" split (one
// implementation shared with log routing); break once there is nothing left to strip.
var parent = SubAgentSessionScope.NormalizeSessionId(scopeId);

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

LGTM

Assert.Equal(4, attempts);
}

// NOTE: RetryingChatClient deliberately does NOT open its own SessionId scope — it

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

LGTM

AssertScopedTo(sessionId, captor);
}

private static void AssertScopedTo(SessionId sessionId, OptionsCapturingChatClient captor)

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

LGTM

// the deleted SessionDiagnosticsContext AsyncLocal).
var options = new SessionScopedChatOptions
{
SessionId = sessionId.Value,

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

LGTM

/// <c>WithContext</c> — so the scope is what carries the id. The <paramref name="logger"/> is
/// nullable so tool call sites with an optional logger can share these emitters.
/// </summary>
internal static class SubAgentSpawnBreadcrumbs

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

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

LGTM

@Aaronontheweb
Aaronontheweb merged commit f08cee2 into dev Jul 1, 2026
21 checks passed
@Aaronontheweb
Aaronontheweb deleted the refactor/unify-session-logging branch July 1, 2026 02:12
Aaronontheweb added a commit that referenced this pull request Jul 8, 2026
… (#1600)

Sub-agent LLM calls never recorded token usage, so every sub-agent's
input/output tokens were invisible to `netclaw stats`. This was a
pre-existing gap, not a regression: SubAgentActor never had an
ISessionMetrics dependency and discarded the ChatResponse.Usage it already
receives from StreamingResponseReader. The recent observability PRs
(#1428, #1468, #1472/#1499) only added logs and pruned dead OTel Activities;
none ever touched token tracking.

Fix records at the source, mirroring the main session:
- Inject ISessionMetrics into SubAgentActor (via SubAgentSpawner/CreateProps).
  DI already registers it as a process-wide singleton, so no Program.cs change.
- Record response.Usage on every LlmResponseReceived (one per LLM turn:
  tool-call turns, retries, the forced-no-tools final turn, repair turns).
- Add cumulative input/output token totals to the completion summary log.

Recorded in the child, not propagated to the parent: ISessionMetrics is the
SAME process-wide singleton both share, so re-recording in the parent would
double-count, and folding sub-agent tokens into the parent's UsageOutput
would corrupt its context-window percentage (the sub-agent has its own
context window).

Regression coverage (all four fail if the recording is removed):
- SubAgentActor bills usage per LLM call and sums across the turn loop.
- Completion summary log carries token totals.
- Full spawner->CreateProps->actor wiring bills tokens to the spawner's metrics.

Adds a UsageOverride hook to the sub-agent test FakeChatClient and extracts a
shared RecordingSessionMetrics test helper.
Aaronontheweb added a commit that referenced this pull request Jul 8, 2026
… (#1600)

Sub-agent LLM calls never recorded token usage, so every sub-agent's
input/output tokens were invisible to `netclaw stats`. This was a
pre-existing gap, not a regression: SubAgentActor never had an
ISessionMetrics dependency and discarded the ChatResponse.Usage it already
receives from StreamingResponseReader. The recent observability PRs
(#1428, #1468, #1472/#1499) only added logs and pruned dead OTel Activities;
none ever touched token tracking.

Fix records at the source, mirroring the main session:
- Inject ISessionMetrics into SubAgentActor (via SubAgentSpawner/CreateProps).
  DI already registers it as a process-wide singleton, so no Program.cs change.
- Record response.Usage on every LlmResponseReceived (one per LLM turn:
  tool-call turns, retries, the forced-no-tools final turn, repair turns).
- Add cumulative input/output token totals to the completion summary log.

Recorded in the child, not propagated to the parent: ISessionMetrics is the
SAME process-wide singleton both share, so re-recording in the parent would
double-count, and folding sub-agent tokens into the parent's UsageOutput
would corrupt its context-window percentage (the sub-agent has its own
context window).

Regression coverage (all four fail if the recording is removed):
- SubAgentActor bills usage per LLM call and sums across the turn loop.
- Completion summary log carries token totals.
- Full spawner->CreateProps->actor wiring bills tokens to the spawner's metrics.

Adds a UsageOverride hook to the sub-agent test FakeChatClient and extracts a
shared RecordingSessionMetrics test helper.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

cleanup Code quality improvements and tech debt reduction observability

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant