feat(observability): add structured application logging

Emit correlated JSON logs from the API and FunASR services, propagate request IDs to the client, and configure bounded opt-in Docker logging.

Document the host-wide Grafana/Loki query workflow and keep observability deployment ownership outside the application repository.

server/src/main.rs

@@ -7,12 +7,25 @@ mod speech;
 mod summary;
 mod transcription_worker;
 
-use std::{path::PathBuf, sync::Arc};
+use std::{path::PathBuf, sync::Arc, time::Duration};
 
-use axum::{Json, Router, extract::DefaultBodyLimit, http::HeaderValue, routing::get};
-use config::Config;
+use axum::{
+    Json, Router,
+    extract::{DefaultBodyLimit, MatchedPath},
+    http::{HeaderName, HeaderValue, Request},
+    response::Response,
+    routing::get,
+};
+use config::{Config, LogFormat};
 use sqlx::{PgPool, postgres::PgPoolOptions};
-use tower_http::{cors::CorsLayer, trace::TraceLayer};
+use tower::ServiceBuilder;
+use tower_http::{
+    classify::ServerErrorsFailureClass,
+    cors::CorsLayer,
+    request_id::{MakeRequestUuid, PropagateRequestIdLayer, SetRequestIdLayer},
+    trace::TraceLayer,
+};
+use tracing::Span;
 use tracing_subscriber::EnvFilter;
 use utoipa_scalar::{Scalar, Servable};
 
@@ -25,15 +38,30 @@ pub struct AppState {
     pub auth: auth::AuthService,
 }
 
