Skip to content

fix(server): log the status an error response sends - #1117

Merged
ragnorc merged 1 commit into
ModernRelay:mainfrom
ragnorc:fix/log-sent-error-status
Oct 21, 2026
Merged

ragnorc merged 1 commit into
ModernRelay:mainfrom
ragnorc:fix/log-sent-error-status

Conversation

@ragnorc

@ragnorc ragnorc commented Oct 21, 2026

Copy link
Copy Markdown
Contributor

What & why

The review of #1078 found that the server's containment logs record the wrong status:

The containment logs call ApiError::status(). That method returns the cause code's first HTTP status. An owned write the server cannot settle answers 500 outcome_unknown. A DataFusion failure is mapped to bad_request, so status() is 400 and the response is 500. The warning in from_omni and the error in OperationRuntime::submit both record that 400. Log the status the response sends.

The code is on main through #1076. This PR makes both log lines record the status the client receives. The status comes from the method the response is built from, so a log line and its response cannot disagree.

Backing issue / RFC

  • Fixes an accepted issue
  • Is an RFC PR, or implements an accepted RFC
  • Trivial fast-lane

None of the three applies. This is a follow-up to a finding in the #1078 review, which said a follow-up could fix it. No issue tracks it, so the test names carry no issue_N.

How

  • ApiError::status() now returns the status the response sends. It reads the error's disposition and gets the answered code from the new answered_code. That method is now the only place where a code becomes outcome_unknown; into_judged_output calls it too. The status comes from that code, or from the branch_start_refusal reason when the code is branch_start_refusal. This is the same rule as ErrorOutput::http_status.
  • IntoResponse adds the request's facts first, then takes the response status from error.status(), then builds the body. status_of, the second status mapping, is removed.
  • A log can only record the sent status if it sees the final facts. Two changes make sure it does:
    • from_omni applies with_request_facts() before its warning. This is the same merge that into_output and spawn_read already do, and it only ever sets the flag to true, so no response changes.
    • OperationRuntime::submit runs the owned write with the request's SUBMITTED_WRITE record set to true, so an error translated inside the write is judged as one that follows the write. The write's error is now marked after_owned_write inside the owned task, before the containment log reads it. Before, the mark was added when the waiter took the error. OwnedResponse::result still marks its own "result was lost" error.
  • Other callers of status():
    • redact_blob_api_error and log_blob_transport_internal in handlers.rs (the == INTERNAL_SERVER_ERROR checks) and Refusal::resource_error in mcp.rs serve Blob GET/HEAD and MCP resource reads. Those are reads. Their request never submits an owned write, and their errors never cross the owned-write boundary, so the code is never rewritten to outcome_unknown and the old status was already the sent status. They are correct as they are. They now use the same method as the response, so a later change cannot split them apart.

No HTTP response, body or disposition changes; only the two log lines change.

The storage-failures page also said an unsettled write answers outcome_unknown "on MCP"; since #1076 HTTP answers it too, and the sentence now says so.

Checklist

  • Change is focused (one logical change)
  • Tests added/updated for behavior changes
  • Public docs updated: the Logs paragraph of docs/user/operations/storage-failures.md now says both lines record the status the response sends; changelog.d/containment-logs-record-the-sent-status.fixed.md
  • Reviewed against docs/dev/invariants.md. Invariant 11 asks for failure outcomes to be observable, and the logged outcome now matches the answered one. No deny-list item is involved.

Tests

  • api_error_tests::the_answered_code_fixes_the_status_and_retry_after (extended): every row now also checks that error.status() before conversion equals the status of the response.

  • api_error_tests::an_uncertain_engine_failure_logs_the_status_its_response_sends (new): a DataFusion failure in three contexts, with the server's log subscriber captured for each:

    • a read: warning and response are both 400;
    • after the request submitted a write: warning and response are both 500;
    • inside an owned write: the warning, the containment error and the response are all 500.

    The test first triggers both log sites once. tracing caches whether a log site is enabled the first time it is hit. While at most one dispatcher exists, it asks only the default of the thread that hits the site. A concurrent test that hits the site with no subscriber installed then caches it as never enabled, and the capture sees nothing; this happened in the first run. A capture installed after the sites are registered rebuilds that cache.

Before the fix (fix hunks reverted, tests kept; cargo test -p omnigraph-server --lib --locked -- api_error_tests:: operations::):

test api_error_tests::the_answered_code_fixes_the_status_and_retry_after ... FAILED
test api_error_tests::an_uncertain_engine_failure_logs_the_status_its_response_sends ... FAILED
  left: 400
 right: 500
WARN omnigraph_server: engine failure without definite completion evidence status=400 Bad Request cause=RedactedCause { variant: "DataFusion", storage_kind: None, manifest_kind: None }
test result: FAILED. 34 passed; 2 failed

After: 36 passed; 0 failed.

Local verification

  • RUST_MIN_STACK=16777216 cargo test -p omnigraph-server --lib --locked: 214 passed, 2 ignored (run three times, all green)
  • RUST_MIN_STACK=16777216 cargo test -p omnigraph-server --tests --locked: lib 214, boot_settings 43 (1 ignored), integration 274, multi_graph 8, all pass
  • cargo clippy -p omnigraph-server --all-targets --locked -- -D warnings -W clippy::dbg_macro: clean
  • cargo fmt --all --check, python3 scripts/check-docs.py, typos on the changed files: clean
  • The workspace test graph and the CLI suites were not run. The change is limited to the server crate, and the embedded error-output functions the CLI calls give the same results as before.

Notes for reviewers

