Improve internal opentelemetry logging

examples/self-diagnostics/Cargo.toml

@@ -7,13 +7,13 @@ publish = false
 
 [dependencies]
 opentelemetry = { path = "../../opentelemetry" }
-opentelemetry_sdk = { path = "../../opentelemetry-sdk", features = ["rt-tokio", "experimental-internal-logs"]}
+opentelemetry_sdk = { path = "../../opentelemetry-sdk", features = ["rt-tokio"]}
 opentelemetry-stdout = { path = "../../opentelemetry-stdout"}
 opentelemetry-appender-tracing = { path = "../../opentelemetry-appender-tracing"}
 tokio = { workspace = true, features = ["full"] }
 tracing = { workspace = true, features = ["std"]}
 tracing-core = { workspace = true }
 tracing-subscriber = { version = "0.3.18", features = ["env-filter","registry", "std"]}
-opentelemetry-otlp = { path = "../../opentelemetry-otlp", features = ["http-proto", "reqwest-client", "logs", "experimental-internal-logs"] }
+opentelemetry-otlp = { path = "../../opentelemetry-otlp", features = ["http-proto", "reqwest-client", "logs"] }
 once_cell ={ version = "1.19.0"}
 ctrlc = "3.4"

opentelemetry-appender-tracing/Cargo.toml

@@ -22,6 +22,7 @@ tracing-subscriber = { workspace = true, features = ["registry", "std"] }
 log = { workspace = true }
 opentelemetry-stdout = { path = "../opentelemetry-stdout", features = ["logs"] }
 opentelemetry_sdk = { path = "../opentelemetry-sdk", features = ["logs", "testing"]  }
+tracing-subscriber = { workspace = true, features = ["registry", "std", "env-filter"] }
 tracing-log = "0.2"
 async-trait = { workspace = true }
 criterion = { workspace = true }

opentelemetry-appender-tracing/src/layer.rs

