From 771c3716ea230407e46c4ee1a21c0fa8ef6fa831 Mon Sep 17 00:00:00 2001 From: abdoolyaro Date: Mon, 27 Jul 2026 23:22:14 +0100 Subject: [PATCH 1/2] feat: structured logging with request correlation for verifier (#1058) - Apply TraceLayer to the router with a per-request span that carries the request ID as a field, so every log line for a request is correlated - Honour an inbound X-Request-Id header (propagated from the NestJS backend per BE-136); generate a UUID only when absent, and echo it back on the response via PropagateRequestIdLayer - Emit JSON logs in production and human-readable logs in development, controlled by a new APP_ENV config value (defaults to development) - Instrument Stellar and cache module methods with #[instrument] spans and enable span-close timing events, so their latency is attributable per request - Skip secret keys and full document hashes from span fields; only a truncated hash prefix is recorded, matching the existing log convention in stellar.rs Closes #1058 --- contract/Cargo.toml | 4 ++-- contract/src/cache.rs | 6 ++++++ contract/src/config.rs | 21 +++++++++++++++++++++ contract/src/lib.rs | 41 +++++++++++++++++++++++++++++++++++++++-- contract/src/main.rs | 18 ++++++++++++++++-- contract/src/stellar.rs | 30 ++++++++++++++++++++++++++++++ 6 files changed, 114 insertions(+), 6 deletions(-) diff --git a/contract/Cargo.toml b/contract/Cargo.toml index b134228..c7434ba 100644 --- a/contract/Cargo.toml +++ b/contract/Cargo.toml @@ -8,7 +8,7 @@ edition = "2021" axum = "0.7" tokio = { version = "1.35", features = ["full"] } tower = "0.4" -tower-http = { version = "0.5", features = ["trace", "cors"] } +tower-http = { version = "0.5", features = ["trace", "cors", "request-id"] } url = "2" futures = "0.3" @@ -33,7 +33,7 @@ prometheus = "0.13" # Logging tracing = "0.1" -tracing-subscriber = { version = "0.3", features = ["env-filter"] } +tracing-subscriber = { version = "0.3", features = ["env-filter", "json"] } # Error handling thiserror = "1.0" diff --git a/contract/src/cache.rs b/contract/src/cache.rs index c9460b8..dcf59cb 100644 --- a/contract/src/cache.rs +++ b/contract/src/cache.rs @@ -11,6 +11,7 @@ pub enum CacheBackend { } impl CacheBackend { + #[tracing::instrument(name = "cache.check_connection", skip(self))] pub async fn check_connection(&self) -> bool { match self { Self::Redis(c) => c.check_connection().await, @@ -18,6 +19,7 @@ impl CacheBackend { } } + #[tracing::instrument(name = "cache.get_raw", skip(self), fields(key = %key))] pub async fn get_raw(&self, key: &str) -> Result> { match self { Self::Redis(c) => c.get_raw(key).await, @@ -25,6 +27,7 @@ impl CacheBackend { } } + #[tracing::instrument(name = "cache.set_raw", skip(self, value), fields(key = %key, ttl = ttl))] pub async fn set_raw(&self, key: &str, value: &str, ttl: u64) -> Result<()> { match self { Self::Redis(c) => c.set_raw(key, value, ttl).await, @@ -32,6 +35,7 @@ impl CacheBackend { } } + #[tracing::instrument(name = "cache.get", skip(self), fields(key = %key))] pub async fn get(&self, key: &str) -> Result> where T: for<'de> Deserialize<'de>, @@ -42,6 +46,7 @@ impl CacheBackend { } } + #[tracing::instrument(name = "cache.set", skip(self, value), fields(key = %key, ttl = ttl))] pub async fn set(&self, key: &str, value: &T, ttl: u64) -> Result<()> where T: Serialize, @@ -50,6 +55,7 @@ impl CacheBackend { self.set_raw(key, &serialized, ttl).await } + #[tracing::instrument(name = "cache.delete", skip(self), fields(key = %key))] pub async fn delete(&self, key: &str) -> Result<()> { match self { Self::Redis(c) => c.delete(key).await, diff --git a/contract/src/config.rs b/contract/src/config.rs index 573b835..6119d79 100644 --- a/contract/src/config.rs +++ b/contract/src/config.rs @@ -3,6 +3,23 @@ use std::env; use thiserror::Error; use url::Url; +/// Deployment environment. Controls log output format: JSON in production, +/// human-readable in development. Unrecognized values default to development. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum Environment { + Development, + Production, +} + +impl Environment { + fn from_env_str(value: &str) -> Self { + match value.trim().to_ascii_lowercase().as_str() { + "production" | "prod" => Self::Production, + _ => Self::Development, + } + } +} + #[derive(Debug, Clone)] pub struct AppConfig { pub port: u16, @@ -13,6 +30,7 @@ pub struct AppConfig { pub rate_limit_burst: u32, pub stellar_max_retries: u32, pub log_level: String, + pub environment: Environment, pub webhook_urls: Vec, pub webhook_secret: Option, pub cache_verification_ttl: u64, @@ -39,6 +57,7 @@ impl AppConfig { get_env_or_default("STELLAR_HORIZON_URL", "https://horizon-testnet.stellar.org"); let redis_url = get_env_or_default("REDIS_URL", "redis://127.0.0.1:6379"); let log_level = get_env_or_default("LOG_LEVEL", "info"); + let environment = Environment::from_env_str(&get_env_or_default("APP_ENV", "development")); let webhook_urls_raw = get_env_or_default("WEBHOOK_URLS", ""); let stellar_secret_key = match env::var("STELLAR_SECRET_KEY") { @@ -161,6 +180,7 @@ impl AppConfig { rate_limit_burst, stellar_max_retries, log_level, + environment, webhook_urls, webhook_secret, cache_verification_ttl, @@ -185,6 +205,7 @@ mod tests { "RATE_LIMIT_BURST", "STELLAR_MAX_RETRIES", "LOG_LEVEL", + "APP_ENV", "WEBHOOK_URLS", "WEBHOOK_SECRET", "CACHE_VERIFICATION_TTL", diff --git a/contract/src/lib.rs b/contract/src/lib.rs index a555e88..af81918 100644 --- a/contract/src/lib.rs +++ b/contract/src/lib.rs @@ -7,7 +7,7 @@ pub mod stellar; use axum::{ extract::{Path, State}, - http::StatusCode, + http::{HeaderName, Request, StatusCode}, response::{IntoResponse, Response}, routing::{get, post}, Json, Router, @@ -18,6 +18,8 @@ use serde::{Deserialize, Serialize}; use sha2::{Digest, Sha256}; use std::collections::HashMap; use std::sync::Arc; +use tower::ServiceBuilder; +use tower_http::request_id::{MakeRequestUuid, PropagateRequestIdLayer, SetRequestIdLayer}; use tower_http::trace::TraceLayer; use tracing::{info, warn}; @@ -26,6 +28,11 @@ use hash_validator::{HashValidator, ValidationError as HashValidationError}; use metrics::MetricsRegistry; use stellar::{derive_account_id, StellarClient, TransactionRecord}; +/// Header used to correlate a single logical operation across the NestJS +/// backend and this verifier service (see BE-136). Must match the header +/// name used by the backend. +pub const REQUEST_ID_HEADER: &str = "x-request-id"; + // Application state #[derive(Clone)] pub struct AppState { @@ -178,6 +185,9 @@ fn map_validation_error(err: HashValidationError) -> (StatusCode, ValidationErro } pub fn app(state: AppState) -> Router { + let request_id_header = HeaderName::from_static(REQUEST_ID_HEADER); + let span_header = request_id_header.clone(); + Router::new() .route("/health", get(health_check)) .route("/metrics", get(metrics_handler)) @@ -188,7 +198,34 @@ pub fn app(state: AppState) -> Router { .route("/submit", post(submit_document)) .route("/revoke", post(revoke_document)) .route("/transfer", post(record_transfer)) - .layer(TraceLayer::new_for_http()) + .layer( + ServiceBuilder::new() + // Honour an inbound X-Request-Id (propagated from the NestJS + // backend, per BE-136); generate one only if it's absent. + .layer(SetRequestIdLayer::new( + request_id_header.clone(), + MakeRequestUuid, + )) + .layer( + TraceLayer::new_for_http().make_span_with(move |request: &Request<_>| { + let request_id = request + .headers() + .get(&span_header) + .and_then(|v| v.to_str().ok()) + .unwrap_or("unknown"); + + tracing::info_span!( + "http_request", + method = %request.method(), + path = %request.uri().path(), + request_id = %request_id, + ) + }), + ) + // Echo the request id back on the response so callers (and + // the backend) can confirm which id was used for this op. + .layer(PropagateRequestIdLayer::new(request_id_header)), + ) .with_state(state) } diff --git a/contract/src/main.rs b/contract/src/main.rs index 380140e..84bb36a 100644 --- a/contract/src/main.rs +++ b/contract/src/main.rs @@ -1,7 +1,7 @@ use std::sync::Arc; use stellar_doc_verifier::app; use stellar_doc_verifier::cache::{CacheBackend, RedisCache}; -use stellar_doc_verifier::config::AppConfig; +use stellar_doc_verifier::config::{AppConfig, Environment}; use stellar_doc_verifier::metrics::MetricsRegistry; use stellar_doc_verifier::stellar::StellarClient; use stellar_doc_verifier::*; @@ -22,7 +22,21 @@ async fn main() -> Result<(), Box> { )) }); - tracing_subscriber::fmt().with_env_filter(env_filter).init(); + match config.environment { + Environment::Production => { + tracing_subscriber::fmt() + .with_env_filter(env_filter) + .with_span_events(tracing_subscriber::fmt::format::FmtSpan::CLOSE) + .json() + .init(); + } + Environment::Development => { + tracing_subscriber::fmt() + .with_env_filter(env_filter) + .with_span_events(tracing_subscriber::fmt::format::FmtSpan::CLOSE) + .init(); + } + } info!("Starting Stellar Document Verification Service"); diff --git a/contract/src/stellar.rs b/contract/src/stellar.rs index 675aba9..1d1edd5 100644 --- a/contract/src/stellar.rs +++ b/contract/src/stellar.rs @@ -123,6 +123,7 @@ impl StellarClient { } } + #[tracing::instrument(name = "stellar.check_connection", skip(self))] pub async fn check_connection(&self) -> bool { self.http_client .get(&self.horizon_url) @@ -135,6 +136,11 @@ impl StellarClient { /// Verifies a document hash against Horizon using the `ManageData` approach. /// /// Reads `account.data_attr` for key `"doc_" + &hash[..58]`. + #[tracing::instrument( + name = "stellar.verify_hash", + skip(self, hash), + fields(hash_prefix = %hash_prefix(hash), anchor_account_id = %anchor_account_id) + )] pub async fn verify_hash( &self, hash: &str, @@ -188,6 +194,11 @@ impl StellarClient { } /// Fetches all ManageData history entries for a given document hash (anchors, updates, transfers). + #[tracing::instrument( + name = "stellar.get_hash_history", + skip(self, hash), + fields(hash_prefix = %hash_prefix(hash), anchor_account_id = %anchor_account_id) + )] pub async fn get_hash_history( &self, hash: &str, @@ -247,6 +258,11 @@ impl StellarClient { } /// Anchor a transfer record on Stellar using a `ManageData` operation. + #[tracing::instrument( + name = "stellar.anchor_transfer", + skip(self, transfer_hash, secret_key), + fields(hash_prefix = %hash_prefix(transfer_hash), public_key = %public_key) + )] pub async fn anchor_transfer( &self, transfer_hash: &str, @@ -359,6 +375,11 @@ impl StellarClient { /// /// # Key format /// `"doc_" + &hash[..58]` — matches NestJS `buildDataKey()`. + #[tracing::instrument( + name = "stellar.anchor_hash", + skip(self, hash, secret_key), + fields(hash_prefix = %hash_prefix(hash), public_key = %public_key) + )] pub async fn anchor_hash( &self, hash: &str, @@ -467,6 +488,11 @@ impl StellarClient { /// /// Key: `"revoked_" + &hash[..56]` (max 64 bytes). /// Value: the revocation JSON payload (truncated to 64 bytes). + #[tracing::instrument( + name = "stellar.anchor_revocation", + skip(self, hash, revocation_json, secret_key), + fields(hash_prefix = %hash_prefix(hash), public_key = %public_key) + )] pub async fn anchor_revocation( &self, hash: &str, @@ -575,6 +601,10 @@ impl StellarClient { } /// Build the ManageData key: `"doc_" + &hash[..58]` (max 62 bytes ≤ 64-byte limit). +fn hash_prefix(hash: &str) -> &str { + &hash[..hash.len().min(16)] +} + pub fn build_data_key(hash: &str) -> String { let suffix_len = hash.len().min(58); format!("doc_{}", &hash[..suffix_len]) From 316d8164e06791dab6d421a18d7d4326a44ac7ab Mon Sep 17 00:00:00 2001 From: abdoolyaro Date: Tue, 28 Jul 2026 09:04:38 +0100 Subject: [PATCH 2/2] fix: unblock compilation on main after lib.rs module split main was broken at HEAD (introduced by the lib-split refactor, d0eae81) with three compile errors unrelated to CT-59: - handlers/submit.rs called a nonexistent map_validation_error_inline; fixed to use the real map_validation_error from crate::types - CacheBackend and MetricsRegistry were used behind #[derive(Clone)] on AppState but didn't implement Clone themselves (nor did their inner RedisCache/InMemoryCache variants) - CacheBackend was missing a public close() dispatcher that main.rs's graceful-shutdown path already called Also derives Clone on RedisCache/InMemoryCache, adds the missing CacheBackend::close() dispatcher matching the existing check_connection() pattern, removes now-unused imports flagged by the compiler, and applies cargo fmt to a few files that were already out of sync with rustfmt. Note: cargo test --all still fails on main independent of this fix, in files unrelated to CT-59 (metrics.rs test assertions call methods on impl IntoResponse before extracting the body; handler_integration_tests.rs is missing a tower::util::ServiceExt import for .oneshot()). Not fixed here as it's outside this issue's scope -- flagging separately. --- contract/src/cache.rs | 21 +++++++++++++++++++-- contract/src/handlers/health.rs | 6 +----- contract/src/handlers/submit.rs | 5 ++--- contract/src/handlers/transfer.rs | 2 +- contract/src/handlers/verify.rs | 2 +- contract/src/metrics.rs | 1 + contract/src/routes.rs | 10 ++++++++-- contract/src/types.rs | 2 +- contract/tests/handler_integration_tests.rs | 20 ++++++++++++++------ 9 files changed, 48 insertions(+), 21 deletions(-) diff --git a/contract/src/cache.rs b/contract/src/cache.rs index fe67d40..bc110e8 100644 --- a/contract/src/cache.rs +++ b/contract/src/cache.rs @@ -6,6 +6,7 @@ use std::sync::Arc; use tokio::sync::RwLock; use tracing::warn; +#[derive(Clone)] pub enum CacheBackend { Redis(RedisCache), InMemory(InMemoryCache), @@ -20,6 +21,14 @@ impl CacheBackend { } } + #[tracing::instrument(name = "cache.close", skip(self))] + pub async fn close(&self) { + match self { + Self::Redis(c) => c.close().await, + Self::InMemory(c) => c.close().await, + } + } + #[tracing::instrument(name = "cache.get_raw", skip(self), fields(key = %key))] pub async fn get_raw(&self, key: &str) -> Result> { match self { @@ -65,6 +74,7 @@ impl CacheBackend { } } +#[derive(Clone)] pub struct RedisCache { connection: ConnectionManager, } @@ -111,6 +121,7 @@ impl RedisCache { } } +#[derive(Clone)] pub struct InMemoryCache { store: Arc>>, } @@ -179,7 +190,10 @@ mod tests { async fn test_overwrite_value() { let cache = in_memory_backend(); cache.set("key1", &"first".to_string(), 3600).await.unwrap(); - cache.set("key1", &"second".to_string(), 3600).await.unwrap(); + cache + .set("key1", &"second".to_string(), 3600) + .await + .unwrap(); let result: Option = cache.get("key1").await.unwrap(); assert_eq!(result, Some("second".to_string())); } @@ -261,7 +275,10 @@ mod tests { #[tokio::test] async fn test_cache_backend_enum_dispatch() { let cache = in_memory_backend(); - cache.set("enum_key", &"enum_value".to_string(), 3600).await.unwrap(); + cache + .set("enum_key", &"enum_value".to_string(), 3600) + .await + .unwrap(); let result: Option = cache.get("enum_key").await.unwrap(); assert_eq!(result, Some("enum_value".to_string())); } diff --git a/contract/src/handlers/health.rs b/contract/src/handlers/health.rs index cf5e29f..1ee24c5 100644 --- a/contract/src/handlers/health.rs +++ b/contract/src/handlers/health.rs @@ -1,8 +1,4 @@ -use axum::{ - extract::State, - response::IntoResponse, - Json, -}; +use axum::{extract::State, response::IntoResponse, Json}; use crate::types::{AppState, HealthResponse}; diff --git a/contract/src/handlers/submit.rs b/contract/src/handlers/submit.rs index 41fd125..e27ddfc 100644 --- a/contract/src/handlers/submit.rs +++ b/contract/src/handlers/submit.rs @@ -7,8 +7,7 @@ use axum::{ use tracing::{info, warn}; use crate::hash_validator::HashValidator; -use crate::stellar::derive_account_id; -use crate::types::{AppState, SubmitRequest, SubmitResponse}; +use crate::types::{map_validation_error, AppState, SubmitRequest, SubmitResponse}; /// POST /submit — anchor a document hash to Stellar using a ManageData operation. /// @@ -22,7 +21,7 @@ pub async fn submit_document( ) -> Response { let normalized_hash = HashValidator::normalize(&req.document_hash); if let Err(err) = HashValidator::validate_sha256(&normalized_hash) { - let (status, body) = super::verify::map_validation_error_inline(err); + let (status, body) = map_validation_error(err); return (status, Json(body)).into_response(); } diff --git a/contract/src/handlers/transfer.rs b/contract/src/handlers/transfer.rs index f952b60..cbb1ec1 100644 --- a/contract/src/handlers/transfer.rs +++ b/contract/src/handlers/transfer.rs @@ -1,7 +1,7 @@ use axum::{ extract::{Path, State}, http::StatusCode, - response::{IntoResponse, Response}, + response::IntoResponse, Json, }; use chrono::{NaiveDate, Utc}; diff --git a/contract/src/handlers/verify.rs b/contract/src/handlers/verify.rs index 928d5a8..0bad739 100644 --- a/contract/src/handlers/verify.rs +++ b/contract/src/handlers/verify.rs @@ -11,7 +11,7 @@ use crate::hash_validator::{HashValidator, ValidationError as HashValidationErro use crate::stellar::derive_account_id; use crate::types::{ map_validation_error, AppState, BatchVerifyItem, BatchVerifyRequest, BatchVerifyResponse, - HistoryResponse, VerifyRequest, VerifyResponse, ValidationErrorResponse, + HistoryResponse, ValidationErrorResponse, VerifyRequest, VerifyResponse, }; // Verify document by POST diff --git a/contract/src/metrics.rs b/contract/src/metrics.rs index 67c3bb5..86cb81d 100644 --- a/contract/src/metrics.rs +++ b/contract/src/metrics.rs @@ -1,6 +1,7 @@ use axum::response::IntoResponse; use prometheus::{Counter, Encoder, Registry, TextEncoder}; +#[derive(Clone)] pub struct MetricsRegistry { registry: Registry, request_count: Counter, diff --git a/contract/src/routes.rs b/contract/src/routes.rs index b3bd61f..69d2f82 100644 --- a/contract/src/routes.rs +++ b/contract/src/routes.rs @@ -14,11 +14,17 @@ pub fn app(state: AppState) -> Router { .route("/verify", post(verify::verify_document)) .route("/verify/batch", post(verify::batch_verify_documents)) .route("/verify/:hash", get(verify::verify_document_by_hash)) - .route("/verify/:hash/history", get(verify::verify_document_history)) + .route( + "/verify/:hash/history", + get(verify::verify_document_history), + ) .route("/submit", post(submit::submit_document)) .route("/revoke", post(revoke::revoke_document)) .route("/transfer", post(transfer::record_transfer)) - .route("/transfer/:document_hash", get(transfer::get_transfer_history)) + .route( + "/transfer/:document_hash", + get(transfer::get_transfer_history), + ) .layer(TraceLayer::new_for_http()) .with_state(state) } diff --git a/contract/src/types.rs b/contract/src/types.rs index 3d9060f..4e9658e 100644 --- a/contract/src/types.rs +++ b/contract/src/types.rs @@ -3,7 +3,7 @@ use serde::{Deserialize, Serialize}; use sha2::{Digest, Sha256}; use std::collections::HashMap; -use crate::hash_validator::{HashValidator, ValidationError as HashValidationError}; +use crate::hash_validator::ValidationError as HashValidationError; use crate::stellar::TransactionRecord; // Application state diff --git a/contract/tests/handler_integration_tests.rs b/contract/tests/handler_integration_tests.rs index 2933749..069f3c4 100644 --- a/contract/tests/handler_integration_tests.rs +++ b/contract/tests/handler_integration_tests.rs @@ -1,12 +1,12 @@ -use axum::http::{Request, StatusCode}; use axum::body::Body; +use axum::http::{Request, StatusCode}; +use std::sync::Arc; use stellar_doc_verifier::app; use stellar_doc_verifier::cache::{CacheBackend, InMemoryCache}; use stellar_doc_verifier::config::AppConfig; use stellar_doc_verifier::metrics::MetricsRegistry; use stellar_doc_verifier::stellar::StellarClient; use stellar_doc_verifier::AppState; -use std::sync::Arc; use tower::ServiceExt; fn test_app_state() -> AppState { @@ -39,7 +39,9 @@ async fn test_health_check_returns_200() { assert_eq!(response.status(), StatusCode::OK); - let body = axum::body::to_bytes(response.into_body(), usize::MAX).await.unwrap(); + let body = axum::body::to_bytes(response.into_body(), usize::MAX) + .await + .unwrap(); let json: serde_json::Value = serde_json::from_slice(&body).unwrap(); assert!(json.get("status").is_some()); assert!(json.get("stellar_connected").is_some()); @@ -63,7 +65,9 @@ async fn test_metrics_handler_returns_prometheus_text() { assert_eq!(response.status(), StatusCode::OK); - let body = axum::body::to_bytes(response.into_body(), usize::MAX).await.unwrap(); + let body = axum::body::to_bytes(response.into_body(), usize::MAX) + .await + .unwrap(); let text = String::from_utf8(body.to_vec()).unwrap(); assert!(text.contains("requests_total")); } @@ -162,7 +166,9 @@ async fn test_submit_with_invalid_hash_returns_400() { .method("POST") .uri("/submit") .header("content-type", "application/json") - .body(Body::from(r#"{"document_hash": "invalid", "document_id": "doc1", "submitter": "test"}"#)) + .body(Body::from( + r#"{"document_hash": "invalid", "document_id": "doc1", "submitter": "test"}"#, + )) .unwrap(), ) .await @@ -182,7 +188,9 @@ async fn test_revoke_with_invalid_hash_returns_400() { .method("POST") .uri("/revoke") .header("content-type", "application/json") - .body(Body::from(r#"{"document_hash": "invalid", "reason": "test", "revoked_by": "admin"}"#)) + .body(Body::from( + r#"{"document_hash": "invalid", "reason": "test", "revoked_by": "admin"}"#, + )) .unwrap(), ) .await