+#[derive(Clone)]
+pub(crate) struct LogContext {
+    pub(crate) environment: String,
+    pub(crate) app_version: String,
+    pub(crate) git_sha: String,
+}
+
+impl From<&Config> for LogContext {
+    fn from(config: &Config) -> Self {
+        Self {
+            environment: config.app_env.clone(),
+            app_version: config.app_version.clone(),
+            git_sha: config.git_sha.clone(),
+        }
+    }
+}
+
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn std::error::Error>> {
     dotenvy::dotenv().ok();
-    tracing_subscriber::fmt()
-        .with_env_filter(EnvFilter::try_from_default_env().unwrap_or_else(|_| "info".into()))
-        .init();
-
     let config = Config::from_env().map_err(std::io::Error::other)?;
-    let pool = connect_database(&config).await?;
+    init_tracing(&config);
+    let log_context = LogContext::from(&config);
+    let pool = connect_database(&config, &log_context).await?;
     let speech = speech::SpeechService::new(config.speech.clone());
     let auth = auth::AuthService::new(config.auth.clone());
     let state = AppState {
@@ -45,21 +73,57 @@ async fn main() -> Result<(), Box<dyn std::error::Error>> {
     };
     if let Some(pool) = state.pool.clone() {
         if speech.configured() {
-            transcription_worker::spawn(pool, speech);
+            transcription_worker::spawn(pool, speech.clone(), log_context.clone());
         }
     }
-    let app = build_app(state, config.cors_allowed_origin.as_deref())?;
+    let app = build_app(
+        state,
+        config.cors_allowed_origin.as_deref(),
+        log_context.clone(),
+    )?;
     let address = std::net::SocketAddr::from((config.host, config.port));
     let listener = tokio::net::TcpListener::bind(address).await?;
 
-    tracing::info!(%address, scalar = %format!("http://{address}/scalar"), "API server is listening");
+    tracing::info!(
+        service = "api",
+        environment = %log_context.environment,
+        app_version = %log_context.app_version,
+        git_sha = %log_context.git_sha,
+        event = "api_started",
+        %address,
+        scalar = %format!("http://{address}/scalar"),
+        provider = ?speech.provider_name(),
+        "API server is listening"
+    );
     axum::serve(listener, app)
-        .with_graceful_shutdown(shutdown_signal())
+        .with_graceful_shutdown(shutdown_signal(log_context))
         .await?;
     Ok(())
 }
 
-pub fn build_app(state: AppState, cors_allowed_origin: Option<&str>) -> Result<Router, String> {
+fn init_tracing(config: &Config) {
+    let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| "info".into());
+    match config.log_format {
+        LogFormat::Json => tracing_subscriber::fmt()
+            .json()
+            .flatten_event(true)
+            .with_ansi(false)
+            .with_current_span(true)
+            .with_span_list(true)
+            .with_env_filter(filter)
+            .init(),
+        LogFormat::Pretty => tracing_subscriber::fmt()
+            .with_env_filter(filter)
+            .pretty()
+            .init(),
+    }
+}
+
+fn build_app(
+    state: AppState,
+    cors_allowed_origin: Option<&str>,
+    log_context: LogContext,
+) -> Result<Router, String> {
     let (api_router, openapi) = routes::router();
     let openapi_json = openapi.clone();
     let mut app = api_router
@@ -72,21 +136,142 @@ pub fn build_app(state: AppState, cors_allowed_origin: Option<&str>) -> Result<R
         )
         .merge(Scalar::with_url("/scalar", openapi))
         .with_state(Arc::new(state))
-        .layer(DefaultBodyLimit::max(20 * 1024 * 1024))
-        .layer(TraceLayer::new_for_http());
+        .layer(DefaultBodyLimit::max(20 * 1024 * 1024));
 
     if let Some(origin) = cors_allowed_origin {
         let allowed_origin = HeaderValue::from_str(origin)
             .map_err(|_| "CORS_ALLOWED_ORIGIN must be a valid HTTP header value".to_owned())?;
-        app = app.layer(CorsLayer::new().allow_origin(allowed_origin));
+        app = app.layer(
+            CorsLayer::new()
+                .allow_origin(allowed_origin)
+                .expose_headers([HeaderName::from_static("x-request-id")]),
+        );
     }
 
-    Ok(app)
+    let request_span_context = log_context.clone();
+    let request_started_context = log_context.clone();
+    let request_finished_context = log_context.clone();
+    let request_failed_context = log_context;
+    Ok(app.layer(
+        ServiceBuilder::new()
+            .layer(SetRequestIdLayer::x_request_id(MakeRequestUuid))
+            .layer(
+                TraceLayer::new_for_http()
+                    .make_span_with(move |request: &Request<_>| {
+                        make_http_request_span(request, &request_span_context)
+                    })
+                    .on_request(move |request: &Request<_>, span: &Span| {
+                        tracing::info!(
+                            parent: span,
+                            service = "api",
+                            environment = %request_started_context.environment,
+                            app_version = %request_started_context.app_version,
+                            git_sha = %request_started_context.git_sha,
+                            event = "http_request_started",
+                            request_id = request_id_from_headers(request),
+                            "HTTP request started"
+                        );
+                    })
+                    .on_response(move |response: &Response, latency: Duration, span: &Span| {
+                        let status = response.status();
+                        let latency_ms = u64::try_from(latency.as_millis()).unwrap_or(u64::MAX);
+                        let request_id = response
+                            .headers()
+                            .get("x-request-id")
+                            .and_then(|value| value.to_str().ok())
+                            .unwrap_or("unknown");
+                        if status.is_server_error() {
+                            tracing::error!(
+                                parent: span,
+                                service = "api",
+                                environment = %request_finished_context.environment,
+                                app_version = %request_finished_context.app_version,
+                                git_sha = %request_finished_context.git_sha,
+                                event = "http_request_finished",
+                                status = status.as_u16(),
+                                latency_ms,
+                                request_id,
+                                error_class = "server_error",
+                                "HTTP request finished"
+                            );
+                        } else {
+                            tracing::info!(
+                                parent: span,
+                                service = "api",
+                                environment = %request_finished_context.environment,
+                                app_version = %request_finished_context.app_version,
+                                git_sha = %request_finished_context.git_sha,
+                                event = "http_request_finished",
+                                status = status.as_u16(),
+                                latency_ms,
+                                request_id,
+                                "HTTP request finished"
+                            );
+                        }
+                    })
+                    .on_failure(
+                        move |failure: ServerErrorsFailureClass, latency: Duration, span: &Span| {
+                            let latency_ms = u64::try_from(latency.as_millis()).unwrap_or(u64::MAX);
+                            tracing::error!(
+                                parent: span,
+                                service = "api",
+                                environment = %request_failed_context.environment,
+                                app_version = %request_failed_context.app_version,
+                                git_sha = %request_failed_context.git_sha,
+                                event = "http_request_failed",
+                                latency_ms,
+                                error_class = ?failure,
+                                "HTTP request failed"
+                            );
+                        },
+                    ),
+            )
+            .layer(PropagateRequestIdLayer::x_request_id()),
+    ))
 }
 
