fix all usages of logging, kill me please

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" }

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 {

bin/router/src/jwt/mod.rs

@@ -12,9 +12,14 @@ mod supergraph;
 pub mod telemetry;
 mod utils;
 
+use http::{
+    header::{ACCEPT, CONTENT_TYPE, USER_AGENT},
+    HeaderName,
+};
+use ntex_http::body::{BodySize, MessageBody};
 use std::ops::ControlFlow;
 use std::sync::Arc;
-use tracing::error;
+use tracing::{debug, error};
 
 use crate::{
     consts::ROUTER_VERSION,
@@ -61,10 +66,8 @@ pub use hive_router_config::humantime_serde;
 use hive_router_config::{load_config, subscriptions::CallbackConfig, HiveRouterConfig};
 pub use hive_router_internal::background_tasks;
 use hive_router_internal::telemetry::{
-    logging::{log_http_request_end, log_http_request_start},
-    otel::tracing_opentelemetry::OpenTelemetrySpanExt,
-    traces::spans::http_request::HttpServerRequestSpan,
-    TelemetryContext,
+    logging::targets, otel::tracing_opentelemetry::OpenTelemetrySpanExt,
+    traces::spans::http_request::HttpServerRequestSpan, TelemetryContext,
 };
 pub use hive_router_internal::BoxError;
 use hive_router_internal::{
@@ -125,6 +128,17 @@ impl BackgroundTask for CallbackServer {
     }
 }
 
+#[inline]
+fn obtain_header_value<'a>(
+    header_map: &'a ntex::http::HeaderMap,
+    header_name: &HeaderName,
+) -> &'a str {
+    header_map
+        .get(header_name)
+        .map(|h| h.to_str().unwrap_or(""))
+        .unwrap_or("")
+}
+
 async fn graphql_endpoint_handler(
     mut request: HttpRequest,
     body_stream: web::types::Payload,
@@ -152,11 +166,42 @@ async fn graphql_endpoint_handler(
         .capture_request(&request);
 
     let response = async {
-        log_http_request_start(&request);
+        let content_type = obtain_header_value(request.headers(), &CONTENT_TYPE);
+        let accept = obtain_header_value(request.headers(), &ACCEPT);
+        let user_agent = obtain_header_value(request.headers(), &USER_AGENT);
+
+        info!(
+            target: targets::HTTP_SERVER,
+            method = request.method().as_str(),
+            path = request.path(),
+            "http request started",
+        );
+
+        debug!(
+            target: targets::HTTP_SERVER,
+            query_string = request.query_string(),
+            content_type,
+            accept,
+            user_agent,
+            "http request attributes",
+        );
+
         let inner_res =
             graphql_endpoint_dispatch(&mut request, body_stream, schema_state, app_state.clone())
                 .await;
-        log_http_request_end(&inner_res);
+
+        let payload_bytes = match inner_res.body().size() {
+            BodySize::Empty | BodySize::None => 0,
+            BodySize::Sized(size) => size as i64,
+            BodySize::Stream => -1,
+        };
+
+        info!(
+            target: targets::HTTP_SERVER,
+            status_code = inner_res.status().as_u16(),
+            payload_bytes,
+            "http request completed",
+        );
 
         inner_res
     }
@@ -237,7 +282,7 @@ async fn graphql_endpoint_dispatch(
             .take()
             .modify_client_response_headers(response.headers_mut())
         {
-            error!(error = %err, "Failed to apply response header rules to the outgoing client response");
+            error!(target: targets::HEADER_MANIPULATION, error = %err, "failed to apply response header rules to the outgoing client response");
         }
 
         // Apply CORS headers to the final response if CORS is configured.
@@ -260,7 +305,7 @@ async fn graphql_endpoint_dispatch(
                     ControlFlow::Break(updated_response) | ControlFlow::Continue(updated_response),
                 ) => updated_response,
                 Err(error) => {
-                    warn!(%error, "coprocessor graphql.response stage failed");
+                    warn!(target: targets::COPROCESSOR, error = ?error, "coprocessor graphql.response stage failed");
                     write_graphql_response_metric_status(request, GraphQLResponseStatus::Error);
                     handle_pipeline_error(error.into(), request, &app_state, &response_mode)
                 }
@@ -291,7 +336,7 @@ pub async fn router_entrypoint(plugin_registry: PluginRegistry) -> Result<(), Ro
         .prometheus
         .as_ref()
         .and_then(|prom| prom.to_attached());
-    info!("hive-router@{} starting...", ROUTER_VERSION);
+    info!(target: targets::CORE, version = ROUTER_VERSION, "hive-router starting...");
     let addr = router_config.address();
     let graphql_path = router_config.graphql_path().to_string();
     let websocket_path = router_config.websocket_path().map(|p| p.to_string());
@@ -332,8 +377,9 @@ pub async fn router_entrypoint(plugin_registry: PluginRegistry) -> Result<(), Ro
             });
             if let Some(workers) = workers {
                 info!(
-                    "configuring HTTP callback server with {} worker(s)",
-                    workers
+                    target: targets::CORE,
+                    workers_count = workers,
+                    "configuring HTTP callback server worker(s)",
                 );
                 cb_server_builder = cb_server_builder.workers(workers.get());
             }
@@ -386,7 +432,7 @@ pub async fn router_entrypoint(plugin_registry: PluginRegistry) -> Result<(), Ro
     });
 
     if let Some(workers) = workers {
-        info!("configuring HTTP server with {} worker(s)", workers);
+        info!(target: targets::CORE, workers_count = workers, "configuring HTTP server worker(s)");
         server = server.workers(workers.get());
     }
 
