diff --git a/CHANGELOG.adoc b/CHANGELOG.adoc index 39dace8aa..f5c8bfede 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/examples/panic-handler.rs b/dropshot/examples/panic-handler.rs new file mode 100644 index 000000000..d29bd458c --- /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/src/handler.rs b/dropshot/src/handler.rs index 7152d7062..87caff62a 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 9e4fa2b48..71363f7be 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, } diff --git a/dropshot/tests/integration-tests/main.rs b/dropshot/tests/integration-tests/main.rs index fe10b99a4..22a302fb6 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 000000000..c4296d16d --- /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 000000000..ca43de44e --- /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(); +}