traceid logging

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/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;
@@ -66,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<()> {
@@ -270,6 +272,15 @@ 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())