@@ -426,7 +472,7 @@ pub async fn router_entrypoint(plugin_registry: PluginRegistry) -> Result<(), Ro
     .await
     .map_err(RouterInitError::HttpServerStartError);
 
-    info!("server stopped, clearing background tasks");
+    info!(target: targets::CORE, "router stopped, clearing background tasks");
     bg_tasks_manager.shutdown();
     telemetry.graceful_shutdown().await;
 
@@ -437,7 +483,8 @@ pub async fn router_entrypoint(plugin_registry: PluginRegistry) -> Result<(), Ro
 
 pub async fn invoke_shutdown_hooks(shared_state: &RouterSharedState) {
     if let Some(plugins) = &shared_state.plugins {
-        info!("invoking plugin shutdown hooks");
+        debug!(target: targets::CORE, "invoking plugin shutdown hooks");
+
         for plugin in plugins.as_ref() {
             plugin.on_shutdown().await;
         }
@@ -676,7 +723,7 @@ pub fn init_rustls_crypto_provider() {
         .install_default()
         .is_err()
     {
-        warn!("Rustls crypto provider already installed");
+        error!(target: targets::TLS, "rustls crypto provider already installed, ignoring");
     }
 }
 

bin/router/src/lib.rs

@@ -2,6 +2,7 @@ use std::sync::Arc;
 
 use bytes::Bytes;
 use dashmap::DashMap;
+use hive_router_internal::telemetry::logging::targets;
 use hive_router_plan_executor::response::graphql_error::GraphQLError;
 use tokio::sync::broadcast;
 use tracing::trace;
@@ -54,7 +55,7 @@ impl ActiveSubscriptions {
             _guard: guard,
         };
 
-        trace!(subscription_id = %id, "registered new subscription");
+        trace!(target: targets::SUBSCRIPTIONS, subscription_id = %id, "registered new subscription");
 
         (handle, receiver)
     }
@@ -93,6 +94,6 @@ impl ProducerHandle {
 impl Drop for ProducerHandle {
     fn drop(&mut self) {
         self.map.remove(&self.id);
-        trace!(subscription_id = %self.id, "producer dropped, upstream closed");
+        trace!(target: targets::SUBSCRIPTIONS, subscription_id = %self.id, "producer dropped, upstream closed");
     }
 }

bin/router/src/pipeline/active_subscriptions.rs

@@ -29,6 +29,7 @@ use crate::pipeline::normalize::{hash_normalized_operation, GraphQLNormalization
 use hive_router_config::authorization::UnauthorizedMode;
 use hive_router_config::HiveRouterConfig;
 use hive_router_internal::authorization::metadata::AuthorizationMetadata;
+use hive_router_internal::telemetry::logging::targets;
 use hive_router_plan_executor::execution::client_request_details::JwtRequestDetails;
 use hive_router_plan_executor::execution::plan::CoerceVariablesPayload;
 use hive_router_plan_executor::introspection::schema::SchemaMetadata;
@@ -180,7 +181,8 @@ pub fn apply_authorization_to_operation(
     }
 
     if reject_mode {
-        tracing::debug!("Request rejected due to unauthorized fields and reject mode being set");
+        tracing::warn!(target: targets::AUTHORIZATION, "request rejected due to unauthorized fields and reject mode being set");
+
         return AuthorizationDecision::Reject {
             errors: collection_result.errors,
         };