Improve internal opentelemetry logging

opentelemetry-appender-tracing/Cargo.toml

@@ -12,16 +12,16 @@ rust-version = "1.65"
 
 [dependencies]
 log = { workspace = true, optional = true }
-opentelemetry = { version = "0.25", path = "../opentelemetry", features = ["logs"] }
+opentelemetry = { version = "0.25", path = "../opentelemetry", features = ["logs","experimental-internal-debugging"] }
 tracing = { workspace = true, features = ["std"]}
 tracing-core = { workspace = true }
 tracing-log = { version = "0.2", optional = true }
-tracing-subscriber = { workspace = true, features = ["registry", "std"] }
+tracing-subscriber = { workspace = true, features = ["registry", "std", "fmt", "ansi", "env-filter"] }
 
 [dev-dependencies]
 log = { workspace = true }
 opentelemetry-stdout = { path = "../opentelemetry-stdout", features = ["logs"] }
-opentelemetry_sdk = { path = "../opentelemetry-sdk", features = ["logs", "testing"]  }
+opentelemetry_sdk = { path = "../opentelemetry-sdk", features = ["logs", "testing", "experimental-internal-debugging"]  }
 tracing-log = "0.2"
 async-trait = { workspace = true }
 criterion = { workspace = true }

opentelemetry-appender-tracing/examples/basic.rs

@@ -4,6 +4,9 @@ use opentelemetry::KeyValue;
 use opentelemetry_appender_tracing::layer;
 use opentelemetry_sdk::{logs::LoggerProvider, Resource};
 use tracing::error;
+use tracing_subscriber::filter::{filter_fn, EnvFilter};
+use tracing_subscriber::fmt;
+use tracing_subscriber::layer::Layer;
 use tracing_subscriber::prelude::*;
 
 fn main() {
@@ -15,9 +18,19 @@ fn main() {
         )]))
         .with_simple_exporter(exporter)
         .build();
-    let layer = layer::OpenTelemetryTracingBridge::new(&provider);
-    tracing_subscriber::registry().with(layer).init();
-
-    error!(name: "my-event-name", target: "my-system", event_id = 20, user_name = "otel", user_email = "otel@opentelemetry.io", message = "This is an example message");
+    let env_filter = EnvFilter::from_default_env();
+    let otel_layer = layer::OpenTelemetryTracingBridge::new(&provider);
+    let internal_log_layer = fmt::Layer::default()
+        .with_writer(std::io::stdout) // Writes to stdout
+        .pretty()
+        .with_filter(filter_fn(|meta| meta.target().starts_with("opentelemetry"))) // Custom filter function
+        .with_filter(env_filter);
+    tracing_subscriber::registry()
+        .with(internal_log_layer)
+        .with(otel_layer)
+        .init();
+    for i in 0..3 {
+        error!(name: "my-event-name", target: "my-system", event_id = 20, user_name = "otel", user_email = "otel@opentelemetry.io", message = "This is an example message", iteration = i);
+    }
     let _ = provider.shutdown();
 }

opentelemetry-appender-tracing/src/layer.rs

