Skip to content

Schema-aware coercion of per-call meta arguments (fix Qwen near-miss tool-arg rejections)#3

Closed
Aaronontheweb wants to merge 3 commits into
devfrom
worktree-coerce-meta-arg-names
Closed

Schema-aware coercion of per-call meta arguments (fix Qwen near-miss tool-arg rejections)#3
Aaronontheweb wants to merge 3 commits into
devfrom
worktree-coerce-meta-arg-names

Conversation

@Aaronontheweb

Copy link
Copy Markdown
Owner

Problem

Self-hosted Qwen3.6 emits per-call meta hints (_rationale/_timeout_seconds/_background) using ChatGPT-style names without the underscore — TimeoutSeconds, Timeout, Rationale. Since netclaw-dev#1398's loud tool-argument validation, those near-misses are hard-rejected ("the tool was NOT executed"), which pushed the model off tools entirely and into emitting ChatGPT-style sandbox:/… download links instead of calling attach_file.

Observed in production sessions D0AC6CKBK5K/1781746527.976389 and C0B1GKNLZD3/1782215358.474099: 26 "Unrecognized argument" rejections across the fleet in the days after the 0.24 deploy (Rationale_rationale, TimeoutSeconds_timeout_seconds, …), and a cluster of dead sandbox: links the user kept correcting by hand.

Approach

Make per-call meta-argument resolution schema-aware, applied uniformly to every tool:

A key is a meta field iff it's an exact canonical name (_timeout_seconds…), or it resolves to a meta name and is not a declared parameter of this tool.

The daemon loads the full schema for every tool — native and MCP — so the declared-param check is authoritative everywhere; no native/MCP special-casing. The no-silent-discard invariant holds for all tools: every supplied value is either consumed (correctly mapped) or loudly rejected (unknown key / invalid value / ambiguous spelling).

