From b1182fe8a4065eb6edcfc992118b630f7baf5afc Mon Sep 17 00:00:00 2001
From: Jason Volk <jason@zemos.net>
Date: Thu, 2 Jan 2025 07:16:46 +0000
Subject: [PATCH] improve some router tracing spans

Signed-off-by: Jason Volk <jason@zemos.net>
---
 src/router/request.rs    | 69 ++++++++++++++++++++++++++--------------
 src/router/serve/unix.rs | 50 +++++++++++++++++++++--------
 2 files changed, 83 insertions(+), 36 deletions(-)

diff --git a/src/router/request.rs b/src/router/request.rs
index 559c7f88..ab98fe4f 100644
--- a/src/router/request.rs
+++ b/src/router/request.rs
@@ -12,6 +12,18 @@ use http::{Method, StatusCode, Uri};
 	parent = None,
 	level = "trace",
 	skip_all,
+	fields(
+		handled = %services
+			.server
+			.metrics
+			.requests_spawn_finished
+			.fetch_add(1, Ordering::Relaxed),
+		active = %services
+			.server
+			.metrics
+			.requests_spawn_active
+			.fetch_add(1, Ordering::Relaxed),
+	)
 )]
 pub(crate) async fn spawn(
 	State(services): State<Arc<Services>>,
@@ -19,34 +31,56 @@ pub(crate) async fn spawn(
 	next: axum::middleware::Next,
 ) -> Result<Response, StatusCode> {
 	let server = &services.server;
+
+	#[cfg(debug_assertions)]
+	defer! {{
+		_ = server
+			.metrics
+			.requests_spawn_active
+			.fetch_sub(1, Ordering::Relaxed);
+	}};
+
 	if !server.running() {
 		debug_warn!("unavailable pending shutdown");
 		return Err(StatusCode::SERVICE_UNAVAILABLE);
 	}
 
-	let active = server
-		.metrics
-		.requests_spawn_active
-		.fetch_add(1, Ordering::Relaxed);
-	trace!(active, "enter");
-	defer! {{
-		let active = server.metrics.requests_spawn_active.fetch_sub(1, Ordering::Relaxed);
-		let finished = server.metrics.requests_spawn_finished.fetch_add(1, Ordering::Relaxed);
-		trace!(active, finished, "leave");
-	}};
-
 	let fut = next.run(req);
 	let task = server.runtime().spawn(fut);
 	task.await.map_err(|_| StatusCode::INTERNAL_SERVER_ERROR)
 }
 
-#[tracing::instrument(level = "debug", skip_all)]
+#[tracing::instrument(
+	level = "debug",
+	skip_all,
+	fields(
+		handled = %services
+			.server
+			.metrics
+			.requests_handle_finished
+			.fetch_add(1, Ordering::Relaxed),
+		active = %services
+			.server
+			.metrics
+			.requests_handle_active
+			.fetch_add(1, Ordering::Relaxed),
+	)
+)]
 pub(crate) async fn handle(
 	State(services): State<Arc<Services>>,
 	req: http::Request<axum::body::Body>,
 	next: axum::middleware::Next,
 ) -> Result<Response, StatusCode> {
 	let server = &services.server;
+
+	#[cfg(debug_assertions)]
+	defer! {{
+		_ = server
+			.metrics
+			.requests_handle_active
+			.fetch_sub(1, Ordering::Relaxed);
+	}};
+
 	if !server.running() {
 		debug_warn!(
 			method = %req.method(),
@@ -57,17 +91,6 @@ pub(crate) async fn handle(
 		return Err(StatusCode::SERVICE_UNAVAILABLE);
 	}
 
-	let active = server
-		.metrics
-		.requests_handle_active
-		.fetch_add(1, Ordering::Relaxed);
-	trace!(active, "enter");
-	defer! {{
-		let active = server.metrics.requests_handle_active.fetch_sub(1, Ordering::Relaxed);
-		let finished = server.metrics.requests_handle_finished.fetch_add(1, Ordering::Relaxed);
-		trace!(active, finished, "leave");
-	}};
-
 	let uri = req.uri().clone();
 	let method = req.method().clone();
 	let result = next.run(req).await;
diff --git a/src/router/serve/unix.rs b/src/router/serve/unix.rs
index f5018455..fcd361f0 100644
--- a/src/router/serve/unix.rs
+++ b/src/router/serve/unix.rs
@@ -2,6 +2,7 @@
 
 use std::{
 	net::{self, IpAddr, Ipv4Addr},
+	os::fd::AsRawFd,
 	path::Path,
 	sync::{atomic::Ordering, Arc},
 };
@@ -60,31 +61,54 @@ pub(super) async fn serve(
 	Ok(())
 }
 
+#[tracing::instrument(
+	level = "trace",
+	skip_all,
+	fields(
+		?listener,
+		socket = ?conn.0,
+	),
+)]
 async fn accept(
 	server: &Arc<Server>,
 	listener: &UnixListener,
 	tasks: &mut JoinSet<()>,
-	mut app: MakeService,
+	app: MakeService,
 	builder: server::conn::auto::Builder<TokioExecutor>,
 	conn: (UnixStream, SocketAddr),
 ) {
-	let (socket, remote) = conn;
-	let socket = TokioIo::new(socket);
-	trace!(?listener, ?socket, ?remote, "accepted");
-
-	let called = app.call(NULL_ADDR).await.unwrap_infallible();
-
-	let service = move |req: Request<Incoming>| called.clone().oneshot(req);
-	let handler = service_fn(service);
-	let task = async move {
-		// bug on darwin causes all results to be errors. do not unwrap this
-		_ = builder.serve_connection(socket, handler).await;
-	};
+	let (socket, _) = conn;
+	let server_ = server.clone();
+	let task = async move { accepted(server_, builder, socket, app).await };
 
 	_ = tasks.spawn_on(task, server.runtime());
 	while tasks.try_join_next().is_some() {}
 }
 
+#[tracing::instrument(
+	level = "trace",
+	skip_all,
+	fields(
+		fd = %socket.as_raw_fd(),
+		path = ?socket.local_addr(),
+	),
+)]
+async fn accepted(
+	server: Arc<Server>,
+	builder: server::conn::auto::Builder<TokioExecutor>,
+	socket: UnixStream,
+	mut app: MakeService,
+) {
+	let socket = TokioIo::new(socket);
+	let called = app.call(NULL_ADDR).await.unwrap_infallible();
+	let service = move |req: Request<Incoming>| called.clone().oneshot(req);
+	let handler = service_fn(service);
+	trace!(?socket, ?handler, "serving connection");
+
+	// bug on darwin causes all results to be errors. do not unwrap this
+	_ = builder.serve_connection(socket, handler).await;
+}
+
 async fn init(server: &Arc<Server>) -> Result<UnixListener> {
 	use std::os::unix::fs::PermissionsExt;