@@ -217,14 +217,26 @@ mod tests {
     use opentelemetry_sdk::trace;
     use opentelemetry_sdk::trace::{Sampler, TracerProvider};
     use tracing::error;
-    use tracing_subscriber::layer::SubscriberExt;
+    use tracing_subscriber::prelude::__tracing_subscriber_SubscriberExt;
+    use tracing_subscriber::Layer;
 
     pub fn attributes_contains(log_record: &LogRecord, key: &Key, value: &AnyValue) -> bool {
         log_record
             .attributes_iter()
             .any(|(k, v)| k == key && v == value)
     }
 
+    fn create_tracing_subscriber(
+        _exporter: InMemoryLogsExporter,
+        logger_provider: &LoggerProvider,
+    ) -> impl tracing::Subscriber {
+        let level_filter = tracing_subscriber::filter::LevelFilter::WARN; // Capture WARN and ERROR levels
+        let layer =
+            layer::OpenTelemetryTracingBridge::new(logger_provider).with_filter(level_filter); // No filter based on target, only based on log level
+
+        tracing_subscriber::registry().with(layer)
+    }
+
     // cargo test --features=testing
     #[test]
     fn tracing_appender_standalone() {
@@ -234,8 +246,7 @@ mod tests {
             .with_simple_exporter(exporter.clone())
             .build();
 
-        let layer = layer::OpenTelemetryTracingBridge::new(&logger_provider);
-        let subscriber = tracing_subscriber::registry().with(layer);
+        let subscriber = create_tracing_subscriber(exporter.clone(), &logger_provider);
 
         // avoiding setting tracing subscriber as global as that does not
         // play well with unit tests.
@@ -315,8 +326,7 @@ mod tests {
             .with_simple_exporter(exporter.clone())
             .build();
 
-        let layer = layer::OpenTelemetryTracingBridge::new(&logger_provider);
-        let subscriber = tracing_subscriber::registry().with(layer);
+        let subscriber = create_tracing_subscriber(exporter.clone(), &logger_provider);
 
         // avoiding setting tracing subscriber as global as that does not
         // play well with unit tests.
@@ -427,16 +437,15 @@ mod tests {
             .with_simple_exporter(exporter.clone())
             .build();
 
-        let layer = layer::OpenTelemetryTracingBridge::new(&logger_provider);
-        let subscriber = tracing_subscriber::registry().with(layer);
+        let subscriber = create_tracing_subscriber(exporter.clone(), &logger_provider);
 
         // avoiding setting tracing subscriber as global as that does not
         // play well with unit tests.
         let _guard = tracing::subscriber::set_default(subscriber);
         drop(tracing_log::LogTracer::init());
 
         // Act
-        log::error!("log from log crate");
+        log::error!(target: "my-system", "log from log crate");
         logger_provider.force_flush();
 
         // Assert TODO: move to helper methods
@@ -493,8 +502,7 @@ mod tests {
             .with_simple_exporter(exporter.clone())
             .build();
 
-        let layer = layer::OpenTelemetryTracingBridge::new(&logger_provider);
-        let subscriber = tracing_subscriber::registry().with(layer);
+        let subscriber = create_tracing_subscriber(exporter.clone(), &logger_provider);
 
         // avoiding setting tracing subscriber as global as that does not
         // play well with unit tests.
@@ -513,7 +521,7 @@ mod tests {
             let span_id = cx.span().span_context().span_id();
 
             // logging is done inside span context.
-            log::error!("log from log crate");
+            log::error!(target: "my-system", "log from log crate");
             (trace_id, span_id)
         });
 

opentelemetry-otlp/Cargo.toml

@@ -58,12 +58,12 @@ trace = ["opentelemetry/trace", "opentelemetry_sdk/trace", "opentelemetry-proto/
 metrics = ["opentelemetry/metrics", "opentelemetry_sdk/metrics", "opentelemetry-proto/metrics"]
 logs = ["opentelemetry/logs", "opentelemetry_sdk/logs", "opentelemetry-proto/logs"]
 populate-logs-event-name = ["opentelemetry-proto/populate-logs-event-name"]
-experimental-internal-logs = ["tracing"]
+internal-logs = ["tracing"]
 
 # add ons
 serialize = ["serde", "serde_json"]
 
-default = ["grpc-tonic", "trace", "metrics", "logs"]
+default = ["grpc-tonic", "trace", "metrics", "logs", "internal-logs"]
 
 # grpc using tonic
 grpc-tonic = ["tonic", "prost", "http", "tokio", "opentelemetry-proto/gen-tonic"]

opentelemetry-otlp/src/metric.rs

@@ -7,6 +7,7 @@
 use async_trait::async_trait;
 use core::fmt;
 use opentelemetry::metrics::Result;
+use opentelemetry::otel_debug;
 
 #[cfg(feature = "grpc-tonic")]
 use crate::exporter::tonic::TonicExporterBuilder;
@@ -294,22 +295,19 @@
 #[async_trait]
 impl PushMetricsExporter for MetricsExporter {
     async fn export(&self, metrics: &mut ResourceMetrics) -> Result<()> {
-        #[cfg(feature = "experimental-internal-logs")]
-        tracing::debug!(
-            name = "export_metrics",
-            target = "opentelemetry-otlp",
+        otel_debug!(
+            name: "export_metrics",
             metrics_count = metrics
                 .scope_metrics
                 .iter()
                 .map(|scope| scope.metrics.len())
                 .sum::<usize>(),
             status = "started"
         );
+        #[allow(clippy::let_and_return)] // for scenario where internal logs is disabled
         let result = self.client.export(metrics).await;
-        #[cfg(feature = "experimental-internal-logs")]
-        tracing::debug!(
-            name = "export_metrics",
-            target = "opentelemetry-otlp",
+        otel_debug!(
+            name: "export_metrics",
             status = if result.is_ok() {
                 "completed"
             } else {

opentelemetry-sdk/Cargo.toml

@@ -42,7 +42,7 @@ temp-env = { workspace = true }
 pprof = { version = "0.13", features = ["flamegraph", "criterion"] }
 
 [features]
-default = ["trace", "metrics", "logs"]
+default = ["trace", "metrics", "logs", "internal-logs"]
 trace = ["opentelemetry/trace", "rand", "async-trait", "percent-encoding"]
 jaeger_remote_sampler = ["trace", "opentelemetry-http", "http", "serde", "serde_json", "url"]
 logs = ["opentelemetry/logs", "async-trait", "serde_json"]
@@ -52,7 +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-logs = ["tracing"]
+internal-logs = ["tracing"]
 
 [[bench]]
 name = "context"

opentelemetry-sdk/src/logs/log_emitter.rs

@@ -6,6 +6,7 @@
     trace::TraceContextExt,
     Context, InstrumentationLibrary,
 };
+use opentelemetry::{otel_debug, otel_info, otel_warn};
 
 #[cfg(feature = "logs_level_enabled")]
 use opentelemetry::logs::Severity;
@@ -49,6 +50,12 @@
         attributes: Option<Vec<opentelemetry::KeyValue>>,
     ) -> Logger {
         let name = name.into();
+        otel_info!(
+            name: "logger_versioned_creation",
+            instr_lib_name= &*name,
+            version = version.as_deref(),
+            schema_url = schema_url.as_deref(),
+        );
 
         let component_name = if name.is_empty() {
             Cow::Borrowed(DEFAULT_COMPONENT_NAME)
@@ -72,6 +79,9 @@
     }
 
     fn library_logger(&self, library: Arc<InstrumentationLibrary>) -> Self::Logger {
+        otel_info!(
+            name: "logger_library_logger_creation"
+        );
         // 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 +93,33 @@
 impl LoggerProvider {
     /// Create a new `LoggerProvider` builder.
     pub fn builder() -> Builder {
+        otel_info!(
+            name: "logger_provider_builder"
+        );
         Builder::default()
     }
 
     pub(crate) fn log_processors(&self) -> &[Box<dyn LogProcessor>] {
+        otel_debug!(
+            name: "logger_provider_log_processors",
+            processor_count= self.inner.processors.len()
+        );
         &self.inner.processors
     }
 
     pub(crate) fn resource(&self) -> &Resource {
+        otel_debug!(
+            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!(
+            name: "logger_provider_force_flush"
+        );
         self.log_processors()
             .iter()
             .map(|processor| processor.force_flush())
@@ -104,6 +128,9 @@
 
     /// Shuts down this `LoggerProvider`
     pub fn shutdown(&self) -> LogResult<()> {
+        otel_info!(
+            name: "logger_provider_shutdown"
+        );
         if self
             .is_shutdown
             .compare_exchange(false, true, Ordering::SeqCst, Ordering::SeqCst)
@@ -114,6 +141,10 @@
             let mut errs = vec![];
             for processor in &self.inner.processors {
                 if let Err(err) = processor.shutdown() {
+                    otel_warn!(
+                        name: "logger_provider_shutdown_error",
+                        error = format!("{:?}", err)
+                    );
                     errs.push(err);
                 }
             }
@@ -124,6 +155,9 @@
                 Err(LogError::Other(format!("{errs:?}").into()))
             }
         } else {
+            otel_warn!(
+                name: "logger_provider_already_shutdown"
+            );
             Err(LogError::Other("logger provider already shut down".into()))
         }
     }
@@ -203,6 +237,11 @@
         for processor in logger_provider.log_processors() {
             processor.set_resource(logger_provider.resource());
         }
+        otel_debug!(
+            name: "logger_provider_build",
+            resource_count = logger_provider.resource().len(),
+            processor_count = logger_provider.log_processors().len()
+        );
         logger_provider
     }
 }
@@ -221,6 +260,9 @@
         instrumentation_lib: Arc<InstrumentationLibrary>,
         provider: LoggerProvider,
     ) -> Self {
+        otel_info!(
+            name: "logger_new"
+        );
         Logger {
             instrumentation_lib,
             provider,
@@ -247,6 +289,10 @@
 
     /// Emit a `LogRecord`.
     fn emit(&self, mut record: Self::LogRecord) {
+        otel_debug!(
+            name: "log_record_emit_start",
+            record = format!("{:?}", record)
+        );
         let provider = self.provider();
         let processors = provider.log_processors();
         let trace_context = Context::map_current(|cx| {
@@ -280,6 +326,12 @@
                     self.instrumentation_library().name.as_ref(),
                 );
         }
+        otel_debug!(
+            name: "log_record_event_enabled_check",
+            enabled_status = enabled,
+            level = level.name(),
+            log_target = target
+        );
         enabled
     }
 }