1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212
use std::collections::HashMap;
use std::fmt;
use std::time::Instant;
use tracing::field::{Field, Visit};
use tracing::span::{Attributes, Record};
use tracing::{Id, Subscriber};
use tracing_subscriber::layer::Context;
use tracing_subscriber::Layer;
/// This layer is only concerned with information storage, it does not do any formatting or provide any output.
///
/// It's purpose is to store the fields associated to spans in an easy-to-consume format
/// for downstream layers concerned with emitting a formatted representation of
/// spans or events.
#[derive(Clone, Debug)]
pub struct JsonStorageLayer;
/// `JsonStorage` will collect information about a span when it's created (`new_span` handler)
/// or when new records are attached to it (`on_record` handler) and store it in its `extensions`
/// for future retrieval from other layers interested in formatting or further enrichment.
///
/// We are re-implementing (well, copy-pasting, apart from using an HashMap instead of a BTreeMap)
/// `JsonVisitor` from `tracing-subscriber` given that we can't access/insert/iterate over
/// the underlying BTreeMap using its public API.
///
/// For spans, we also store the duration of each span with the `elapsed_milliseconds` key using
/// the `on_exit`/`on_enter` handlers.
#[derive(Clone, Debug)]
pub struct JsonStorage<'a> {
values: HashMap<&'a str, serde_json::Value>,
}
impl<'a> JsonStorage<'a> {
/// Get the set of stored values, as a set of keys and JSON values.
pub fn values(&self) -> &HashMap<&'a str, serde_json::Value> {
&self.values
}
}
/// Get a new visitor, with an empty bag of key-value pairs.
impl Default for JsonStorage<'_> {
fn default() -> Self {
Self {
values: HashMap::new(),
}
}
}
/// Taken verbatim from tracing-subscriber
impl Visit for JsonStorage<'_> {
/// Visit a signed 64-bit integer value.
fn record_i64(&mut self, field: &Field, value: i64) {
self.values
.insert(field.name(), serde_json::Value::from(value));
}
/// Visit an unsigned 64-bit integer value.
fn record_u64(&mut self, field: &Field, value: u64) {
self.values
.insert(field.name(), serde_json::Value::from(value));
}
/// Visit a 64-bit floating point value.
fn record_f64(&mut self, field: &Field, value: f64) {
self.values
.insert(field.name(), serde_json::Value::from(value));
}
/// Visit a boolean value.
fn record_bool(&mut self, field: &Field, value: bool) {
self.values
.insert(field.name(), serde_json::Value::from(value));
}
/// Visit a string value.
fn record_str(&mut self, field: &Field, value: &str) {
self.values
.insert(field.name(), serde_json::Value::from(value));
}
fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
match field.name() {
// Skip fields that are actually log metadata that have already been handled
name if name.starts_with("log.") => (),
name if name.starts_with("r#") => {
self.values
.insert(&name[2..], serde_json::Value::from(format!("{:?}", value)));
}
name => {
self.values
.insert(name, serde_json::Value::from(format!("{:?}", value)));
}
};
}
#[cfg(all(tracing_unstable, feature = "valuable"))]
#[cfg_attr(docsrs, doc(cfg(all(tracing_unstable, feature = "valuable"))))]
fn record_value(&mut self, field: &Field, value: valuable::Value<'_>) {
let serializable = valuable_serde::Serializable::new(value);
match serde_json::to_value(serializable) {
Ok(json_value) => {
self.values.insert(field.name(), json_value);
}
Err(error) => {
tracing::debug!(
// The parent span may be the one with this
// unserializable field value. If so logging an event
// under this parent span might trigger it field value
// to be serialized again, causing an infinite loop.
// Avoid this by explicitly setting the parent span to `None`.
parent: None,
?error,
field_name = field.name(),
"serde_json serialization error while recording valuable field."
);
}
}
}
}
impl<S: Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>> Layer<S>
for JsonStorageLayer
{
/// Span creation.
/// This is the only occasion we have to store the fields attached to the span
/// given that they might have been borrowed from the surrounding context.
fn on_new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
let span = ctx.span(id).expect("Span not found, this is a bug");
// We want to inherit the fields from the parent span, if there is one.
let mut visitor = if let Some(parent_span) = span.parent() {
// Extensions can be used to associate arbitrary data to a span.
// We'll use it to store our representation of its fields.
// We create a copy of the parent visitor!
let mut extensions = parent_span.extensions_mut();
extensions
.get_mut::<JsonStorage>()
.map(|v| v.to_owned())
.unwrap_or_default()
} else {
JsonStorage::default()
};
let mut extensions = span.extensions_mut();
// Register all fields.
// Fields on the new span should override fields on the parent span if there is a conflict.
attrs.record(&mut visitor);
// Associate the visitor with the Span for future usage via the Span's extensions
extensions.insert(visitor);
}
fn on_record(&self, span: &Id, values: &Record<'_>, ctx: Context<'_, S>) {
let span = ctx.span(span).expect("Span not found, this is a bug");
// Before you can associate a record to an existing Span, well, that Span has to be created!
// We can thus rely on the invariant that we always associate a JsonVisitor with a Span
// on creation (`new_span` method), hence it's safe to unwrap the Option.
let mut extensions = span.extensions_mut();
let visitor = extensions
.get_mut::<JsonStorage>()
.expect("Visitor not found on 'record', this is a bug");
// Register all new fields
values.record(visitor);
}
/// When we enter a span **for the first time** save the timestamp in its extensions.
fn on_enter(&self, span: &Id, ctx: Context<'_, S>) {
let span = ctx.span(span).expect("Span not found, this is a bug");
let mut extensions = span.extensions_mut();
if extensions.get_mut::<Instant>().is_none() {
extensions.insert(Instant::now());
}
}
/// When we close a span, register how long it took in milliseconds.
fn on_close(&self, span: Id, ctx: Context<'_, S>) {
let span = ctx.span(&span).expect("Span not found, this is a bug");
// Using a block to drop the immutable reference to extensions
// given that we want to borrow it mutably just below
let elapsed_milliseconds = {
let extensions = span.extensions();
extensions
.get::<Instant>()
.map(|i| i.elapsed().as_millis())
// If `Instant` is not in the span extensions it means that the span was never
// entered into.
.unwrap_or(0)
};
#[cfg(not(feature = "arbitrary-precision"))]
// without the arbitrary_precision feature u128 values are not supported,
// but u64 is still more than enough for our purposes
let elapsed_milliseconds: u64 = {
use std::convert::TryInto;
elapsed_milliseconds.try_into().unwrap_or_default()
};
let mut extensions_mut = span.extensions_mut();
let visitor = extensions_mut
.get_mut::<JsonStorage>()
.expect("Visitor not found on 'record', this is a bug");
if let Ok(elapsed) = serde_json::to_value(elapsed_milliseconds) {
visitor.values.insert("elapsed_milliseconds", elapsed);
}
}
}