refactor(logging): partition the log stream by session — session.log per session, daemon.log sparse, OTEL the union (#1472)#1499
Merged
Conversation
…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.
…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.
…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.
…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
Comment on lines
+123
to
+125
| foreach (var kv in kvps) | ||
| if (kv.Key == NetclawLogProperties.SessionId && kv.Value is string s) | ||
| return s; |
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
commented
Jul 1, 2026
| captor, sessionId, history: [], self: CreateTestProbe().Ref, | ||
| log: NoLogger.Instance, timeout: TimeSpan.FromSeconds(5)); | ||
|
|
||
| AssertScopedTo(sessionId, captor); |
| // 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); |
| Assert.Equal(4, attempts); | ||
| } | ||
|
|
||
| // NOTE: RetryingChatClient deliberately does NOT open its own SessionId scope — it |
| AssertScopedTo(sessionId, captor); | ||
| } | ||
|
|
||
| private static void AssertScopedTo(SessionId sessionId, OptionsCapturingChatClient captor) |
| // the deleted SessionDiagnosticsContext AsyncLocal). | ||
| var options = new SessionScopedChatOptions | ||
| { | ||
| SessionId = sessionId.Value, |
| /// <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 |
Merged
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.
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.
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
SessionDiagnosticsContextAsyncLocal 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.
WithContext("SessionId", …), a{SessionId}message field, or aSessionIdlogging scope (the chat-client decorators) — is written to that session'ssession.logand not todaemon.log. Nothing is duplicated locally.daemon.logholds only sessionless, daemon-wide lines: startup/config, session start/stop, and operational alerts (e.g. theprovider.unreachablealert when an inference provider goes down — surfaced here and to webhooks by the notification sink).SessionIdas an attribute; the OTEL receiver does the global slicing/distilling.Net:
daemon.logis sparse,session.logis the session's full local slice (transcript + every session-scoped operational line, wall-clock interleaved), OTEL is the union.How
RollingFileLoggerProviderimplementsISupportExternalScopeand owns the local partition. Per line it resolves the session id from the event's structured state (the Akka→MEL bridge,AddLoggerFactory, surfacesWithContext/{SessionId}) or the active scopes; session-tagged →TelltheSessionLogDispatcheraSessionLogDiagnostic; otherwise →daemon.log. The dispatcher is a single volatile reference resolved in the background viaIRequiredActor.GetAsync()— no buffer, no lock (a line logged before it resolves falls back todaemon.log).SessionLogActor's own lines (identified by its AkkaLogSource/ActorPath) are forced todaemon.logso a write-failure log can never recurse into the file that just failed.SessionLogActor— the single writer persession.log— switches from per-lineAutoFlushto a batched/idle flush (~1s or 256 lines), since it now carries the session's whole stream.SessionScopedChatOptions+ aSessionIdscope (ChatClientSessionScope) — a typed property, notAdditionalProperties(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.SessionId/SubSessionIdlog-attribute keys inNetclawLogProperties.SessionDiagnosticsContextAsyncLocal and the interimEmitSessionLogLineside-channel.Evolution (see commit history)
This PR first tried explicit-publish — an
Action<string> EmitSessionLogLinehand-driven alongside each log call — and, before that, a sink that routed anySessionId-tagged line tosession.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-resolutiondaemon.logfallback, and the resolution-failure beacon.SessionLogPartitionIntegrationTests— end-to-end through the real Akka→MEL bridge: a real actor'sWithContext("SessionId").Info(...)lands in itssession.logfile and notdaemon.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).slopwatchclean; 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.logis now sparse;session.logis effectively a per-session debug log (hence the batched flush) and interleaves the clean transcript with operational lines. Debugging one session → read itssession.log; a daemon-wide problem →daemon.log+ the operational-alert/webhook path.SessionIdscope (it relies onLoggingChatClient's streaming scope) and would route todaemon.log— caveated atRetryingChatClient.BackoffAsync.