Say what actually went wrong when a service fails - #631
Merged
Conversation
1 task
elias-ba
force-pushed
the
sse-heartbeat
branch
from
August 15, 2026 01:14
7d28284 to
c4b957e
Compare
elias-ba
force-pushed
the
typed-service-failures
branch
2 times, most recently
from
August 15, 2026 22:33
6aa0ab0 to
7f29bc7
Compare
Three ways a failing service lost its own diagnosis on the way out. The bridge rejected with a bare exit code. A number is not an Error, so the handler downstream fell through to its fallback and sent the client the string "Unknown error" - no code, no type, and the exit code we did have was logged and discarded. It also rejected without returning, so a non-zero exit went on to resolve as well. A failed spawn was only logged. Nothing settled the promise, so poetry missing from PATH did not look like a broken install, it looked like a service that never answered, and the request hung until something upstream gave up. Exiting cleanly with an empty output file resolved as null, which was sent to the client as a successful completion carrying nothing. Lightning could then only report it as a stream that ended without a response. Failures now carry a code, a type and the detail worth keeping, through one envelope shared by the streaming and synchronous routes. The synchronous route had no error handling at all, so a rejected run escaped it and became a bare framework 500. Two of those empty output files came from entry.py itself: three error paths returned before the write, and two of them referenced an unbound exception variable, so a missing input file raised NameError rather than reporting the missing file. Every path out now goes through one write. ruff confirms it: two F821 undefined-name findings on main, gone here.
Nothing told us the caller had left. The python child kept running, kept calling the model, and wrote its answer into a socket with nobody on the other end. On a planner request that can be another ten model calls after the user closed the panel, all of them billed. The stream now signals an abort when it is cancelled, and the bridge kills the child on that signal. poetry run execs into python rather than forking it, so the pid we hold is the interpreter and a plain SIGTERM reaches it; killing it closes the socket to Anthropic, which stops generation. A hard kill follows five seconds later only for a child wedged somewhere that never sees the signal. The saving is on the streaming calls, which is where a long request spends its time. A non-streaming call has already been submitted and will be billed whether or not we are still listening. A cancelled run settles as its own kind of failure rather than a fault, so deliberately abandoning a request does not read as something breaking. The test spawns a real child, waits until python is genuinely inside the service, aborts, and checks the process is gone. Two things it had to get right to be worth having: the process list matches the poetry wrapper long before the interpreter exists, so the probe announces itself instead; and BSD pgrep has no count flag, so asking for one reads as "no processes" and passes regardless. Checked by disabling the abort listener - the test then takes 90 seconds and reports EMPTY_RESULT.
elias-ba
force-pushed
the
sse-heartbeat
branch
from
August 15, 2026 23:40
3c45b57 to
8a5b925
Compare
elias-ba
force-pushed
the
typed-service-failures
branch
from
August 15, 2026 23:40
7f29bc7 to
93ef024
Compare
The async Promise executor was the same trap as the JSON.parse one, a hundred lines above it. The constructor only catches a synchronous throw, so a failing Bun.write left run() pending for ever and the caller's stream open. Setup happens outside the promise now, where run() being async is enough, and the input file - which holds the key - is removed if the second write fails. Cancellation only ever covered the streaming route. A plain POST and a websocket both left the model generating when the caller went away, which is the cost the change exists to stop. Both pass a signal now; the socket gets its own controller and a close handler to fire it. A child killed by a signal reports a null exit code, so the OOM killer - the likeliest way a service dies without exiting - was reported as an empty result with the signal thrown away. Every stderr line was forwarded to the caller with no filter, so an interpreter traceback carrying server paths and whatever a frame held went straight out. Stderr now follows the same rule as stdout: only what a service logged deliberately. The health check calls run() too, and was the one caller that never got a catch when run() started rejecting. Also: the heartbeat interval had a floor but no ceiling, and setInterval turns a delay past 2^31-1 into every tick - so the value someone picks to mean "effectively never" would have flooded every open stream. And the WS handler used .then().catch(), which also catches a throw from the success path and reports it as a service failure.
serve.idleTimeout does not reach websockets - Bun keeps a separate timer for them, defaulting to two minutes. So the route most likely to be waiting on a slow answer was still being dropped, and the heartbeat bought it nothing. The comment next to it claimed app.listen sets no reusePort. Elysia's Bun adapter sets it unconditionally, so the guard that warns about a per-process internal token meeting a shared port was being silenced on a false premise. It is accurate now, and goes quiet once APOLLO_INTERNAL_TOKEN is set.
A run's input file holds whatever the server put on the payload, and the only thing that removes it is the bridge's close handler - so anything that stopped the process mid-run left one behind, readable by anyone on the box, in a directory nothing sweeps. The shutdown handler says as much: in-flight children are not drained. It is 0600 now, and startup clears whatever a previous process left. This worktree had four sitting in it from earlier test runs.
The commit messages and the issue were written carefully and the code comments were not, which is the same mistake one layer down - this repo is public and a comment is as readable as anything else.
echo returned its input verbatim and logged it. A payload reaching a service can carry values the server set rather than the caller, and logger output is forwarded to the client as SSE log events, so anything in there leaves twice. It now runs the payload through mask_secrets before returning or logging it. That helper already existed for Langfuse traces and does the same job here, so there is no second one to keep in step. The mask itself was narrower than what the server can fill in: it listed three field names and recognised one provider's key format. It now covers the fields for the other providers too, and matches both key shapes, so a value under a name nobody listed is still caught. Follow-ups in #634.
A payload reaching a service carries values the server put there rather than the caller. Three routes led back out: echo returned its input verbatim, any service logging its payload reached the caller too (logger output is forwarded as SSE log events), and the error envelope returns the exception text. The logger is the one that matters, because it needs nothing of the service: vocab_mapper logs its whole payload on the first line of main. Masking in create_logger covers that and anything written later without each service having to remember. Also masks the request context search_adaptor_docs sends to Sentry, which the three sibling services already stripped. The mask itself was narrower than what the server can fill in, so it now lists the other providers' fields. Widening its value pattern to a general sk- shape first made it match ordinary words - task-, risk-, disk- and friends - which would have quietly corrupted every Langfuse trace, since this is the same function used as the export mask. It is anchored now, with tests pinning both directions. The instance-auth tests read a masked field off echo's response, which they can no longer do. They assert that the request is accepted and that what the caller sent does not come back; what the server substitutes is covered directly against InstanceAuth.authenticate.
Review of the masking itself found four ways round it. The error envelope masked two branches and not the one services take. Nearly all of them catch broadly and rewrap as ApolloError(500, str(e)), which entry.py returned untouched - the same disclosure, by the sibling branch of the same case statement. Masking now happens once at the exit, so it covers the message, the details, and whatever gets added later. The log filter was attached to each logger built by create_logger, and a filter on a logger only runs for records emitted through it. A plain getLogger, or a third-party logger like httpx, writes to the same stdout handler and sailed past - and vocab_mapper already silences httpx precisely because it reaches that stream. It sits on the handler now, so what a service uses to log makes no difference. Rendering the message inside the filter moved %-formatting out of the handler, where a bad format string is caught and reported, and into the caller's own logging call, where it is not. A cosmetic typo in a log line would have failed the request. And a message that was neither string nor container passed through unmasked, because the formatter calls str() on it after the filter has run. Sentry saw everything unmasked: it scrubs frame locals by name, but not exception text and not a set_context payload. A before_send hook covers both, and replaces the per-service discipline three services each hand-rolled differently. Also: the lookbehind excluded a leading hyphen or underscore, which are legitimately in front of a key; api-key and apiKey were not recognised alongside api_key, and x-api-key stopped being recognised when the names were normalised; the recursion had no depth bound, which a deep payload could turn into a failed request; and two except clauses captured an exception variable they never bound, raising NameError instead of the 500 they meant to return.
The follow-up from #634, done at the boundary rather than per service. Driven through an unmounted probe that reflects its payload and masks nothing itself, plus one that raises with the payload in scope, since pointing these at echo would only prove echo masks. All three fail if the mask at entry.call's exit is removed.
The exit mask is now a function every path calls, including the two that returned early. That also settles a conflict with the cancellation stack, which restructured the same branches the other way: both now write the output file on every path and mask on every path, so the two agree instead of one silently winning. Sentry got an allowlist of sections and breadcrumbs were not on it. Every INFO record becomes a breadcrumb, and they ride along on the next error event - so a key logged through a handler the filter had not reached left that way. Masking the whole event covers the sections nobody listed, and transactions get the same hook, since before_send is for errors only. The log filter went on at the first create_logger call, over the handlers that existed by then. Langfuse attaches one to the httpx logger during import, before any service module runs, and it writes to stderr, which the bridge forwards to the caller line for line. The sweep now runs at import and again once the service module is loaded, and covers handlers on other loggers rather than only root. The value pattern matched sk- followed by any hyphenated words, so sk-antelope-migration-plan came back redacted. Now that the same function masks what a service returns, that silently corrupts a caller's own data. It anchors on the prefixes providers use, or wants an unbroken run long enough not to be a name. Also drops the server's absolute path from the input-not-found message.
Events reach the caller by a third route: not the result, not the log stream, so neither of those masks sees them. Nothing puts a key in one today, which is the moment to close it rather than after something does.
Three services each stripped api_key from their Sentry context by name, in three slightly different ways, and one of them missed nested values and key-shaped strings entirely. They call the shared mask now. The stream manager is still dropped by name, because that is an object rather than data and not a secret at all. Also removes set_log_output and the filename it sets: nothing has read either since logging moved to stdout.
The regex had three comments for one pattern, and the longest recounted the two shapes I tried before this one rather than explaining the one that is there. The depth guard said the same thing twice, once beside the constant and once in its test. Also drops a phrase that named what the temp payload holds - the same thing the commit messages were careful about, missed one layer down in a public repo.
Live testing found the close handler was aborting nothing. Elysia builds a fresh wrapper object for each websocket event, so the one the close handler receives is never the one the message handler stored against - the lookup missed every time, and the child kept generating. Keyed on the underlying socket now, which is what the two events share. Nothing caught this: the run settles on its own eventually, so the only signal was a python process still alive after the socket went away. The test looks for exactly that, and closes early enough that echo has not finished by itself - a longer wait passes whether or not the fix is there, which is how the first version of it fooled me.
1 task
Masking echo took away the only test of this. The five instance-auth rows used to read the substituted value back off the response; with everything coming back "[REDACTED]" a swap that wrote the wrong value, or forwarded the caller's own, would look exactly like a correct one. applyResolvedKey is now its own exported function and asserted directly, so the substitution is checked without a service having to hand a value back to prove it. Paired with the InstanceAuth rows that pin which resolution a credential produces, that covers the ground the round trip did. Checked by breaking it both ways: forwarding the caller's credential fails two of the five, and blanking the field rather than dropping it fails one.
Contributor
|
Thank you Elias, this is great. I've added a couple of things, could you confirm if these look ok:
|
Mask sensitive values on their way out of a service
Stop a run when the client goes away
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
2 participants
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.
Short Description
Makes a failing service report a real code, type and message, instead of arriving at the client as "Unknown error".
Stacked on #630 → #629. Review those first; this branch contains them.
Implementation Details
Three ways a failure lost its own diagnosis.
A bare exit code.
bridge.tsrejected withcode. A number is not anError, so the handler downstream fell through toerror instanceof Error ? error.message : "Unknown error"and sent the client exactly that - no code, no type, and the exit code discarded. It also rejected without returning, so a non-zero exit went on to resolve as well.A failed spawn was only logged, so nothing settled the promise: poetry missing from PATH looked like a service that never answered, and the request hung until something upstream gave up.
Empty output resolved as success, sent as
event: completewith a null payload, which Lightning reports as a stream that ended without a response.Two of those empty output files came from
entry.py: three error paths returned before the output file was written, and two referenced an unbound exception variable, so a missing input file raisedNameErrorrather than reporting the missing file.ruffflags both - twoF821 Undefined name 'e'findings onmain, gone here. Every path out ofrun_servicenow goes through one write, which is what makes an empty file mean the run died rather than that it failed politely.Shape.
ApolloThrowableextendsErrorwhile implementing the existingApolloErrorinterface, so it can be thrown and still carries the envelope used everywhere else.toJSONis required:JSON.stringifyon anErroris{}, so without it the synchronous route answers with the right status and an empty body. There's a test on that.Three factories:
SUBPROCESS_FAILED(500, carries the exit code),SUBPROCESS_SPAWN_FAILED(500, never started),EMPTY_RESULT(502 - it ran and exited cleanly, what came back was unusable).The synchronous route also gains error handling, which it had none of.
bun test platform/test: 101 pass, 0 fail.ruff check services/entry.py: 26 → 24 findings, nothing new.AI Usage
Please disclose whether you've used AI in this work (it's cool, we just want to
know!):
You can read more details in our
Responsible AI Policy