From b791ca42b59ebed007f694ff3e83acd28a97df8d Mon Sep 17 00:00:00 2001 From: Brandon Thomas Date: Fri, 3 Jul 2026 02:22:44 -0400 Subject: [PATCH] traceid logging --- Cargo.lock | 15 +++++++++++++++ Cargo.toml | 2 ++ crates/service/web/storyteller_web/src/main.rs | 15 +++++++++++++-- 3 files changed, 30 insertions(+), 2 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 9ac3bb827b..9248b7a4d9 100644 --- a/Cargo.lock +++ b/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" diff --git a/Cargo.toml b/Cargo.toml index 63b990d369..251a0093cd 100644 --- a/Cargo.toml +++ b/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" } diff --git a/crates/service/web/storyteller_web/src/main.rs b/crates/service/web/storyteller_web/src/main.rs index 50627aa863..6bb5bbd3b1 100644 --- a/crates/service/web/storyteller_web/src/main.rs +++ b/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::() + .map(|t| t.to_string()) + .unwrap_or_else(|| "-".to_string()) + }) .exclude("/liveness") .exclude("/readiness")) .wrap(middleware::Compress::default())