-async fn connect_database(config: &Config) -> Result<Option<PgPool>, sqlx::Error> {
+fn make_http_request_span<B>(request: &Request<B>, context: &LogContext) -> Span {
+    let route = request
+        .extensions()
+        .get::<MatchedPath>()
+        .map(MatchedPath::as_str)
+        .unwrap_or_else(|| request.uri().path());
+    let request_id = request_id_from_headers(request);
+
+    tracing::info_span!(
+        "http_request",
+        service = "api",
+        environment = %context.environment,
+        app_version = %context.app_version,
+        git_sha = %context.git_sha,
+        method = %request.method(),
+        route,
+        path = %request.uri().path(),
+        request_id,
+    )
+}
+
+fn request_id_from_headers<B>(request: &Request<B>) -> &str {
+    request
+        .headers()
+        .get("x-request-id")
+        .and_then(|value| value.to_str().ok())
+        .unwrap_or("invalid")
+}
+
+async fn connect_database(
+    config: &Config,
+    log_context: &LogContext,
+) -> Result<Option<PgPool>, sqlx::Error> {
     let Some(database_url) = &config.database_url else {
-        tracing::warn!("DATABASE_URL is not set; data endpoints will return HTTP 503");
+        tracing::warn!(
+            service = "api",
+            environment = %log_context.environment,
+            app_version = %log_context.app_version,
+            git_sha = %log_context.git_sha,
+            event = "database_not_configured",
+            "DATABASE_URL is not set; data endpoints will return HTTP 503"
+        );
         return Ok(None);
     };
 
@@ -94,11 +279,95 @@ async fn connect_database(config: &Config) -> Result<Option<PgPool>, sqlx::Error
         .max_connections(config.database_max_connections)
         .connect(database_url)
         .await?;
-    tracing::info!("connected to PostgreSQL");
+    tracing::info!(
+        service = "api",
+        environment = %log_context.environment,
+        app_version = %log_context.app_version,
+        git_sha = %log_context.git_sha,
+        event = "database_connected",
+        "connected to PostgreSQL"
+    );
     Ok(Some(pool))
 }
 
-async fn shutdown_signal() {
+async fn shutdown_signal(log_context: LogContext) {
     let _ = tokio::signal::ctrl_c().await;
-    tracing::info!("shutdown signal received");
+    tracing::info!(
+        service = "api",
+        environment = %log_context.environment,
+        app_version = %log_context.app_version,
+        git_sha = %log_context.git_sha,
+        event = "api_shutdown",
+        "shutdown signal received"
+    );
+}
+
+#[cfg(test)]
+mod tests {
+    use axum::{body::Body, http::Request};
+    use tower::ServiceExt;
+    use uuid::Uuid;
+
+    use super::{AppState, LogContext, build_app};
+    use crate::{
+        auth::AuthService, config::AuthConfig, speech::SpeechService, summary::SummaryService,
+    };
+
+    fn app() -> axum::Router {
+        build_app(
+            AppState {
+                pool: None,
+                audio_storage_dir: std::path::PathBuf::from("./data/audio"),
+                speech: SpeechService::new(None),
+                summary: SummaryService::new(None),
+                auth: AuthService::new(AuthConfig {
+                    wechat: None,
+                    session_ttl_days: 30,
+                    allow_development_user_header: false,
+                }),
+            },
+            None,
+            LogContext {
+                environment: "test".to_owned(),
+                app_version: "test".to_owned(),
+                git_sha: "test".to_owned(),
+            },
+        )
+        .unwrap()
+    }
+
+    #[tokio::test]
+    async fn health_generates_a_uuid_request_id() {
+        let response = app()
+            .oneshot(
+                Request::builder()
+                    .uri("/health")
+                    .body(Body::empty())
+                    .unwrap(),
+            )
+            .await
+            .unwrap();
+        let request_id = response
+            .headers()
+            .get("x-request-id")
+            .unwrap()
+            .to_str()
+            .unwrap();
+        assert!(Uuid::parse_str(request_id).is_ok());
+    }
+
+    #[tokio::test]
+    async fn health_propagates_a_client_request_id() {
+        let response = app()
+            .oneshot(
+                Request::builder()
+                    .uri("/health")
+                    .header("x-request-id", "test-request-id")
+                    .body(Body::empty())
+                    .unwrap(),
+            )
+            .await
+            .unwrap();
+        assert_eq!(response.headers()["x-request-id"], "test-request-id");
+    }
 }