To record the flow of execution through a program,
tracingintroduces the concept of spans. Unlike a log line that represents a moment in time, a span represents a period of time with a beginning and an end. When a program begins executing in a context or performing a unit of work, it enters that context’s span, and when it stops executing in that context, it exits the span.
Let's see if we can add some of this context to our log output.
If we're gonna do some exploration around spans, we need a few spans. Let's create an outer span and an inner span. Conceptually, the spans and the event create something nested like
- Outer span is entered
- Inner span is entered
- Event is created with the inner span as the parent and the outer span as the grandparent
- Inner span is exited
- Inner span is entered
- Outer span is exited
So let's update our
span.enter() uses the guard pattern to keep the span entered until it goes out of scope, and then exit it. So in our main, we exit inner and then outer in order at the end of the function.
Back in our event handler, we're able to get this context.
ctx.event_span(event) will give us the event's parent span, if one exists. We could use that, but there's something even better:
ctx.event_scope(event) will give an iterator of all of the spans.
In our case, it would give us the "inner span" first, then the "outer span".
And if we want them the other way around,
scope.from_root() will flip them around and give us spans from the outside in. "Outer span" then "inner span" in our case.
Oh by the way, to use
ctx.event_scope(), our subscriber needs to implement
LookupRef. This ends up with a gnarly existential trait bound that – if I'm being 100% honest – I don't completely understand.
Alright, let's see what we get with a
OK, we can work with this. But just like in the first article, we don't have any field data. And it's the field data that really makes the context useful.
Of course, we remember visitors from the first article, so this should be easy, right? Right?
Where's the span data?
Well, we know about visitors. But the things we get back from
ctx.event_scope don't have any way to visit their fields. What's up?
You probably remember why we had to use a visitor to get event data: because
tracing never holds on to the field data. And if it doesn't hold on to the data, we probably shouldn't expect it to still have the data for a span that could have been entered a long, long time ago.
But not all is lost. It's time to start exploring some of
Layer's other trait methods. Specifically, let's look at
new_span which is called when – as you probably guessed by the name – a new span is created.
There's our data. Now here's the kicker: we only get one chance to visit the data from a span – when it's created.
tracing does not keep it around for us to access later. And that's fine if we're logging spans. Not so great if we're trying to get the span data later when we are logging an event, because the span data no longer exists.
tracing doesn't store the data for us, what's a poor developer to do?
Storing span data ourselves
What we really want to do is capture the span data when we see it, then store it somewhere so we can get at it later.
tracing patently refuses to store the data itself,
tracing-subscriber makes it very easy to store the data ourselves. It calls this "extensions", and every span we see has a way to attach extensions onto it.
We could technically store the
BTreeMap<String, serde_json::Value> from our previous article in the extensions. But because the extension data is shared by all layers in the registry, it's considered good form to only store private types that we created ourselves. So we'll create a newtype wrapper around it.
Any time we see a new span, we build our JSON field object and we store it in the extension data.
Now, anywhere we have a span (like in our
on_event method), we can get the data that we stored.
An almost fully functional JSON logger
OK. So we take what we've learned so far, mix it up with the JSON logger that we already have, and we should be able to add contextual span data to our logger. Easy peasy.
I mean, let's run it just to be sure.
Ha, perfect! Ship it, squirrel.
Wait, did you say almost fully functional?
When I did this for my work, I did ship it. And it worked great. But then I discovered that to get a fully functional logger, there's one more small step. And I do mean small, I promise.
The reason this isn't already fully functional is because spans can record data after they're created. And by that, I mean that this is possible.
And if we would run our logger as-is right now, we would miss the
"other_field" because it didn't exist when we received our
But now that we've dug into how layers and spans and extensions work, this shouldn't even phase us anymore. The only thing we really need to know is that
Layer also has an
on_record method for this situation. Everything else is a variation of the work we've already done.
And now, two articles later, we have a fully functioning custom JSON logger. Nice work, team.