feat(telemetry): add configurability of span attributes in logs

.changesets/feat_bnjjj_feat_5540.md

@@ -0,0 +1,39 @@
+### Add configurability of span attributes in logs ([Issue #5540](https://github.com/apollographql/router/issues/5540))
+
+The router supports a new  `telemetry.exporters.logging.stdout.format.json.span_attributes` option that enables you to choose a subset of all span attributes to display in your logs.
+
+When `span_attributes` is specified, the router searches for the first attribute in its input list of span attributes from the root span to the current span and attaches it to the outermost JSON object for the log event. If you set the same attribute name for different spans at different levels, the router chooses the attributes of child spans before the attributes of parent spans.
+
+
+For example, if you have spans that contains `span_attr_1` attribute and you only want to display this span attribute:
+
+```yaml title="router.yaml"
+telemetry:
+  exporters:
+     logging:
+       stdout:
+         enabled: true
+         format: 
+           json:
+             display_span_list: false
+             span_attributes:
+             - span_attr_1
+```
+
+Example output with a list of spans:
+
+```json
+{
+  "timestamp": "2023-10-30T14:09:34.771388Z",
+  "level": "INFO",
+  "fields": {
+    "event_attr_1": "event_attr_1",
+    "event_attr_2": "event_attr_2"
+  },
+  "target": "event_target",
+  "span_attr_1": "span_attr_1"
+}
+```
+
+To learn more, go to [`span_attributes`](https://www.apollographql.com/docs/router/configuration/telemetry/exporters/logging/stdout#span_attributes) docs.
+By [@bnjjj](https://github.com/bnjjj) in https://github.com/apollographql/router/pull/5867

apollo-router/src/configuration/snapshots/apollo_router__configuration__tests__schema_generation.snap

@@ -8151,6 +8151,15 @@ expression: "&schema"
                 "display_trace_id": {
                   "$ref": "#/definitions/DisplayTraceIdFormat",
                   "description": "#/definitions/DisplayTraceIdFormat"
+                },
+                "span_attributes": {
+                  "default": [],
+                  "description": "List of span attributes to attach to the json log object",
+                  "items": {
+                    "type": "string"
+                  },
+                  "type": "array",
+                  "uniqueItems": true
                 }
               },
               "type": "object"

apollo-router/src/plugins/telemetry/config_new/logging.rs

@@ -1,4 +1,5 @@
 use std::collections::BTreeMap;
+use std::collections::HashSet;
 use std::io::IsTerminal;
 use std::time::Duration;
 
@@ -339,6 +340,8 @@ pub(crate) struct JsonFormat {
     pub(crate) display_trace_id: DisplayTraceIdFormat,
     /// Include the span id (if any) with the log event. (default: true)
     pub(crate) display_span_id: bool,
+    /// List of span attributes to attach to the json log object
+    pub(crate) span_attributes: HashSet<String>,
 }
 
 #[derive(Clone, Debug, Deserialize, JsonSchema, PartialEq, Eq)]
@@ -389,6 +392,7 @@ impl Default for JsonFormat {
             display_resource: true,
             display_trace_id: DisplayTraceIdFormat::Bool(true),
             display_span_id: true,
+            span_attributes: HashSet::new(),
         }
     }
 }

apollo-router/src/plugins/telemetry/formatters/json.rs

@@ -1,9 +1,11 @@
+use std::collections::HashMap;
 use std::collections::HashSet;
 use std::fmt;
 use std::io;
 
 use opentelemetry::sdk::Resource;
 use opentelemetry::Array;
+use opentelemetry::Key;
 use opentelemetry::OrderMap;
 use opentelemetry::Value;
 use serde::ser::SerializeMap;
@@ -283,6 +285,14 @@ where
                 }
             }
 
+            if !self.config.span_attributes.is_empty() {
+                for (key, value) in
+                    extract_span_attributes(ctx.lookup_current(), &self.config.span_attributes)
+                {
+                    serializer.serialize_entry(key.as_str(), &AttributeValue::from(value))?;
+                }
+            }
+
             let mut visitor = tracing_serde::SerdeMapVisitor::new(serializer);
             event.record(&mut visitor);
 
