feat: More granular instrumentation and remove long running spans (#811)

* chore(stackable-telemetry): use default sampler and id generators

Defaults are:

```
            sampler: Box::new(Sampler::ParentBased(Box::new(Sampler::AlwaysOn))),
            id_generator: Box::<RandomIdGenerator>::default(),
```

* chore: remove instrumentation from trivial methods, set events to trace level

* chore: remove long running spans

* fix: carry over otel context (incl parent span) between low level tls handling, and high level route handling

This fixes the trace hierarchy which used to be disjoint because the parent span/trace id was missing and a new one was being generated in the axum layers

* feat: granular instrumentation of futures

* chore: add reminder about naming of special layer

* chore: tidy up tracing events

* chore: update changelogs

* chore(stackable-telemetry): remove commented span attributes

* chore(stackable-telemetry): remove seemingly unnecessary context guard

* fix(stackable-telemetry): cast numeric span attributes as i64

* chore(stackable-telemetry): add missing span attributes for client

* chore(stackable-telemetry): add comment explaining that we need to pass tracing context

* chore(stackable-telemetry): demote event levels for low level errors that can easily be triggered by clients

* chore(stackable-telemetry): upgrade opentelemetry crates

* fix(stackable-telemetry): only set parent context if the context is different. Add links between traces

* chore(stackable-telemetry): add important developer notes

* chore(stackable-telemetry): emit a tracing event when the otlp providers are about to shut down

* chore(stackable-telemetry): rename event fields because the providers are defined in opentelemetry, not opentelemetry_otlp. Even though we happen to be using otlp providers.

* chore(stackable-telemetry): improve field names in events

* fix(stackable-telemetry): only shutdown the global TracerProvider if we set it

* chore(stackable-operator): update changelog

* chore(stackable-telemetry): update changelog

* Apply suggestions from code review

Co-authored-by: Techassi <[email protected]>

* Apply suggestions from code review

Co-authored-by: Techassi <[email protected]>

* chore(stackable-telemetry): remove indentation on otherwise empty lines

* chore(stackable-telemetry): add an important doc-comment note to the Tracing::init method

---------

Co-authored-by: Techassi <[email protected]>

Author: NickLarsenNZ

Cargo.lock

@@ -32,12 +32,12 @@ k8s-openapi = { version = "0.22.0", default-features = false, features = ["schem
 # We use rustls instead of openssl for easier portablitly, e.g. so that we can build stackablectl without the need to vendor (build from source) openssl
 kube = { version = "0.92.0", default-features = false, features = ["client", "jsonpatch", "runtime", "derive", "rustls-tls"] }
 lazy_static = "1.4.0"
-opentelemetry = "0.22.0"
-opentelemetry_sdk = { version = "0.22.1", features = ["rt-tokio"] }
-opentelemetry-appender-tracing = "0.3.0"
-opentelemetry-jaeger = { version = "0.21.0", features = ["rt-tokio"] }
-opentelemetry-otlp = "0.15.0"
-opentelemetry-semantic-conventions = "0.14.0"
+opentelemetry = "0.23.0"
+opentelemetry_sdk = { version = "0.23.0", features = ["rt-tokio"] }
+opentelemetry-appender-tracing = "0.4.0"
+opentelemetry-jaeger = { version = "0.22.0", features = ["rt-tokio"] }
+opentelemetry-otlp = "0.16.0"
+opentelemetry-semantic-conventions = "0.15.0"
 p256 = { version = "0.13.2", features = ["ecdsa"] }
 pin-project = "1.1.5"
 proc-macro2 = "1.0.83"
@@ -67,7 +67,7 @@ tokio-test = "0.4.4"
 tower = "0.4.13"
 tower-http = { version = "0.5.2", features = ["trace"] }
 tracing = "0.1.40"
-tracing-opentelemetry = "0.23.0"
+tracing-opentelemetry = "0.24.0"
 tracing-subscriber = { version = "0.3.18", features = ["env-filter"] }
 url = { version = "2.5.0", features = ["serde"] }
 x509-cert = { version = "0.2.5", features = ["builder"] }

Cargo.toml

@@ -12,12 +12,14 @@ All notable changes to this project will be documented in this file.
   - [Blog Post - Breaking Change](https://kube.rs/blog/2024/06/11/watcher-memory-improvements/#breaking-change)
   - [kube#1494](https://github.com/kube-rs/kube/pull/1494)
   - [kube#1504](https://github.com/kube-rs/kube/pull/1504)
+- Upgrade opentelemetry crates ([#811]).
 
 ### Fixed
 
 - Product image selection pull request version override now only applies to pull requests ([#812]).
 
 [#804]: https://github.com/stackabletech/operator-rs/pull/804
+[#811]: https://github.com/stackabletech/operator-rs/pull/811
 [#812]: https://github.com/stackabletech/operator-rs/pull/812
 
 ## [0.69.3] - 2024-06-12

crates/stackable-operator/CHANGELOG.md

@@ -7,8 +7,12 @@ All notable changes to this project will be documented in this file.
 ### Changed
 
 - Add support for setting the environment variable for each configured tracing subscriber ([#801]).
+- Use OpenTelemetry Context in Axum instrumentation layer, adjust log and span level, simplify trace config ([#811]).
+  - tracing: Upgrade opentelemetry crates, simplify trace config, fix shutdown conditions, use new way to shutdown LoggerProvider.
+  - instrumentation/axum: demote event severity for errors easily caused by clients, replace parent span context if given in http header and link to previous trace contexts.
 
 [#801]: https://github.com/stackabletech/operator-rs/pull/801
+[#811]: https://github.com/stackabletech/operator-rs/pull/811
 
 ## [0.1.0] - 2024-05-08
 

crates/stackable-telemetry/CHANGELOG.md

@@ -13,7 +13,7 @@ opentelemetry = { workspace = true, features = ["logs"] }
 opentelemetry-appender-tracing.workspace = true
 opentelemetry-otlp = { workspace = true, features = ["gzip-tonic", "logs"] }
 opentelemetry-semantic-conventions.workspace = true
-opentelemetry_sdk = { workspace = true, features = ["logs", "rt-tokio"] }
+opentelemetry_sdk = { workspace = true, features = ["logs", "rt-tokio", "logs_level_enabled"] }
 pin-project.workspace = true
 snafu.workspace = true
 tokio.workspace = true

crates/stackable-telemetry/Cargo.toml

@@ -21,11 +21,14 @@ use axum::{
     response::Response,
 };
 use futures_util::ready;
-use opentelemetry::trace::SpanKind;
+use opentelemetry::{
+    trace::{SpanKind, TraceContextExt},
+    Context,
+};
 use pin_project::pin_project;
 use snafu::{ResultExt, Snafu};
 use tower::{Layer, Service};
-use tracing::{debug, field::Empty, instrument, trace_span, Span};
+use tracing::{field::Empty, Span};
 use tracing_opentelemetry::OpenTelemetrySpanExt;
 
 mod extractor;
@@ -91,7 +94,6 @@ impl<S> Layer<S> for TraceLayer {
 
 impl TraceLayer {
     /// Creates a new default trace layer.
-    #[instrument(name = "create_trace_layer")]
     pub fn new() -> Self {
         Self::default()
     }
@@ -367,7 +369,7 @@ impl SpanExt for Span {
         let span_name = req.span_name();
         let url = req.uri();
 
-        debug!(
+        tracing::trace!(
             http_method,
             span_name,
             ?url,
@@ -396,8 +398,7 @@ impl SpanExt for Span {
         // Setting common fields first
         // See https://opentelemetry.io/docs/specs/semconv/http/http-spans/#common-attributes
 
-        debug!("create http span");
-        let span = trace_span!(
+        let span = tracing::trace_span!(
             "HTTP request",
             "otel.name" = span_name,
             "otel.kind" = ?SpanKind::Server,
@@ -418,9 +419,44 @@ impl SpanExt for Span {
         );
 
         // Set the parent span based on the extracted context
-        debug!("set parent span based on extracted context");
-        let parent = HeaderExtractor::new(req.headers()).extract_context();
-        span.set_parent(parent);
+        //
+        // The OpenTelemetry spec does not allow trace ids to be updated after
+        // a span has been created. Since the (optional) new trace id given by
+        // a client is only knowable after handling the request, it is not
+        // available to the existing parent spans for the lower layers (tcp/tls
+        // handling).
+        //
+        // Therefore, we have to made a decision about linking the two traces.
+        // These are the options:
+        // 1. Link to the trace id supplied in the incoming request, or
+        // 2. Link to the current trace id, then set the parent contex based on
+        //    trace information supplied in the incoming request.
+        //
+        // Neither is ideal, as it means there are (at least) two traces to look
+        // at to get a complete picture of what happened over the request.
+        //
+        // Option 1 is not viable, as the trace id in the response headers will
+        // not be the same as what the client sent. Yet we are supposed to pass
+        // their trace id in any further requests.
+        //
+        // We will go with option 2 as it at least keeps the higher layer spans
+        // in one trace, which is likely going to be more useful to the person
+        // visualising the traces.
+        let new_parent = HeaderExtractor::new(req.headers()).extract_context();
+        let new_span_context = new_parent.span().span_context().clone();
+        let current_span_context = Context::current().span().span_context().clone();
+
+        if new_span_context != current_span_context {
+            tracing::trace!(
+                opentelemetry.trace_id.from = ?current_span_context.trace_id(),
+                opentelemetry.trace_id.to = ?new_span_context.trace_id(),
+                "set parent span context based on context extracted from request headers"
+            );
+
+            Span::current().add_link(new_parent.span().span_context().clone());
+            span.add_link(Context::current().span().span_context().to_owned());
+            span.set_parent(new_parent);
+        }
 
         if let Some(user_agent) = req.user_agent() {
             span.record("user_agent.original", user_agent);

crates/stackable-telemetry/src/instrumentation/axum/mod.rs

@@ -9,10 +9,9 @@
 use opentelemetry::KeyValue;
 use opentelemetry_appender_tracing::layer::OpenTelemetryTracingBridge;
 use opentelemetry_sdk::{
-    logs,
+    logs::{self, LoggerProvider},
     propagation::TraceContextPropagator,
-    trace::{self, RandomIdGenerator, Sampler},
-    Resource,
+    trace, Resource,
 };
 use opentelemetry_semantic_conventions::resource;
 use snafu::{ResultExt as _, Snafu};
@@ -46,6 +45,8 @@ pub enum Error {
 ///
 /// #[tokio::main]
 /// async fn main() -> Result<(), Error> {
+///     // IMPORTANT: Name the guard variable appropriately, do not just use
+///     // `let _ =`, as that will drop immediately.
 ///     let _tracing_guard = Tracing::builder()
 ///         .service_name("test")
 ///         .with_console_output("TEST_CONSOLE", LevelFilter::INFO)
@@ -125,6 +126,7 @@ pub struct Tracing {
     console_log_config: SubscriberConfig,
     otlp_log_config: SubscriberConfig,
     otlp_trace_config: SubscriberConfig,
+    logger_provider: Option<LoggerProvider>,
 }
 
 impl Tracing {
@@ -134,7 +136,10 @@ impl Tracing {
 
     /// Initialise the configured tracing subscribers, returning a guard that
     /// will shutdown the subscribers when dropped.
-    pub fn init(self) -> Result<Tracing> {
+    ///
+    /// IMPORTANT: Name the guard variable appropriately, do not just use
+    /// `let _ =`, as that will drop immediately.
+    pub fn init(mut self) -> Result<Tracing> {
         let mut layers: Vec<Box<dyn Layer<Registry> + Sync + Send>> = Vec::new();
 
         if self.console_log_config.enabled {
@@ -168,10 +173,11 @@ impl Tracing {
 
             // Convert `tracing::Event` to OpenTelemetry logs
             layers.push(
-                OpenTelemetryTracingBridge::new(otel_log.provider())
+                OpenTelemetryTracingBridge::new(&otel_log)
                     .with_filter(env_filter_layer)
                     .boxed(),
             );
+            self.logger_provider = Some(otel_log);
         }
 
         if self.otlp_trace_config.enabled {
@@ -186,15 +192,9 @@ impl Tracing {
             let otel_tracer = opentelemetry_otlp::new_pipeline()
                 .tracing()
                 .with_exporter(trace_exporter)
-                .with_trace_config(
-                    trace::config()
-                        .with_sampler(Sampler::AlwaysOn) // TODO (@NickLarsenNZ): Make this configurable. See also Sampler::ParentBased
-                        .with_id_generator(RandomIdGenerator::default())
-                        .with_resource(Resource::new(vec![KeyValue::new(
-                            resource::SERVICE_NAME,
-                            self.service_name,
-                        )])),
-                )
+                .with_trace_config(trace::config().with_resource(Resource::new(vec![
+                    KeyValue::new(resource::SERVICE_NAME, self.service_name),
+                ])))
                 .install_batch(opentelemetry_sdk::runtime::Tokio)
                 .context(InstallOtelTraceExporterSnafu)?;
 
@@ -223,16 +223,31 @@ impl Tracing {
                 .context(SetGlobalDefaultSubscriberSnafu)?;
         }
 
+        // IMPORTANT: we must return self, otherwise Drop will be called and uninitialise tracing
         Ok(self)
     }
 }
 
 impl Drop for Tracing {
     fn drop(&mut self) {
-        // NOTE (@NickLarsenNZ): These might eventually be replaced with something like SdkMeterProvider::shutdown(&self)
-        // see: https://github.com/open-telemetry/opentelemetry-rust/pull/1412/files#r1409608679
-        opentelemetry::global::shutdown_tracer_provider();
-        opentelemetry::global::shutdown_logger_provider();
+        tracing::debug!(
+            opentelemetry.tracing.enabled = self.otlp_trace_config.enabled,
+            opentelemetry.logger.enabled = self.otlp_log_config.enabled,
+            "shutting down opentelemetry OTLP providers"
+        );
+
+        if self.otlp_trace_config.enabled {
+            // NOTE (@NickLarsenNZ): This might eventually be replaced with something like SdkMeterProvider::shutdown(&self)
+            // as has been done with the LoggerProvider (further below)
+            // see: https://github.com/open-telemetry/opentelemetry-rust/pull/1412/files#r1409608679
+            opentelemetry::global::shutdown_tracer_provider();
+        }
+
+        if let Some(logger_provider) = &self.logger_provider {
+            if let Err(error) = logger_provider.shutdown() {
+                tracing::error!(%error, "unable to shutdown LoggerProvider");
+            }
+        }
     }
 }
 
@@ -417,6 +432,7 @@ impl TracingBuilder<builder_state::Config> {
             console_log_config: self.console_log_config,
             otlp_log_config: self.otlp_log_config,
             otlp_trace_config: self.otlp_trace_config,
+            logger_provider: None,
         }
     }
 }

crates/stackable-telemetry/src/tracing.rs

@@ -4,6 +4,10 @@ All notable changes to this project will be documented in this file.
 
 ## [Unreleased]
 
+## Changed
+
+- Remove instrumentation of long running functions, add more granular instrumentation of futures. Adjust span and event levels ([#811]).
+
 ### Fixed
 
 - Fix the extraction of `ConnectInfo` (data about the connection client) and
@@ -12,6 +16,7 @@ All notable changes to this project will be documented in this file.
   compatible traces ([#806]).
 
 [#806]: https://github.com/stackabletech/operator-rs/pull/806
+[#811]: https://github.com/stackabletech/operator-rs/pull/811
 
 ## [0.3.0] - 2024-05-08
 

crates/stackable-webhook/CHANGELOG.md

@@ -17,10 +17,12 @@ hyper-util.workspace = true
 hyper.workspace = true
 k8s-openapi.workspace = true
 kube.workspace = true
+opentelemetry.workspace = true
 serde_json.workspace = true
 snafu.workspace = true
 tokio-rustls.workspace = true
 tokio.workspace = true
 tower-http.workspace = true
 tower.workspace = true
 tracing.workspace = true
+tracing-opentelemetry.workspace = true

crates/stackable-webhook/Cargo.toml

@@ -30,7 +30,6 @@ use stackable_telemetry::AxumTraceLayer;
 use tokio::signal::unix::{signal, SignalKind};
 use tower::ServiceBuilder;
 // use tower_http::trace::TraceLayer;
-use tracing::{debug, instrument};
 
 use crate::tls::TlsServer;
 
@@ -127,9 +126,8 @@ impl WebhookServer {
     /// let router = Router::new();
     /// let server = WebhookServer::new(router, options);
     /// ```
-    #[instrument(name = "create_webhook_server", skip(router))]
     pub fn new(router: Router, options: Options) -> Self {
-        debug!("create new webhook server");
+        tracing::trace!("create new webhook server");
         Self { options, router }
     }
 
@@ -142,17 +140,17 @@ impl WebhookServer {
             let mut sigint = signal(SignalKind::interrupt()).expect("create SIGINT listener");
             let mut sigterm = signal(SignalKind::terminate()).expect("create SIGTERM listener");
 
-            debug!("created unix signal handlers");
+            tracing::debug!("created unix signal handlers");
 
             select! {
                 signal = sigint.recv().fuse() => {
                     if signal.is_some() {
-                        debug!( "received SIGINT");
+                        tracing::debug!( "received SIGINT");
                     }
                 },
                 signal = sigterm.recv().fuse() => {
                     if signal.is_some() {
-                        debug!( "received SIGTERM");
+                        tracing::debug!( "received SIGTERM");
                     }
                 },
             };
@@ -169,36 +167,36 @@ impl WebhookServer {
 
     /// Runs the webhook server by creating a TCP listener and binding it to
     /// the specified socket address.
-    #[instrument(name = "run_webhook_server", skip(self), fields(self.options))]
     async fn run_server(self) -> Result<()> {
-        debug!("run webhook server");
+        tracing::debug!("run webhook server");
 
         // TODO (@Techassi): Make opt-in configurable from the outside
         // Create an OpenTelemetry tracing layer
-        debug!("create tracing service (layer)");
+        tracing::trace!("create tracing service (layer)");
         let trace_layer = AxumTraceLayer::new().with_opt_in();
 
         // Use a service builder to provide multiple layers at once. Recommended
         // by the Axum project.
         //
         // See https://docs.rs/axum/latest/axum/middleware/index.html#applying-multiple-middleware
+        // TODO (@NickLarsenNZ): rename this server_builder and keep it specific to tracing, since it's placement in the chain is important
         let service_builder = ServiceBuilder::new().layer(trace_layer);
 
         // Create the root router and merge the provided router into it.
-        debug!("create core router and merge provided router");
+        tracing::debug!("create core router and merge provided router");
         let router = self
             .router
             .layer(service_builder)
             // The health route is below the AxumTraceLayer so as not to be instrumented
             .route("/health", get(|| async { "ok" }));
 
         // Create server for TLS termination
-        debug!("create TLS server");
+        tracing::debug!("create TLS server");
         let tls_server = TlsServer::new(self.options.socket_addr, router)
             .await
             .context(CreateTlsServerSnafu)?;
 
-        debug!("running TLS server");
+        tracing::info!("running TLS server");
         tls_server.run().await.context(RunTlsServerSnafu)
     }
 }