api: a log line per HTTP request

Requests weren't logged at all, short of what a handler logs itself. Now a middleware,
outermost on the API (and on a relay-only node's), logs a line per request as web
servers do: method and path (with the query), status, the milliseconds until the answer
began (a stream goes on after), where it came from (the address, or `unix`), and the
user (`-` where none was authenticated). The user comes back on the response:
`basic_auth` puts it there, for a token as for a password or a trusted proxy's header.

At debug, under the target `http` (`RUST_LOG=info,http=debug`, or `PUT /admin/log`):
an open dashboard alone would fill the log at info. With the target off, the request
passes untouched.

3 files changed, 67 insertions, 5 deletions

diff --git a/src/api/auth.rs b/src/api/auth.rs
index ac70b82..f4806ca 100644
--- a/src/api/auth.rs
+++ b/src/api/auth.rs
@@ -211,7 +211,8 @@ fn parse_basic(headers: &HeaderMap) -> Option<(String, String)> {
 }
 
 /// The user a request authenticated as (a request extension, set by [`basic_auth`], or
-/// by `login::bearer` for a token).
+/// by `login::bearer` for a token; on the response too, for the request log,
+/// `request_log`).
 #[derive(Clone, Debug)]
 pub(crate) struct AuthenticatedUser(pub(crate) String);
 
@@ -293,8 +294,8 @@ pub(crate) async fn basic_auth(
     next: axum::middleware::Next,
 ) -> Response {
     // A token, taken already (`login::bearer`).
-    if request.extensions().get::<AuthenticatedUser>().is_some() {
-        return next.run(request).await;
+    if let Some(user) = request.extensions().get::<AuthenticatedUser>().cloned() {
+        return with_user(next.run(request).await, user);
     }
     let from = request
         .extensions()
@@ -343,9 +344,17 @@ pub(crate) async fn basic_auth(
         };
     };
 
-    request.extensions_mut().insert(AuthenticatedUser(user));
+    request
+        .extensions_mut()
+        .insert(AuthenticatedUser(user.clone()));
     request.extensions_mut().insert(via);
-    next.run(request).await
+    with_user(next.run(request).await, AuthenticatedUser(user))
+}
+
+/// `response`, naming the user it answered (`request_log`).
+fn with_user(mut response: Response, user: AuthenticatedUser) -> Response {
+    response.extensions_mut().insert(user);
+    response
 }
 
 #[cfg(test)]
diff --git a/src/api/mod.rs b/src/api/mod.rs
index 5c7c8e7..437f932 100644
--- a/src/api/mod.rs
+++ b/src/api/mod.rs
@@ -15,6 +15,7 @@ pub(crate) mod listen;
 mod log;
 mod login;
 mod peers;
+mod request_log;
 mod stats;
 mod store;
 mod users;
@@ -142,6 +143,8 @@ pub(crate) fn router(state: AppState, auth_state: AuthState, debug_api: bool) ->
     // Outermost, so authentication failures get the error body too.
     .layer(middleware::from_fn(json_errors))
     .layer(middleware::from_fn(relative_redirects))
+    // A line per request, as it is answered.
+    .layer(middleware::from_fn(request_log::log_requests))
     .with_state(state)
 }
 
@@ -166,6 +169,7 @@ pub(crate) fn relay_only_router(
         .route("/health", get(health::health))
         .layer(middleware::from_fn(json_errors))
         .layer(middleware::from_fn(relative_redirects))
+        .layer(middleware::from_fn(request_log::log_requests))
         .with_state(relay)
 }
 
diff --git a/src/api/request_log.rs b/src/api/request_log.rs
new file mode 100644
index 0000000..418fe14
--- /dev/null
+++ b/src/api/request_log.rs
@@ -0,0 +1,49 @@
+//! A line per HTTP request, as web servers log them: the method and path, the status,
+//! how long until the answer began (a stream, such as the dashboard's events, goes on
+//! after), where it came from, and the user. At debug, under the target `http`
+//! (`RUST_LOG=info,http=debug`, or `PUT /admin/log`): an open dashboard alone would
+//! fill the log at info.
+
+use axum::extract::{ConnectInfo, Request};
+use axum::middleware::Next;
+use axum::response::Response;
+use tokio::time::Instant;
+use tracing::{Level, debug, enabled};
+
+use super::auth::AuthenticatedUser;
+use super::listen::Peer;
+
+/// Outermost: what the layers inside answer too (a `401` included). The user comes back
+/// on the response (`auth::basic_auth`).
+pub(crate) async fn log_requests(request: Request, next: Next) -> Response {
+    if !enabled!(target: "http", Level::DEBUG) {
+        return next.run(request).await;
+    }
+    let method = request.method().clone();
+    let path = request
+        .uri()
+        .path_and_query()
+        .map_or_else(|| request.uri().path().to_owned(), ToString::to_string);
+    let from = match request.extensions().get::<ConnectInfo<Peer>>() {
+        Some(ConnectInfo(Peer::Tcp(address))) => address.to_string(),
+        Some(ConnectInfo(Peer::Unix)) => "unix".to_owned(),
+        None => "-".to_owned(),
+    };
+    let started = Instant::now();
+    let response = next.run(request).await;
+    let user = response
+        .extensions()
+        .get::<AuthenticatedUser>()
+        .map_or("-", |AuthenticatedUser(user)| user.as_str());
+    debug!(
+        target: "http",
+        method = %method,
+        path = %path,
+        status = response.status().as_u16(),
+        ms = started.elapsed().as_millis(),
+        from = %from,
+        user = %user,
+        "HTTP request"
+    );
+    response
+}