What's in here (3 commits)

  1. Schema-aware coercionToolArgumentValidator.ResolveMetaField(tool, key) resolves near-miss meta names but yields to a tool's own declared parameter (so a third-party MCP timeout is forwarded, never hijacked). Validation and extraction share this one resolver. Validator cache switched to per-instance (ConditionalWeakTable) because MCP tools share a type but carry distinct schemas.
  2. Unified InterpretToolCall seam — one IToolExecutor method (validate + extract in one step, resolving the tool and resolver once) that both the main pipeline and the sub-agent route through, so neither can skip a step. Fixes the sub-agent silently dropping timeout hints (it previously didn't extract meta at all). The meta-ambiguity guard moved to ValidateMetaValues, which runs for every tool (it was native-only, leaving an MCP silent-drop).
  3. Re-drive preserves metaToAiMessage(reinjectMeta: true) re-injects the persisted MetaJson hints on the approval re-drive path, so a re-executed call honors its timeout instead of falling back to the default (a pre-existing latent bug surfaced by the deep review; MetaJson was written but never read by the re-drive dispatch).

Persistence now records tool calls exactly as the executor interprets them (LlmSessionActor passes the schema-aware interpreter to ChatMessageConverter.FromAiMessage), so history matches what ran.

Review

Authored against an xhigh code review (10 finder angles) plus a focused deep review of the persistence/re-drive seam (3 adversarial tracers). Findings either fixed (ambiguity gap, persistence divergence, re-drive meta loss, stale docs, dead code, dup work) or accepted with rationale in the commit bodies (undeclared near-miss on additionalProperties:true MCP schemas — off the declared interface, narrow; CWT vs ConcurrentDictionary micro-cost — required for per-instance MCP schemas).

Verification

  • Netclaw.Actors.Tests: 2477 passed; Netclaw.Daemon.Tests: 738 passed.
  • New coverage: MCP ambiguity rejection, InterpretToolCall success/rejection, schema-aware resolution yields to declared params, persistence near-miss round-trip, re-drive hint restoration, meta-field switch-coverage guard.
  • dotnet slopwatch analyze clean; copyright headers verified.
  • netclaw-operations skill bumped to v2.15.0 (spelling-tolerant arg guidance).

Eval/smoke suites N/A (no identity/TUI/skill-matching surface changed). The eval case tool_timeout_arg_recovery still passes by construction; worth a run against the live Qwen endpoint before release.

ChatGPT-trained models (Qwen3.6) name the per-call meta fields the ChatGPT
way — TimeoutSeconds/Rationale/bare Timeout instead of the canonical
_timeout_seconds/_rationale/_background. Since netclaw-dev#1398's loud validation, those
near-misses are hard-rejected ("tool was NOT executed"), which pushes the model
off tools and into emitting ChatGPT-style sandbox: download links instead of
calling attach_file (observed in sessions D0AC6CKBK5K_1781746527 and
C0B1GKNLZD3_1782215358).

Resolve a supplied key to a meta field when its normalized form matches a
canonical name AND the tool does not declare a real parameter that binds to it.
This is schema-aware: a third-party MCP server's own 'timeout' parameter is
forwarded untouched, while the model's near-miss is still coerced where no such
parameter exists. The value is consumed, never silently dropped — preserving the
no-silent-fallback invariant netclaw-dev#1398 established. Ambiguous double-spellings and
invalid values are still rejected loudly.

- ToolArgumentValidator.ResolveMetaField(tool, key): single schema-aware resolver;
  validator cache switched to instance-keyed (ConditionalWeakTable) so MCP tools
  sharing McpToolAdapter no longer conflate schemas.
- ToolCallMeta.ExtractFrom / ValidateMetaValues / Extract take a resolver delegate
  (default exact, schema-blind) used by persistence; the executor passes the
  schema-aware resolver via IToolExecutor.PrepareToolCall.
- Sub-agent loop now runs ValidateToolCall -> PrepareToolCall -> apply timeout hint,
  the same shared seam as the main pipeline (it previously skipped extraction and
  silently dropped the hint).
- Loud default in the meta switch; dead SuggestFor branch removed; recognition
  loops merged.
- netclaw-operations skill v2.15.0; tool_timeout_arg_recovery eval comment updated.

Full Netclaw.Actors.Tests green (2471); Daemon provider-boundary green (91);
slopwatch clean; headers verified.
…review findings

Follow-up to the schema-aware meta-arg change (d43a16f), addressing an xhigh
code review. Three substantive fixes plus cleanups.

Correctness — ambiguity guard now covers MCP. The 'two keys map to one meta
field' guard lived only in ToolArgumentValidator.ValidateArgumentKeys, which the
executor skips for MCP tools; but MCP gets schema-aware near-miss extraction, so a
double-spelled meta key on an MCP call silently last-write-wins. Moved the guard
into ToolCallMetaExtractor.ValidateMetaValues (runs for every tool via
DispatchingToolExecutor.ValidateArguments), checked ahead of value errors so it
keeps priority. Removed the now-redundant guard from ValidateArgumentKeys.

Altitude — one InterpretToolCall seam. Added IToolExecutor.InterpretToolCall
(returns rejection? + meta + cleaned), which resolves the tool and builds the meta
resolver ONCE, then validates and (only on success) extracts via a shared
ValidateCore. The main pipeline and the sub-agent loop both route through it instead
of calling ValidateToolCall then PrepareToolCall as two un-ordered steps (removes the
double registry lookup and the extract-without-validate footgun). Timeout-hint
application centralized in ToolExecutionContext.ApplyMeta (used by the sub-agent's
two sites). Sub-agent's intentional ignore of _background/_rationale is now
commented.

Persistence matches runtime — ChatMessageConverter.FromAiMessage takes an optional
schema-aware interpreter; LlmSessionActor passes the executor's PrepareToolCall at
the tool-call persistence site, so a near-miss meta key is stripped and captured in
MetaJson in recorded history (was persisted raw, schema-blind). Default stays exact
for tests/replay.

Cleanups: PrepareToolCall default delegates to ToolCallMetaExtractor.Extract;
ValidateArgumentKeys computes NormalizeKey once; removed the stale 'exact-match for
MCP' docs and the duplicate XML-doc on ResolveMetaField; added a loud default in the
ExtractFrom meta switch plus a test that every MetaFieldNames entry is bound.

Accepted (documented): undeclared near-miss on additionalProperties:true MCP
schemas (off the declared interface; narrow); ConditionalWeakTable vs
ConcurrentDictionary micro-cost (CWT required for per-instance MCP schemas).

Tests: MCP ambiguity rejection; InterpretToolCall success/rejection; persistence
near-miss round-trip; exact-resolver tests renamed off the misleading 'MCP' name;
meta-field coverage guard. Full Netclaw.Actors.Tests green (2476); Daemon
provider-boundary green (91); slopwatch clean; headers verified.
A tool call that needs approval, whose session passivates before approval and
then cold-recovers, is re-driven through ChatMessageConverter.ToAiMessage, which
rebuilt the call from ArgumentsJson only and never re-injected the meta hints that
persistence had stripped into MetaJson. So the re-driven execution extracted no meta
and silently fell back to the default timeout — dropping the agent's _timeout_seconds
(and _background/_rationale). This reproduced the original 'long call killed at the
default timeout' symptom on the post-approval re-drive path.

Pre-existing (it affected canonical _timeout_seconds before the meta-arg work too;
MetaJson was written and round-tripped but only ever read by CompactionPromptBuilder,
never by the re-drive dispatch). Surfaced by the deep persistence review.

ToAiMessage gains a reinjectMeta flag (default false): when set it parses the
persisted MetaJson and re-injects the canonical keys (_rationale/_timeout_seconds/
_background) into the reconstructed arguments, so the re-dispatched call's extraction
reapplies the hint. RedriveToolBatchForApproval opts in; the other four ToAiMessage
callers (outbound provider history, compaction, sub-agent) keep it false — the model
must never receive meta keys. Re-drive reconstructs for execution only (not
re-persisted), so no meta keys leak back into the journal.

Test: ToAiMessage_reinjectMeta_restores_hint_for_redrive_but_not_outbound proves
the strip→reinject→re-extract round-trip restores the 1800s hint on re-drive while
outbound history stays clean. Full Netclaw.Actors.Tests green (2477); slopwatch clean;
headers verified.
@Aaronontheweb

Copy link
Copy Markdown
Owner Author

Opened against the wrong repo (fork). Superseded by netclaw-dev#1470.

Aaronontheweb added a commit that referenced this pull request Jul 1, 2026
…per session, daemon.log sparse, OTEL the union (netclaw-dev#1472) (netclaw-dev#1499)

* refactor(logging): route session logs off the log event, delete the AsyncLocal (netclaw-dev#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 netclaw-dev#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 netclaw-dev#1472.

* test(logging): end-to-end proof actor _log routes to session.log via the real bridge (netclaw-dev#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 netclaw-dev#1499, netclaw-dev#1472.

* refactor(logging): publish session logs explicitly instead of routing 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 netclaw-dev#1499, netclaw-dev#1472.

* fix(logging): publish routed-skill sub-agent spawn lifecycle to session.log (netclaw-dev#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 netclaw-dev#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).

* feat(logging): correlate LLM chat-client diagnostics to sessions via explicit ChatOptions

Deleting the SessionDiagnosticsContext AsyncLocal (netclaw-dev#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).

* refactor(logging): address code-review findings on session-log correlation

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.

* refactor(logging): centralize the "SessionId"/"SubSessionId" log-attribute 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.

* refactor(logging): drop RetryingChatClient's redundant SessionId scope

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.

* refactor(logging): collapse sub-agent spawn breadcrumbs to one fan-out 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.

* feat(logging): partition the log stream by session instead of explicit-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.

* test(logging): end-to-end partition proof through the real Akka->MEL 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.

* fix(logging): harden the session-partition sink (code-review follow-up)

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.

* docs(logging): document the dormant non-streaming retry session-scope 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.

* refactor(logging): drop the startup buffer + lock for a single volatile 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.

* fix(logging): breadcrumb emitters take SubAgentRunId after the merged 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.

* feat(logging): give each sub-agent run its own session.log, keyed by 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).

* fix(logging): restore session correlation for sidecar LLM paths (code-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 netclaw-dev#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).

* feat(logging): flush the audit transcript immediately, keep diagnostics 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.

* refactor(logging): batch daemon.log flushes + consolidate the /subagent/ 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.

* fix(logging): guard PostStop dispose, fix audit-durability doc, scope 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.

* fix(logging): keep daemon-infra session-named lines in daemon.log; cap-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).

* test(logging): address code-quality bot findings (Path.Join, drain-loop 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.
Aaronontheweb added a commit that referenced this pull request Jul 4, 2026
…does not contain 'memory'

The memory_identity_preference_routing assertion was failing intermittently because correct
model responses often say 'memories' (plural), but the assertion required the literal
substring 'memory' (singular). 'memories' does NOT contain 'memory' as a substring —
the plural drops the y.

Regression proof from run af0883b5: runs #3 and netclaw-dev#5 exhibited correct behavior
("That's already saved — ... in my durable memories", no file edits, no redundant
store call) but were rejected by the old pattern.

The -a flags added in the prior commit are retained as cheap defensive hardening
for transcripts that may carry terminal control bytes, but they are NOT the fix for
this flake. The invalid-UTF-8 justification was incorrect and is retracted.
Aaronontheweb added a commit that referenced this pull request Jul 4, 2026
…lently defeats matching) (netclaw-dev#1576)

* fix(evals): grep transcripts with -a — invalid UTF-8 was silently defeating assertions

GNU grep in a UTF-8 locale silently skips lines with invalid multibyte sequences
when the -a flag is absent. Eval transcripts contain terminal control bytes and
other non-UTF-8 sequences, causing assertion helpers to randomly fail when
escape bytes landed on a matching line — the mechanism explains the historic
flakiness of memory_identity_preference_routing (0/5→3/5→5/5→3/5 swings).

Fixed all 14 grep call sites in the assertion helpers and inline transcript
assertions by adding -a:
- stdout_contains, stdout_not_contains (grep -qi → grep -qia)
- stdout_response_contains, stdout_response_not_contains (both pipes: -v → -av, -qi → -qia)
- daemon_log_contains, daemon_log_skill_loaded, daemon_log_no_skill_loaded (grep -qE → grep -qaE)
- stdout_tool_called (grep -qE → grep -qaE)
- store_metrics: grep on usage_line (grep -oP → grep -aoP, 5 invocations)
- run_prompt_resume: grep on turn_file (grep -o → grep -ao)
- assert_multi_turn_text_growth: grep on STDOUT_FILE (grep -c → grep -ac)
- assert_approval_set_working_directory_positive: grep -nE on STDOUT_FILE (2 invocations, → grep -anE)

Proven on run af0883b5: memory_identity_preference_routing cases had correct
behavior ('durable memories' literal text in transcript), but grep -ci returned 0,
while grep -cia returned the correct count. This fix eliminates the instrumentation
source of the flakiness.

* fix(evals): match 'memor' in identity-routing assertion — 'memories' does not contain 'memory'

The memory_identity_preference_routing assertion was failing intermittently because correct
model responses often say 'memories' (plural), but the assertion required the literal
substring 'memory' (singular). 'memories' does NOT contain 'memory' as a substring —
the plural drops the y.

Regression proof from run af0883b5: runs #3 and netclaw-dev#5 exhibited correct behavior
("That's already saved — ... in my durable memories", no file edits, no redundant
store call) but were rejected by the old pattern.

The -a flags added in the prior commit are retained as cheap defensive hardening
for transcripts that may carry terminal control bytes, but they are NOT the fix for
this flake. The invalid-UTF-8 justification was incorrect and is retracted.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant