starknet_transaction_prover: per-request structured log with request-id

Cargo.toml

@@ -415,6 +415,7 @@ tracing-test = "0.2"
 trybuild = "1.0.105"
 unsigned-varint = "0.8.0"
 url = "2.5.0"
+uuid = "1"
 validator = "0.20"
 void = "1.0.2"
 waker-fn = "1.2.0"

crates/starknet_transaction_prover/Cargo.toml

@@ -57,6 +57,7 @@ tower_ohttp.workspace = true
 tracing.workspace = true
 tracing-subscriber = { workspace = true, features = ["env-filter"] }
 url.workspace = true
+uuid = { workspace = true, features = ["v4"] }
 
 [dev-dependencies]
 apollo_starknet_os_program.workspace = true

crates/starknet_transaction_prover/src/server.rs

@@ -40,7 +40,8 @@ pub const OHTTP_JSONRPSEE_BODY_BUILDER: fn(Full<Bytes>) -> HttpBody = HttpBody::
 /// each call site.
 ///
 /// Layer order (tower makes the last-added layer innermost):
-/// - `HealthLayer` sits outermost so `GET /health` is answered before any other middleware runs.
+/// - `RequestLogLayer` is outermost so the latency it measures covers every other layer.
+/// - `HealthLayer` sits inside it so probes complete before CORS/OHTTP.
 /// - `OhttpLayer` must sit OUTSIDE `CompressionLayer` so compression applies to the inner JSON-RPC
 ///   response (the client's inner `Accept-Encoding` travels through BHTTP into jsonrpsee) rather
 ///   than to the OHTTP ciphertext envelope. `MapRequestBodyLayer`/`MapResponseBodyLayer` keep
@@ -49,6 +50,7 @@ pub const OHTTP_JSONRPSEE_BODY_BUILDER: fn(Full<Bytes>) -> HttpBody = HttpBody::
 macro_rules! prover_http_middleware {
     ($cors_layer:expr, $ohttp_layer:expr $(,)?) => {
         ServiceBuilder::new()
+            .layer(RequestLogLayer)
             .layer(HealthLayer)
             .option_layer($cors_layer)
             .layer(MapRequestBodyLayer::new(HttpBody::new))
@@ -65,11 +67,13 @@ pub mod health;
 pub mod log_redact;
 #[cfg(test)]
 pub mod mock_rpc;
+pub mod request_log;
 pub mod rpc_api;
 pub mod rpc_impl;
 pub mod tls;
 
 pub use health::{HealthLayer, HEALTH_PATH};
+pub use request_log::{RequestLogLayer, REQUEST_ID_HEADER};
 
 #[cfg(test)]
 mod rpc_spec_test;

crates/starknet_transaction_prover/src/server/request_log.rs

@@ -0,0 +1,165 @@
+//! tower middleware that logs one structured line per HTTP request and
+//! propagates a request id.
+//!
+//! This is the outermost, envelope-level layer: it emits one log line with
+//! `event="http_request"`, `request_id`, `method`, `path`, `status`, and
+//! `latency_ms` per HTTP request, and echoes `request_id` on the response so
+//! callers can quote it. The id is accepted from the incoming `x-request-id`
+//! header or generated as a UUID v4.
+//!
+//! It deliberately does NOT bind the id to a span covering the downstream
+//! dispatch. For OHTTP traffic this layer runs on the *outer* envelope, whose
+//! id is visible to the relay (echoed on the ciphertext response). Propagating
+//! that id into the logs describing the *decapsulated* contents would create a
+//! join key linking the relay's view (who) to the gateway's view (what),
+//! defeating OHTTP unlinkability. Content-level correlation — a fresh,
+//! envelope-unlinkable id bound below the OHTTP layer — is added by a
+//! follow-up layer.
+//!
+//! Body bytes are never inspected — transaction calldata is private user data
+//! per the privacy-pool threat model.
+
+use std::pin::Pin;
+use std::task::{Context, Poll};
+use std::time::Instant;
+
+use http::{HeaderValue, Request, Response};
+use jsonrpsee::server::HttpBody;
+use tower::{Layer, Service};
+use tracing::info;
+
+#[cfg(test)]
+#[path = "request_log_test.rs"]
+mod request_log_test;
+
+/// HTTP header carrying the request id.
+pub const REQUEST_ID_HEADER: &str = "x-request-id";
+
+/// Cap on accepted incoming request-id length. Anything longer is dropped
+/// in favour of a freshly generated id so the value never balloons into
+/// AsyncLocalStorage / tracing fields and so log aggregators don't have
+/// to parse megabyte-scale ids.
+const MAX_REQUEST_ID_LEN: usize = 128;
+
+/// Cap on the logged request path. The URI is attacker-controlled and this
+/// layer is outermost, so an over-long path would bloat every log line; it is
+/// truncated for logging only (the request itself is untouched).
+const MAX_LOG_PATH_LEN: usize = 256;
+
+pub(crate) fn new_request_id() -> String {
+    uuid::Uuid::new_v4().to_string()
+}
+
+/// Truncates an over-long path on a char boundary for safe logging.
+fn truncated_log_path(path: &str) -> String {
+    if path.len() <= MAX_LOG_PATH_LEN {
+        return path.to_string();
+    }
+    let mut end = MAX_LOG_PATH_LEN;
+    while !path.is_char_boundary(end) {
+        end -= 1;
+    }
+    format!("{}…(truncated)", &path[..end])
+}
+
+/// Accepts the incoming `x-request-id` only when it's a short printable
+/// ASCII token. CR/LF would let a client smuggle headers into the
+/// response; arbitrary bytes (including unicode) make the value unsafe
+/// to round-trip through `HeaderValue::from_str`. Any reject falls back
+/// to a freshly generated UUID v4.
+pub(crate) fn extract_or_generate_request_id<B>(request: &Request<B>) -> String {
+    request
+        .headers()
+        .get(REQUEST_ID_HEADER)
+        .and_then(|value| value.to_str().ok())
+        .filter(|value| !value.is_empty() && value.len() <= MAX_REQUEST_ID_LEN)
+        .filter(|value| value.bytes().all(is_safe_request_id_byte))
+        .map(|value| value.to_string())
+        .unwrap_or_else(new_request_id)
+}
+
+fn is_safe_request_id_byte(byte: u8) -> bool {
+    // Reject whitespace/CR/LF/NUL/control bytes so the id can't smuggle headers
+    // into the response or break structured-log parsers.
+    byte.is_ascii_graphic()
+}
+
+/// tower [`Layer`] producing [`RequestLogService`].
+#[derive(Clone, Copy, Default)]
+pub struct RequestLogLayer;
+
+impl<S> Layer<S> for RequestLogLayer {
+    type Service = RequestLogService<S>;
+
+    fn layer(&self, inner: S) -> Self::Service {
+        RequestLogService { inner }
+    }
+}
+
+#[derive(Clone)]
+pub struct RequestLogService<S> {
+    inner: S,
+}
+
+impl<S, ReqB> Service<Request<ReqB>> for RequestLogService<S>
+where
+    S: Service<Request<ReqB>, Response = Response<HttpBody>>,
+    S::Future: Send + 'static,
+    S::Error: Send + 'static,
+{
+    type Response = Response<HttpBody>;
+    type Error = S::Error;
+    type Future =
+        Pin<Box<dyn std::future::Future<Output = Result<Self::Response, Self::Error>> + Send>>;
+
+    fn poll_ready(&mut self, cx: &mut Context<'_>) -> Poll<Result<(), Self::Error>> {
+        self.inner.poll_ready(cx)
+    }
+
+    fn call(&mut self, mut request: Request<ReqB>) -> Self::Future {
+        let request_id = extract_or_generate_request_id(&request);
+        if let Ok(header_value) = HeaderValue::from_str(&request_id) {
+            request.headers_mut().insert(REQUEST_ID_HEADER, header_value);
+        }
+        let method = request.method().clone();
+        let path = truncated_log_path(request.uri().path());
+        let start = Instant::now();
+
+        let future = self.inner.call(request);
+
+        Box::pin(async move {
+            let result = future.await;
+            let latency_ms = u64::try_from(start.elapsed().as_millis()).unwrap_or(u64::MAX);
+            match result {
+                Ok(mut response) => {
+                    let status = response.status().as_u16();
+                    if let Ok(header_value) = HeaderValue::from_str(&request_id) {
+                        response.headers_mut().insert(REQUEST_ID_HEADER, header_value);
+                    }
+                    info!(
+                        event = "http_request",
+                        request_id = %request_id,
+                        method = %method,
+                        path = %path,
+                        status = status,
+                        latency_ms = latency_ms,
+                        "HTTP request handled."
+                    );
+                    Ok(response)
+                }
+                Err(err) => {
+                    info!(
+                        event = "http_request",
+                        request_id = %request_id,
+                        method = %method,
+                        path = %path,
+                        latency_ms = latency_ms,
+                        outcome = "service_error",
+                        "HTTP request failed in tower stack."
+                    );
+                    Err(err)
+                }
+            }
+        })
+    }
+}

crates/starknet_transaction_prover/src/server/request_log_test.rs

@@ -0,0 +1,120 @@
+use bytes::Bytes;
+use http::{Method, Request, Response, StatusCode};
+use http_body_util::{BodyExt, Full};
+use jsonrpsee::server::HttpBody;
+use tower::{Layer, ServiceExt};
+
+use crate::server::request_log::{RequestLogLayer, REQUEST_ID_HEADER};
+
+fn echo_request_id_service() -> impl tower::Service<
+    Request<HttpBody>,
+    Response = Response<HttpBody>,
+    Error = std::convert::Infallible,
+    Future = futures::future::Ready<Result<Response<HttpBody>, std::convert::Infallible>>,
+> + Clone {
+    tower::service_fn(|req: Request<HttpBody>| {
+        let id = req
+            .headers()
+            .get(REQUEST_ID_HEADER)
+            .map(|value| value.to_str().unwrap().to_string())
+            .unwrap_or_default();
+        let response = Response::builder()
+            .status(StatusCode::OK)
+            .body(HttpBody::new(Full::new(Bytes::from(id))))
+            .expect("static body is infallible");
+        futures::future::ready(Ok::<_, std::convert::Infallible>(response))
+    })
+}
+
+fn request_with_header(value: Option<&str>) -> Request<HttpBody> {
+    let mut builder = Request::builder().method(Method::POST).uri("/");
+    if let Some(value) = value {
+        builder = builder.header(REQUEST_ID_HEADER, value);
+    }
+    builder.body(HttpBody::new(Full::new(Bytes::new()))).expect("static body is infallible")
+}
+
+async fn read_body(response: Response<HttpBody>) -> (Vec<u8>, http::HeaderMap) {
+    let (parts, body) = response.into_parts();
+    let bytes = body.collect().await.expect("body collect").to_bytes().to_vec();
+    (bytes, parts.headers)
+}
+
+#[tokio::test]
+async fn echoes_supplied_request_id_on_response() {
+    let svc = RequestLogLayer.layer(echo_request_id_service());
+
+    let response = svc.oneshot(request_with_header(Some("client-supplied-id"))).await.unwrap();
+
+    let (body, headers) = read_body(response).await;
+    assert_eq!(headers.get(REQUEST_ID_HEADER).unwrap(), "client-supplied-id");
+    assert_eq!(String::from_utf8(body).unwrap(), "client-supplied-id");
+}
+
+#[tokio::test]
+async fn generates_request_id_when_absent_and_echoes_it() {
+    let svc = RequestLogLayer.layer(echo_request_id_service());
+
+    let response = svc.oneshot(request_with_header(None)).await.unwrap();
+
+    let (body, headers) = read_body(response).await;
+    let header_id = headers.get(REQUEST_ID_HEADER).unwrap().to_str().unwrap();
+    let body_id = String::from_utf8(body).unwrap();
+    // Body is what the inner service saw — they must match (the layer
+    // rewrote the request header before forwarding).
+    assert_eq!(header_id, body_id);
+    // Canonical UUID v4: 8-4-4-4-12 hex with hyphens.
+    assert!(uuid::Uuid::parse_str(header_id).is_ok(), "expected a UUID, got {header_id:?}");
+    assert_eq!(uuid::Uuid::parse_str(header_id).unwrap().get_version_num(), 4);
+}
+
+#[tokio::test]
+async fn drops_non_ascii_incoming_id_and_generates_a_fresh_one() {
+    let mut request = request_with_header(None);
+    request
+        .headers_mut()
+        .insert(REQUEST_ID_HEADER, http::HeaderValue::from_bytes(b"\xff\xfe").unwrap());
+
+    let svc = RequestLogLayer.layer(echo_request_id_service());
+    let response = svc.oneshot(request).await.unwrap();
+
+    let (_body, headers) = read_body(response).await;
+    let header_id = headers.get(REQUEST_ID_HEADER).unwrap().to_str().unwrap();
+    assert!(uuid::Uuid::parse_str(header_id).is_ok(), "should have generated a fresh UUID");
+}
+
+#[tokio::test]
+async fn drops_request_id_containing_whitespace() {
+    // CRLF in header values is rejected by the http crate itself at parse
+    // time, so the residual concern is whitespace and other ASCII bytes
+    // that would confuse log parsers if echoed verbatim into structured
+    // fields.
+    for hostile in ["with space", "tab\there", "leading space "] {
+        let mut request = request_with_header(None);
+        request
+            .headers_mut()
+            .insert(REQUEST_ID_HEADER, http::HeaderValue::from_bytes(hostile.as_bytes()).unwrap());
+        let svc = RequestLogLayer.layer(echo_request_id_service());
+        let response = svc.oneshot(request).await.unwrap();
+        let (_body, headers) = read_body(response).await;
+        let header_id = headers.get(REQUEST_ID_HEADER).unwrap().to_str().unwrap();
+        assert!(
+            uuid::Uuid::parse_str(header_id).is_ok(),
+            "expected fresh UUID for hostile input {hostile:?}, got {header_id:?}",
+        );
+    }
+}
+
+#[tokio::test]
+async fn drops_oversize_request_id() {
+    let huge = "a".repeat(2048);
+    let mut request = request_with_header(None);
+    request
+        .headers_mut()
+        .insert(REQUEST_ID_HEADER, http::HeaderValue::from_bytes(huge.as_bytes()).unwrap());
+    let svc = RequestLogLayer.layer(echo_request_id_service());
+    let response = svc.oneshot(request).await.unwrap();
+    let (_body, headers) = read_body(response).await;
+    let header_id = headers.get(REQUEST_ID_HEADER).unwrap().to_str().unwrap();
+    assert!(uuid::Uuid::parse_str(header_id).is_ok());
+}

crates/starknet_transaction_prover/src/server/tls.rs

@@ -27,7 +27,7 @@ use tower_http::map_request_body::MapRequestBodyLayer;
 use tower_http::map_response_body::MapResponseBodyLayer;
 use tracing::warn;
 
-use crate::server::{HealthLayer, OhttpJsonrpseeLayer};
+use crate::server::{HealthLayer, OhttpJsonrpseeLayer, RequestLogLayer};
 
 /// Maximum time allowed for a TLS handshake before the connection is dropped.
 const TLS_HANDSHAKE_TIMEOUT: Duration = Duration::from_secs(10);