Tracing initialization improvements (#1244)

Tracing initialization improvements

bridge/svix-bridge/src/main.rs

@@ -14,7 +14,7 @@ use svix_ksuid::{KsuidLike as _, KsuidMs};
 #[cfg(all(not(target_env = "msvc"), feature = "jemalloc"))]
 use tikv_jemallocator::Jemalloc;
 use tracing::Instrument;
-use tracing_subscriber::prelude::*;
+use tracing_subscriber::{layer::SubscriberExt as _, util::SubscriberInitExt as _};
 
 mod allocator;
 mod config;
@@ -52,16 +52,20 @@ fn get_svc_identifiers(cfg: &Config) -> opentelemetry_sdk::Resource {
 }
 
 fn setup_tracing(cfg: &Config) {
-    if std::env::var_os("RUST_LOG").is_none() {
+    let filter_directives = std::env::var("RUST_LOG").unwrap_or_else(|e| {
+        if let std::env::VarError::NotUnicode(_) = e {
+            eprintln!("RUST_LOG environment variable has non-utf8 contents, ignoring!");
+        }
+
         const CRATE_NAME: &str = env!("CARGO_CRATE_NAME");
         let level = cfg.log_level.to_string();
         let var = [
             format!("{CRATE_NAME}={level}"),
             // XXX: Assuming this applies to the Producer side (aka `og-ingester`) when we fold it back in.
             format!("tower_http={level}"),
         ];
-        std::env::set_var("RUST_LOG", var.join(","));
-    }
+        var.join(",")
+    });
 
     let otel_layer = cfg.opentelemetry.as_ref().map(|otel_cfg| {
         // Configure the OpenTelemetry tracing layer
@@ -92,17 +96,16 @@ fn setup_tracing(cfg: &Config) {
         tracing_opentelemetry::layer().with_tracer(tracer)
     });
 
-    // Then initialize logging with an additional layer printing to stdout. This additional layer is
-    // either formatted normally or in JSON format
-    // Fails if the subscriber was already initialized, which we can safely and silently ignore.
-    let _ = match cfg.log_format {
+    // Then create a subscriber with an additional layer printing to stdout.
+    // This additional layer is either formatted normally or in JSON format.
+    match cfg.log_format {
         config::LogFormat::Default => {
             let stdout_layer = tracing_subscriber::fmt::layer();
             tracing_subscriber::Registry::default()
                 .with(otel_layer)
                 .with(stdout_layer)
-                .with(tracing_subscriber::EnvFilter::from_default_env())
-                .try_init()
+                .with(tracing_subscriber::EnvFilter::new(filter_directives))
+                .init()
         }
         config::LogFormat::Json => {
             let fmt = tracing_subscriber::fmt::format().json().flatten_event(true);
@@ -115,8 +118,8 @@ fn setup_tracing(cfg: &Config) {
             tracing_subscriber::Registry::default()
                 .with(otel_layer)
                 .with(stdout_layer)
-                .with(tracing_subscriber::EnvFilter::from_default_env())
-                .try_init()
+                .with(tracing_subscriber::EnvFilter::new(filter_directives))
+                .init()
         }
     };
 }

server/svix-server/src/lib.rs

@@ -21,7 +21,7 @@ use std::{
 };
 use tower::ServiceBuilder;
 use tower_http::cors::{AllowHeaders, Any, CorsLayer};
-use tracing_subscriber::{prelude::*, util::SubscriberInitExt};
+use tracing_subscriber::layer::SubscriberExt as _;
 
 use crate::{
     cfg::{CacheBackend, Configuration},
@@ -226,8 +226,12 @@ pub async fn run_with_prefix(
     expired_message_cleaner_loop.expect("Error initializing expired message cleaner")
 }
 
-pub fn setup_tracing(cfg: &ConfigurationInner) -> impl Drop {
-    if std::env::var_os("RUST_LOG").is_none() {
+pub fn setup_tracing(cfg: &ConfigurationInner) -> (tracing::Dispatch, sentry::ClientInitGuard) {
+    let filter_directives = std::env::var("RUST_LOG").unwrap_or_else(|e| {
+        if let std::env::VarError::NotUnicode(_) = e {
+            eprintln!("RUST_LOG environment variable has non-utf8 contents, ignoring!");
+        }
+
         let level = cfg.log_level.to_string();
         let mut var = vec![
             format!("{CRATE_NAME}={level}"),
@@ -238,8 +242,8 @@ pub fn setup_tracing(cfg: &ConfigurationInner) -> impl Drop {
             var.push(format!("sqlx={level}"));
         }
 
-        std::env::set_var("RUST_LOG", var.join(","));
-    }
+        var.join(",")
+    });
 
     let otel_layer = cfg.opentelemetry_address.as_ref().map(|addr| {
         // Configure the OpenTelemetry tracing layer
@@ -283,18 +287,17 @@ pub fn setup_tracing(cfg: &ConfigurationInner) -> impl Drop {
             _ => EventFilter::Ignore,
         });
 
-    // Then initialize logging with an additional layer printing to stdout. This additional layer is
-    // either formatted normally or in JSON format
-    // Fails if the subscriber was already initialized, which we can safely and silently ignore
-    let _ = match cfg.log_format {
+    // Then create a subscriber with an additional layer printing to stdout.
+    // This additional layer is either formatted normally or in JSON format.
+    let dispatch = match cfg.log_format {
         cfg::LogFormat::Default => {
             let stdout_layer = tracing_subscriber::fmt::layer();
             tracing_subscriber::Registry::default()
                 .with(otel_layer)
                 .with(sentry_layer)
                 .with(stdout_layer)
-                .with(tracing_subscriber::EnvFilter::from_default_env())
-                .try_init()
+                .with(tracing_subscriber::EnvFilter::new(filter_directives))
+                .into()
         }
         cfg::LogFormat::Json => {
             let fmt = tracing_subscriber::fmt::format().json().flatten_event(true);
@@ -308,11 +311,12 @@ pub fn setup_tracing(cfg: &ConfigurationInner) -> impl Drop {
                 .with(otel_layer)
                 .with(sentry_layer)
                 .with(stdout_layer)
-                .with(tracing_subscriber::EnvFilter::from_default_env())
-                .try_init()
+                .with(tracing_subscriber::EnvFilter::new(filter_directives))
+                .into()
         }
     };
-    sentry_guard
+
+    (dispatch, sentry_guard)
 }
 
 mod docs {

server/svix-server/src/main.rs

@@ -7,6 +7,7 @@
 use dotenv::dotenv;
 use svix_server::core::types::{EndpointSecretInternal, OrganizationId};
 use svix_server::db::wipe_org;
+use tracing_subscriber::util::SubscriberInitExt;
 use validator::Validate;
 
 use svix_server::core::security::{default_org_id, generate_org_token};
@@ -110,7 +111,8 @@ async fn main() {
     let args = Args::parse();
     let cfg = cfg::load().expect("Error loading configuration");
 
-    let _guard = setup_tracing(&cfg);
+    let (tracing_subscriber, _guard) = setup_tracing(&cfg);
+    tracing_subscriber.init();
 
     if let Some(wait_for_seconds) = args.wait_for {
         let mut wait_for = Vec::with_capacity(2);

server/svix-server/tests/it/utils/mod.rs

@@ -24,6 +24,7 @@ use svix_server::{
 };
 
 use http::HeaderMap;
+use tracing::instrument::WithSubscriber;
 
 pub mod common_calls;
 
@@ -271,19 +272,22 @@ pub async fn start_svix_server_with_cfg_and_org_id(
     cfg: &ConfigurationInner,
     org_id: OrganizationId,
 ) -> (TestClient, tokio::task::JoinHandle<()>) {
-    let _guard = setup_tracing(cfg);
+    let (tracing_subscriber, _guard) = setup_tracing(cfg);
 
     let cfg = Arc::new(cfg.clone());
 
     let token = generate_org_token(&cfg.jwt_signing_config, org_id).unwrap();
     let listener = TcpListener::bind("127.0.0.1:0").unwrap();
     let base_uri = format!("http://{}", listener.local_addr().unwrap());
 
-    let jh = tokio::spawn(svix_server::run_with_prefix(
-        Some(svix_ksuid::Ksuid::new(None, None).to_string()),
-        cfg,
-        Some(listener),
-    ));
+    let jh = tokio::spawn(
+        svix_server::run_with_prefix(
+            Some(svix_ksuid::Ksuid::new(None, None).to_string()),
+            cfg,
+            Some(listener),
+        )
+        .with_subscriber(tracing_subscriber),
+    );
 
     (TestClient::new(base_uri, &token), jh)
 }