From 30f05df37f970775298d76133331967d0968ac53 Mon Sep 17 00:00:00 2001 From: Nahum Shalman Date: Fri, 14 Aug 2026 13:42:37 -0400 Subject: [PATCH 1/2] add tests covering every way a request can end A handler panic, an extractor panic, a panic elsewhere in request handling (a version policy), a mid-handler client disconnect, and server teardown caused by a panic elsewhere in the process -- in both handler task modes where the mode matters. The tests distinguish panics on either side of the handler boundary: a panic in the handler or its extractors must be reported as "request handler panicked", and a panic anywhere else in request handling as "request handling panicked (outside the handler)"; neither is ever conflated with a client disconnection. The same contract is pinned at the DTrace level by a dtrace(8)-verified test of the USDT probe payloads, covering every terminal shape of a request-done record: 200, 400, 499 (client disconnect), and status code 0 ("no response was received") with the panic message for both kinds of panic. It runs where dtrace and the privileges to use it exist (DROPSHOT_DTRACE_TEST=require turns its skip into a failure). Also an example, panic-handler, for reproducing the reporting interactively: it prints its pid and a dtrace one-liner for watching the request-done probe, makes a request to its own panicking endpoint, and reports exactly what the client observed on the wire. Run it at this commit and at the next to compare the sequences directly. The panic tests fail until the next commit: a panic escaping request handling is currently misreported as a client disconnection -- in the log, and in the request-done probe as a 499. The success, error response, and true-disconnect cases (including the 499 probe record) pass either way: that behavior predates the fix and must not change. Co-Authored-By: Claude Fable 5 --- dropshot/examples/panic-handler.rs | 126 ++++ dropshot/tests/integration-tests/main.rs | 2 + .../tests/integration-tests/panic_handling.rs | 625 ++++++++++++++++++ dropshot/tests/integration-tests/probes.rs | 451 +++++++++++++ 4 files changed, 1204 insertions(+) create mode 100644 dropshot/examples/panic-handler.rs create mode 100644 dropshot/tests/integration-tests/panic_handling.rs create mode 100644 dropshot/tests/integration-tests/probes.rs diff --git a/dropshot/examples/panic-handler.rs b/dropshot/examples/panic-handler.rs new file mode 100644 index 00000000..d29bd458 --- /dev/null +++ b/dropshot/examples/panic-handler.rs @@ -0,0 +1,126 @@ +// Copyright 2026 Oxide Computer Company + +//! Reproduces, interactively, how Dropshot reports a request handler that +//! panics: what appears in the log, what the request-done DTrace probe +//! reports, and what the client observes on the wire. +//! +//! Run it with the probes compiled in: +//! +//! ```text +//! cargo run --example panic-handler --features usdt-probes +//! ``` +//! +//! then follow the printed instructions: optionally attach dtrace with the +//! printed one-liner, press Enter, and watch the sequence for a request to +//! `/panic`. The server stays up afterward for further poking with curl. +//! +//! The log goes to stderr at debug level so that every message involved in +//! the sequence is visible, including debug-level breadcrumbs. + +use dropshot::ApiDescription; +use dropshot::ConfigLogging; +use dropshot::ConfigLoggingLevel; +use dropshot::HttpError; +use dropshot::HttpResponseOk; +use dropshot::ProbeRegistration; +use dropshot::RequestContext; +use dropshot::ServerBuilder; +use dropshot::endpoint; +use tokio::io::AsyncReadExt; +use tokio::io::AsyncWriteExt; + +#[endpoint { + method = GET, + path = "/panic", +}] +async fn example_panic( + _rqctx: RequestContext<()>, +) -> Result, HttpError> { + panic!("oh no, a panic!"); +} + +#[endpoint { + method = GET, + path = "/ok", +}] +async fn example_ok( + _rqctx: RequestContext<()>, +) -> Result, HttpError> { + Ok(HttpResponseOk(1)) +} + +#[tokio::main] +async fn main() -> Result<(), String> { + let config_logging = + ConfigLogging::StderrTerminal { level: ConfigLoggingLevel::Debug }; + let log = config_logging + .to_logger("panic-handler-example") + .map_err(|error| format!("failed to create logger: {}", error))?; + + let mut api = ApiDescription::new(); + api.register(example_panic).unwrap(); + api.register(example_ok).unwrap(); + + let server = ServerBuilder::new(api, (), log) + .start() + .map_err(|error| format!("failed to start server: {}", error))?; + let addr = server.local_addr(); + let pid = std::process::id(); + + println!(); + println!("server: http://{}", addr); + println!("pid: {}", pid); + match server.probe_registration() { + ProbeRegistration::Succeeded => println!("probes: registered"), + other => println!( + "probes: NOT registered ({:?}); \ + rebuild with --features usdt-probes", + other + ), + } + println!(); + println!("to watch the request-done probe, run (in another terminal):"); + println!(); + println!( + " dtrace -q -p {} -n 'dropshot$target:::request-done \ + {{ printf(\"%s\\n\", copyinstr(arg0)); }}'", + pid + ); + println!(); + println!( + "press Enter to make a request to /panic \ + (attach dtrace first if you want the probe) ..." + ); + tokio::task::spawn_blocking(|| { + let mut line = String::new(); + let _ = std::io::stdin().read_line(&mut line); + }) + .await + .unwrap(); + + // Make the request over a raw TCP connection so that exactly what the + // client observes on the wire can be reported. + let mut stream = tokio::net::TcpStream::connect(addr) + .await + .map_err(|error| format!("failed to connect: {}", error))?; + stream + .write_all(b"GET /panic HTTP/1.1\r\nhost: example\r\n\r\n") + .await + .map_err(|error| format!("failed to send request: {}", error))?; + let mut buf = Vec::new(); + let result = stream.read_to_end(&mut buf).await; + println!(); + println!("the client's view of GET /panic:"); + println!(" response bytes received: {}", buf.len()); + match result { + Ok(_) => println!(" connection closed (clean EOF), no response"), + Err(error) => println!(" connection aborted: {}", error), + } + + println!(); + println!("server still running; things to try:"); + println!(" curl -v http://{}/panic", addr); + println!(" curl -v http://{}/ok", addr); + println!("^C to exit"); + server.await +} diff --git a/dropshot/tests/integration-tests/main.rs b/dropshot/tests/integration-tests/main.rs index fe10b99a..22a302fb 100644 --- a/dropshot/tests/integration-tests/main.rs +++ b/dropshot/tests/integration-tests/main.rs @@ -21,7 +21,9 @@ mod multipart; mod openapi; mod pagination; mod pagination_schema; +mod panic_handling; mod path_names; +mod probes; mod starter; mod streaming; mod tls; diff --git a/dropshot/tests/integration-tests/panic_handling.rs b/dropshot/tests/integration-tests/panic_handling.rs new file mode 100644 index 00000000..c4296d16 --- /dev/null +++ b/dropshot/tests/integration-tests/panic_handling.rs @@ -0,0 +1,625 @@ +// Copyright 2026 Oxide Computer Company + +//! Test cases for how the ways a request can end are reported, with +//! particular attention to panicking handlers. +//! +//! A request that reaches a handler can end in one of these ways: +//! +//! 1. the handler produces a response (success or error): reported as +//! "request completed"; +//! 2. the client disconnects first, in `HandlerTaskMode::CancelOnDisconnect`: +//! the handler future is cancelled, reported as "request handling +//! cancelled (client disconnected)"; +//! 3. the client disconnects first, in `HandlerTaskMode::Detached`: reported +//! as in (2), but the handler runs to completion, additionally reported +//! as "request completed after handler was already cancelled"; +//! 4. the handler -- including its extractors, which run on the handler's +//! side of the boundary -- panics (in either task mode): the panic +//! propagates and the connection is aborted with no response; reported +//! as "request handler panicked" and NOT as a client disconnection; +//! 5. something in request handling *other than* the handler -- a +//! user-provided version policy, dropshot's own routing -- panics: the +//! connection is aborted as in (4), but reported as "request handling +//! panicked (outside the handler)", distinguishing a broken handler +//! from a bug elsewhere; +//! 6. the server is torn down with the request in flight -- including +//! teardown caused by a panic elsewhere in the process (e.g. a failing +//! test in a consumer's test suite that drops its runtime while +//! unwinding). This is a cancellation, and it must be reported as in +//! (2), NOT as a panic, no matter why teardown happened. +//! +//! These tests pin all six, so that changes to how panics are detected can +//! demonstrate they distinguish the cases correctly. +//! +//! The contract, in short: "request handling cancelled (client +//! disconnected)" means the client went away; the two panic reports mean +//! the server software is broken, and name which side of the +//! handler boundary is at fault. None of the three are ever conflated. +//! `panic_reported_as_panic` (a handler panic), +//! `extractor_panic_reported_as_handler_panic` (an extractor panic), and +//! `test_panic_outside_handler_reported_as_panic` (a version policy panic) +//! demonstrate the boundary side by side; in every case the +//! "panic_message" property identifies the broken code. + +use camino::{Utf8Path, Utf8PathBuf}; +use dropshot::test_util::{ + BunyanLogRecord, ClientTestContext, log_file_for_test, read_bunyan_log, +}; +use dropshot::{ + ApiDescription, Body, ConfigDropshot, ConfigLogging, ConfigLoggingIfExists, + ConfigLoggingLevel, DynamicVersionPolicy, HandlerTaskMode, HttpError, + HttpResponseOk, Query, RequestContext, ServerBuilder, VersionPolicy, + endpoint, +}; +use http::{Method, StatusCode}; +use hyper::Request; +use semver::Version; +use slog::Logger; +use std::sync::Arc; +use std::sync::atomic::{AtomicBool, Ordering}; +use std::time::{Duration, Instant}; +use tokio::io::{AsyncReadExt, AsyncWriteExt}; + +/// How long the `/slow` handler takes. Long enough that a client can +/// reliably disconnect (or tear the server down) mid-handler; short enough +/// to keep the tests quick. +const SLOW_HANDLER_DURATION: Duration = Duration::from_millis(1000); + +/// How long to wait for an expected event before declaring failure. +const POLL_TIMEOUT: Duration = Duration::from_secs(15); + +/// State shared with the `/slow` handler so tests can observe its progress. +#[derive(Default)] +struct TestState { + slow_started: AtomicBool, + slow_completed: AtomicBool, +} + +fn api() -> ApiDescription> { + let mut api = ApiDescription::new(); + api.register(handler_panic).unwrap(); + api.register(handler_panic_extractor).unwrap(); + api.register(handler_ok).unwrap(); + api.register(handler_slow).unwrap(); + api +} + +#[endpoint { + method = GET, + path = "/panic", +}] +async fn handler_panic( + _rqctx: RequestContext>, +) -> Result, HttpError> { + panic!("oh no, a panic!"); +} + +/// A query type whose deserialization panics: a stand-in for a bug in an +/// extractor. Extractors run on the handler's side of the reporting +/// boundary (inside `handle_request`), so this panic must be reported as a +/// handler panic. +#[derive(schemars::JsonSchema)] +struct PanickyQuery { + #[allow(dead_code)] + x: String, +} + +impl<'de> serde::Deserialize<'de> for PanickyQuery { + fn deserialize(_deserializer: D) -> Result + where + D: serde::Deserializer<'de>, + { + panic!("deliberate panic in extractor"); + } +} + +#[endpoint { + method = GET, + path = "/panic-extractor", +}] +async fn handler_panic_extractor( + _rqctx: RequestContext>, + _query: Query, +) -> Result, HttpError> { + unreachable!("the extractor panics before the handler body runs"); +} + +#[endpoint { + method = GET, + path = "/ok", +}] +async fn handler_ok( + _rqctx: RequestContext>, +) -> Result, HttpError> { + Ok(HttpResponseOk(1)) +} + +#[endpoint { + method = GET, + path = "/slow", +}] +async fn handler_slow( + rqctx: RequestContext>, +) -> Result, HttpError> { + let state = rqctx.context(); + state.slow_started.store(true, Ordering::SeqCst); + tokio::time::sleep(SLOW_HANDLER_DURATION).await; + state.slow_completed.store(true, Ordering::SeqCst); + Ok(HttpResponseOk(2)) +} + +/// Creates a file-based logger so that tests can verify what was reported. +/// Debug level, so that debug-level breadcrumbs (like Detached mode's +/// "handler panicked; relaying panic") are observable too. +fn file_logger(test_name: &str) -> (Utf8PathBuf, slog::Logger) { + let log_path = log_file_for_test(test_name); + let config_logging = ConfigLogging::File { + level: ConfigLoggingLevel::Debug, + path: log_path.clone(), + if_exists: ConfigLoggingIfExists::Fail, + }; + let log = config_logging.to_logger(test_name).unwrap(); + (log_path, log) +} + +fn log_has(records: &[BunyanLogRecord], msg: &str) -> bool { + records.iter().any(|r| r.msg == msg) +} + +/// The report for a panic in the handler (or its extractors). +const HANDLER_PANIC: &str = "request handler panicked"; +/// The report for a panic anywhere else in request handling. +const OTHER_PANIC: &str = "request handling panicked (outside the handler)"; +/// The report for a client disconnect (or server teardown) mid-request. +const DISCONNECT: &str = "request handling cancelled (client disconnected)"; + +/// Returns the "panic_message" property of the log record whose message is +/// `msg`, if any. (`BunyanLogRecord` does not carry custom properties, so +/// this parses the raw log.) +fn logged_panic_message(log_path: &Utf8Path, msg: &str) -> Option { + std::fs::read_to_string(log_path) + .unwrap() + .lines() + .filter_map(|line| serde_json::from_str::(line).ok()) + .find(|record| record["msg"] == msg) + .and_then(|record| record["panic_message"].as_str().map(str::to_string)) +} + +/// Reads the bunyan log until `pred` is satisfied or `POLL_TIMEOUT` elapses +/// (the slog-async drain writes asynchronously), returning the records last +/// read. Only called after the last `Logger` clone has been dropped, which +/// joins the drain thread; the poll loop is belt-and-braces. +fn wait_for_log( + log_path: &Utf8Path, + pred: impl Fn(&[BunyanLogRecord]) -> bool, +) -> Vec { + let deadline = Instant::now() + POLL_TIMEOUT; + loop { + let records = read_bunyan_log(log_path.as_std_path()); + if pred(&records) || Instant::now() >= deadline { + return records; + } + std::thread::sleep(Duration::from_millis(20)); + } +} + +/// Polls until `flag` becomes true, panicking with `failure` after +/// `POLL_TIMEOUT`. +async fn wait_for_flag(flag: &AtomicBool, failure: &str) { + let deadline = Instant::now() + POLL_TIMEOUT; + while !flag.load(Ordering::SeqCst) { + assert!(Instant::now() < deadline, "{}", failure); + tokio::time::sleep(Duration::from_millis(10)).await; + } +} + +/// Issues a GET for `path` over a raw TCP connection, without waiting for a +/// response, returning the connection. Used where an HTTP client's +/// lifecycle would get in the way: to observe an aborted connection, or to +/// disconnect mid-request by dropping the stream. +async fn raw_get( + addr: std::net::SocketAddr, + path: &str, +) -> tokio::net::TcpStream { + let mut stream = tokio::net::TcpStream::connect(addr).await.unwrap(); + stream + .write_all( + format!("GET {} HTTP/1.1\r\nhost: test\r\n\r\n", path).as_bytes(), + ) + .await + .unwrap(); + stream +} + +/// Case 4: a panicking handler aborts the connection with no response; the +/// panic is reported as a panic, not as a client disconnect, and the server +/// remains usable. +async fn panic_reported_as_panic(test_name: &str, task_mode: HandlerTaskMode) { + let (log_path, log) = file_logger(test_name); + let server = ServerBuilder::new(api(), Default::default(), log.clone()) + .config(ConfigDropshot { + default_handler_task_mode: task_mode, + ..Default::default() + }) + .start() + .unwrap(); + + // Depending on platform and timing, the read may end with a clean EOF + // or a connection-reset error. What matters is that no response bytes + // were written. + let mut stream = raw_get(server.local_addr(), "/panic").await; + let mut buf = Vec::new(); + let _ = stream.read_to_end(&mut buf).await; + assert!( + buf.is_empty(), + "expected no response bytes, got: {:?}", + String::from_utf8_lossy(&buf) + ); + + let client = ClientTestContext::new(server.local_addr(), log.clone()); + client + .make_request_no_body(Method::GET, "/ok", StatusCode::OK) + .await + .expect("server should still be usable after a handler panic"); + + server.close().await.unwrap(); + drop(client); + drop(log); + let records = wait_for_log(&log_path, |r| log_has(r, HANDLER_PANIC)); + assert!( + log_has(&records, HANDLER_PANIC), + "expected the panic to be reported as a handler panic" + ); + assert!( + !log_has(&records, OTHER_PANIC), + "a handler panic must be attributed to the handler, not reported \ + as a panic outside it" + ); + assert!( + !records.iter().any(|r| r.msg.contains("client disconnected")), + "a handler panic must not be reported as a client disconnect" + ); + // Case 1: the follow-up request to `/ok` is reported as completed. + assert!( + log_has(&records, "request completed"), + "expected the follow-up request to be reported as completed" + ); + // Detached mode relays the panic out of the handler task; check for its + // breadcrumb so a regression can't silently reroute one mode's panics + // through the other's path. + match task_mode { + HandlerTaskMode::Detached => assert!( + log_has(&records, "handler panicked; relaying panic"), + "expected the panic to be relayed from the detached handler task" + ), + HandlerTaskMode::CancelOnDisconnect => assert!( + !log_has(&records, "handler panicked; relaying panic"), + "in CancelOnDisconnect mode the panic is caught around the \ + handler call itself, not relayed from a detached task" + ), + } + // The report identifies the broken code: the handler's own panic + // message is carried in the "panic_message" property. + let panic_message = logged_panic_message(&log_path, HANDLER_PANIC) + .expect("expected a panic_message property on the panic report"); + assert!( + panic_message.contains("oh no, a panic!"), + "expected the handler's panic message, got: {:?}", + panic_message + ); + std::fs::remove_file(&log_path).unwrap(); +} + +/// A version policy that panics while extracting the version: a stand-in +/// for a bug anywhere in request handling outside the handler itself +/// (routing, extractors, and the like). +#[derive(Debug)] +struct PanickyVersionPolicy; + +impl DynamicVersionPolicy for PanickyVersionPolicy { + fn request_extract_version( + &self, + _request: &Request, + _log: &Logger, + ) -> Result { + panic!("deliberate panic in version policy"); + } +} + +/// Case 5: a panic in request handling outside the handler aborts the +/// connection just like a handler panic, but is reported distinctly, as +/// "request handling panicked (outside the handler)" -- so a bug in (say) +/// a version policy is not blamed on the endpoint handler. The version +/// policy runs before the handler is even looked up, so this is +/// independent of the handler task mode. +#[tokio::test] +async fn test_panic_outside_handler_reported_as_panic() { + let (log_path, log) = + file_logger("panic_outside_handler_reported_as_panic"); + let server = ServerBuilder::new(api(), Default::default(), log) + .version_policy(VersionPolicy::Dynamic(Box::new(PanickyVersionPolicy))) + .start() + .unwrap(); + + let mut stream = raw_get(server.local_addr(), "/ok").await; + let mut buf = Vec::new(); + let _ = stream.read_to_end(&mut buf).await; + assert!( + buf.is_empty(), + "expected no response bytes, got: {:?}", + String::from_utf8_lossy(&buf) + ); + + server.close().await.unwrap(); + let records = wait_for_log(&log_path, |r| log_has(r, OTHER_PANIC)); + assert!( + log_has(&records, OTHER_PANIC), + "expected the panic to be reported as a panic outside the handler" + ); + assert!( + !log_has(&records, HANDLER_PANIC), + "a panic outside the handler must not be blamed on the handler" + ); + assert!( + !records.iter().any(|r| r.msg.contains("client disconnected")), + "a panic must not be reported as a client disconnect" + ); + let panic_message = logged_panic_message(&log_path, OTHER_PANIC) + .expect("expected a panic_message property on the panic report"); + assert!( + panic_message.contains("version policy"), + "expected the version policy's panic message, got: {:?}", + panic_message + ); + std::fs::remove_file(&log_path).unwrap(); +} + +#[tokio::test] +async fn test_panic_reported_as_panic_detached() { + panic_reported_as_panic( + "panic_reported_as_panic_detached", + HandlerTaskMode::Detached, + ) + .await; +} + +#[tokio::test] +async fn test_panic_reported_as_panic_cancel_on_disconnect() { + panic_reported_as_panic( + "panic_reported_as_panic_cancel_on_disconnect", + HandlerTaskMode::CancelOnDisconnect, + ) + .await; +} + +/// Case 4, via an extractor: extractors run on the handler's side of the +/// reporting boundary (inside the handler dispatch, in both task modes), +/// so a panicking extractor is reported as a handler panic. +async fn extractor_panic_reported_as_handler_panic( + test_name: &str, + task_mode: HandlerTaskMode, +) { + let (log_path, log) = file_logger(test_name); + let server = ServerBuilder::new(api(), Default::default(), log) + .config(ConfigDropshot { + default_handler_task_mode: task_mode, + ..Default::default() + }) + .start() + .unwrap(); + + let mut stream = raw_get(server.local_addr(), "/panic-extractor").await; + let mut buf = Vec::new(); + let _ = stream.read_to_end(&mut buf).await; + assert!( + buf.is_empty(), + "expected no response bytes, got: {:?}", + String::from_utf8_lossy(&buf) + ); + + server.close().await.unwrap(); + let records = wait_for_log(&log_path, |r| log_has(r, HANDLER_PANIC)); + assert!( + log_has(&records, HANDLER_PANIC), + "expected an extractor panic to be reported as a handler panic" + ); + assert!( + !log_has(&records, OTHER_PANIC), + "an extractor panic belongs to the handler, not to the rest of \ + request handling" + ); + assert!( + !records.iter().any(|r| r.msg.contains("client disconnected")), + "an extractor panic must not be reported as a client disconnect" + ); + let panic_message = logged_panic_message(&log_path, HANDLER_PANIC) + .expect("expected a panic_message property on the panic report"); + assert!( + panic_message.contains("deliberate panic in extractor"), + "expected the extractor's panic message, got: {:?}", + panic_message + ); + std::fs::remove_file(&log_path).unwrap(); +} + +#[tokio::test] +async fn test_extractor_panic_reported_as_handler_panic_detached() { + extractor_panic_reported_as_handler_panic( + "extractor_panic_reported_as_handler_panic_detached", + HandlerTaskMode::Detached, + ) + .await; +} + +#[tokio::test] +async fn test_extractor_panic_reported_as_handler_panic_cancel_on_disconnect() { + extractor_panic_reported_as_handler_panic( + "extractor_panic_reported_as_handler_panic_cancel_on_disconnect", + HandlerTaskMode::CancelOnDisconnect, + ) + .await; +} + +/// Cases 2 and 3: a mid-handler client disconnect is reported as a client +/// disconnect (never as a panic); in `Detached` mode the handler +/// additionally runs to completion, and in `CancelOnDisconnect` mode it is +/// cancelled. +async fn disconnect_reported_as_disconnect( + test_name: &str, + task_mode: HandlerTaskMode, +) { + let (log_path, log) = file_logger(test_name); + let state = Arc::new(TestState::default()); + let server = ServerBuilder::new(api(), state.clone(), log.clone()) + .config(ConfigDropshot { + default_handler_task_mode: task_mode, + ..Default::default() + }) + .start() + .unwrap(); + + // Connect, get the handler running, then disconnect. + let stream = raw_get(server.local_addr(), "/slow").await; + wait_for_flag(&state.slow_started, "handler never started").await; + drop(stream); + + // Observe the handler's fate through the shared state; the log is + // examined only after teardown. + match task_mode { + HandlerTaskMode::Detached => { + wait_for_flag( + &state.slow_completed, + "detached handler never completed", + ) + .await; + } + HandlerTaskMode::CancelOnDisconnect => { + // Give the handler its full duration (and margin) to show that + // it never completes. + tokio::time::sleep(SLOW_HANDLER_DURATION * 2).await; + assert!( + !state.slow_completed.load(Ordering::SeqCst), + "handler should have been cancelled by the disconnect" + ); + } + } + + server.close().await.unwrap(); + drop(log); + let records = wait_for_log(&log_path, |r| log_has(r, DISCONNECT)); + let messages = records.iter().map(|r| &r.msg).collect::>(); + assert!( + log_has(&records, DISCONNECT), + "expected a client disconnect to be reported; log: {:?}", + messages + ); + if task_mode == HandlerTaskMode::Detached { + assert!( + log_has( + &records, + "request completed after handler was already cancelled", + ), + "expected the detached handler's completion to be reported; \ + log: {:?}", + messages + ); + } + assert!( + !log_has(&records, HANDLER_PANIC) && !log_has(&records, OTHER_PANIC), + "a client disconnect must not be reported as a panic; log: {:?}", + messages + ); + std::fs::remove_file(&log_path).unwrap(); +} + +#[tokio::test] +async fn test_disconnect_reported_as_disconnect_detached() { + disconnect_reported_as_disconnect( + "disconnect_reported_as_disconnect_detached", + HandlerTaskMode::Detached, + ) + .await; +} + +#[tokio::test] +async fn test_disconnect_reported_as_disconnect_cancel_on_disconnect() { + disconnect_reported_as_disconnect( + "disconnect_reported_as_disconnect_cancel_on_disconnect", + HandlerTaskMode::CancelOnDisconnect, + ) + .await; +} + +/// Case 6: tearing the server down while a request is in flight is a +/// cancellation, and must be reported as one even when the teardown is +/// caused by a panic elsewhere in the process. Concretely: a consumer's +/// test creates a Dropshot server, makes a request, and then fails +/// (panics), dropping its runtime -- and with it the server and the +/// in-flight request -- while the thread is unwinding. The handler did +/// not panic, and must not be reported as having panicked. +fn teardown_during_external_panic(test_name: &str, task_mode: HandlerTaskMode) { + let (log_path, log) = file_logger(test_name); + + let state = Arc::new(TestState::default()); + let thread_state = state.clone(); + let thread = std::thread::spawn(move || { + let rt = tokio::runtime::Builder::new_current_thread() + .enable_all() + .build() + .unwrap(); + rt.block_on(async move { + let server = ServerBuilder::new(api(), thread_state.clone(), log) + .config(ConfigDropshot { + default_handler_task_mode: task_mode, + ..Default::default() + }) + .start() + .unwrap(); + + // Get a request in flight and its handler running. + let _stream = raw_get(server.local_addr(), "/slow").await; + wait_for_flag(&thread_state.slow_started, "handler never started") + .await; + + // The consumer's own code fails. Unwinding drops the runtime, + // tearing down the server and the in-flight request. + panic!("deliberate panic external to any handler"); + }); + }); + assert!(thread.join().is_err(), "the external panic should propagate"); + + let records = wait_for_log(&log_path, |r| { + log_has(r, DISCONNECT) + || log_has(r, HANDLER_PANIC) + || log_has(r, OTHER_PANIC) + }); + assert!( + !log_has(&records, HANDLER_PANIC) && !log_has(&records, OTHER_PANIC), + "a request cancelled by server teardown must not be reported as a \ + panic (nothing in request handling panicked); log: {:?}", + records.iter().map(|r| &r.msg).collect::>() + ); + assert!( + log_has(&records, DISCONNECT), + "expected the torn-down request to be reported as cancelled; \ + log: {:?}", + records.iter().map(|r| &r.msg).collect::>() + ); + std::fs::remove_file(&log_path).unwrap(); +} + +#[test] +fn test_teardown_during_external_panic_detached() { + teardown_during_external_panic( + "teardown_during_external_panic_detached", + HandlerTaskMode::Detached, + ); +} + +#[test] +fn test_teardown_during_external_panic_cancel_on_disconnect() { + teardown_during_external_panic( + "teardown_during_external_panic_cancel_on_disconnect", + HandlerTaskMode::CancelOnDisconnect, + ); +} diff --git a/dropshot/tests/integration-tests/probes.rs b/dropshot/tests/integration-tests/probes.rs new file mode 100644 index 00000000..ca43de44 --- /dev/null +++ b/dropshot/tests/integration-tests/probes.rs @@ -0,0 +1,451 @@ +// Copyright 2026 Oxide Computer Company + +//! Test that the USDT probes fire with the expected contents, verified by +//! running the real `dtrace(8)` against our own process. +//! +//! One dtrace session observes every terminal shape of a request-done +//! record: a success (200), an error response (400), a mid-handler client +//! disconnect (the non-standard 499), a handler panic (the sentinel 0, "no +//! response was received", with the panic message), and -- on a second +//! server in the same process, since its version policy panics for every +//! request -- a panic outside the handler (0 again, with a message +//! attributing the panic to request handling rather than the handler). +//! Every request-start is paired with exactly one request-done. +//! +//! This can only work where dtrace exists and we have the privileges to use +//! it (e.g. as root, or in an illumos zone with the `dtrace_user` privilege +//! and friends). Anywhere else -- including typical CI -- the test prints +//! why it is being skipped and passes vacuously. Set the environment +//! variable `DROPSHOT_DTRACE_TEST=require` to turn those skips into failures +//! on hosts where the test is expected to run for real. +//! +//! A note on plumbing: dtrace's stdout is fully buffered when it's a pipe, +//! so record output cannot be streamed reliably. Instead, once the requests +//! have been made (and dtrace's principal buffer given a switchrate's grace +//! to be consumed), dtrace is stopped with SIGTERM -- which it handles +//! gracefully, flushing everything on exit -- and its complete output is +//! collected then. The `BEGIN { READY }` marker is the exception: it is +//! emitted during dtrace startup, where it does reach the pipe promptly, so +//! it serves to detect successful attachment (and, by its absence, missing +//! privileges). +//! +//! Other tests in this process may fire the same probes concurrently (under +//! plain `cargo test`; nextest runs each test in its own process), so +//! everything observed here is filtered down to this test's server by its +//! local address and request ids. + +use dropshot::test_util::ClientTestContext; +use dropshot::{ + ApiDescription, Body, DynamicVersionPolicy, HttpError, HttpResponseOk, + ProbeRegistration, RequestContext, ServerBuilder, VersionPolicy, endpoint, +}; +use http::{Method, StatusCode}; +use hyper::Request; +use semver::Version; +use slog::Logger; +use std::collections::HashMap; +use std::process::Stdio; +use std::sync::atomic::{AtomicBool, Ordering}; +use std::time::{Duration, Instant}; +use tokio::io::{AsyncBufReadExt, AsyncReadExt, AsyncWriteExt, BufReader}; + +fn api() -> ApiDescription<()> { + let mut api = ApiDescription::new(); + api.register(probe_ok).unwrap(); + api.register(probe_fail).unwrap(); + api.register(probe_panic).unwrap(); + api.register(probe_slow).unwrap(); + api +} + +#[endpoint { + method = GET, + path = "/ok", +}] +async fn probe_ok( + _rqctx: RequestContext<()>, +) -> Result, HttpError> { + Ok(HttpResponseOk(1)) +} + +#[endpoint { + method = GET, + path = "/fail", +}] +async fn probe_fail( + _rqctx: RequestContext<()>, +) -> Result, HttpError> { + Err(HttpError::for_bad_request(None, "bad request".to_string())) +} + +#[endpoint { + method = GET, + path = "/panic", +}] +async fn probe_panic( + _rqctx: RequestContext<()>, +) -> Result, HttpError> { + panic!("deliberate panic"); +} + +/// Signals that the `/slow` handler is running, so the test can disconnect +/// mid-handler. (A static is fine: only the one dtrace test uses `/slow`.) +static SLOW_STARTED: AtomicBool = AtomicBool::new(false); + +#[endpoint { + method = GET, + path = "/slow", +}] +async fn probe_slow( + _rqctx: RequestContext<()>, +) -> Result, HttpError> { + SLOW_STARTED.store(true, Ordering::SeqCst); + tokio::time::sleep(Duration::from_secs(1)).await; + Ok(HttpResponseOk(2)) +} + +/// A version policy that panics while extracting the version: a stand-in +/// for a bug in request handling outside the handler. It runs before +/// routing, so a server using it panics for every request. +#[derive(Debug)] +struct PanickyVersionPolicy; + +impl DynamicVersionPolicy for PanickyVersionPolicy { + fn request_extract_version( + &self, + _request: &Request, + _log: &Logger, + ) -> Result { + panic!("deliberate panic in version policy"); + } +} + +/// Skips the test (or fails it, if `DROPSHOT_DTRACE_TEST=require`). +fn skip(reason: &str) { + if std::env::var("DROPSHOT_DTRACE_TEST").as_deref() == Ok("require") { + panic!( + "DROPSHOT_DTRACE_TEST=require but the dtrace test cannot \ + run: {}", + reason + ); + } + eprintln!("skipping dtrace probe test: {}", reason); +} + +const DTRACE_PROGRAM: &str = r#" +BEGIN { printf("READY\n"); } +dropshot$target:::request-start { printf("START %s\n", copyinstr(arg0)); } +dropshot$target:::request-done { printf("DONE %s\n", copyinstr(arg0)); } +"#; + +/// Sifts dtrace output lines into this test's request-start records (keyed +/// by path) and request-done records (keyed by request id), keeping only +/// records for the server at `local_addr` (other tests in this process fire +/// the same probes). +/// +/// usdt serializes each probe argument wrapped in the result of its +/// serialization, so the payload proper is nested under an "ok" key (and +/// "err" would carry a serialization error message). Unwrap that envelope, +/// tolerating its absence in case usdt ever drops it. +fn sift_records( + lines: &[String], + local_addr: &str, +) -> (HashMap, HashMap) { + let unwrap_envelope = |mut record: serde_json::Value| { + assert!( + record.get("err").is_none(), + "probe argument failed to serialize: {}", + record["err"] + ); + match record.get_mut("ok") { + Some(inner) => inner.take(), + None => record, + } + }; + let mut starts = HashMap::new(); + let mut dones = HashMap::new(); + for line in lines { + if let Some(json) = line.strip_prefix("START ") { + let record = unwrap_envelope(serde_json::from_str(json).unwrap()); + if record["local_addr"] == local_addr { + let path = record["path"].as_str().unwrap().to_string(); + starts.insert(path, record); + } + } else if let Some(json) = line.strip_prefix("DONE ") { + let record = unwrap_envelope(serde_json::from_str(json).unwrap()); + if record["local_addr"] == local_addr { + let id = record["id"].as_str().unwrap().to_string(); + dones.insert(id, record); + } + } + } + (starts, dones) +} + +/// Checks the record sifting (in particular the "ok" envelope handling) +/// against verbatim output captured from a real dtrace run, so that this +/// much is verified even where dtrace itself is unavailable. +#[test] +fn test_sift_records() { + let lines: Vec = [ + "READY", + r#"START {"ok":{"id":"7198f46a-2a62-492d-86e4-ce257615dfc7","local_addr":"127.0.0.1:34991","remote_addr":"127.0.0.1:50556","method":"GET","path":"/panic","query":null}}"#, + r#"START {"ok":{"id":"6c98b16b-3e81-4a5b-8645-e2faeefcb738","local_addr":"127.0.0.1:34991","remote_addr":"127.0.0.1:64479","method":"GET","path":"/ok","query":null}}"#, + r#"DONE {"ok":{"id":"6c98b16b-3e81-4a5b-8645-e2faeefcb738","local_addr":"127.0.0.1:34991","remote_addr":"127.0.0.1:64479","status_code":200,"message":""}}"#, + r#"START {"ok":{"id":"00000000-0000-0000-0000-000000000000","local_addr":"127.0.0.1:9999","remote_addr":"127.0.0.1:64479","method":"GET","path":"/other-test","query":null}}"#, + "", + ] + .iter() + .map(|s| s.to_string()) + .collect(); + + let (starts, dones) = sift_records(&lines, "127.0.0.1:34991"); + assert_eq!(starts.len(), 2, "starts: {:?}", starts); + assert_eq!(starts["/panic"]["method"], "GET"); + assert_eq!(starts["/ok"]["id"], "6c98b16b-3e81-4a5b-8645-e2faeefcb738"); + assert_eq!(dones.len(), 1); + let done = &dones["6c98b16b-3e81-4a5b-8645-e2faeefcb738"]; + assert_eq!(done["status_code"], 200); + assert_eq!(done["message"], ""); +} + +#[tokio::test] +async fn test_usdt_probes_fire_with_expected_contents() { + let logctx = crate::common::create_log_context( + "usdt_probes_fire_with_expected_contents", + ); + let log = logctx.log.new(slog::o!()); + let server = ServerBuilder::new(api(), (), log.clone()).start().unwrap(); + match server.probe_registration() { + ProbeRegistration::Succeeded => (), + other => { + skip(&format!("probe registration did not succeed: {:?}", other)); + server.close().await.unwrap(); + logctx.cleanup_successful(); + return; + } + } + + // Run dtrace against our own process. If the binary is missing or we + // lack the privileges to use it, skip. + let child = tokio::process::Command::new("dtrace") + .arg("-q") + .arg("-p") + .arg(std::process::id().to_string()) + .arg("-n") + .arg(DTRACE_PROGRAM) + .stdout(Stdio::piped()) + .stderr(Stdio::piped()) + .kill_on_drop(true) + .spawn(); + let mut child = match child { + Ok(child) => child, + Err(e) => { + skip(&format!("could not run dtrace: {}", e)); + server.close().await.unwrap(); + logctx.cleanup_successful(); + return; + } + }; + let dtrace_pid = child.id().expect("child has not been waited on"); + + // Read dtrace's output continuously (so its stdout pipe can never fill + // up), signalling when the BEGIN probe's READY marker is seen. + let stdout = child.stdout.take().unwrap(); + let (ready_tx, ready_rx) = tokio::sync::oneshot::channel::<()>(); + let reader = tokio::spawn(async move { + let mut ready_tx = Some(ready_tx); + let mut collected = Vec::new(); + let mut lines = BufReader::new(stdout).lines(); + while let Ok(Some(line)) = lines.next_line().await { + if line.contains("READY") { + if let Some(tx) = ready_tx.take() { + let _ = tx.send(()); + } + } + collected.push(line); + } + collected + }); + + // Wait for the READY marker. If dtrace exits or times out instead, + // it's (almost certainly) a privilege problem; report its stderr and + // skip. + let ready = tokio::time::timeout(Duration::from_secs(30), ready_rx).await; + if !matches!(ready, Ok(Ok(()))) { + let mut stderr = String::new(); + if let Some(mut err) = child.stderr.take() { + let _ = tokio::time::timeout( + Duration::from_secs(5), + err.read_to_string(&mut stderr), + ) + .await; + } + let _ = child.kill().await; + skip(&format!( + "dtrace did not become ready (insufficient privileges?): {}", + stderr.trim() + )); + server.close().await.unwrap(); + logctx.cleanup_successful(); + return; + } + + // From here on, the environment has proven itself: failures are real + // failures. + // + // Exercise every terminal shape of a request: a handler panic, a + // success, an error response, a mid-handler client disconnect, and a + // panic outside the handler. + let mut stream = + tokio::net::TcpStream::connect(server.local_addr()).await.unwrap(); + stream + .write_all(b"GET /panic HTTP/1.1\r\nhost: test\r\n\r\n") + .await + .unwrap(); + let mut buf = Vec::new(); + // The connection is aborted without a response; ignore how. + let _ = stream.read_to_end(&mut buf).await; + + let client = ClientTestContext::new(server.local_addr(), log.clone()); + client + .make_request_no_body(Method::GET, "/ok", StatusCode::OK) + .await + .unwrap(); + client + .make_request_error(Method::GET, "/fail", StatusCode::BAD_REQUEST) + .await; + + // The mid-handler disconnect: request the slow endpoint, wait for its + // handler to start, then drop the connection. + let mut slow_stream = + tokio::net::TcpStream::connect(server.local_addr()).await.unwrap(); + slow_stream + .write_all(b"GET /slow HTTP/1.1\r\nhost: test\r\n\r\n") + .await + .unwrap(); + let deadline = Instant::now() + Duration::from_secs(15); + while !SLOW_STARTED.load(Ordering::SeqCst) { + assert!(Instant::now() < deadline, "the /slow handler never started"); + tokio::time::sleep(Duration::from_millis(10)).await; + } + drop(slow_stream); + + // The panic outside the handler: a second server in this process (the + // records are sifted per-server by local address) whose version policy + // panics before routing even happens -- no endpoints needed. + let server2 = ServerBuilder::new(ApiDescription::<()>::new(), (), log) + .version_policy(VersionPolicy::Dynamic(Box::new(PanickyVersionPolicy))) + .start() + .unwrap(); + let mut vp_stream = + tokio::net::TcpStream::connect(server2.local_addr()).await.unwrap(); + vp_stream + .write_all(b"GET /version-policy-panic HTTP/1.1\r\nhost: test\r\n\r\n") + .await + .unwrap(); + let mut buf = Vec::new(); + // Aborted without a response, like the handler panic; ignore how. + let _ = vp_stream.read_to_end(&mut buf).await; + + // Give dtrace's principal buffer time to be consumed (the default + // switchrate is one second), then stop dtrace gracefully with SIGTERM + // so that it flushes its buffered output on exit. + tokio::time::sleep(Duration::from_secs(2)).await; + let terminated = tokio::process::Command::new("kill") + .arg(dtrace_pid.to_string()) + .status() + .await; + assert!( + matches!(terminated, Ok(status) if status.success()), + "failed to send SIGTERM to dtrace: {:?}", + terminated + ); + let waited = + tokio::time::timeout(Duration::from_secs(15), child.wait()).await; + if waited.is_err() { + // dtrace did not exit on SIGTERM; kill it so the reader + // terminates, and fail below if output is missing. + let _ = child.kill().await; + } + let lines = reader.await.unwrap(); + + // Sift the output for this test's records. + let local_addr = server.local_addr().to_string(); + let (starts, dones) = sift_records(&lines, &local_addr); + + // All four requests must have fired request-start with the right + // contents. + for path in ["/panic", "/ok", "/fail", "/slow"] { + let start = starts.get(path).unwrap_or_else(|| { + panic!( + "no request-start probe for {}; dtrace output: {:?}", + path, lines + ) + }); + assert_eq!(start["method"], "GET"); + assert_eq!(start["local_addr"], local_addr.as_str()); + assert!(start["remote_addr"].as_str().is_some()); + assert!(start["id"].as_str().is_some()); + } + + // The success and the error must have fired request-done, correlated by + // request id, with the status codes and messages the client saw. + let ok_id = starts["/ok"]["id"].as_str().unwrap(); + let ok_done = &dones[ok_id]; + assert_eq!(ok_done["status_code"], 200); + assert_eq!(ok_done["message"], ""); + + let fail_id = starts["/fail"]["id"].as_str().unwrap(); + let fail_done = &dones[fail_id]; + assert_eq!(fail_done["status_code"], 400); + assert_eq!(fail_done["message"], "bad request"); + + // The panicked request fires request-done too, reporting status code 0 + // ("no response was received") and the panic message. + let panic_id = starts["/panic"]["id"].as_str().unwrap(); + let panic_done = &dones[panic_id]; + assert_eq!(panic_done["status_code"], 0); + assert_eq!( + panic_done["message"], + "request handler panicked: deliberate panic" + ); + + // The disconnected request fires request-done reporting the + // non-standard 499 ("client disconnected") -- and only a disconnect + // does; the panicked requests above and below must not (they report 0). + let slow_id = starts["/slow"]["id"].as_str().unwrap(); + let slow_done = &dones[slow_id]; + assert_eq!(slow_done["status_code"], 499); + assert_eq!( + slow_done["message"], + "client disconnected before response returned" + ); + assert_eq!(dones.len(), 4, "unexpected extra request-done probes"); + + // The version-policy panic on the second server is paired and reported + // as a panic outside the handler: status code 0 again, with a message + // that does not blame the (nonexistent) handler. + let local_addr2 = server2.local_addr().to_string(); + let (starts2, dones2) = sift_records(&lines, &local_addr2); + let vp_start = starts2.get("/version-policy-panic").unwrap_or_else(|| { + panic!( + "no request-start probe for /version-policy-panic; \ + dtrace output: {:?}", + lines + ) + }); + let vp_id = vp_start["id"].as_str().unwrap(); + let vp_done = &dones2[vp_id]; + assert_eq!(vp_done["status_code"], 0); + assert_eq!( + vp_done["message"], + "request handling panicked (outside the handler): \ + deliberate panic in version policy" + ); + assert_eq!(dones2.len(), 1, "unexpected extra request-done probes"); + + server.close().await.unwrap(); + server2.close().await.unwrap(); + logctx.cleanup_successful(); +} From 94cf4f26b7860da689485192048ac74e1857fcf7 Mon Sep 17 00:00:00 2001 From: Nahum Shalman Date: Fri, 14 Aug 2026 13:42:37 -0400 Subject: [PATCH 2/2] report handler panics as panics, not client disconnects Thread a handler panic out of http_request_handle as a value, via a new HandlerError::Panicked variant carrying the panic payload and its message. In Detached mode this needs no catch_unwind at all: tokio already caught the panic at the task boundary, and JoinError::into_panic hands us the payload. In CancelOnDisconnect mode the handler runs inline, so a narrow catch_unwind around the handler call converts the panic to the same variant. The wrap reports it -- "request handler panicked", with the panic message, and a request-done probe with status code 0 ("no response") -- and then resumes the unwind, so panic propagation is unchanged and the connection aborts with no response, as before. (Now that a handler panic is distinguished, that spot is also where behavior could optionally change to send a 500 instead; a TODO marks it.) A catch_unwind in http_request_handle_wrap serves as a backstop for panics outside the handler (e.g. a user-provided version policy, or dropshot's own routing), which have no other way to avoid unwinding through the cancellation-reporting scopeguard; these are reported distinctly as "request handling panicked (outside the handler)". The scopeguard itself now runs only on cancellation, however caused. A panic produces no response and so has no status code: HandlerError::Panicked's status_code() and into_response() are unreachable, keeping the log and the probe from ever disagreeing (e.g. logging a 500 while the probe reports 0). Co-Authored-By: Claude Fable 5 --- CHANGELOG.adoc | 2 + dropshot/src/handler.rs | 35 ++++++++++ dropshot/src/server.rs | 146 ++++++++++++++++++++++++++++++++++++++-- 3 files changed, 176 insertions(+), 7 deletions(-) diff --git a/CHANGELOG.adoc b/CHANGELOG.adoc index 39dace8a..f5c8bfed 100644 --- a/CHANGELOG.adoc +++ b/CHANGELOG.adoc @@ -15,6 +15,8 @@ https://github.com/oxidecomputer/dropshot/compare/v0.17.1\...HEAD[Full list of commits] +* https://github.com/oxidecomputer/dropshot/pull/1677[#1677] A panic during request handling is now reported as a panic rather than misreported as a client disconnection: a panic in the handler (or its extractors) is logged as "request handler panicked", and a panic elsewhere in request handling (e.g. a version policy) as "request handling panicked (outside the handler)", each with the panic message; the `request-done` DTrace probe reports status code 0 and the panic message. Panic propagation itself is unchanged. + == 0.17.1 (released 2026-06-02) https://github.com/oxidecomputer/dropshot/compare/v0.17.0\...v0.17.1[Full list of commits] diff --git a/dropshot/src/handler.rs b/dropshot/src/handler.rs index 7152d706..87caff62 100644 --- a/dropshot/src/handler.rs +++ b/dropshot/src/handler.rs @@ -306,6 +306,20 @@ pub enum HandlerError { /// a structured value, so that the internal and external messages of the /// error can both be logged. Dropshot(HttpError), + /// The handler panicked while executing. + /// + /// The panic payload is carried as a value so that the server can report + /// the panic -- attributed to the handler, with its message -- and then + /// resume the unwind, preserving the behavior that a handler panic aborts + /// the connection without a response. In + /// [`HandlerTaskMode::Detached`][crate::HandlerTaskMode::Detached], the + /// payload comes from tokio's `JoinError` (the panic was already caught + /// at the task boundary); in `CancelOnDisconnect`, it is caught around + /// the handler call itself. + Panicked { + message: String, + payload: Box, + }, } impl HandlerError { @@ -313,6 +327,16 @@ impl HandlerError { match self { Self::Handler { rsp, .. } => rsp.status(), Self::Dropshot(e) => e.status_code.as_status(), + // A panic produces no response and therefore has no status code + // (the request-done DTrace probe reports the sentinel 0, "no + // response was received"). Reporting any real status here would + // contradict that. `http_request_handle_wrap` matches `Panicked` + // before any path that asks for a status code. + Self::Panicked { message, .. } => { + unreachable!( + "a handler panic ({message:?}) has no status code", + ); + } } } @@ -320,6 +344,7 @@ impl HandlerError { match self { Self::Handler { message, .. } => message, Self::Dropshot(e) => &e.internal_message, + Self::Panicked { message, .. } => message, } } @@ -327,6 +352,7 @@ impl HandlerError { match self { Self::Handler { .. } => None, Self::Dropshot(e) => Some(&e.external_message), + Self::Panicked { .. } => None, } } @@ -359,6 +385,15 @@ impl HandlerError { rsp } Self::Dropshot(e) => e.into_response(request_id), + // A panic is reported and then resumed by + // `http_request_handle_wrap`, never converted into a response; + // see the `HandlerError::Panicked` match arm there. + Self::Panicked { message, .. } => { + unreachable!( + "a handler panic ({message:?}) must be resumed, \ + not converted into a response", + ); + } } } } diff --git a/dropshot/src/server.rs b/dropshot/src/server.rs index 9e4fa2b4..71363f7b 100644 --- a/dropshot/src/server.rs +++ b/dropshot/src/server.rs @@ -733,6 +733,28 @@ impl FusedFuture for HttpServer { } } +/// Extracts a human-readable message from a panic payload. +fn panic_message(payload: &(dyn std::any::Any + Send)) -> &str { + if let Some(s) = payload.downcast_ref::<&'static str>() { + s + } else if let Some(s) = payload.downcast_ref::() { + s + } else { + "(non-string panic payload)" + } +} + +/// Wraps a caught panic payload from a request handler as a +/// [`HandlerError::Panicked`], capturing its message for reporting. +fn handler_panicked( + payload: Box, +) -> HandlerError { + // `&*` is load-bearing: `&payload` would coerce the `Box` itself into + // the `dyn Any` and every downcast would miss. + let message = panic_message(&*payload).to_string(); + HandlerError::Panicked { message, payload } +} + /// Initial entry point for handling a new request to the HTTP server. This is /// invoked by Hyper when a new request is received. This function returns a /// Result that either represents a valid HTTP response or an error (which will @@ -801,7 +823,9 @@ async fn http_request_handle_wrap( let local_addr = server.local_addr; // In the case the client disconnects early, the scopeguard allows us - // to perform extra housekeeping before this task is dropped. + // to perform extra housekeeping before this task is dropped. The guard + // runs only if this future is dropped without completing (a + // cancellation). let on_disconnect = guard((), |_| { let latency_us = start_time.elapsed().as_micros(); @@ -824,14 +848,60 @@ async fn http_request_handle_wrap( }); }); - let maybe_response = http_request_handle( + // 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); + } + }; // If `http_request_handle` completed, it means the request wasn't // cancelled and we can safely "defuse" the scopeguard. @@ -839,6 +909,37 @@ async fn http_request_handle_wrap( let latency_us = start_time.elapsed().as_micros(); let response = match maybe_response { + Err(HandlerError::Panicked { message, payload }) => { + error!(request_log, "request handler panicked"; + "latency_us" => latency_us, + "panic_message" => message.as_str(), + ); + + // 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 handler panicked: {message}"), + } + }); + + // Resume the unwind, preserving the long-standing behavior of + // a handler panic: the connection is aborted with no response. + // + // TODO: this is the spot where we could optionally change + // behavior to send the client a 500 response instead of + // resuming the unwind, now that a handler panic is + // distinguished from a panic elsewhere in request handling. + panic::resume_unwind(payload); + } + Err(error) => { { let status = error.status_code(); @@ -932,7 +1033,20 @@ async fn http_request_handle( // For CancelOnDisconnect, we run the request handler directly: if // the client disconnects, we will be cancelled, and therefore this // future will too. - handler.handle_request(rqctx, request).await? + // + // 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)), + } } HandlerTaskMode::Detached => { // Spawn the handler so if we're cancelled, the handler still runs @@ -975,16 +1089,18 @@ async fn http_request_handle( match rx.await { Ok(result) => result?, Err(_) => { - error!(request_log, "handler panicked; propagating panic"); + debug!(request_log, "handler panicked; relaying panic"); // To get the panic, we now need to await `handler_task`; we // know it is complete _and_ it failed, because it has // dropped `tx` without sending us a result, which is only - // possible if it panicked. + // possible if it panicked. Note that tokio already caught + // the panic at the task boundary, so the payload comes + // back to us as a value -- no `catch_unwind` needed. let task_err = handler_task.await.expect_err( "task failed to send result but didn't panic", ); - panic::resume_unwind(task_err.into_panic()); + return Err(handler_panicked(task_err.into_panic())); } } } @@ -1259,6 +1375,22 @@ mod test { Ok(HttpResponseOk(3)) } + #[test] + fn test_panic_message() { + // panic!("literal") produces a &'static str payload. + let payload: Box = Box::new("boom"); + assert_eq!(panic_message(&*payload), "boom"); + + // panic!("{}", ...) produces a String payload. + let payload: Box = + Box::new(String::from("kaboom")); + assert_eq!(panic_message(&*payload), "kaboom"); + + // panic_any() can produce anything else. + let payload: Box = Box::new(42_u32); + assert_eq!(panic_message(&*payload), "(non-string panic payload)"); + } + struct TestConfig { log_context: LogContext, }