trace id logging (#1725)

Cargo.lock

@@ -3621,6 +3621,7 @@ dependencies = [
  "env_logger 0.11.9",
  "log",
  "storyteller_root",
+ "trace_id",
  "workspace-build-acceleration",
 ]
 
@@ -6766,6 +6767,7 @@ version = "0.0.1"
 dependencies = [
  "env_logger 0.11.9",
  "log",
+ "trace_id",
  "workspace-build-acceleration",
 ]
 
@@ -8286,6 +8288,7 @@ dependencies = [
  "rootly_client",
  "sha2 0.11.0-rc.5",
  "tokio",
+ "trace_id",
  "workspace-build-acceleration",
 ]
 
@@ -11678,6 +11681,7 @@ dependencies = [
  "tokens",
  "tokio",
  "toml 1.0.7+spec-1.1.0",
+ "trace_id",
  "tts_common",
  "url",
  "url_config",
@@ -13316,6 +13320,17 @@ version = "0.3.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "8df9b6e13f2d32c91b9bd719c00d1958837bc7dec474d94952798cc8e69eeec3"
 
+[[package]]
+name = "trace_id"
+version = "0.0.1"
+dependencies = [
+ "rand 0.8.5",
+ "serde",
+ "serde_derive",
+ "tokio",
+ "workspace-build-acceleration",
+]
+
 [[package]]
 name = "tracing"
 version = "0.1.41"

Cargo.toml

@@ -130,6 +130,7 @@ members = [
   "crates/schema/public/enums",
   "crates/schema/public/reusable_types", # TODO(bt, 2022-12-21): Deprecate
   "crates/schema/public/tokens",
+  "crates/schema/trace_id",
 
   # Services: API servers, jobs, workers, etc.
   "crates/service/job/gmicloud_job",
@@ -293,6 +294,7 @@ subprocess_common = { path = "crates/lib/deprecated/subprocess_common" }
 test_data = { path = "crates/testing/test_data" }
 test_utils = { path = "crates/testing/test_utils" }
 tokens = { path = "crates/schema/public/tokens" }
+trace_id = { path = "crates/schema/trace_id" }
 url_utils = { path = "crates/lib/url_utils" }
 users = { path = "crates/lib/users" }
 uuid_utils = { path = "crates/lib/uuid_utils" }

crates/lib/easyenv/Cargo.toml

@@ -25,6 +25,7 @@ workspace-build-acceleration = { version = "0.1", path = "../../workspace-build-
 # External
 dotenv.workspace = true
 env_logger = "0.11.3"
+trace_id.workspace = true
 log = "0.4.14"
 
 [dev-dependencies]

crates/lib/easyenv/src/logging.rs

@@ -29,6 +29,37 @@ pub fn init_env_logger(default_if_absent: Option<&str>) {
     env::set_var(ENV_RUST_LOG, default_log_level);
   }
 
-  env_logger::init();
+  // Custom format so that log lines emitted while serving an HTTP request
+  // automatically carry the request's trace id (see the `trace_id` crate and
+  // the `TraceIdMiddleware` in storyteller-web). Outside of a request scope
+  // the trace segment is simply omitted.
+  env_logger::Builder::from_env(env_logger::Env::default())
+      .format(|buf, record| {
+        use std::io::Write;
+
+        let timestamp = buf.timestamp();
+        let level_style = buf.default_level_style(record.level());
+
+        match trace_id::current_trace_id() {
+          Some(trace) => writeln!(
+            buf,
+            "[{} {level_style}{}{level_style:#} {} {}] {}",
+            timestamp,
+            record.level(),
+            record.target(),
+            trace,
+            record.args(),
+          ),
+          None => writeln!(
+            buf,
+            "[{} {level_style}{}{level_style:#} {}] {}",
+            timestamp,
+            record.level(),
+            record.target(),
+            record.args(),
+          ),
+        }
+      })
+      .init();
 }
 

crates/lib/logging/Cargo.toml

@@ -25,6 +25,7 @@ workspace-build-acceleration = { workspace = true }
 
 # External
 env_logger = "0.11.3"
+trace_id.workspace = true
 log = { workspace = true }
 
 [dev-dependencies]

crates/lib/logging/src/lib.rs

@@ -68,6 +68,37 @@ pub fn init_env_logger(default_if_absent: Option<&str>) {
     env::set_var(ENV_RUST_LOG, default_log_level);
   }
 
-  env_logger::init();
+  // Custom format so that log lines emitted while serving an HTTP request
+  // automatically carry the request's trace id (see the `trace_id` crate and
+  // the `TraceIdMiddleware` in storyteller-web). Outside of a request scope
+  // the trace segment is simply omitted.
+  env_logger::Builder::from_env(env_logger::Env::default())
+      .format(|buf, record| {
+        use std::io::Write;
+
+        let timestamp = buf.timestamp();
+        let level_style = buf.default_level_style(record.level());
+
+        match trace_id::current_trace_id() {
+          Some(trace) => writeln!(
+            buf,
+            "[{} {level_style}{}{level_style:#} {} {}] {}",
+            timestamp,
+            record.level(),
+            record.target(),
+            trace,
+            record.args(),
+          ),
+          None => writeln!(
+            buf,
+            "[{} {level_style}{}{level_style:#} {}] {}",
+            timestamp,
+            record.level(),
+            record.target(),
+            record.args(),
+          ),
+        }
+      })
+      .init();
 }
 

crates/lib/pager/Cargo.toml

@@ -24,6 +24,7 @@ chrono.workspace = true
 sha2.workspace = true
 log.workspace = true
 tokio.workspace = true
+trace_id.workspace = true
 
 [dev-dependencies]
 tokio = { version = "1", features = ["full"] }

crates/lib/pager/src/notification/notification_details.rs

@@ -49,6 +49,9 @@ pub struct NotificationDetails {
   /// Third-party identifier associated with the event, if any.
   pub(crate) third_party_id: Option<String>,
 
+  /// The request-scoped trace id associated with the event, if any.
+  pub(crate) trace_id: Option<String>,
+
   /// IP address of the request that triggered this notification, if any.
   pub(crate) request_ip_address: Option<String>,
 
@@ -189,6 +192,10 @@ impl NotificationDetails {
       parts.push(format!("Request IP: {}", ip));
     }
 
+    if let Some(trace_id) = &self.trace_id {
+      parts.push(format!("Trace ID: {}", trace_id));
+    }
+
     if parts.is_empty() { None } else { Some(parts.join("\n")) }
   }
 

crates/lib/pager/src/notification/notification_details_builder.rs

@@ -31,6 +31,10 @@ pub struct NotificationDetailsBuilder {
   pub(crate) avt_cookie_token: Option<String>,
   pub(crate) session_token: Option<String>,
   pub(crate) session_user_token: Option<String>,
+
+  /// The request-scoped trace id, if any. Auto-filled from the tokio
+  /// task-local at `build()` time when not explicitly set.
+  pub(crate) trace_id: Option<String>,
 }
 
 impl NotificationDetailsBuilder {
@@ -57,6 +61,7 @@ impl NotificationDetailsBuilder {
       avt_cookie_token: None,
       session_token: None,
       session_user_token: None,
+      trace_id: None,
     }
   }
 
@@ -87,6 +92,7 @@ impl NotificationDetailsBuilder {
       avt_cookie_token: None,
       session_token: None,
       session_user_token: None,
+      trace_id: None,
     }
   }
 
@@ -167,6 +173,11 @@ impl NotificationDetailsBuilder {
     self
   }
 
+  pub fn set_trace_id(mut self, trace_id: Option<String>) -> Self {
+    self.trace_id = trace_id;
+    self
+  }
+
   pub fn set_session_user_token(mut self, session_user_token: Option<String>) -> Self {
     self.session_user_token = session_user_token;
     self
@@ -199,6 +210,11 @@ impl NotificationDetailsBuilder {
       avt_cookie_token: self.avt_cookie_token,
       session_token: self.session_token,
       session_user_token: self.session_user_token,
+      // Auto-fill from the request's task-local so any page fired while
+      // serving a request is correlated even if the caller never set it.
+      trace_id: self.trace_id.or_else(|| {
+        trace_id::current_trace_id().map(|t| t.to_string())
+      }),
     }
   }
 

crates/schema/trace_id/Cargo.toml

@@ -0,0 +1,25 @@
+[package]
+name = "trace_id"
+edition = "2018"
+version = "0.0.1"
+authors = [
+    "Brandon Thomas <bt@brand.io>",
+    "Brandon Thomas <echelon@gmail.com>",
+]
+publish = false
+
+[package.metadata.cargo-udeps.ignore]
+normal = ["workspace-build-acceleration"]
+
+[lib]
+name = "trace_id"
+path = "src/lib.rs"
+
+[dependencies]
+# Workspace hack (faster compile times)
+workspace-build-acceleration.workspace = true
+
+rand = { version = "0.8.5", features = ["std_rng"] }
+serde.workspace = true
+serde_derive.workspace = true
+tokio.workspace = true

crates/schema/trace_id/src/lib.rs

@@ -0,0 +1,156 @@
+//! trace_id
+//!
+//! Request-scoped trace identifiers for observability.
+//!
+//! A `TraceId` is generated for every inbound HTTP request (see the
+//! `trace_id_middleware` in `storyteller-web`), stored in a tokio task-local,
+//! and emitted with every log line and pager notification produced while
+//! serving that request.
+
+use std::fmt;
+
+use serde_derive::{Deserialize, Serialize};
+
+/// The string prefix for trace ids.
+pub const TRACE_ID_PREFIX: &str = "trace_";
+
+/// Number of Crockford base32 characters after the prefix.
+/// 26 characters × 5 bits = 130 bits of entropy (≥ the 128-bit industry
+/// standard for trace ids). Total length: 6 + 26 = 32 characters.
+pub const TRACE_ID_ENTROPY_CHARS: usize = 26;
+
+/// Total serialized length of a trace id ("trace_" + entropy).
+pub const TRACE_ID_TOTAL_LENGTH: usize = 32;
+
+/// Crockford base32 alphabet, lowercase (no i, l, o, u).
+const CROCKFORD_LOWERCASE_CHARSET: &[u8] = b"0123456789abcdefghjkmnpqrstvwxyz";
+
+/// A unique-per-request trace identifier, eg. `trace_1h3x9k2m4p7q8r5t6v0w2y3z4a`.
+#[derive(Clone, Eq, PartialEq, Ord, PartialOrd, Hash, Serialize, Deserialize)]
+pub struct TraceId(String);
+
+impl TraceId {
+  /// Generate a new random trace id. Infallible.
+  #[inline]
+  pub fn generate() -> Self {
+    use rand::Rng;
+
+    let mut rng = rand::thread_rng();
+
+    let entropy: String = (0..TRACE_ID_ENTROPY_CHARS)
+      .map(|_| {
+        let idx = rng.gen_range(0..CROCKFORD_LOWERCASE_CHARSET.len());
+        CROCKFORD_LOWERCASE_CHARSET[idx] as char
+      })
+      .collect();
+
+    TraceId(format!("{}{}", TRACE_ID_PREFIX, entropy))
+  }
+
+  #[inline]
+  pub fn as_str(&self) -> &str {
+    &self.0
+  }
+}
+
+impl fmt::Display for TraceId {
+  fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+    write!(f, "{}", self.0)
+  }
+}
+
+impl fmt::Debug for TraceId {
+  fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+    write!(f, "{}", self.0)
+  }
+}
+
+tokio::task_local! {
+  /// The trace id for the currently-executing request, if any.
+  ///
+  /// Set by the HTTP middleware via [`TRACE_ID_TASK_LOCAL.scope(...)`], and
+  /// readable from anywhere within the request's task — including the
+  /// logger's format closure and the pager — via [`current_trace_id`].
+  pub static TRACE_ID_TASK_LOCAL: TraceId;
+}
+
+/// The trace id of the currently-executing request, if one is in scope.
+///
+/// Returns `None` outside of a request context (startup, background threads,
+/// detached `tokio::spawn` tasks that weren't explicitly re-scoped).
+#[inline]
+pub fn current_trace_id() -> Option<TraceId> {
+  TRACE_ID_TASK_LOCAL.try_with(|trace_id| trace_id.clone()).ok()
+}
+
+#[cfg(test)]
+mod tests {
+  use super::*;
+
+  mod generation {
+    use super::*;
+
+    #[test]
+    fn total_length_is_32() {
+      assert_eq!(TraceId::generate().as_str().len(), TRACE_ID_TOTAL_LENGTH);
+    }
+
+    #[test]
+    fn has_prefix() {
+      assert!(TraceId::generate().as_str().starts_with(TRACE_ID_PREFIX));
+    }
+
+    #[test]
+    fn entropy_uses_crockford_lowercase_only() {
+      let trace_id = TraceId::generate();
+      let entropy = &trace_id.as_str()[TRACE_ID_PREFIX.len()..];
+      assert_eq!(entropy.len(), TRACE_ID_ENTROPY_CHARS);
+      for c in entropy.chars() {
+        assert!(
+          CROCKFORD_LOWERCASE_CHARSET.contains(&(c as u8)),
+          "unexpected character: {}",
+          c
+        );
+      }
+    }
+
+    #[test]
+    fn ids_are_unique() {
+      let a = TraceId::generate();
+      let b = TraceId::generate();
+      assert_ne!(a, b);
+    }
+  }
+
+  mod task_local {
+    use super::*;
+
+    #[tokio::test]
+    async fn absent_outside_scope() {
+      assert!(current_trace_id().is_none());
+    }
+
+    #[tokio::test]
+    async fn present_inside_scope() {
+      let trace_id = TraceId::generate();
+      let expected = trace_id.clone();
+      TRACE_ID_TASK_LOCAL
+        .scope(trace_id, async move {
+          assert_eq!(current_trace_id(), Some(expected));
+        })
+        .await;
+    }
+
+    #[tokio::test]
+    async fn survives_await_points() {
+      let trace_id = TraceId::generate();
+      let expected = trace_id.clone();
+      TRACE_ID_TASK_LOCAL
+        .scope(trace_id, async move {
+          tokio::task::yield_now().await;
+          assert_eq!(current_trace_id(), Some(expected));
+        })
+        .await;
+    }
+  }
+}

