[Bug]: Appender-tracing creates log records with the wrong metadata under `experimental_span_attributes` feature

[dquirl-R1]

What happened?

When using opentelemetry-appender-tracing in conjunction with tracing-log to generate log records, the exported log records carry the target of the original log record. The tracing-log crate statically reports this (its Metadata::target) as "log" for all of its events. However, under the experimental_span_attributes feature flag it looks like this was supposed to be uplifted from log.target through NormalizeEvent - yet it isn't, because the target is evaluated first. This leads to the instrumentation scope name also being wrong, as that is filled in from the target.

I've tried to reconstruct the relevant history to the best of my ability:

• In Normalized metadata in opentelemetry-appender-tracing. #1380, normalization was added. Because the semantic conventions are still unstable, this happened under an experimental feature flag (cf. Normalized metadata in opentelemetry-appender-tracing. #1380 (comment))
• Appender-tracing and target #1683 then asked for filling in the instrumentation scope from target.
• This was implemented in Adding target as LogRecord field, and using it as scope.name in OTLP exporter #1869, at the time respecting the feature flag because normalization happened before anything else if the feature was enabled.
• In Fix OTel Appender for tracing from suppressing other layers #2668, extraction of metadata severity and target is moved to the top of the event handler to allow dynamically checking if the event should be enabled, fixing otel-appender-tracing can suppress other tracing layers #1682.
  • This breaks the feature flag, since the two attributes are not recomputed after the metadata is normalized.
• To make this check more dynamic (feat: Allow event name to be provided to IsEnabled check in Logger #2756), feat: Allow event name to be provided to IsEnabled check in Logger #2756 hoists name up to the top as well.
  • This completely decouples the fields set on log_record from the normalized metadata, as even the severity text (that is not pre-computed) now refers back to the original metadata. Only the visitor for extracting the code. now uses the normalized metadata.

Independently of whether the code. attributes are wanted, normalizing the event seems appropriate. While the NormalizeEvent trait seems to have been primarily introduced to allow printing the correct name in tracing-fmt, the target / scope of the original log::log! (or info! or error! etc.) invocation is by definition more correct than just log, as it reports the actual location of the log event in the originating crate. I'm not sure if it needs to be tied to the same feature flag as the experimental attributes, which are uplifted through the dedicated visitor, but at the very least when the event metadata is normalized I'd expect the resulting target to be post-norm.

OpenTelemetry API Version (i.e version of opentelemetry crate)

0.32.0

OpenTelemetry SDK Version (i.e version of opentelemetry_sdk crate)

0.32.0

What Exporter(s) are you seeing the problem on?

OTLP

Relevant log output

Tip

_{React with 👍 to help prioritize this issue. Please use comments to provide useful context, avoiding +1 or me too, to help us triage it. Learn more here.}

[dquirl-R1]

Fixing this is pretty trivial, e.g. below is a patch that fixes this under the feature flag (note that applying this patch additionally requires adjusting the tests, which currently always assert against "log"):

git patch

diff --git a/opentelemetry-appender-tracing/src/layer.rs b/opentelemetry-appender-tracing/src/layer.rs
index 91f7d449..7f3001be 100644
--- a/opentelemetry-appender-tracing/src/layer.rs
+++ b/opentelemetry-appender-tracing/src/layer.rs
@@ -454,7 +454,14 @@ where
         #[cfg_attr(not(feature = "experimental_span_attributes"), allow(unused_variables))]
         ctx: tracing_subscriber::layer::Context<'_, S>,
     ) {
+        #[cfg(feature = "experimental_metadata_attributes")]
+        let normalized_meta = event.normalized_metadata();
+        #[cfg(feature = "experimental_metadata_attributes")]
+        let metadata = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
+
+        #[cfg(not(feature = "experimental_metadata_attributes"))]
         let metadata = event.metadata();
+
         let severity = severity_of_level(metadata.level());
         let target = metadata.target();
         let name = metadata.name();
@@ -463,15 +470,9 @@ where
             return;
         }
 
-        #[cfg(feature = "experimental_metadata_attributes")]
-        let normalized_meta = event.normalized_metadata();
-
-        #[cfg(feature = "experimental_metadata_attributes")]
-        let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
-
         let mut log_record = self.logger.create_log_record();
 
-        log_record.set_target(target);
+        log_record.set_target(target.to_string());
         log_record.set_event_name(name);
         log_record.set_severity_number(severity);
         log_record.set_severity_text(metadata.level().as_str());
@@ -495,7 +496,7 @@ where
 
         let mut visitor = EventVisitor::new(&mut log_record);
         #[cfg(feature = "experimental_metadata_attributes")]
-        visitor.visit_experimental_metadata(meta);
+        visitor.visit_experimental_metadata(metadata);
         // Visit fields.
         event.record(&mut visitor);

I wanted to solicit your feedback before posting a PR with this, however, since

• It's unclear to me whether the normalization should happen by default / always, only under the existing feature flag or only under a separate feature flag.
• It's also unclear to me whether the current experimental feature flag is desired. Graduate stable spec features out of experimental feature flags before 1.0 #3376 says that it is "Not directly spec-driven but widely requested." and should be "Evaluate[d] for graduation.". On the other hand, this comment from the PR adding target as a field asks for this feature (or at least I think it's referring to this feature) to be removed.
• The optimization from perf: Small perf optimization for logs #2799 is reverted by my patch, as the lifetime is different after normalization.
• I'm not sure how you expect this feature to interact with the event_enabled filter. Personally, I'd argue that providing the normalized target for filtering is more useful to implementors of Logger, as if it was me I'd want to filter things like "events from mio" and not "libraries that use log and not tracing". But obviously today these implementors receive "log" as the target and changing that might break their workflows.

[dquirl-R1]

I just learned that there is another kind of "normalization" that happens inside tracing-log where AsTrace is invoked in dispatch_record to generate "fake" metadata that is exclusively used to pass it to the check if the dispatcher is enabled.

Because of this, an EnvFilter applied to a layer receiving log events correctly filters against the actual target, because Filtered caches the result of enabled in its FilterState (generically by FilterId) and EnvFilter doesn't override event_enabled itself to look at the actual event (which would have a different metadata / target).

However, this makes it possible for the inner layer to see an event who's metadata is different from what was used to check whether the layer should receive the event.

[scottgerring]

Hey @dquirl-R1 thanks for the detailed analysis! I think your patch is on the right path - behind the feature flag we should normalise once, early, and use it everywhere. That does mean event_enabled will see the normalised target too when the flag is on, which seems like the right behaviour. Would you like to raise a PR for this?