@@ -318,7 +328,6 @@ where
                     serializer.serialize_entry("dd.trace_id", &dd_trace_id)?;
                 }
             }
-
             if self.config.display_span_list && current_span.is_some() {
                 serializer.serialize_entry(
                     "spans",
@@ -370,6 +379,66 @@ fn extract_dd_trace_id<'a, 'b, T: LookupSpan<'a>>(span: &SpanRef<'a, T>) -> Opti
     dd_trace_id
 }
 
+fn extract_span_attributes<'a, 'b, Span>(
+    current: Option<SpanRef<'a, Span>>,
+    include_attributes: &HashSet<String>,
+) -> HashMap<Key, Value>
+where
+    Span: for<'lookup> tracing_subscriber::registry::LookupSpan<'lookup>,
+{
+    let mut attributes = HashMap::new();
+    if let Some(leaf_span) = &current {
+        for span in leaf_span.scope().from_root() {
+            let ext = span.extensions();
+
+            // Get otel attributes
+            {
+                let otel_attributes = ext
+                    .get::<OtelData>()
+                    .and_then(|otel_data| otel_data.builder.attributes.as_ref());
+                if let Some(otel_attributes) = otel_attributes {
+                    attributes.extend(
+                        otel_attributes
+                            .iter()
+                            .filter(|(key, _)| {
+                                let key_name = key.as_str();
+                                !key_name.starts_with(APOLLO_PRIVATE_PREFIX)
+                                    && include_attributes.contains(key_name)
+                            })
+                            .map(|(key, val)| (key.clone(), val.clone())),
+                    );
+                }
+            }
+            // Get custom dynamic attributes
+            {
+                let custom_attributes = ext.get::<LogAttributes>().map(|attrs| attrs.attributes());
+                if let Some(custom_attributes) = custom_attributes {
+                    #[cfg(test)]
+                    let custom_attributes: Vec<&opentelemetry::KeyValue> = {
+                        let mut my_custom_attributes: Vec<&opentelemetry::KeyValue> =
+                            custom_attributes.iter().collect();
+                        my_custom_attributes.sort_by_key(|kv| &kv.key);
+                        my_custom_attributes
+                    };
+                    #[allow(clippy::into_iter_on_ref)]
+                    attributes.extend(
+                        custom_attributes
+                            .into_iter()
+                            .filter(|kv| {
+                                let key_name = kv.key.as_str();
+                                !key_name.starts_with(APOLLO_PRIVATE_PREFIX)
+                                    && include_attributes.contains(key_name)
+                            })
+                            .map(|kv| (kv.key.clone(), kv.value.clone())),
+                    );
+                }
+            }
+        }
+    }
+
+    attributes
+}
+
 struct WriteAdaptor<'a> {
     fmt_write: &'a mut dyn fmt::Write,
 }

apollo-router/tests/integration/telemetry/fixtures/json.span_attributes.router.yaml

