Improve error logging and observability (#4443)

* Replace actix tracing with custom error tracing

* Fix logging

* wip: JSON logging

* Use LABRINTH_FORMAT to change to JSON output

* sqlx fix?

* CI fix

* Add tracing span info to HTTP requests

* Merge Result and Option error wrapping

* Add http.authorized to tracing

Author: aecsocket

Cargo.lock

@@ -67,6 +67,7 @@ hex = "0.4.3"
 hickory-resolver = "0.25.2"
 hmac = "0.12.1"
 hyper = "1.6.0"
+tracing-ecs = "0.5.0"
 hyper-rustls = { version = "0.27.7", default-features = false, features = [
 	"http1",
 	"native-tokio",
@@ -165,9 +166,11 @@ tokio-stream = "0.1.17"
 tokio-util = "0.7.16"
 totp-rs = "5.7.0"
 tracing = "0.1.41"
-tracing-actix-web = "0.7.19"
+tracing-actix-web = { version = "0.7.19", default-features = false }
 tracing-error = "0.2.1"
 tracing-subscriber = "0.3.19"
+eyre = "0.6.12"
+color-eyre = "0.6.5"
 url = "2.5.4"
 urlencoding = "2.1.3"
 uuid = "1.17.0"

Cargo.toml

@@ -23,6 +23,10 @@ actix-web-prom = { workspace = true, features = ["process"] }
 tracing.workspace = true
 tracing-actix-web.workspace = true
 console-subscriber.workspace = true
+tracing-subscriber.workspace = true
+tracing-ecs.workspace = true
+eyre.workspace = true
+color-eyre.workspace = true
 
 tokio = { workspace = true, features = ["sync", "rt-multi-thread"] }
 tokio-stream.workspace = true

apps/labrinth/Cargo.toml

@@ -1,7 +1,9 @@
+use actix_web::dev::Service;
 use actix_web::middleware::from_fn;
 use actix_web::{App, HttpServer};
 use actix_web_prom::PrometheusMetricsBuilder;
 use clap::Parser;
+
 use labrinth::app_config;
 use labrinth::background_task::BackgroundTask;
 use labrinth::database::redis::RedisPool;
@@ -13,9 +15,15 @@ use labrinth::util::env::parse_var;
 use labrinth::util::ratelimit::rate_limit_middleware;
 use labrinth::{check_env_vars, clickhouse, database, file_hosting, queue};
 use std::ffi::CStr;
+use std::str::FromStr;
 use std::sync::Arc;
-use tracing::{error, info};
+use tracing::level_filters::LevelFilter;
+use tracing::{Instrument, error, info, info_span};
 use tracing_actix_web::TracingLogger;
+use tracing_ecs::ECSLayerBuilder;
+use tracing_subscriber::EnvFilter;
+use tracing_subscriber::layer::SubscriberExt;
+use tracing_subscriber::util::SubscriberInitExt;
 
 #[cfg(target_os = "linux")]
 #[global_allocator]
@@ -46,12 +54,59 @@ struct Args {
     run_background_task: Option<BackgroundTask>,
 }
 
+#[derive(Debug, Clone, Default, PartialEq, Eq)]
+enum OutputFormat {
+    #[default]
+    Human,
+    Json,
+}
+
+impl FromStr for OutputFormat {
+    type Err = ();
+
+    fn from_str(s: &str) -> Result<Self, Self::Err> {
+        match s {
+            "human" => Ok(Self::Human),
+            "json" => Ok(Self::Json),
+            _ => Err(()),
+        }
+    }
+}
+
 #[actix_rt::main]
 async fn main() -> std::io::Result<()> {
     let args = Args::parse();
 
+    color_eyre::install().expect("failed to install `color-eyre`");
     dotenvy::dotenv().ok();
-    console_subscriber::init();
+    let console_layer = console_subscriber::spawn();
+    let env_filter = EnvFilter::builder()
+        .with_default_directive(LevelFilter::INFO.into())
+        .from_env_lossy();
+
+    let output_format =
+        dotenvy::var("LABRINTH_FORMAT").map_or(OutputFormat::Human, |format| {
+            format
+                .parse::<OutputFormat>()
+                .unwrap_or_else(|_| panic!("invalid output format '{format}'"))
+        });
+
+    match output_format {
+        OutputFormat::Human => {
+            tracing_subscriber::registry()
+                .with(console_layer)
+                .with(env_filter)
+                .with(tracing_subscriber::fmt::layer())
+                .init();
+        }
+        OutputFormat::Json => {
+            tracing_subscriber::registry()
+                .with(console_layer)
+                .with(env_filter)
+                .with(ECSLayerBuilder::default().stdout())
+                .init();
+        }
+    }
 
     if check_env_vars() {
         error!("Some environment variables are missing!");
@@ -199,6 +254,33 @@ async fn main() -> std::io::Result<()> {
     HttpServer::new(move || {
         App::new()
             .wrap(TracingLogger::default())
+            .wrap_fn(|req, srv| {
+                // We capture the same fields as `tracing-actix-web`'s `RootSpanBuilder`.
+                // See `root_span!` macro.
+                let span = info_span!(
+                    "HTTP request",
+                    http.method = %req.method(),
+                    http.client_ip = %req.connection_info().realip_remote_addr().unwrap_or(""),
+                    http.user_agent = %req.headers().get("User-Agent").map_or("", |h| h.to_str().unwrap_or("")),
+                    http.target = %req.uri().path_and_query().map_or("", |p| p.as_str()),
+                    http.authenticated = %req.headers().get("Authorization").is_some()
+                );
+
+                let fut = srv.call(req);
+                async move {
+                    fut.await.inspect(|resp| {
+                        let _span = info_span!(
+                            "HTTP response",
+                            http.status = %resp.response().status().as_u16(),
+                        ).entered();
+
+                        resp.response()
+                            .error()
+                            .inspect(|err| log_error(err));
+                    })
+                }
+                .instrument(span)
+            })
             .wrap(prometheus.clone())
             .wrap(from_fn(rate_limit_middleware))
             .wrap(actix_web::middleware::Compress::default())
@@ -209,3 +291,15 @@ async fn main() -> std::io::Result<()> {
     .run()
     .await
 }
+
+fn log_error(err: &actix_web::Error) {
+    if err.as_response_error().status_code().is_client_error() {
+        tracing::debug!(
+            "Error encountered while processing the incoming HTTP request: {err}"
+        );
+    } else {
+        tracing::error!(
+            "Error encountered while processing the incoming HTTP request: {err}"
+        );
+    }
+}