logger improvements

Author: dotansimha

Cargo.lock

@@ -113,6 +113,7 @@ tracing-subscriber = { version = "0.3.22", features = [
   "json",
 ] }
 tracing-tree = "0.4.0"
+tracing-appender = "0.2.5"
 
 # Storage
 object_store = { version = "0.13.2", features = ["aws"] }

Cargo.toml

@@ -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

@@ -60,12 +60,17 @@ use graphql_tools::validation::rules::default_rules_validation_plan;
 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::background_tasks::{BackgroundTask, CancellationToken};
 use hive_router_internal::telemetry::{
+    logging::{log_http_request_end, log_http_request_start},
     otel::tracing_opentelemetry::OpenTelemetrySpanExt,
-    traces::spans::http_request::HttpServerRequestSpan, TelemetryContext,
+    traces::spans::http_request::HttpServerRequestSpan,
+    TelemetryContext,
 };
 pub use hive_router_internal::BoxError;
+use hive_router_internal::{
+    background_tasks::{BackgroundTask, CancellationToken},
+    telemetry::logging::logger_span::LoggerRootSpan,
+};
 use hive_router_internal::{
     http::read_request_body_size, telemetry::metrics::catalog::values::GraphQLResponseStatus,
 };
@@ -126,14 +131,37 @@ async fn graphql_endpoint_handler(
     schema_state: web::types::State<Arc<SchemaState>>,
     app_state: web::types::State<Arc<RouterSharedState>>,
 ) -> web::HttpResponse {
+    let parent_ctx = app_state
+        .telemetry_context
+        .extract_context(&HeaderExtractor(request.headers()));
+    let trace_id = app_state
+        .telemetry_context
+        .logging_correlation_extractor
+        .extract_trace_id(&parent_ctx);
+    let req_id = app_state
+        .telemetry_context
+        .logging_correlation_extractor
+        .extract_req_id(&request);
+
+    let root_logging_span = LoggerRootSpan::create(&req_id, &trace_id);
+
     let http_request_capture = app_state
         .telemetry_context
         .metrics
         .http_server
         .capture_request(&request);
 
-    let response =
-        graphql_endpoint_dispatch(&mut request, body_stream, schema_state, app_state.clone()).await;
+    let response = async {
+        log_http_request_start(&request);
+        let inner_res =
+            graphql_endpoint_dispatch(&mut request, body_stream, schema_state, app_state.clone())
+                .await;
+        log_http_request_end(&inner_res);
+
+        inner_res
+    }
+    .instrument(root_logging_span.span)
+    .await;
 
     let graphql_operation = read_graphql_operation_metric_identity(&request);
     let graphql_operation_name = graphql_operation

bin/router/src/lib.rs

@@ -1,11 +1,13 @@
-use std::{io::IsTerminal, str::FromStr, sync::Mutex};
-
-use hive_router_config::{log::LogFormat, HiveRouterConfig};
+use hive_router_config::{
+    log::{LogFormat, LoggingConfig},
+    HiveRouterConfig,
+};
 use hive_router_internal::{
     http::normalize_route_path,
     telemetry::{
         build_otel_layer_from_config, build_resource, build_scope,
         error::TelemetryError,
+        logging::utils::{create_ignore_otel_filter, create_targets_filter, DynLayer},
         metrics::{build_meter_provider_from_config, PrometheusRuntimeConfig},
         otel::{
             opentelemetry::{
@@ -25,12 +27,11 @@ use hive_router_internal::{
 use ntex::web::{self};
 use ntex::web::{App, HttpResponse, HttpServer};
 use prometheus::{Encoder, TextEncoder};
-use tracing_subscriber::{filter::filter_fn, util::SubscriberInitExt, Layer};
-use tracing_subscriber::{fmt::time::UtcTime, EnvFilter};
-use tracing_subscriber::{
-    fmt::{self},
-    layer::SubscriberExt,
-};
+use std::{io::IsTerminal, sync::Mutex};
+use tracing_appender::non_blocking::WorkerGuard;
+use tracing_subscriber::Layer;
+use tracing_subscriber::{fmt::time::UtcTime, Registry};
+use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
 
 pub struct HeaderExtractor<'a>(pub &'a ntex::http::HeaderMap);
 
@@ -62,6 +63,7 @@ pub struct Telemetry {
     pub metrics_provider: Option<SdkMeterProvider>,
     pub prometheus: Option<PrometheusRuntime>,
     pub context: TelemetryContext,
+    pub logging_writer_guard: tracing_appender::non_blocking::WorkerGuard,
 }
 
 pub enum PrometheusRuntime {
@@ -128,11 +130,16 @@ impl Telemetry {
             (None, None)
         };
 
-        let registry = tracing_subscriber::registry().with(otel_layer);
-        init_logging(config, registry)?;
+        let (logging_layer, stdout_guard) = init_logging::<Registry>(&config.log);
+        let registry = tracing_subscriber::registry()
+            .with(logging_layer)
+            .with(otel_layer);
+
+        registry.init();
 
         let context = TelemetryContext::from_propagation_config_with_meter(
             &config.telemetry.tracing.propagation,
+            &config.log,
             metrics_provider
                 .as_ref()
                 .map(|provider| provider.meter_with_scope(scope)),
@@ -145,6 +152,7 @@ impl Telemetry {
             metrics_provider,
             prometheus,
             context,
+            logging_writer_guard: stdout_guard,
         })
     }
 
@@ -195,6 +203,7 @@ impl Telemetry {
             .map(|setup| setup.provider.meter_with_scope(scope));
         let context = TelemetryContext::from_propagation_config_with_meter(
             &config.telemetry.tracing.propagation,
+            &config.log,
             meter,
         );
 
@@ -368,62 +377,43 @@ async fn metrics_handler(registry: web::types::State<prometheus::Registry>) -> H
     build_metrics_response(&registry)
 }
 
-pub fn init_logging<S>(config: &HiveRouterConfig, registry: S) -> Result<(), TelemetryInitError>
+pub fn init_logging<S>(config: &LoggingConfig) -> (DynLayer<S>, WorkerGuard)
 where
     S: tracing::Subscriber
         + for<'span> tracing_subscriber::registry::LookupSpan<'span>
         + Send
         + Sync,
 {
+    let stdout_stream = std::io::stdout();
+    let is_terminal = stdout_stream.is_terminal();
+    let (stdout_writer, stdout_guard) = tracing_appender::non_blocking(stdout_stream);
+    let targets_filter = create_targets_filter(&config.level, config.log_internals);
+    let ignore_otel_filter = create_ignore_otel_filter();
+    let stdout_layer = tracing_subscriber::fmt::layer().with_writer(stdout_writer);
     let timer = UtcTime::rfc_3339();
-    let filter = EnvFilter::from_str(config.log.env_filter_str())?;
-    let is_terminal = std::io::stdout().is_terminal();
-
-    let events_only = filter_fn(|m| !m.is_span());
-
-    match config.log.format {
-        LogFormat::PrettyTree => {
-            registry
-                .with(
-                    tracing_tree::HierarchicalLayer::new(2)
-                        .with_ansi(is_terminal)
-                        .with_bracketed_fields(true)
-                        .with_deferred_spans(false)
-                        .with_wraparound(25)
-                        .with_indent_lines(true)
-                        .with_timer(tracing_tree::time::Uptime::default())
-                        .with_thread_names(false)
-                        .with_thread_ids(false)
-                        .with_targets(false)
-                        .with_filter(events_only),
-                )
-                .with(filter)
-                .init();
-        }
-        LogFormat::Json => {
-            registry
-                .with(
-                    fmt::layer()
-                        .json()
-                        .with_timer(timer)
-                        .with_filter(events_only),
-                )
-                .with(filter)
-                .init();
-        }
-        LogFormat::PrettyCompact => {
-            registry
-                .with(
-                    fmt::layer()
-                        .compact()
-                        .with_ansi(is_terminal)
-                        .with_timer(timer)
-                        .with_filter(events_only),
-                )
-                .with(filter)
-                .init();
-        }
+
+    let layer = match config.format {
+        LogFormat::Json => stdout_layer
+            .json()
+            .with_timer(timer)
+            .with_thread_ids(false)
+            .with_target(true)
+            .with_ansi(is_terminal)
+            .flatten_event(true)
+            .with_span_list(false)
+            .with_filter(targets_filter)
+            .with_filter(ignore_otel_filter)
+            .boxed(),
+        LogFormat::Text => stdout_layer
+            .compact()
+            .with_thread_ids(false)
+            .with_timer(timer)
+            .with_target(true)
+            .with_ansi(is_terminal)
+            .with_filter(targets_filter)
+            .with_filter(ignore_otel_filter)
+            .boxed(),
     };
 
-    Ok(())
+    (layer, stdout_guard)
 }