mini-serve 0.13.12

//! Opt-in logging, and the two failures that were previously invisible.

use std::io::Write;
use std::sync::{Arc, Mutex};
use std::time::Duration;

use hyper::StatusCode;
use mini_serve::{handler, RouteBuilder, ServeError};
use tokio::io::{AsyncReadExt, AsyncWriteExt};
use tokio::net::TcpListener;
use tokio::sync::oneshot;

/// A sink the test can read back. `with_request_logging_to` takes ownership of the
/// writer, so sharing the buffer through an `Arc` is the only way to inspect it — which
/// is why the builder takes a writer at all rather than hardcoding stderr: libtest
/// cannot capture output written from a spawned server task.
#[derive(Clone, Default)]
struct SharedBuffer(Arc<Mutex<Vec<u8>>>);

impl SharedBuffer {
	fn contents(&self) -> String {
		String::from_utf8(self.0.lock().unwrap().clone()).unwrap()
	}
}

impl Write for SharedBuffer {
	fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
		self.0.lock().unwrap().extend_from_slice(buf);
		Ok(buf.len())
	}

	fn flush(&mut self) -> std::io::Result<()> {
		Ok(())
	}
}

/// Serve `builder` on an ephemeral port until the returned sender drops.
async fn serve(builder: RouteBuilder<()>) -> (String, oneshot::Sender<()>) {
	let app = builder.seal();
	let listener = TcpListener::bind("127.0.0.1:0").await.unwrap();
	let addr = listener.local_addr().unwrap().to_string();
	let (tx, rx) = oneshot::channel::<()>();
	tokio::spawn(async move {
		app.run(listener, async move {
			let _ = rx.await;
		})
		.await
	});
	tokio::time::sleep(Duration::from_millis(50)).await;
	(addr, tx)
}

fn ok_route(builder: RouteBuilder<()>) -> RouteBuilder<()> {
	builder.get(
		"/health",
		handler(|_req, _state| async {
			mini_serve::json(StatusCode::OK, &serde_json::json!({"ok": true}))
		}),
	)
}

#[tokio::test]
async fn a_served_request_is_logged_with_its_method_path_and_status() {
	let log = SharedBuffer::default();
	let (addr, _shutdown) = serve(ok_route(
		RouteBuilder::stateless().with_request_logging_to(Box::new(log.clone())),
	))
	.await;

	reqwest::get(format!("http://{addr}/health")).await.unwrap();
	tokio::time::sleep(Duration::from_millis(100)).await;

	let line = log.contents();
	assert!(line.starts_with("GET /health 200 "), "got: {line:?}");
	assert!(
		line.trim_end().ends_with("ms"),
		"a duration should close the line, got: {line:?}"
	);
}

/// Logging is opt-in: a library writing to its host's output uninvited is a surprise.
#[tokio::test]
async fn nothing_is_logged_without_the_builder() {
	let log = SharedBuffer::default();
	// Deliberately not wired to the app — proving the sink stays empty because nothing
	// logged, not because the sink was unreachable.
	let (addr, _shutdown) = serve(ok_route(RouteBuilder::stateless())).await;

	reqwest::get(format!("http://{addr}/health")).await.unwrap();
	tokio::time::sleep(Duration::from_millis(100)).await;

	assert_eq!(log.contents(), "");
}

/// The client body for a 5xx is sanitized on purpose; without a sink the real message
/// was discarded along with it, leaving an operator nothing to debug from.
#[tokio::test]
async fn a_5xx_reports_its_internal_message_while_the_client_body_stays_sanitized() {
	let log = SharedBuffer::default();
	let (addr, _shutdown) = serve(
		RouteBuilder::stateless()
			.with_request_logging_to(Box::new(log.clone()))
			.get(
				"/boom",
				handler(|_req, _state| async {
					Err(ServeError::new(500, "connection pool exhausted for shard 7"))
				}),
			),
	)
	.await;

	let response = reqwest::get(format!("http://{addr}/boom")).await.unwrap();
	assert_eq!(response.status(), StatusCode::INTERNAL_SERVER_ERROR);
	let body = response.text().await.unwrap();
	assert!(
		!body.contains("shard 7"),
		"the client must not see internals: {body}"
	);

	tokio::time::sleep(Duration::from_millis(100)).await;
	assert!(
		log.contents().contains("connection pool exhausted for shard 7"),
		"the operator must see them, got: {:?}",
		log.contents()
	);
}

/// A 4xx message is already sent to the client, so repeating it in the log would be
/// noise — the sink is for what the client cannot see.
#[tokio::test]
async fn a_4xx_message_is_not_duplicated_into_the_log() {
	let log = SharedBuffer::default();
	let (addr, _shutdown) = serve(
		RouteBuilder::stateless()
			.with_request_logging_to(Box::new(log.clone()))
			.get(
				"/bad",
				handler(|_req, _state| async {
					Err(ServeError::new(400, "malformed cursor token"))
				}),
			),
	)
	.await;

	reqwest::get(format!("http://{addr}/bad")).await.unwrap();
	tokio::time::sleep(Duration::from_millis(100)).await;

	let contents = log.contents();
	assert!(
		contents.contains("GET /bad 400"),
		"the request line should still be logged, got: {contents:?}"
	);
	assert!(
		!contents.contains("malformed cursor token"),
		"a 4xx message reaches the client already, got: {contents:?}"
	);
}

/// A panicking handler dropped the client's connection and left no record anywhere —
/// indistinguishable from a network fault to the client, and invisible to the operator.
#[tokio::test]
async fn a_handler_panic_is_reported() {
	let log = SharedBuffer::default();
	let (addr, _shutdown) = serve(
		RouteBuilder::stateless()
			.with_request_logging_to(Box::new(log.clone()))
			.get(
				"/panic",
				handler(|_req, _state| async {
					panic!("handler exploded");
				}),
			),
	)
	.await;

	// The connection is dropped, so the client sees a transport error, not a status.
	let _ = reqwest::get(format!("http://{addr}/panic")).await;
	tokio::time::sleep(Duration::from_millis(300)).await;

	assert!(
		log.contents().contains("panicked"),
		"a handler panic must reach the sink, got: {:?}",
		log.contents()
	);
}

/// The path is logged exactly as received. A probe is the line an operator most needs
/// verbatim, and normalizing it would hide what was actually sent.
#[tokio::test]
async fn the_logged_path_is_the_raw_request_path() {
	let log = SharedBuffer::default();
	let (addr, _shutdown) = serve(ok_route(
		RouteBuilder::stateless().with_request_logging_to(Box::new(log.clone())),
	))
	.await;

	// Sent over a raw socket rather than through `reqwest`, which normalizes `%2E%2E`
	// to `..` and resolves it away client-side — testing the client's URL handling
	// instead of the server's logging, which is what an earlier version of this test
	// accidentally asserted.
	let mut stream = tokio::net::TcpStream::connect(&addr).await.unwrap();
	stream
		.write_all(b"GET /%2E%2E/etc/passwd HTTP/1.1\r\nHost: localhost\r\nConnection: close\r\n\r\n")
		.await
		.unwrap();
	let mut sink = Vec::new();
	let _ = stream.read_to_end(&mut sink).await;
	tokio::time::sleep(Duration::from_millis(100)).await;

	assert!(
		log.contents().contains("/%2E%2E/etc/passwd"),
		"the raw, undecoded path should appear, got: {:?}",
		log.contents()
	);
}