crates/service/web/storyteller_web/Cargo.toml

@@ -89,6 +89,7 @@ seedance2pro_client.workspace = true
 server_environment = { path = "../../../lib/server_environment" }
 thumbnail_generator = { path = "../../../api_clients/thumbnail_generator" }
 tokens.workspace = true
+trace_id.workspace = true
 tts_common = { path = "../../../lib/deprecated/tts_common" }
 url_config = { path = "../../../lib/url_config" }
 url_utils = { path = "../../../lib/url_utils" }

crates/service/web/storyteller_web/src/http_server/middleware/error_alerting_middleware/handlers/check_common_web_error.rs

@@ -44,6 +44,7 @@ pub(crate) fn check_common_web_error(
       .set_urgency(Some(NotificationUrgency::Medium))
       .set_http_method(Some(method.to_string()))
       .set_http_path(Some(path.to_string()))
+      .set_trace_id(metadata.trace_id.clone())
       .set_http_status_code(Some(500))
       .set_request_ip_address(metadata.request_ip_address.clone())
       .set_avt_cookie_token(metadata.avt_cookie_token.clone())

crates/service/web/storyteller_web/src/http_server/middleware/error_alerting_middleware/handlers/check_status_code_fallback.rs

@@ -30,6 +30,7 @@ pub(crate) fn check_status_code_fallback(
           .set_urgency(Some(NotificationUrgency::Medium))
           .set_http_method(Some(method.to_string()))
           .set_http_path(Some(path.to_string()))
+          .set_trace_id(metadata.trace_id.clone())
           .set_http_status_code(Some(status_code))
           .set_request_ip_address(metadata.request_ip_address.clone())
           .set_avt_cookie_token(metadata.avt_cookie_token.clone())

crates/service/web/storyteller_web/src/http_server/middleware/error_alerting_middleware/request_debugging_metadata.rs

@@ -2,9 +2,12 @@ use std::sync::Arc;
 
 use actix_web::dev::ServiceRequest;
 use actix_web::web;
+use actix_web::HttpMessage;
 use http_server_common::request::get_request_ip::get_request_ip;
 use log::debug;
 
+use trace_id::TraceId;
+
 use crate::state::server_state::ServerState;
 
 /// Optional per-request context extracted by the error alerting middleware
@@ -16,6 +19,8 @@ pub(crate) struct RequestDebuggingMetadata {
   pub avt_cookie_token: Option<String>,
   pub session_token: Option<String>,
   pub session_user_token: Option<String>,
+  /// Set by `TraceIdMiddleware` (outermost middleware) on every request.
+  pub trace_id: Option<String>,
 }
 
 impl RequestDebuggingMetadata {
@@ -26,6 +31,10 @@ impl RequestDebuggingMetadata {
 
     let request_ip_address = Some(get_request_ip(http_request));
 
+    let trace_id = http_request.extensions()
+      .get::<TraceId>()
+      .map(|t| t.to_string());
+
     let server_state = req.app_data::<web::Data<Arc<ServerState>>>();
 
     let avt_cookie_token = server_state
@@ -58,6 +67,7 @@ impl RequestDebuggingMetadata {
       avt_cookie_token,
       session_token,
       session_user_token,
+      trace_id,
     }
   }
 }

crates/service/web/storyteller_web/src/http_server/middleware/mod.rs

@@ -1,3 +1,4 @@
 pub mod error_alerting_middleware;
 pub mod metrics_middleware;
 pub mod pushback_filter_middleware;
+pub mod trace_id_middleware;

crates/service/web/storyteller_web/src/http_server/middleware/trace_id_middleware/mod.rs

@@ -0,0 +1 @@
+pub mod trace_id_middleware;

crates/service/web/storyteller_web/src/http_server/middleware/trace_id_middleware/trace_id_middleware.rs

@@ -0,0 +1,95 @@
+//! Per-request trace id middleware.
+//!
+//! Generates a unique [`TraceId`] for every inbound HTTP request and makes it
+//! available three ways:
+//!
+//!   1. **Request extensions** — downstream middleware and handlers can read
+//!      it via `req.extensions().get::<TraceId>()`.
+//!   2. **Tokio task-local** — the whole request runs inside
+//!      [`trace_id::TRACE_ID_TASK_LOCAL`], so `trace_id::current_trace_id()`
+//!      works from anywhere in the request's task. The env-logger format
+//!      hook uses this to stamp every log line, and the pager uses it to tag
+//!      notifications.
+//!   3. **`x-trace-id` response header** — so clients and support tickets can
+//!      quote the id.
+//!
+//! Register this middleware LAST in the actix `.wrap(...)` chain so it runs
+//! FIRST (actix middleware executes in reverse registration order) and every
+//! other middleware sees the trace id.
+//!
+//! NB: Detached `tokio::spawn` tasks do NOT inherit the task-local. Wrap
+//! spawned futures in `TRACE_ID_TASK_LOCAL.scope(trace_id, fut)` if they
+//! should stay correlated.
+
+use std::future::{Future, Ready, ready};
+use std::pin::Pin;
+
+use actix_web::Error;
+use actix_web::HttpMessage;
+use actix_web::dev::{Service, ServiceRequest, ServiceResponse, Transform};
+use actix_web::http::header::{HeaderName, HeaderValue};
+
+use trace_id::{TraceId, TRACE_ID_TASK_LOCAL};
+
+/// Response header carrying the request's trace id.
+pub const TRACE_ID_HEADER: &str = "x-trace-id";
+
+#[derive(Clone, Default)]
+pub struct TraceIdMiddleware;
+
+impl<S, B> Transform<S, ServiceRequest> for TraceIdMiddleware
+where
+  S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = Error> + 'static,
+  S::Future: 'static,
+  B: 'static,
+{
+  type Response = ServiceResponse<B>;
+  type Error = Error;
+  type InitError = ();
+  type Transform = TraceIdService<S>;
+  type Future = Ready<Result<Self::Transform, Self::InitError>>;
+
+  fn new_transform(&self, service: S) -> Self::Future {
+    ready(Ok(TraceIdService { service }))
+  }
+}
+
+pub struct TraceIdService<S> {
+  service: S,
+}
+
+impl<S, B> Service<ServiceRequest> for TraceIdService<S>
+where
+  S: Service<ServiceRequest, Response = ServiceResponse<B>, Error = Error> + 'static,
+  S::Future: 'static,
+  B: 'static,
+{
+  type Response = ServiceResponse<B>;
+  type Error = Error;
+  type Future = Pin<Box<dyn Future<Output = Result<Self::Response, Self::Error>>>>;
+
+  actix_service::forward_ready!(service);
+
+  fn call(&self, req: ServiceRequest) -> Self::Future {
+    let trace_id = TraceId::generate();
+
+    // Make the trace id readable from the request itself.
+    req.extensions_mut().insert(trace_id.clone());
+
+    let response_trace_id = trace_id.clone();
+    let fut = self.service.call(req);
+
+    Box::pin(TRACE_ID_TASK_LOCAL.scope(trace_id, async move {
+      let mut response = fut.await?;
+
+      if let Ok(header_value) = HeaderValue::from_str(response_trace_id.as_str()) {
+        response.headers_mut().insert(
+          HeaderName::from_static(TRACE_ID_HEADER),
+          header_value,
+        );
+      }
+
+      Ok(response)
+    }))
+  }
+}

crates/service/web/storyteller_web/src/main.rs

@@ -26,6 +26,7 @@ use actix_helpers::middleware::banned_cidr_filter::banned_cidr_filter::BannedCid
 use actix_helpers::middleware::banned_ip_filter::banned_ip_filter::BannedIpFilter;
 use actix_helpers::middleware::disabled_endpoint_filter::disabled_endpoint_filter::DisabledEndpointFilter;
 use actix_multipart::form::MultipartFormConfig;
+use actix_web::HttpMessage;
 use actix_web::middleware::{DefaultHeaders, Logger};
 use actix_web::{middleware, web, App, HttpServer};
 use billing_component::stripe::traits::internal_product_to_stripe_lookup::InternalProductToStripeLookup;
@@ -46,6 +47,7 @@ use crate::billing::stripe_internal_user_lookup_impl::StripeInternalUserLookupIm
 use crate::http_server::middleware::error_alerting_middleware::error_alerting_middleware::ErrorAlertingMiddleware;
 use crate::http_server::middleware::metrics_middleware::metrics_middleware::MetricsMiddleware;
 use crate::http_server::middleware::pushback_filter_middleware::PushbackFilter;
+use crate::http_server::middleware::trace_id_middleware::trace_id_middleware::TraceIdMiddleware;
 use crate::http_server::routes::add_routes::add_routes;
 use crate::http_server::web_utils::handle_multipart_error::handle_multipart_error;
 use crate::startup::build_dependencies::setup_dependencies;
@@ -65,9 +67,10 @@ pub mod state;
 pub mod threads;
 pub mod util;
 
-// Report cloudflare trace ID header (CF-Ray) in logs
+// Report cloudflare trace ID header (CF-Ray) and our request trace id in logs.
+// %{trace_id}xi is resolved by `custom_request_replace` below.
 const LOG_FORMAT: &str =
-  "[%{HOSTNAME}e] IP=[%{X-Forwarded-For}i] %{CF-Ray}i \"%r\" %s %b \"%{Referer}i\" \"%{User-Agent}i\" %T";
+  "[%{HOSTNAME}e] IP=[%{X-Forwarded-For}i] %{CF-Ray}i %{trace_id}xi \"%r\" %s %b \"%{Referer}i\" \"%{User-Agent}i\" %T";
 
 #[actix_web::main]
 async fn main() -> AnyhowResult<()> {
@@ -269,9 +272,21 @@ pub async fn serve(
       .wrap(BannedIpFilter::new(ip_ban_list))
       .wrap(BannedCidrFilter::new(cidr_ban_set))
       .wrap(Logger::new(LOG_FORMAT)
+        // NB: The access-log line is written after the response body completes,
+        // which is OUTSIDE the trace-id task-local scope — so we resolve the
+        // trace id from request extensions at request time instead.
+        .custom_request_replace("trace_id", |req| {
+          req.extensions()
+              .get::<trace_id::TraceId>()
+              .map(|t| t.to_string())
+              .unwrap_or_else(|| "-".to_string())
+        })
         .exclude("/liveness")
         .exclude("/readiness"))
-      .wrap(middleware::Compress::default());
+      .wrap(middleware::Compress::default())
+      // NB: Registered last => runs FIRST. Every request gets a trace id
+      // before any other middleware or handler executes.
+      .wrap(TraceIdMiddleware);
 
     add_routes(app, server_environment)
   })