Implement dynamic metadata injection

Now that places are using non-'static metadata, we can overlay a patched
view of the metadata. Using the strategy seen in tracing-log, we
recognize specifically named metadata/fields and use the values they
provide to create metadata with the resolved runtime values.

Importantly, we also strive to only expose dynamic injection fields when
explicitly asked for. This means that most code can continue on without
knowing that these fields even exist.

Applying these patches does have a cost; notably, things which used to
deal in references like &Metadata or &FieldSet now often use an owned,
patched version instead. These types are primarily bags of references
themselves, and no copying of actual data is involved, but the fact that
the bags of references (which aren't exactly tiny) are copied does have
an impact.

More places which don't have to deal with metadata patching (e.g. the
macro support code) should be audited for what can use the _prenormal
versions of methods.

Additionally, there are likely places where the magic fields leak out
without being explicitly asked for. Ideally, these are all bugs which
can be fixed. There aren't really any tests that effectively check for
this, so new tests will need to be written.

Finaly, there's the question of actually dispatching such a dynamic
event. tracing-log is an example of doing so (but uses touchy, hidden
API to construct the ValueSet) (implemented in the next commit), but a
generally applicable is likely desirable. This will probably take the
shape of dynamic_span! and dynamic_event! macros in tracing proper.

tracing-core/src/event.rs

@@ -95,8 +95,10 @@ impl<'a> Event<'a> {
     /// Returns [metadata] describing this `Event`.
     ///
     /// [metadata]: super::Metadata
-    pub fn metadata(&self) -> &'a Metadata<'a> {
+    pub fn metadata(&self) -> Metadata<'a> {
         self.metadata
+            .normalized(self)
+            .unwrap_or_else(|| self.metadata.clone())
     }
 
     /// Returns true if the new event should be a root.
@@ -131,4 +133,8 @@ impl<'a> field::RecordFields<'a> for Event<'a> {
     fn record(&self, visitor: &mut dyn field::Visit<'a>) {
         Event::record(self, visitor)
     }
+
+    fn record_prenormal(&self, visitor: &mut dyn field::Visit<'a>) {
+        self.fields.record_prenormal(visitor)
+    }
 }

tracing-core/src/field.rs

@@ -80,6 +80,7 @@ pub struct Empty;
 ///
 /// [initialized]: Self::new
 /// [callsite identifiers]: callsite::Identifier
+#[derive(Clone)]
 pub struct FieldSet {
     /// The names of each field on the described span.
     names: &'static [&'static str],
@@ -275,8 +276,13 @@ pub trait Visit<'a> {
 /// [`span::Attributes`]: crate::span::Attributes
 /// [`span::Record`]: crate::span::Record
 pub trait RecordFields<'a> {
-    /// Record all the fields in `self` with the provided `visitor`.
+    /// Record all the fields in `self` with the provided `visitor`, excluding
+    /// those used for [dynamic metadata][crate::dynamic].
     fn record(&self, visitor: &mut dyn Visit<'a>);
+
+    /// Record all the fields in `self` with the provided `visitor`, *including*
+    /// those used for [dynamic metadata][crate::dynamic].
+    fn record_prenormal(&self, visitor: &mut dyn Visit<'a>);
 }
 
 /// A field value of an erased type.
@@ -352,6 +358,10 @@ where
     fn record(&self, visitor: &mut dyn Visit<'a>) {
         F::record(*self, visitor)
     }
+
+    fn record_prenormal(&self, visitor: &mut dyn Visit<'a>) {
+        F::record_prenormal(*self, visitor)
+    }
 }
 
 // ===== impl Value =====
