Add few internal logs for Metrics sdks (#2350)

examples/self-diagnostics/src/main.rs

@@ -1,6 +1,7 @@
 use opentelemetry::global;
 use opentelemetry::KeyValue;
 use opentelemetry_sdk::metrics::PeriodicReader;
+use opentelemetry_sdk::Resource;
 use std::error::Error;
 use tracing::info;
 use tracing_subscriber::fmt;
@@ -13,6 +14,10 @@ fn init_meter_provider() -> opentelemetry_sdk::metrics::SdkMeterProvider {
     let reader = PeriodicReader::builder(exporter, opentelemetry_sdk::runtime::Tokio).build();
 
     let provider = opentelemetry_sdk::metrics::SdkMeterProvider::builder()
+        .with_resource(Resource::new([KeyValue::new(
+            "service.name",
+            "self-diagnostics-example",
+        )]))
         .with_reader(reader)
         .build();
 
@@ -26,7 +31,7 @@ async fn main() -> Result<(), Box<dyn Error + Send + Sync + 'static>> {
     // OpenTelemetry uses `tracing` crate for its internal logging. Unless a
     // tracing subscriber is set, the logs will be discarded. In this example,
     // we configure a `tracing` subscriber to:
-    // 1. Print logs of level INFO or higher to stdout using tracing's fmt layer.
+    // 1. Print logs of level DEBUG or higher to stdout using tracing's fmt layer.
     // 2. Filter logs from OpenTelemetry's dependencies (like tonic, hyper,
     // reqwest etc. which are commonly used by the OTLP exporter) to only print
     // ERROR-level logs. This filtering helps reduce repetitive log messages
@@ -39,7 +44,7 @@ async fn main() -> Result<(), Box<dyn Error + Send + Sync + 'static>> {
     // Hence, one may use "add_directive("opentelemetry=off".parse().unwrap())"
     // to turn off all logs from OpenTelemetry.
 
-    let filter = EnvFilter::new("info")
+    let filter = EnvFilter::new("debug")
         .add_directive("hyper=error".parse().unwrap())
         .add_directive("tonic=error".parse().unwrap())
         .add_directive("h2=error".parse().unwrap())
@@ -54,11 +59,14 @@ async fn main() -> Result<(), Box<dyn Error + Send + Sync + 'static>> {
     info!("Starting self-diagnostics example");
 
     let meter = global::meter("example");
-    // Create a counter using an invalid name to trigger
-    // internal log about the same.
-    let counter = meter.u64_counter("my_counter with_space").build();
+    let counter = meter.u64_counter("my_counter").build();
     counter.add(10, &[KeyValue::new("key", "value")]);
 
+    let _observable_counter = meter
+        .u64_observable_counter("my_observable_counter")
+        .with_callback(|observer| observer.observe(10, &[KeyValue::new("key", "value")]))
+        .build();
+
     meter_provider.shutdown()?;
     info!("Shutdown complete. Bye!");
     Ok(())

opentelemetry-sdk/src/metrics/meter_provider.rs

@@ -174,6 +174,10 @@ impl MeterProvider for SdkMeterProvider {
 
     fn meter_with_scope(&self, scope: InstrumentationScope) -> Meter {
         if self.inner.is_shutdown.load(Ordering::Relaxed) {
+            otel_debug!(
+                name: "MeterProvider.NoOpMeterReturned",
+                meter_name = scope.name(),
+            );
             return Meter::new(Arc::new(NoopMeter::new()));
         }
 
@@ -182,14 +186,26 @@ impl MeterProvider for SdkMeterProvider {
         };
 
         if let Ok(mut meters) = self.inner.meters.lock() {
-            let meter = meters
-                .entry(scope)
-                .or_insert_with_key(|scope| {
-                    Arc::new(SdkMeter::new(scope.clone(), self.inner.pipes.clone()))
-                })
-                .clone();
-            Meter::new(meter)
+            if let Some(existing_meter) = meters.get(&scope) {
+                otel_debug!(
+                    name: "MeterProvider.ExistingMeterReturned",
+                    meter_name = scope.name(),
+                );
+                Meter::new(existing_meter.clone())
+            } else {
+                let new_meter = Arc::new(SdkMeter::new(scope.clone(), self.inner.pipes.clone()));
+                meters.insert(scope.clone(), new_meter.clone());
+                otel_debug!(
+                    name: "MeterProvider.NewMeterCreated",
+                    meter_name = scope.name(),
+                );
+                Meter::new(new_meter)
+            }
         } else {
+            otel_debug!(
+                name: "MeterProvider.NoOpMeterReturned",
+                meter_name = scope.name(),
+            );
             Meter::new(Arc::new(NoopMeter::new()))
         }
     }
@@ -242,6 +258,11 @@ impl MeterProviderBuilder {
     /// Construct a new [MeterProvider] with this configuration.
 
     pub fn build(self) -> SdkMeterProvider {
+        otel_debug!(
+            name: "MeterProvider.Building",
+            builder = format!("{:?}", &self),
+        );
+
         let meter_provider = SdkMeterProvider {
             inner: Arc::new(SdkMeterProviderInner {
                 pipes: Arc::new(Pipelines::new(

opentelemetry-sdk/src/metrics/periodic_reader.rs

@@ -132,6 +132,7 @@ where
             name: "PeriodicReader.BuildCompleted",
             message = "Periodic reader built.",
             interval_in_secs = self.interval.as_secs(),
+            temporality = format!("{:?}", self.exporter.temporality()),
         );
 
         PeriodicReader {

opentelemetry-sdk/src/metrics/pipeline.rs

@@ -72,6 +72,10 @@ impl Pipeline {
     /// unique values.
     fn add_sync(&self, scope: InstrumentationScope, i_sync: InstrumentSync) {
         let _ = self.inner.lock().map(|mut inner| {
+            otel_debug!(
+                name : "InstrumentCreated",
+                instrument_name = i_sync.name.as_ref(),
+            );
             inner.aggregations.entry(scope).or_default().push(i_sync);
         });
     }
@@ -99,6 +103,10 @@ impl SdkProducer for Pipeline {
     /// Returns aggregated metrics from a single collection.
     fn produce(&self, rm: &mut ResourceMetrics) -> MetricResult<()> {
         let inner = self.inner.lock()?;
+        otel_debug!(
+            name: "MeterProviderInvokingObservableCallbacks",
+            count =  inner.callbacks.len(),
+        );
         for cb in &inner.callbacks {
             // TODO consider parallel callbacks.
             cb();