Report handler panics as panics, not client disconnects

[nshalman]

Supersedes #1359

[nshalman]

a19b6f9 adds a more thorough set of test cases and confirms your analysis that std::thread::panicking() was indeed the wrong check.

48f7c1a makes the tests pass. I need to reread it a few more times to wrap my head around it and trim down the comments to a more appropriate quantity. I might be able to make the code a little more readable to my own eye as well.

The main question that this surfaces is what kind of dtrace probe you would want to fire. Reuse request_done (as sketched out in 7609e8f) or create something else for it...

I also imagine that for your programs in release builds where

[profile.release]
panic = 'abort'

that the abort would prevent the dtrace probe from actually firing? Is my mental model accurate on that?

[davepacheco]

Sorry in advance if I'm being dense but I'm confused by this version so I want to get on the same page. In terms of goals: as I understand it, if you're using Detached mode today and panic = unwind, and the request handler panics, then what you currently see is

1. an error-level log message saying handler panicked; propagating panic, followed by
2. a warning-level log message saying request handling cancelled (client disconnected), then
3. a DTrace probe reporting a 499, and finally
4. the client sees an abrupt termination (violation of HTTP; the socket presumably closes before getting a response).

Can you confirm that's your understanding?

And your goal is to change:

1. The log message about the handler panicking is okay as is.
2. The warning message about the client having disconnected is wrong and should not happen at all.
3. The DTrace probe should reflect a panic rather than a client disconnect (499).
4. We're not trying to change the observed client behavior.

Is that right, too?

In this version of the PR, it looks like the control flow for a panic is:

enter http_request_handle_wrap
- create scope guard
  - enter http_request_handle
    - spawn task and wait for it
      - task runs, panics
    - log message (1) above
    - resume panic
- catch panic
- disarm the guard, log what we want (fixes (2) and (3) above)
- resume panic (again)

The use of AssertUnwindSafe and catch_unwind() in this critical path does make me pretty nervous. But I also don't think they're necessary at all? We already know there's been a panic inside http_request_handle and we have the panic object. We don't need to resume the panic there, only to catch it again and resume it again.

It seems like the way things are factored right now, we want http_request_handle to return a tri-state of:

• successful response (Response)
• error during execution (HandlerError)
• panic during execution (with datum being the panic object)