@@ -786,7 +796,17 @@ impl FieldSet {
     /// of those callsites are not equivalent.
     /// </pre></div>
     pub fn contains(&self, field: &Field) -> bool {
-        field.callsite() == self.callsite() && field.i <= self.len()
+        if field.callsite() != self.callsite() {
+            return false;
+        }
+
+        // Example:
+        // Sliced Fieldset: [                 "carol", "david" ]
+        // Field, Unsliced: [ "alice", "bob", "carol", "david" ], 3
+        let slice_offset = field.fields.names.len() as isize - self.len() as isize;
+        let field_index_in_me = field.i as isize - slice_offset;
+
+        0 <= field_index_in_me && field_index_in_me <= self.len() as isize
     }
 
     /// Returns an iterator over the `Field`s in this `FieldSet`.
@@ -827,6 +847,22 @@ impl FieldSet {
     pub fn is_empty(&self) -> bool {
         self.names.is_empty()
     }
+
+    pub(crate) fn slice(&self, range: core::ops::RangeFrom<usize>) -> Self {
+        Self {
+            names: &self.names[range],
+            callsite: self.callsite.clone(),
+        }
+    }
+}
+
+impl IntoIterator for FieldSet {
+    type IntoIter = Iter;
+    type Item = Field;
+    #[inline]
+    fn into_iter(self) -> Self::IntoIter {
+        self.iter()
+    }
 }
 
 impl<'a> IntoIterator for &'a FieldSet {
@@ -897,10 +933,7 @@ impl Iterator for Iter {
         let i = self.idxs.next()?;
         Some(Field {
             i,
-            fields: FieldSet {
-                names: self.fields.names,
-                callsite: self.fields.callsite(),
-            },
+            fields: self.fields.clone(),
         })
     }
 }
@@ -922,6 +955,17 @@ impl<'a> ValueSet<'a> {
     ///
     /// [visitor]: Visit
     pub fn record(&self, visitor: &mut dyn Visit<'a>) {
+        for (field, value) in self.values {
+            if !self.fields.contains(field) {
+                continue;
+            }
+            if let Some(value) = value {
+                value.record(field, visitor);
+            }
+        }
+    }
+
+    fn record_unsliced(&self, visitor: &mut dyn Visit<'a>) {
         let my_callsite = self.callsite();
         for (field, value) in self.values {
             if field.callsite() != my_callsite {
@@ -935,7 +979,7 @@ impl<'a> ValueSet<'a> {
 
     /// Returns `true` if this `ValueSet` contains a value for the given `Field`.
     pub(crate) fn contains(&self, field: &Field) -> bool {
-        field.callsite() == self.callsite()
+        self.fields.contains(field)
             && self
                 .values
                 .iter()
@@ -944,10 +988,9 @@ impl<'a> ValueSet<'a> {
 
     /// Returns true if this `ValueSet` contains _no_ values.
     pub(crate) fn is_empty(&self) -> bool {
-        let my_callsite = self.callsite();
         self.values
             .iter()
-            .all(|(key, val)| val.is_none() || key.callsite() != my_callsite)
+            .all(|(key, val)| val.is_none() || !self.fields.contains(key))
     }
 
     pub(crate) fn field_set(&self) -> &FieldSet {
@@ -959,6 +1002,10 @@ impl<'a> RecordFields<'a> for ValueSet<'a> {
     fn record(&self, visitor: &mut dyn Visit<'a>) {
         ValueSet::record(self, visitor)
     }
+
+    fn record_prenormal(&self, visitor: &mut dyn Visit<'a>) {
+        ValueSet::record_unsliced(self, visitor)
+    }
 }
 
 impl<'a> fmt::Debug for ValueSet<'a> {
@@ -1093,7 +1140,8 @@ mod test {
             (&fields.field("bar").unwrap(), Some(&2 as &dyn Value)),
             (&fields.field("baz").unwrap(), Some(&3 as &dyn Value)),
         ];
-        let valueset = TEST_META_2.fields().value_set(values);
+        let fields = TEST_META_2.fields();
+        let valueset = fields.value_set(values);
         assert!(valueset.is_empty())
     }
 

tracing-core/src/lib.rs

@@ -289,6 +289,7 @@ pub(crate) mod spin;
 pub mod callsite;
 pub mod collect;
 pub mod dispatch;
+pub mod dynamic;
 pub mod event;
 pub mod field;
 pub mod metadata;

tracing-core/src/metadata.rs

@@ -54,6 +54,7 @@ use core::{
 /// [module path]: Self::module_path
 /// [collector]: super::collect::Collect
 /// [callsite identifiers]: Self::callsite
+#[derive(Clone)]
 pub struct Metadata<'a> {
     /// The name of the span described by this metadata.
     name: &'a str,
@@ -273,11 +274,34 @@ impl<'a> Metadata<'a> {
         }
     }
 
-    /// Returns the names of the fields on the described span or event.
-    pub fn fields(&self) -> &field::FieldSet {
+    /// Returns the kind of this callsite.
+    pub fn kind(&self) -> &Kind {
+        &self.kind
+    }
+
+    /// Returns the names of the fields on the described span or event,
+    /// excluding those used for [dynamic metadata][crate::dynamic].
+    pub fn fields(&self) -> field::FieldSet {
+        if self.is_dynamic() {
+            let magic = self.magic_fields();
+            self.fields.slice(magic.count()..)
+        } else {
+            self.fields.clone()
+        }
+    }
+
+    /// Returns the names of the fields on the described span or event,
+    /// *including* those used for [dynamic metadata][crate::dynamic].
+    pub fn fields_prenormal(&self) -> &field::FieldSet {
         &self.fields
     }
 
+    /// Returns the names of the fields on the described span or event
+    /// used for [dynamic metadata][crate::dynamic].
+    pub(crate) fn magic_fields(&self) -> crate::dynamic::MagicFields {
+        crate::dynamic::MagicFields::new(&self.fields)
+    }
+
     /// Returns the level of verbosity of the described span or event.
     pub fn level(&self) -> &Level {
         &self.level

tracing-core/src/span.rs

@@ -215,6 +215,10 @@ impl<'a> field::RecordFields<'a> for Attributes<'a> {
     fn record(&self, visitor: &mut dyn field::Visit<'a>) {
         Attributes::record(self, visitor)
     }
+
+    fn record_prenormal(&self, visitor: &mut dyn field::Visit<'a>) {
+        self.values.record_prenormal(visitor)
+    }
 }
 
 // ===== impl Record =====
@@ -247,6 +251,10 @@ impl<'a> field::RecordFields<'a> for Record<'a> {
     fn record(&self, visitor: &mut dyn field::Visit<'a>) {
         Record::record(self, visitor)
     }
+
+    fn record_prenormal(&self, visitor: &mut dyn field::Visit<'a>) {
+        self.values.record_prenormal(visitor)
+    }
 }
 
 // ===== impl Current =====

tracing-error/src/subscriber.rs

@@ -99,9 +99,9 @@ where
             .expect("registry should have a span for the current ID");
         for span in span.scope() {
             let cont = if let Some(fields) = span.extensions().get::<FormattedFields<F>>() {
-                f(span.metadata(), fields.fields.as_str())
+                f(&span.metadata(), fields.fields.as_str())
             } else {
-                f(span.metadata(), "")
+                f(&span.metadata(), "")
             };
             if !cont {
                 break;

tracing-journald/src/lib.rs

@@ -217,7 +217,7 @@ where
 
         writeln!(buf, "SPAN_NAME").unwrap();
         put_value(&mut buf, span.name().as_bytes());
-        put_metadata(&mut buf, span.metadata(), Some("SPAN_"));
+        put_metadata(&mut buf, &span.metadata(), Some("SPAN_"));
 
         attrs.record(&mut SpanVisitor {
             buf: &mut buf,
@@ -252,8 +252,8 @@ where
         }
 
         // Record event fields
-        put_priority(&mut buf, event.metadata());
-        put_metadata(&mut buf, event.metadata(), None);
+        put_priority(&mut buf, &event.metadata());
+        put_metadata(&mut buf, &event.metadata(), None);
         put_field_length_encoded(&mut buf, "SYSLOG_IDENTIFIER", |buf| {
             write!(buf, "{}", self.syslog_identifier).unwrap()
         });

tracing-mock/src/event.rs

@@ -563,7 +563,7 @@ impl ExpectedEvent {
         let meta = event.metadata();
         let name = meta.name();
         self.metadata
-            .check(meta, format_args!("event \"{}\"", name), collector_name);
+            .check(&meta, format_args!("event \"{}\"", name), collector_name);
         assert!(
             meta.is_event(),
             "[{}] expected {}, but got {:?}",

tracing-opentelemetry/src/subscriber.rs

@@ -812,7 +812,7 @@ where
             #[cfg(feature = "tracing-log")]
             let normalized_meta = event.normalized_metadata();
             #[cfg(feature = "tracing-log")]
-            let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
+            let meta = normalized_meta.unwrap_or_else(|| event.metadata());
             #[cfg(not(feature = "tracing-log"))]
             let meta = event.metadata();
 
@@ -843,22 +843,8 @@ where
                 }
 
                 if self.location {
-                    #[cfg(not(feature = "tracing-log"))]
-                    let normalized_meta: Option<tracing_core::Metadata<'_>> = None;
-                    let (file, module) = match &normalized_meta {
-                        Some(meta) => (
-                            meta.file().map(|s| Value::from(s.to_owned())),
-                            meta.module_path().map(|s| Value::from(s.to_owned())),
-                        ),
-                        None => (
-                            event.metadata().file().map(String::from).map(Value::from),
-                            event
-                                .metadata()
-                                .module_path()
-                                .map(String::from)
-                                .map(Value::from),
-                        ),
-                    };
+                    let file = meta.file().map(String::from).map(Value::from);
+                    let module = meta.module_path().map(String::from).map(Value::from);
 
                     if let Some(file) = file {
                         otel_event

tracing-serde/src/lib.rs

@@ -267,7 +267,7 @@ impl<'a> Serialize for SerializeMetadata<'a> {
         state.serialize_field("module_path", &self.0.module_path())?;
         state.serialize_field("file", &self.0.file())?;
         state.serialize_field("line", &self.0.line())?;
-        state.serialize_field("fields", &SerializeFieldSet(self.0.fields()))?;
+        state.serialize_field("fields", &SerializeFieldSet(&self.0.fields()))?;
         state.serialize_field("is_span", &self.0.is_span())?;
         state.serialize_field("is_event", &self.0.is_event())?;
         state.end()
@@ -284,7 +284,7 @@ impl<'a> Serialize for SerializeEvent<'a> {
         S: Serializer,
     {
         let mut serializer = serializer.serialize_struct("Event", 2)?;
-        serializer.serialize_field("metadata", &SerializeMetadata(self.0.metadata()))?;
+        serializer.serialize_field("metadata", &SerializeMetadata(&self.0.metadata()))?;
         let mut visitor = SerdeStructVisitor {
             serializer,
             state: Ok(()),

tracing-subscriber/Cargo.toml

@@ -30,7 +30,7 @@ std = ["alloc", "tracing-core/std"]
 env-filter = ["matchers", "regex", "once_cell", "tracing", "std", "thread_local"]
 fmt = ["registry", "std"]
 ansi = ["fmt", "nu-ansi-term"]
-registry = ["sharded-slab", "thread_local", "std"]
+registry = ["sharded-slab", "thread_local", "std", "once_cell"]
 json = ["tracing-serde", "serde", "serde_json"]
 # Enables support for local time when using the `time` crate timestamp
 # formatters.
@@ -42,12 +42,16 @@ tracing-core = { path = "../tracing-core", version = "0.2", default-features = f
 # only required by the `env-filter` feature
 tracing = { optional = true, path = "../tracing", version = "0.2", default-features = false }
 matchers = { optional = true, version = "0.1.0" }
-regex = { optional = true, version = "1.6.0", default-features = false, features = ["std"] }
-smallvec = { optional = true, version = "1.9.0" }
-once_cell = { optional = true, version = "1.13.0" }
+regex = { optional = true, version = "1", default-features = false, features = [
+    "std",
+] }
+smallvec = { optional = true, version = "1" }
 
 # fmt
-tracing-log = { path = "../tracing-log", version = "0.2", optional = true, default-features = false, features = ["log-tracer", "std"] }
+tracing-log = { path = "../tracing-log", version = "0.2", optional = true, default-features = false, features = [
+    "log-tracer",
+    "std",
+] }
 nu-ansi-term = { version = "0.46.0", optional = true }
 time = { version = "0.3.2", features = ["formatting"], optional = true }
 
@@ -63,14 +67,20 @@ parking_lot = { version = "0.12.1", optional = true }
 sharded-slab = { version = "0.1.4", optional = true }
 thread_local = { version = "1.1.4", optional = true }
 
+# registry OR env-filter
+once_cell = { version = "1.12", optional = true }
+
 [dev-dependencies]
 tracing = { path = "../tracing", version = "0.2" }
 tracing-mock = { path = "../tracing-mock", features = ["tracing-subscriber"] }
 log = "0.4.17"
 tracing-log = { path = "../tracing-log", version = "0.2" }
 criterion = { version = "0.3.6", default_features = false }
 regex = { version = "1.6.0", default-features = false, features = ["std"] }
-tracing-futures = { path = "../tracing-futures", version = "0.3", default-features = false, features = ["std-future", "std"] }
+tracing-futures = { path = "../tracing-futures", version = "0.3", default-features = false, features = [
+    "std-future",
+    "std",
+] }
 tokio = { version = "1.20.0", features = ["rt", "macros"] }
 # Enable the `time` crate's `macros` feature, for examples.
 time = { version = "0.3.2", features = ["formatting", "macros"] }