logger improvements

fix all usages of logging, kill me please

added req-id correlation to subscriptions

ok

ok

trying to clear perf refression take 1

ok

hmm ok

fix

ok that's better

ok

ok

fixes

slight refactor

implement request summary, refactor levels, added missing log enties

Author: dotansimha

Cargo.lock

@@ -35,7 +35,7 @@ codegen-units = 1
 serde = { version = "1.0.219", features = ["derive"] }
 serde_json = "1.0.150"
 sonic-rs = "0.5.3"
-insta = { version = "1.42.1", features= ["filters"] }
+insta = { version = "1.42.1", features= ["filters", "json", "redactions"] }
 criterion = { version = "0.8", features = ["html_reports", "async_tokio"] }
 lazy_static = "1.5.0"
 dashmap = { version = "6.2.1" }
@@ -105,14 +105,15 @@ opentelemetry-stdout = "0.31.0"
 opentelemetry-appender-tracing = "0.31.1"
 opentelemetry-jaeger-propagator = "0.31.0"
 opentelemetry-zipkin = { version = "0.31.0", default-features = false, features=["reqwest-rustls", "reqwest-client"] }
-tracing = "0.1.44"
+tracing = { version = "0.1.44", features = ["release_max_level_debug", "max_level_trace"] }
 tracing-opentelemetry = "0.32.0"
 tracing-subscriber = { version = "0.3.22", features = [
   "env-filter",
   "time",
   "json",
 ] }
 tracing-tree = "0.4.0"
+tracing-appender = "0.2.5"
 
 # Storage
 object_store = { version = "0.13.2", features = ["aws"] }

Cargo.toml

@@ -233,7 +233,7 @@ impl Plugin for PersistedDocumentsPlugin {
                                 }
                                 match mgr.resolve_document(document_id).await {
                                     Ok(document) => {
-                                        info!("Document found in persisted documents: {}", document);
+                                        debug!("Document found in persisted documents: {}", document);
 
                                         if req
                                             .context

apollo-router-workspace/bin/router/src/persisted_documents.rs

@@ -37,7 +37,7 @@ reqwest = { workspace = true }
 sonic-rs = { workspace = true }
 tracing = { workspace = true }
 tracing-subscriber = { workspace = true }
-tracing-tree = { workspace = true }
+tracing-appender = { workspace = true }
 hyper = { workspace = true, features = ["server", "http1"] }
 http = { workspace = true }
 http-body-util = { workspace = true }

bin/router/Cargo.toml

@@ -1,5 +1,8 @@
 use hive_router_config::jwt_auth::{JwksProviderSourceConfig, JwtAuthConfig};
-use hive_router_internal::background_tasks::{BackgroundTask, BackgroundTasksManager};
+use hive_router_internal::{
+    background_tasks::{BackgroundTask, BackgroundTasksManager},
+    telemetry::logging::targets,
+};
 use sonic_rs::from_str;
 use std::sync::{Arc, RwLock};
 use tokio::fs::read_to_string;
@@ -29,7 +32,7 @@ impl JwksManager {
             .filter_map(|v| match v.get_jwk_set() {
                 Ok(set) => Some(set),
                 Err(err) => {
-                    error!("Failed to use JWK set: {}, ignoring", err);
+                    error!(target: targets::JWT, error = ?err, "failed to use jwt set, ignoring this set");
 
                     None
                 }
@@ -79,9 +82,10 @@ impl BackgroundTask for JwksSourceTask {
             ..
         } = &self.0.config
         {
-            debug!(
-                "Starting remote jwks polling for source: {:?}",
-                self.0.config
+            info!(
+                target: targets::JWT,
+                source = ?self.0.config,
+                "starting remote jwks polling for source",
             );
             let mut tokio_interval = tokio::time::interval(*interval);
 
@@ -90,10 +94,10 @@ impl BackgroundTask for JwksSourceTask {
                     _ = tokio_interval.tick() => { match self.0.load_and_store_jwks().await {
                         Ok(_) => {}
                         Err(err) => {
-                            error!("Failed to load remote jwks: {}", err);
+                            error!(target: targets::JWT, error = ?err, source = ?self.0.config, "failed to load remote jwks");
                         }
                     } }
-                    _ = token.cancelled() => { info!("Jwks source shutting down."); return; }
+                    _ = token.cancelled() => { info!(target: targets::JWT, "jwks source shutting down."); return; }
                 }
             }
         }
@@ -117,7 +121,7 @@ impl JwksSource {
         let jwks_str = match &self.config {
             JwksProviderSourceConfig::Remote { url, .. } => {
                 let client = reqwest::Client::new();
-                debug!("loading jwks from a remote source: {}", url);
+                debug!(target: targets::JWT, url = ?url, "loading jwks from a remote source");
 
                 let response_text = client
                     .get(url)
@@ -131,7 +135,7 @@ impl JwksSource {
                 response_text
             }
             JwksProviderSourceConfig::File { file, .. } => {
-                debug!("loading jwks from a file source: {}", file.absolute);
+                debug!(target: targets::JWT, path = ?file.absolute, "loading jwks from a file source");
 
                 let file_contents = read_to_string(&file.absolute)
                     .await

bin/router/src/jwt/jwks_manager.rs

@@ -6,7 +6,7 @@ use std::{str::FromStr, sync::Arc};
 
 use cookie::Cookie;
 use hive_router_config::jwt_auth::{JwtAuthConfig, JwtAuthPluginLookupLocation};
-use hive_router_internal::background_tasks::BackgroundTasksManager;
+use hive_router_internal::{background_tasks::BackgroundTasksManager, telemetry::logging::targets};
 use http::header::COOKIE;
 use jsonwebtoken::{
     decode, decode_header,
@@ -94,7 +94,7 @@ impl JwtAuthRuntime {
                         let raw_cookies = match cookie_raw.to_str() {
                             Ok(cookies) => cookies.split(';'),
                             Err(e) => {
-                                warn!("jwt auth failed to convert cookie header to string, ignoring cookie. error: {}", e);
+                                warn!(target: targets::JWT, error = ?e, "jwt auth failed to convert cookie header to string, ignoring cookie");
                                 continue;
                             }
                         };
@@ -111,10 +111,7 @@ impl JwtAuthRuntime {
                                 Err(e) => {
                                     // Should we reject the entire request in case of invalid cookies?
                                     // I think it's better to consider this as a user error? maybe return 400?
-                                    warn!(
-                       "jwt auth failed to parse cookie value, ignoring cookie. error: {}",
-                       e
-                     );
+                                    warn!(target: targets::JWT, error = ?e, "jwt auth failed to parse cookie value, ignoring cookie");
                                 }
                             }
                         }
@@ -173,7 +170,7 @@ impl JwtAuthRuntime {
                     .map(|token_data| (token_data, maybe_prefix, token))
             }
             Err(e) => {
-                warn!("jwt plugin failed to lookup token. error: {}", e);
+                warn!(target: targets::JWT, error = ?e, "jwt plugin failed to lookup token");
 
                 Err(JwtError::LookupFailed(e))
             }
@@ -311,7 +308,7 @@ impl JwtAuthRuntime {
                 token_prefix: maybe_prefix,
             })),
             Err(err) => {
-                warn!("jwt token error: {:?}", err);
+                warn!(target: targets::JWT, error = ?err, "jwt token error");
                 if self.config.require_authentication.is_some_and(|v| v) {
                     Err((*err).clone())
                 } else {