fix all usages of logging, kill me please

Author: dotansimha

bin/router/src/jwt/jwks_manager.rs

@@ -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/mod.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/lib.rs

@@ -14,7 +14,7 @@ mod utils;
 
 use std::ops::ControlFlow;
 use std::sync::Arc;
-use tracing::error;
+use tracing::{debug, error};
 
 use crate::{
     consts::ROUTER_VERSION,
@@ -61,7 +61,7 @@ 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},
+    logging::{log_http_request_end, log_http_request_start, targets},
     otel::tracing_opentelemetry::OpenTelemetrySpanExt,
     traces::spans::http_request::HttpServerRequestSpan,
     TelemetryContext,
@@ -237,7 +237,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 +260,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 +291,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 +332,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 +387,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 +427,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 +438,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 +678,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/pipeline/active_subscriptions.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/authorization/mod.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,
         };

bin/router/src/pipeline/coerce_variables.rs

@@ -1,11 +1,12 @@
 use std::collections::HashMap;
 
+use hive_router_internal::telemetry::logging::targets;
 use hive_router_internal::telemetry::traces::spans::graphql::GraphQLVariableCoercionSpan;
 use hive_router_plan_executor::execution::plan::CoerceVariablesPayload;
 use hive_router_plan_executor::hooks::on_supergraph_load::SupergraphData;
 use hive_router_plan_executor::variables::collect_variables;
 use sonic_rs::Value;
-use tracing::{trace, warn};
+use tracing::{debug, warn};
 
 use crate::pipeline::error::PipelineError;
 use crate::pipeline::normalize::GraphQLNormalizationPayload;
@@ -24,9 +25,10 @@ pub fn coerce_request_variables(
         &supergraph.metadata,
     ) {
         Ok(values) => {
-            trace!(
-                "sucessfully collected variables from incoming request: {:?}",
-                values
+            debug!(
+                target: targets::COERCE_VARIABLES,
+                variables = ?values,
+                "sucessfully collected variables from incoming request",
             );
 
             Ok(CoerceVariablesPayload {
@@ -35,8 +37,9 @@ pub fn coerce_request_variables(
         }
         Err(err_msg) => {
             warn!(
-                "failed to collect variables from incoming request: {}",
-                err_msg
+                target: targets::COERCE_VARIABLES,
+                error = ?err_msg,
+                "failed to collect variables from incoming request",
             );
             Err(PipelineError::VariablesCoercionError(err_msg))
         }

bin/router/src/pipeline/demand_control/formula.rs

@@ -1,5 +1,6 @@
 use ahash::{HashMap as AHashMap, HashMapExt, HashSet as AHashSet, HashSetExt};
 
+use hive_router_internal::telemetry::logging::targets;
 use hive_router_plan_executor::execution::demand_control::demand_control_definition_cost;
 use hive_router_plan_executor::execution::demand_control::CompiledActualCostPlan;
 use hive_router_plan_executor::execution::demand_control::DemandControlEvaluation;
@@ -298,6 +299,7 @@ fn eval_cost_expr(
                     Ok(only_value)
                 } else {
                     warn!(
+                        target: targets::DEMAND_CONTROL,
                         field = field_name.as_str(),
                         found = resolved_count,
                         "rejecting operation: expected exactly one slicing argument for @listSize"

bin/router/src/pipeline/demand_control/runtime.rs

@@ -6,6 +6,7 @@ use hive_router_config::demand_control::{
     DemandControlActualCostMode, DemandControlConfig, DemandControlExposeHeadersConfig,
     DemandControlMode,
 };
+use hive_router_internal::telemetry::logging::targets;
 use hive_router_internal::telemetry::metrics::demand_control_metrics::DemandControlResultCode;
 use hive_router_internal::telemetry::metrics::Metrics;
 use hive_router_internal::telemetry::traces::spans::graphql::GraphQLSpanOperationIdentity;
@@ -44,12 +45,15 @@ impl DemandControlRuntime {
         metrics: Arc<Metrics>,
     ) -> Option<Self> {
         let config = config?;
+
         if !config.enabled {
-            debug!("demand control is disabled");
+            debug!(target: targets::DEMAND_CONTROL, "demand control is disabled");
+
             return None;
         }
 
         info!(
+            target: targets::DEMAND_CONTROL,
             operation_mode = ?config.operation_cost.mode,
             operation_max_cost = config.operation_cost.max,
             subgraph_budget_mode = ?config.subgraphs_budget.mode,
@@ -61,6 +65,7 @@ impl DemandControlRuntime {
         if config.operation_cost.mode == DemandControlMode::Enforce {
             if config.operation_cost.max == 0 {
                 warn!(
+                    target: targets::DEMAND_CONTROL,
                     "demand control is in enforce mode with a max cost of 0; all operations with non-zero cost will be rejected"
                 );
             }
@@ -69,6 +74,7 @@ impl DemandControlRuntime {
                 && config.default_list_size.subgraphs.is_none()
             {
                 warn!(
+                    target: targets::DEMAND_CONTROL,
                     "demand control is in enforce mode without a default list_size; list fields without an @listSize directive are estimated as 0 and may be under-counted"
                 );
             }
@@ -141,6 +147,7 @@ impl DemandControlRuntime {
             match self.config.operation_cost.mode {
                 DemandControlMode::Enforce => {
                     warn!(
+                        target: targets::DEMAND_CONTROL,
                         operation_name = ?operation_name,
                         estimated_cost = evaluation.estimated_cost,
                         max_cost,
@@ -166,6 +173,7 @@ impl DemandControlRuntime {
                 }
                 DemandControlMode::Measure => {
                     info!(
+                        target: targets::DEMAND_CONTROL,
                         operation_name = ?operation_name,
                         estimated_cost = evaluation.estimated_cost,
                         max_cost,
@@ -231,7 +239,13 @@ impl DemandControlRuntime {
 
             if let Some(subgraph_max) = maybe_subgraph_max {
                 if *estimated_cost > subgraph_max {
-                    debug!(subgraph_name = subgraph.as_str(), estimated_cost, subgraph_max, "subgraph call will be blocked dueing execution due to estimated cost exceeding limit");
+                    debug!(
+                        target: targets::DEMAND_CONTROL,
+                        subgraph_name = subgraph.as_str(),
+                        estimated_cost,
+                        subgraph_max,
+                        "subgraph call will be blocked during execution due to estimated cost exceeding limit"
+                    );
                     over_limit.insert(subgraph.clone(), subgraph_max);
                 }
             }