Do we just awnt to add a variant of HandlerError for HandlerPanicked { panic_object: Box<dyn Any + Send + 'static>?

[nshalman]

Sorry in advance if I'm being dense but I'm confused by this version so I want to get on the same page. In terms of goals: as I understand it, if you're using Detached mode today and panic = unwind, and the request handler panics, then what you currently see is

1. an error-level log message saying handler panicked; propagating panic, followed by
2. a warning-level log message saying request handling cancelled (client disconnected), then
3. a DTrace probe reporting a 499, and finally
4. the client sees an abrupt termination (violation of HTTP; the socket presumably closes before getting a response).

Can you confirm that's your understanding?

While I suspect this won't stop you, just know that you never need to apologize to me for this sort of thing. Thank you for continuing to help me with this!

Yes. That four line description is indeed what got me here. In trying to solve for that one and based on your feedback on the earlier version in this PR, I am doing my best to exercise as many failure modes as possible in test cases which seems to have surfaced additional failure modes. That's why this change has gotten so big. I would love to rein it in if I can. I always prefer the lightest touch possible, but it's possible that the rigorous answer here might be verbose.

And your goal is to change:

1. The log message about the handler panicking is okay as is.
2. The warning message about the client having disconnected is wrong and should not happen at all.
3. The DTrace probe should reflect a panic rather than a client disconnect (499).
4. We're not trying to change the observed client behavior.

Is that right, too?

Yes. For this PR, yes.
To be clear. I am open to changing observed client behavior. I personally land on if the whole server isn't going to crash, we should send the user some sort of 500 error (see #1359 (comment))

But I think my personal opinion there is probably still wrong for Dropshot. I have another round of changes (per your suggestion about detecting handler panics,) that are able to distinguish between something inside the handler itself panicking vs something outside the handler panicking. In those situations I would be open to the handler itself panicking generating the 500 error, etc. But this is largely a tangent to what I think we need to accomplish in this PR.

For now I just want to address the issues identified by the test cases.

In this version of the PR, it looks like the control flow for a panic is:

enter http_request_handle_wrap
- create scope guard
  - enter http_request_handle
    - spawn task and wait for it
      - task runs, panics
    - log message (1) above
    - resume panic
- catch panic
- disarm the guard, log what we want (fixes (2) and (3) above)
- resume panic (again)

I believe you read that version of the code correctly. And if you didn't, it was probably hard to read which is its own problem. I'm starting to wonder whether my refactor of instrumentation which makes all the usdt probe points a single line each might be helpful here as it would make all the branching code blocks much shorter and easier to see... Especially since you rightly requested a usdt probe on the panic branch... I just hate scope creep and I naively thought this would be a short and easy fix.

The use of AssertUnwindSafe and catch_unwind() in this critical path does make me pretty nervous. But I also don't think they're necessary at all? We already know there's been a panic inside http_request_handle and we have the panic object. We don't need to resume the panic there, only to catch it again and resume it again.

It seems like the way things are factored right now, we want http_request_handle to return a tri-state of:

• successful response (Response)
• error during execution (HandlerError)
• panic during execution (with datum being the panic object)

Do we just want to add a variant of HandlerError for HandlerPanicked { panic_object: Box<dyn Any + Send + 'static>?

I have incorporated that into the next round of changes. It does feel right to me to be able to distinguish that case. I think that the tricky spot is that even if we do detect the handler panics and categorize them appropriately, there is still the fourth codepath of a panic outside the handler (across both Detached and CancelOnDisconnect modes) . I have wired up test cases for that, and it seems that those cases might make AssertUnwindSafe and catch_unwind() even more load-bearing rather than something we could remove.

This is where I am the most ignorant between you, me, and the LLMs. I am good at telling it to make verbose test cases and examples, and asking it to fix the bugs revealed by the tests, but I easily fell for the original std::thread::panicking() proposal... Hopefully I am improving.

Thank you for reviewing this draft. I really really appreciate it. I was originally trying to just fix that one failure mode, but I do think it's worth having the full set of tests that exercise all the failure modes we can think to throw at dropshot and to have all of them report back accurately.

I might push one or more additional drafts before getting to the next point where I am ready for your review. Feel free to ignore them until I ping you explicitly, but also feel free to review them if you have the time and interest.

[nshalman]

I think I will leave this here for now.

30f05df adds new tests but no fixes, and these new tests fail:

cargo test -p dropshot --all-features --test integration-tests -- panic_handling probes
...
failures:
    panic_handling::test_extractor_panic_reported_as_handler_panic_cancel_on_disconnect
    panic_handling::test_extractor_panic_reported_as_handler_panic_detached
    panic_handling::test_panic_outside_handler_reported_as_panic
    panic_handling::test_panic_reported_as_panic_cancel_on_disconnect
    panic_handling::test_panic_reported_as_panic_detached
    probes::test_usdt_probes_fire_with_expected_contents

With the changes in 94cf4f2 all tests pass.

The current version still uses AssertUnwindSafe/catch_unwind and I think does an okay job explaining which failure modes each one is needed for.

dropshot/dropshot/src/server.rs

Lines 1032 to 1050 in 94cf4f2

	HandlerTaskMode::CancelOnDisconnect => {
	// For CancelOnDisconnect, we run the request handler directly: if
	// the client disconnects, we will be cancelled, and therefore this
	// future will too.
	//
	// Catch a panic in the handler so that it can be reported as a
	// handler panic (see `HandlerError::Panicked`) rather than
	// unwinding through our caller. Unwind safety is not a concern
	// because the panic is resumed once it has been reported.
	match panic::AssertUnwindSafe(
	handler.handle_request(rqctx, request),
	)
	.catch_unwind()
	.await
	{
	Ok(result) => result?,
	Err(payload) => return Err(handler_panicked(payload)),
	}
	}

Experimentally replacing this catch with a plain handler.handle_request(rqctx, request).await? fails only these tests:

• panic_handling::test_panic_reported_as_panic_cancel_on_disconnect
• panic_handling::test_extractor_panic_reported_as_handler_panic_cancel_on_disconnect

dropshot/dropshot/src/server.rs

Lines 851 to 904 in 94cf4f2

	// Backstop: catch a panic escaping from anywhere in request handling
	// other than the handler itself -- e.g. a user-provided version policy,
	// or dropshot's own routing code. (Handler panics never unwind through
	// here; they come back as `HandlerError::Panicked` and are handled
	// below.) Without this, the unwind would drop the scopeguard and
	// misreport the panic as a client disconnection. Unwind safety is not
	// a concern because the panic is resumed immediately after being
	// reported.
	let caught = panic::AssertUnwindSafe(http_request_handle(
	server,
	request,
	&request_id,
	request_log.new(o!()),
	remote_addr,
	))
	.catch_unwind()
	.await;
	let maybe_response = match caught {
	Ok(maybe_response) => maybe_response,
	Err(payload) => {
	// Defuse the guard before resuming the unwind below; otherwise
	// the unwind would drop it and misreport this panic as a client
	// disconnection.
	let _ = ScopeGuard::into_inner(on_disconnect);
	let latency_us = start_time.elapsed().as_micros();
	// `&*` is load-bearing: `&payload` would coerce the `Box`
	// itself into the `dyn Any` and every downcast would miss.
	let message = panic_message(&*payload);
	error!(request_log, "request handling panicked (outside the handler)";
	"latency_us" => latency_us,
	"panic_message" => message,
	);
	// Fire request-done so that every request-start is paired with
	// a request-done even when the request ends in a panic.
	#[cfg(feature = "usdt-probes")]
	probes::request__done!(|| {
	crate::dtrace::ResponseInfo {
	id: request_id.clone(),
	local_addr,
	remote_addr,
	// 0 is not a valid HTTP status code; it conventionally
	// means "no response was received".
	status_code: 0,
	message: format!(
	"request handling panicked (outside the handler): \
	{message}"
	),
	}
	});
	panic::resume_unwind(payload);
	}
	};

Experimententally removing this catch (a plain .await on http_request_handle) fails this test:

• panic_handling::test_panic_outside_handler_reported_as_panic

I went down a follow up rabbit hole with the LLM to try to remove AssertUnwindSafe... Not sure of the value.

I tasked the LLM with finding a solution that didn't involve AssertUnwindSafe and catch_unwind and it came up with something that passes the existing test suite at the cost of:

• CancelOnDisconnect pays one tokio::spawn per request (previously zero), and its cancellation becomes abort() — effective at the task's next await point, with destructors running on a runtime worker — instead of synchronous in-place drop. No test can tell the difference, but it is a real semantic shift a consumer could conceivably observe.
• Detached mode now detaches the whole pipeline, not just the handler: a disconnect during version-policy evaluation no longer cancels that work. (Spawn count in Detached is unchanged — the handler spawn simply became the pipeline spawn.)
• The breadcrumb "handler panicked; relaying panic" is now gated on mode solely to satisfy the existing absence-assert in the CancelOnDisconnect test — under this design both modes relay identically, so that assert becomes vestigial and would deserve removal if this lands.
• One AtomicBool of novel mechanism, versus the well-worn catch-report-rethrow idiom.

One thing in particular stuck out (aside from the cost and drastically rewriting things):

No test can tell the difference, but it is a real semantic shift a consumer could conceivably observe.

That comment struck me so pushed on that detail and got it to write a test that could tell the difference.

What I ended up with is this:
(Compared against this PR as it stands) nshalman/dropshot@panic-isnt-disconnect...panic-isnt-disconnect-task-boundary
(Compared against main) main...nshalman:dropshot:panic-isnt-disconnect-task-boundary

Yes — there is one crisp observable: when a cancelled handler's destructors run relative to the disconnect being reported. In the committed code, CancelOnDisconnect drops the handler future in place, synchronously, inside the same frame that then fires the disconnect scopeguard — Rust guarantees the awaited future's locals drop before the earlier-declared guard. So by the time "request handling cancelled" is logged, the handler's destructors have provably finished. In the prototype, abort() merely requests cancellation, the guard logs immediately, and the destructors run later on another task. A handler local with a deliberately slow Drop makes the ordering visible. Let me write it and prove it distinguishes the two implementations.

I am way out of my depth here. I don't know how important the ordering of the destructors running relative to the disconnect being reported is. Hopefully not very since there's currently no test covering it...

I would genuinely love to just run away from this, but I can't unsee the test failures...