@@ -0,0 +1,136 @@
+telemetry:
+  instrumentation:
+    spans:
+      mode: spec_compliant
+      router:
+        attributes:
+          should_not_log:
+            static: hello
+          too_big:
+            static: true
+          another_one:
+            static: foo
+          graphql.operation.name:
+            operation_name: string
+      supergraph:
+        attributes:
+          graphql.document: true
+      subgraph:
+        attributes:
+          too_big:
+            static: "nope"
+    events:
+      router:
+        # Standard events
+        request: info
+        response: info
+        error: info
+
+        # Custom events
+        my.disabled_request_event:
+          message: "my event message"
+          level: off
+          on: request
+          attributes:
+            http.request.body.size: true
+          # Only log when the x-log-request header is `log` 
+          condition:
+            eq:
+              - "log"
+              - request_header: "x-log-request"
+        my.request_event:
+          message: "my event message"
+          level: info
+          on: request
+          attributes:
+            http.request.body.size: true
+        my.response_event:
+          message: "my response event message"
+          level: info
+          on: response
+          attributes:
+            http.response.body.size: true
+            static_one:
+              static: test
+      supergraph:
+        # Standard events
+        request: info
+        response: info
+        error: info
+
+        # Custom events
+        my.disabled_request.event:
+          message: "my event message"
+          level: off
+          on: request
+          # Only log when the x-log-request header is `log` 
+          condition:
+            eq:
+              - "log"
+              - request_header: "x-log-request"
+        my.request.event:
+          message: "my event message"
+          level: info
+          on: request
+          # Only log when the x-log-request header is `log` 
+          condition:
+            eq:
+              - "log"
+              - request_header: "x-log-request"
+        my.response_event:
+          message: "my response event message"
+          level: warn
+          on: response
+          condition:
+            eq:
+              - "log"
+              - response_header: "x-log-request"
+      subgraph:
+        # Standard events
+        request: info
+        response: warn
+        error: error
+
+        # Custom events
+        my.disabled_request.event:
+          message: "my event message"
+          level: off
+          on: request
+        my.request.event:
+          message: "my event message"
+          level: info
+          on: request
+        my.response.event:
+          message: "my response event message"
+          level: error
+          on: response
+          attributes:
+            subgraph.name: true
+            response_status:
+              subgraph_response_status: code
+            "my.custom.attribute":
+              subgraph_response_data: "$.*"
+              default: "missing"
+  exporters:
+    tracing:
+      propagation:
+        trace_context: true
+      jaeger:
+        enabled: true
+        batch_processor:
+          scheduled_delay: 100ms
+        agent:
+          endpoint: default
+    logging:
+      experimental_when_header:
+        - name: content-type
+          value: "application/json"
+          body: true
+      stdout:
+        format:
+          json:
+            display_span_list: false
+            display_current_span: false
+            span_attributes:
+            - graphql.document
+            - too_big

apollo-router/tests/integration/telemetry/logging.rs

@@ -36,6 +36,47 @@ async fn test_json() -> Result<(), BoxError> {
     Ok(())
 }
 
+#[tokio::test(flavor = "multi_thread")]
+async fn test_json_promote_span_attributes() -> Result<(), BoxError> {
+    if !graph_os_enabled() {
+        eprintln!("test skipped");
+        return Ok(());
+    }
+
+    let mut router = IntegrationTest::builder()
+        .telemetry(Telemetry::Jaeger)
+        .config(include_str!("fixtures/json.span_attributes.router.yaml"))
+        .build()
+        .await;
+
+    router.start().await;
+    router.assert_started().await;
+
+    let query = json!({"query":"query ExampleQuery {topProducts{name}}","variables":{}});
+    router.execute_query(&query).await;
+    router.assert_log_contains("trace_id").await;
+    router.execute_query(&query).await;
+    router.assert_log_contains("span_id").await;
+    router.execute_query(&query).await;
+    router.assert_log_contains(r#""static_one":"test""#).await;
+    router.execute_query(&query).await;
+    router.assert_log_contains(r#""response_status":200"#).await;
+    router.execute_query(&query).await;
+    router.assert_log_contains(r#""too_big":true"#).await;
+    router.execute_query(&query).await;
+    router.assert_log_contains(r#""too_big":"nope""#).await;
+    router.execute_query(&query).await;
+    router
+        .assert_log_contains(r#""graphql.document":"query ExampleQuery {topProducts{name}}""#)
+        .await;
+    router.execute_query(&query).await;
+    router.assert_log_not_contains(r#""should_not_log""#).await;
+    router.assert_log_not_contains(r#""another_one""#).await;
+    router.graceful_shutdown().await;
+
+    Ok(())
+}
+
 #[tokio::test(flavor = "multi_thread")]
 async fn test_json_uuid_format() -> Result<(), BoxError> {
     if !graph_os_enabled() {