@@ -157,6 +157,9 @@ where
         event: &tracing::Event<'_>,
         _ctx: tracing_subscriber::layer::Context<'_, S>,
     ) {
+        if event.metadata().target().starts_with("opentelemetry") {
+            return;
+        }
         #[cfg(feature = "experimental_metadata_attributes")]
         let normalized_meta = event.normalized_metadata();
 

opentelemetry-sdk/Cargo.toml

@@ -28,6 +28,7 @@ url = { workspace = true, optional = true }
 tokio = { workspace = true, features = ["rt", "time"], optional = true }
 tokio-stream = { workspace = true, optional = true }
 http = { workspace = true, optional = true }
+tracing = {workspace = true, optional = true}
 
 [package.metadata.docs.rs]
 all-features = true
@@ -51,6 +52,7 @@ testing = ["opentelemetry/testing", "trace", "metrics", "logs", "rt-async-std",
 rt-tokio = ["tokio", "tokio-stream"]
 rt-tokio-current-thread = ["tokio", "tokio-stream"]
 rt-async-std = ["async-std"]
+experimental-internal-debugging = ["opentelemetry/experimental-internal-debugging", "tracing"]
 
 [[bench]]
 name = "context"

opentelemetry-sdk/src/logs/log_emitter.rs

@@ -6,6 +6,7 @@ use opentelemetry::{
     trace::TraceContextExt,
     Context, InstrumentationLibrary,
 };
+use opentelemetry::{otel_debug, otel_info, otel_target, otel_warn};
 
 #[cfg(feature = "logs_level_enabled")]
 use opentelemetry::logs::Severity;
@@ -49,6 +50,14 @@ impl opentelemetry::logs::LoggerProvider for LoggerProvider {
         attributes: Option<Vec<opentelemetry::KeyValue>>,
     ) -> Logger {
         let name = name.into();
+        otel_info!(
+            target: otel_target!("logs"),
+            name: "logger_versioned_creation",
+            instr_lib_name= name,
+            version = version.as_deref(),
+            schema_url = schema_url.as_deref(),
+            attributes = attributes
+        );
 
         let component_name = if name.is_empty() {
             Cow::Borrowed(DEFAULT_COMPONENT_NAME)
@@ -72,6 +81,11 @@ impl opentelemetry::logs::LoggerProvider for LoggerProvider {
     }
 
     fn library_logger(&self, library: Arc<InstrumentationLibrary>) -> Self::Logger {
+        otel_info!(
+            target: otel_target!("logs"),
+            name: "logger_library_logger_creation",
+            library= library
+        );
         // If the provider is shutdown, new logger will refer a no-op logger provider.
         if self.is_shutdown.load(Ordering::Relaxed) {
             return Logger::new(library, NOOP_LOGGER_PROVIDER.clone());
@@ -83,19 +97,37 @@ impl opentelemetry::logs::LoggerProvider for LoggerProvider {
 impl LoggerProvider {
     /// Create a new `LoggerProvider` builder.
     pub fn builder() -> Builder {
+        otel_info!(
+            target: otel_target!("logs"),
+            name: "logger_provider_builder"
+        );
         Builder::default()
     }
 
     pub(crate) fn log_processors(&self) -> &[Box<dyn LogProcessor>] {
+        otel_debug!(
+            target: otel_target!("logs"),
+            name: "logger_provider_log_processors",
+            processor_count= self.inner.processors.len()
+        );
         &self.inner.processors
     }
 
     pub(crate) fn resource(&self) -> &Resource {
+        otel_debug!(
+            target: otel_target!("logs"),
+            name: "logger_provider_resource",
+            resource_count= self.inner.resource.len()
+        );
         &self.inner.resource
     }
 
     /// Force flush all remaining logs in log processors and return results.
     pub fn force_flush(&self) -> Vec<LogResult<()>> {
+        otel_info!(
+            target: otel_target!("logs"),
+            name: "logger_provider_force_flush"
+        );
         self.log_processors()
             .iter()
             .map(|processor| processor.force_flush())
@@ -104,6 +136,10 @@ impl LoggerProvider {
 
     /// Shuts down this `LoggerProvider`
     pub fn shutdown(&self) -> LogResult<()> {
+        otel_info!(
+            target: otel_target!("logs"),
+            name: "logger_provider_shutdown"
+        );
         if self
             .is_shutdown
             .compare_exchange(false, true, Ordering::SeqCst, Ordering::SeqCst)
@@ -114,6 +150,11 @@ impl LoggerProvider {
             let mut errs = vec![];
             for processor in &self.inner.processors {
                 if let Err(err) = processor.shutdown() {
+                    otel_warn!(
+                        target: otel_target!("logs"),
+                        name: "logger_provider_shutdown_error",
+                        error= err
+                    );
                     errs.push(err);
                 }
             }
@@ -124,6 +165,10 @@ impl LoggerProvider {
                 Err(LogError::Other(format!("{errs:?}").into()))
             }
         } else {
+            otel_warn!(
+                target: otel_target!("logs"),
+                name: "logger_provider_already_shutdown"
+            );
             Err(LogError::Other("logger provider already shut down".into()))
         }
     }
@@ -203,6 +248,12 @@ impl Builder {
         for processor in logger_provider.log_processors() {
             processor.set_resource(logger_provider.resource());
         }
+        otel_debug!(
+            target: otel_target!("logs"),
+            name: "logger_provider_build",
+            resource_count = logger_provider.resource().len(),
+            processor_count = logger_provider.log_processors().len()
+        );
         logger_provider
     }
 }
@@ -221,6 +272,10 @@ impl Logger {
         instrumentation_lib: Arc<InstrumentationLibrary>,
         provider: LoggerProvider,
     ) -> Self {
+        otel_info!(
+            target: otel_target!("logs"),
+            name: "logger_new"
+        );
         Logger {
             instrumentation_lib,
             provider,
@@ -247,6 +302,11 @@ impl opentelemetry::logs::Logger for Logger {
 
     /// Emit a `LogRecord`.
     fn emit(&self, mut record: Self::LogRecord) {
+        otel_debug!(
+            target: otel_target!("logs"),
+            name: "log_record_emit_start",
+            record = record
+        );
         let provider = self.provider();
         let processors = provider.log_processors();
         let trace_context = Context::map_current(|cx| {
@@ -280,6 +340,13 @@ impl opentelemetry::logs::Logger for Logger {
                     self.instrumentation_library().name.as_ref(),
                 );
         }
+        otel_debug!(
+            target: otel_target!("logs"),
+            name: "log_record_event_enabled_check",
+            enabled_status = enabled,
+            level = level,
+            log_target = target
+        );
         enabled
     }
 }