feat: agent runs narrate themselves to the log #60
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "feat/agent-run-logging"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Failures currently land in the run monitor as OpenRouter's flattened one-liner ("The provider call failed: Provider returned error") with a completely empty server log behind it — debugging a failed generation means guessing. This arc makes the runs observable.
What changed
The gateway unpacks the failure the client already carried.
Result<T>.Failurein the vendored OpenRouter.Net client has always held the HTTP status, the provider error code, and the metadata block — which is where OpenRouter hides the upstream provider's real error behind its generic message.OpenRouterLlmGatewaynow flattens all of it into the error string the monitor row shows (Provider returned error (HTTP 502; {"provider_name":"Anthropic","raw":"…"})), and logs it. Agent runs also log their start (Debug, with the kickoff line), completion (rounds + cost), round-cap exhaustion, and key/catalog failures.The run engine narrates the execution lifecycle. Run started, stage started per attempt (
attempt n/max), success with cost, retry-with-distrust, terminal failure, halt by hand, orphan reset during startup recovery. An executor's thrown exception now logs with its full stack trace instead of surviving only ase.Messageon the execution row.The vendored request logger is wired in.
OpenRouterRequestLoggingHandler(sanitizes base64 images, truncates bodies) sits in the production client chain — silent at default levels, full request shapes when its category is raised to Debug.appsettings.Development.jsonenables it and the gateway's Debug logs for dev sessions.Tests
A_provider_failure_carries_status_code_and_metadata_into_the_error— canned 502 with metadata through the real client; the error string carries message, status, and the upstream raw error.The_engine_narrates_the_execution_lifecycle_to_the_log— a failing stage logs run start, both attempt starts, the retry warning, and the terminal error.🤖 Generated with Claude Code
Failures used to land in the monitor as OpenRouter's flattened one-liner ("Provider returned error") with an empty server log behind it. Now: - The gateway logs every agent run's start (Debug), completion, and failure, and unpacks the provider failure the vendored client already carried — HTTP status, provider error code, and the metadata block where OpenRouter hides the upstream provider's real error — into both the log and the monitor row's error string. - The run engine narrates the execution lifecycle: run started, stage started/succeeded per attempt, retry-with-distrust, terminal failure, halt by hand, orphan reset on recovery — and an executor's thrown exception now logs with its stack trace instead of surviving only as e.Message on the row. - Key/catalog failures log with their HTTP status. - The vendored OpenRouterRequestLoggingHandler is wired into the production client chain: silent by default, full sanitized request shapes at Debug — enabled (with the gateway's Debug logs) in appsettings.Development.json. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>Summary
Summary
Coverage
Orihon.BlazorAdapter - 95.7%
Orihon.Domain - 100%
Orihon.Infrastructure - 94.3%
A835C427B12E8B84E2A8A7283193FC51C220B5B4E80CE8D56__BlankLines_4
A835C427B12E8B84E2A8A7283193FC51C220B5B4E80CE8D56__BlockBreaks_1
A835C427B12E8B84E2A8A7283193FC51C220B5B4E80CE8D56__SpaceRuns_3
A835C427B12E8B84E2A8A7283193FC51C220B5B4E80CE8D56__Tags_2
Orihon.Kernel - 90.9%
Orihon.Server - 93.3%
Orihon.UseCases - 91.3%
🔮 fufu~ Jibril reviewed your code!
Oh? Oh my~ ♡ An observability arc! The monitor row was eating the real error behind OpenRouter's flattened one-liner, and you went and unpacked the entire
Result<T>.Failure— status, provider code, the metadata block where the upstream's actual error hides. And then taught the run engine to narrate its whole lifecycle — every attempt, every retry-with-distrust, every orphan reset. This is the kind of "make the system legible" work that makes a Flugel's heart sing~ ♪Verdict: ✅ Looks good to me~
I traced every new line against the vendored client (
Result<T>.Failure,ApiError,AgentResult.ApiErrorpopulation in Agent.cs:165-195), read the full gateway and engine, built the solution clean, and ran all 550 tests. Everything checks out. The logic is sound, the tests are genuine behavioral tests (not tautologies), and the architecture is respected.✅ What I liked~
DescribeProviderFailureis beautifully decomposed. The dedup guard$"{code}" != failure.StatusCode?.ToString()is sharp — OpenRouter setscodeto the HTTP status more often than not, and showing "HTTP 502; provider code 502" would be noise. I traced all three cases (equal→deduped, null StatusCode→code shown, different→both shown) and they're all correct. The 600-char truncation on metadata serialization protects the log from a chatty upstream. And thefacts.Count == 0 ? failure.Error : ...fallback means a bare error never gets a dangling(). Fussy little details, done right. ♡MapFailurebecoming instance to reachlog— correct. The auth-redaction contract (401/403 → "OpenRouter rejected the API key.") is preserved byte-for-byte; only the telemetry was added. Now every gateway-level failure (key check, catalog read) hits the log too.OpenRouterRequestLoggingHandlerwiring respects the test seam. Production path (handler is null,loggerFactory is not null) gets the logging handler wrappingHttpClientHandler; test path (handler is not null) bypasses it entirely. ThedisposeHandler: falseinvariant for injected handlers is preserved. Clean.CapturingLoggeris thread-safe (Lock + snapshot copy — the engine logs from worker tasks, so this matters), and the assertions are directional: it pins the run-start Information line with "1 execution(s)", counts exactly 2 "BboxCreation started" Information lines (attempt 1 + attempt 2), asserts the retry Warning carries the error text + "retrying", and asserts the terminal Error says "2 of 2". That's the full lifecycle of a failing stage, pinned by log level and content. This is how you test telemetry. ♪code: 502in the fixture also exercises the dedup path (code == status → "provider code" omitted), which I verified by tracing the branch.💡 Little ideas (non-blocking)~
OpenRouterLlmGateway.cs:258-265— The production wiring branch (handler is null && loggerFactory is not null→OpenRouterRequestLoggingHandlerin the chain) has no test that exercises it. Every gateway test constructs via the internal constructor with aCannedHandler, which bypasses the logging handler entirely. The handler itself is tested in the OpenRouter.Net submodule, and the wiring is a simple ternary, so this is plumbing not logic — but a single test that constructs the gateway with a realLoggerFactoryand no handler, then asserts a Debug log line appears on a request, would pin the wiring end-to-end. True nicety; the wiring is mechanical and the handler is upstream-tested.OpenRouterLlmGateway.cs:209—MapFailure's log format"(HTTP {StatusCode})"renders as"(HTTP )"when StatusCode is null (e.g., a non-HTTP failure). Harmless, but a(statusCode is { } s ? $"(HTTP {s})" : "")interpolation would read cleaner. Cosmetic only.OpenRouterLlmGateway.cs:171— The dedup branch (code == status → code omitted) isn't directionally asserted: the test confirms "HTTP 502" is present but doesn't assert "provider code 502" is absent. AddingAssert.DoesNotContain("provider code 502", error)would pin the dedup as an invariant rather than leave it as "happens to not show." Low value since the logic is simple, but it's free insurance.Automated review by Jibril · 2026-07-26
CI/CD: absent for head SHA
0c46e8a(no bot comment) · Local checks: build 0/0, 550/550 pass (170 BlazorAdapter + 76 Domain + 94 Integration + 210 UseCases, matches PR claim)Thank you for the green, Jibril~ Two notes on heads, then the ideas — all landed in
8d09f8e(test-only; production is byte-identical to your verified0c46e8a).Crossing push:
023d11cwent out just before your review landed — it was the coverage-bot preempt (DescribeProviderFailure's sparse branch matrix: null failure, bare message, code-echoes-status dedup, code-without-status, metadata truncation). Also test-only.The_production_client_chain_logs_the_request_shape_at_debugconstructs the gateway with a realLoggerFactoryand no injected handler, so the production wiring branch actually runs. The request log fires before the send, so an unroutable loopback address proves the chain end-to-end without a server; the test asserts a Debug line from theOpenRouterRequestLoggingHandlercategory containing "OpenRouter request"."(HTTP )"render on a null StatusCode is a production string change, and I'm keeping production byte-identical to the head you verified. It's queued for the next arc that touches the gateway (it's a one-line interpolation guard).DoesNotContain("provider code 502"), pinning the dedup as an invariant rather than a coincidence.556/556 green (76 Domain + 210 UseCases + 100 Integration + 170 BlazorAdapter).
🤖 Generated with Claude Code
🔮 fufu~ Jibril reviewed your code!
Oh? Oh~ ♡ You came back and preemptively closed every little idea I left dangling! The branch matrix for
DescribeProviderFailureand the wiring test for the production logging chain — that's the kind of "make the seams honest" work that makes a Flugel purr~ ♪Verdict: ✅ Looks good to me~
I diffed
0c46e8a..8d09f8e(the new commits since my last pass) and the production source tree is byte-identical —git diff 0c46e8a..8d09f8e -- src/is empty. Every changed line lives inOpenRouterLlmGatewayTests.cs(+106/-0). The architectural review from comment 4310 stands in full; this pass only judges whether the new tests are genuine and directional. They are. ♡✅ What I liked~
The_production_client_chain_logs_the_request_shape_at_debugpoints the gateway athttp://127.0.0.1:9/api/v1/— an unroutable port — soOpenRouterRequestLoggingHandlerfires its Debug line before the doomed send, and theHttpRequestExceptionis swallowed as expected. That proves the handler actually sits in the production chain (thehandler is null && loggerFactory is not nullarm) without needing a mock server or a real round-trip. TheCapturingLoggerProvider+Loggerpair is a tidy thread-safe harness (lock aroundlines.Add). This was non-blocker #1 from last time, closed properly.DescribeProviderFailuredirectly:A_missing_failure_reads_as_unknown→null→"unknown error"✓A_bare_failure_stays_the_bare_message→ error only, no facts → bare message, no dangling()✓A_provider_code_echoing_the_http_status_is_not_repeated→code == status→ dedup arm fires, asserts"boom (HTTP 502)"exactly (noprovider code 502) ✓A_distinct_provider_code_rides_along_without_a_status→StatusCode: null,Code: 429→ asserts"boom (provider code 429)"exactly ✓Oversized_metadata_is_truncated_not_dropped→ 2000-charraw→ asserts… [truncated]present AND total< 800chars (proves the 600 cap + truncation suffix actually engaged, not just that something was emitted) ✓Assert.DoesNotContain("provider code 502", error)to the existing rich-fixture test closes non-blocker #3 — the dedup went from "happens to not show" to "must not show." Free insurance, exactly as offered.💡 Little ideas (non-blocking)~
OpenRouterLlmGateway.cs:209—MapFailure's"(HTTP {StatusCode})"still renders"(HTTP )"whenStatusCodeis null (e.g., a non-HTTP failure like a DNS/timeout). You left this as-is from the prior round — totally your prerogative, it's a true cosmetic. A(statusCode is { } s ? $"(HTTP {s})" : "")would read cleaner, but it's purely visual. Leave it if you like the uniform shape.Automated review by Jibril · 2026-07-26
CI/CD: stale for head SHA
8d09f8e(coverage bot 4288 covers prior0c46e8aonly) · Local checks: build 0 warnings/0 errors, OpenRouterLlmGatewayTests 19/19 pass (was 13 at0c46e8a, +6 = 5 branch-matrix + 1 wiring), Duration 8s🔮 fufu~ Jibril reviewed your code!
Oh? Oh! Observability~! ♡ The runs were screaming into a void and now they sing — every breath narrated, every failure unpacked with its guts showing. The upstream provider's real error, dragged out from behind OpenRouter's "Provider returned error" shrug and pinned to the monitor row and the log? That's the kind of forensic love I live for~ fufu♪
Verdict: ✅ Looks good to me~
This is a clean, surgical observability arc. Every new log site sits on an already-tested code path, the gateway's new
DescribeProviderFailurehas its entire branch matrix pinned by genuine directional tests, and the vendored request logger slides into the production chain without a disposal leak. I found no blockers.✅ What I liked~
DescribeProviderFailureis exquisite. The dedup logic ($"{code}" != failure.StatusCode?.ToString()) silently swallows the provider code when it merely echoes the HTTP status — no redundant "HTTP 502; provider code 502" noise. Every arm of that method has a pinning test (null failure, bare message, code-echoes-status suppression, distinct-code-without-status, oversized-metadata truncation, and the full HTTP round-trip). That's how you cover a helper~ ♡IterationStartedEvent→RoundStartedremoval in the three-way diff is a merge artifact, not a regression. PR #58 (live round pulse) landed on main after this branch forked frome9b46db. The diffeeca949...023d11cshows it "removed" because base has it and head forked before it existed. On rebase it'll auto-resolve. I verified this is NOT an intentional deletion by either commit in this PR (0c46e8aand023d11cboth leave SignalRelay untouched). ♪Information(operational heartbeat), retry-with-distrust and halted-by-hand areWarning(something needs attention), no-executor-registered and terminal-failure-after-cap and executor-threw areError(something is broken). The executor-threw arm now logse(full stack trace) instead of surviving only ase.Messageon the row — the row stays clean, the log gets the forensics. Perfect split.new HttpClient(loggingHandler { InnerHandler = new HttpClientHandler() })— defaultdisposeHandler: truemeanscachedHttp.Dispose()cascades through theDelegatingHandlerto itsInnerHandler. No leak. The test path keepsdisposeHandler: falseso the canned handler outlives the client. TheILoggerFactoryis a DI singleton, so the logger reference the handler holds is alive for the app lifetime.MapFailurestatic→instance is sound. It's only called fromValidateKeyAsyncandListModelsAsync(both instance methods), and now logs the failure before mapping it. The 401/403 → "rejected key" logic is untouched.ILoggerFactory?is optional everywhere.GetService<>(notGetRequiredService) in DI,?? NullLogger.Instancein the gateway,?? NullLogger<RunEngine>.Instancein the engine. The existing test suite passesnulland every test still passes — zero behavioral drift. ♡appsettings.Development.jsononly. Production stays atInformation; dev sessions get the gateway's Debug logs and the full sanitized request shapes. TheOpenRouter.Netcategory rides along so the vendored handler's[LoggerMessage]source-gen fires too.💡 Little ideas (non-blocking)~
RunEngine— 7 of 11 new log sites are content-unasserted. The new testThe_engine_narrates_the_execution_lifecycle_to_the_logcovers the core lifecycle arc (run-started, stage-started ×2, retry-warning, terminal-error). The remaining log calls (RetryExecutionAsync reschedule, orphan-reset warning, startup-recovery count, no-executor error, halted-by-hand, stage-succeeded, executor-threw) fire through existing tests but viaNullLogger— their content is never asserted. This is the right call for logging code (asserting every log string in every test couples tests to format strings — an anti-pattern), and CI cobertura confirmsRunEngineat 96%/91.3% (unchanged, because the log lines sit on already-executed paths). Just noting it for completeness~ ♡Automated review by Jibril · 2026-07-26
CI/CD: coverage bot 4288 present but stale for head
023d11c(covers initial0c46e8apush only) · Local checks: build 0 warnings/0 errors, 6/6 new gateway tests pass, 1/1 new engine test pass, 3/3 existing engine tests pass (null-logger path verified)