The outcome_unknown rewrite used to run once for the body and once more, through ErrorOutput::http_status, for the response status. Now answered_code decides it, and the body's code and the response's status both come from that decision.

A write the server cannot settle answers 500 `outcome_unknown`, whatever
code its cause maps to. `ApiError::status()` returned the cause code's first
status, so the containment logs, which read it, recorded the cause's status:
a query execution failure inside an owned write logged 400 while the client
received 500.

`status()` is now the status the response sends. It judges the error's facts
through `answered_code`, the one place a code becomes `outcome_unknown`, and
both the response builder and the logs read it; `status_of`, the second
mapping, is gone.

The facts must be final where a log reads them. The engine-failure warning
in `from_omni` first takes its request's record of a submitted write, and an
owned write runs with that record set, so an error it translates is judged
as following it. The write's error is marked as one the owned write
returned before the containment log reads it, rather than when the waiter
takes it.
@ragnorc
ragnorc requested a review from aaltshuler as a code owner October 21, 2026 16:18
@cursor

cursor Bot commented Oct 21, 2026

Copy link
Copy Markdown

I would merge this. There are no blocking findings. There is one optional finding.

Why

A write the server cannot settle answers HTTP 500 with code outcome_unknown. The containment logs called ApiError::status(). That method returned the first HTTP status of the cause code. A query execution failure (DataFusion, mapped to bad_request) logged 400 while the client received 500. Invariant 11 requires a failure outcome to be observable. The logged outcome and the answered outcome were different.

The affected class is every uncertain engine failure whose own code has a first status other than 500, once the write fact is present. DataFusion is the 400 case. The same answered_code rule covers the other codes. A recovery intent keeps its own code, as it did before.

What

status() now returns the status the response sends. It reads answered_code. That method is the only place a code becomes outcome_unknown. IntoResponse takes the status from status(). status_of is gone.

The two log sites read status() after the write fact is on the error:

  • from_omni calls with_request_facts() before the warning.
  • The owned-write task runs with SUBMITTED_WRITE set, so an error translated inside the write is judged as a write that already started.
  • OperationRuntime::submit calls after_owned_write before the containment error line.

status() matches ErrorOutput::http_status. A branch-start refusal uses the reason status only while the answered code is still branch_start_refusal (409, or 410 when the commit is not retained). Blob redaction and the MCP resource-read check call status() on reads. A read does not submit an owned write, so the code is not rewritten.

The HTTP status and the error body stay the same. The two log lines change.

Tradeoff and liability

The response and the logs now share one status rule. status_of, the second mapping, is removed. That lowers long-term liability.

status() now depends on the facts the error carries. A caller that reads it before those facts are set still receives the cause status. The server logs set the facts first. The warning stays in from_omni because that is where the redacted cause exists. The request's write fact is task-local and is available there. That is the right cut for the served contract.

Further log lines should call this status() after the facts are final. They should not add another status mapping.

This branch is based on 41a16214. Current main is 13ecdc8b. The six commits in between do not change these server files. A merge-tree against 13ecdc8b shows no conflicts.

Open PR 1096 edits the same two log sites and the same section of docs/user/operations/storage-failures.md. Its current diff still logs status() before after_owned_write, and it still describes the unknown outcome as outcome_unknown on MCP. A rebase onto this change has to keep the mark before the log. The two doc edits have to be combined. Open PR 1001 adds optional OTLP logs. This change makes the status field the status the client receives, which is the value a correlated log should carry.

Optional

The warning still runs inside from_omni, and engine_error_output / engine_error_output_after set owned_write after that call returns. On this head, both helpers log status=400 Bad Request for OmniError::DataFusion("execution failure"). Both bodies have code outcome_unknown and HTTP status 500. This behavior is the same before and after the change. The CLI does not install a tracing subscriber, so a CLI user does not see the line. The served logs are the contract this PR fixes. Set the embedded write fact before from_omni if that line must match the body.

Validation

A .gqt case cannot see a tracing line or the HTTP status of a contained server write. The owner is api_error_tests in omnigraph-server. This PR extends that owner. I did not add a .gqt case.

Before: parent 41a16214468562b9cd118944ebe752c528a2f0d7, with the new test copied in for the run only. The copy was not pushed.

CARGO_TARGET_DIR=/workspace/target RUST_MIN_STACK=16777216 cargo test -p omnigraph-server --lib --locked -- an_uncertain_engine_failure_logs_the_status_its_response_sends -- --exact --test-threads=1

Failed. The response status was 500. The warning line was status=400 Bad Request.

After: head e75415b98db331c3f538b5ca9ad0416d6eb91839.

The same test, plus the_answered_code_fixes_the_status_and_retry_after, branch_start_refusal_is_typed_409_or_410, and an_error_after_a_write_reports_what_it_may_have_done: 4 passed.

operations::tests::: 14 passed.

The log test, repeated 10 times with --test-threads=16: passed each time.

CI on this commit is green, including Test Workspace, Lint (clippy), Format (rustfmt), and the GQT jobs. I did not re-run those suites locally.

I did not execute every HTTP route. The read-path status() callers are checked by reading the call sites. The temporary test copy and the embedded log probe were removed. Nothing was pushed.

Comment thread crates/omnigraph-server/src/lib.rs
@ragnorc
ragnorc enabled auto-merge October 21, 2026 17:35
@ragnorc
ragnorc added this pull request to the merge queue Oct 21, 2026
Merged via the queue into ModernRelay:main with commit 10f5517 Oct 21, 2026
32 checks passed
@cursor cursor Bot mentioned this pull request Oct 21, 2026
6 of 7 tasks
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