 Hello folks, welcome back to another stream. This time it's another D-Crustid where we pick a crate from the Rust ecosystem and we sort of do a deep dive, not just on the high levels of how it works, but dig a little bit deeper into like, what is the internal architecture a little bit of the program? Like trying to really understand why the crate works the way it does build up the correct mental model for how to work with that crate so that you can do things beyond the basics, you can debug when you get stuck. And this time we're going to look at the tracing crate. And if you haven't already looked at the tracing crate, then first of all, I'm sorry, it is a really good crate to work with. But second of all, sort of at a very high level, tracing is a logging crate. Now, it's actually a bunch more than that, but at a very conceptual level, it's a logging crate. It allows you to emit events that represents things that happen in your program. And then it allows things to, other sort of components in the system to subscribe to those events and do something with them. For example, your events could be log messages and the thing that the subscriber does when it receives them could be to write them to your console, so a traditional logger. Where tracing is not a logging framework is that it doesn't actually need to do logging. It is more of a general purpose system for doing instrumentation of your code such that it can emit events that represent, well, events in the execution of your program. And subscribers, which subscribe to those events and do something meaningful with them. And that could be things like report them as metrics. It could be things like logging to open telemetry. It could be things like produce histograms. It doesn't really matter. Like tracing is agnostic to the types of your events and what you do with those events. And crucially, the two are disconnected. So in your program, what you write is you annotate it with these events and the subscribers are sort of plug and play. And you don't need to, if you want to add a subscriber, for example, that does something different with your events, you don't have to change all of your application code. It can stay the same and the subscriber will just pick up on those same events later. And don't worry, we're gonna dig a lot into the details here, but sort of at a high level, that's what tracing does. It connects events in your application with something that does something with those events when they happen. The docs for tracing are actually pretty good. I recommend you give them a look and read through them. If you ever sort of are curious about this on your own, it's actually worth reading the docs of tracing. It does go into a fair amount of what we'll talk about in the video today. But sometimes it'll be useful to work through it a little bit more sort of directly the way we're gonna do now and really talk through what's happening beyond just reading the text. Tracing has two sides, like I mentioned already. There's the application side, which is what emits events. And then there's the subscriber side, which is the thing that receives or acts upon events. And we'll talk about these separately. So for the first sort of part of the stream, we're going to be talking about the application side, the thing that emits events. On this side, you have two primary things you need to know about, spans and events. A span is essentially a sort of logical grouping of related events. And a span could be anything from the execution of one particular test, the handling of one particular request, the session of a particular user. It could be processing a particular file and spans can be nested. So you could say that, you know, during the execution of this HTTP request, for this part of it, we were processing this file. For this part of it, we were talking to this API. And during the period where we talked to this API, for this part of that, we were, I don't know, issuing HTTP requests and waiting for the response or streaming something, whatever it might be. So you can have these nested scopes almost of regions of time of your execution of your program where something is happening. And events are always recorded in the context of some set of spans, where that set of spans might be empty or it might be, you know, however deeply nested you are. So to make this a little bit more concrete, imagine that you have, here, I'll even pull up a file because you know, that's what we do. Cargo new bin, we're gonna call this one eventful, nice. Okay, nope, streams eventful. So inside of here, I'm gonna cargo add tracing. I'm also gonna add subscriber, which we're not gonna talk about quite yet. And inside of main here, I'm going to use tracing and I'm gonna bring into scope the sort of main macros you use when handling events, which are gonna be the info and warn and error and debug and trace. So these are all macros that allow you to emit particular events in your program. So at a very basic level, you can do things like info. This happened and info, that happened. Oh, my keyboard skills today are not good. And you know, as far as we've gotten right now, this just looks like logging, right? Because you're emitting info level logs that say this happened and that happened. Okay, so where spans get into this is you can have a span. So span is also a macro. So I can create a span that represents, we'll be a good example of this. Let's say that we loop over a bunch of files that are passed in through the arguments of the program, right? This is semi hypothetical. Like I'm not actually gonna write out all the code for doing this. So for file in the args to the program, what we're gonna do is we're gonna create a span for that file. So this is gonna be something like file. And I suppose it's also gonna include a level and we'll talk about what the levels for spans actually mean. I'm gonna pull in level here. And then what I can do with the span is I can enter the span. And this gives back a guard similar to taking a mutex. And while you're inside of that span, while you've entered that span, you can now emit events like opening the file, right? Which is gonna be file open file. I'll unwrap for now. It doesn't really matter. Reading file contents maybe, which is bytes is gonna be file.read mute. Writes is back new. I don't actually want to write the whole thing here unwrap. And then maybe I have another info done reading or parsing. I'm gonna do some kind of parsing in here. And then I'm gonna be done with that, done with file. And I'll bring in this so that it stops complaining at me and this so that it stops complaining at me. And crucially what I've done here is I have created a span for every file and then I have these info blocks that are or these events that are related to that span. And so when the output for this is printed, for instance, if you use a printing subscriber, the message that is printed here is associated with the span. And the way that looks like depends on the subscriber. The standard subscriber is gonna do something like emit the information for the span and then the information from here. And maybe this is actually useful to show you. So I'm gonna do this just so I can actually show you what this might look like and I'm gonna not actually do any of the operations. And if I now run cargo run, you'll see that what I get out here is a bunch of info lines and we'll talk about what some of these other fields here mean but we see the time, we see the level. File here is the name that we gave the span, right? So this is just file. And this actually needs to be a, this is a unique identifier for the span. It doesn't actually need to be unique but it is a name for the span that's set statically. And I can also assign additional fields here. So I can do things like F name, like file name is equal to file. And maybe here I'll do, you know, foo. Actually no, I can just do this right here, can't I? A, B, C, D. So you'll see here that now these same events are emitted for every file but for each one we're also given this additional annotation of the file name here is A, the file name here is B, the file name here is C, the file name here is D. And you might wonder, well, why is the span useful? Why couldn't I just include the file here and you could but you would have to include it with every logging statement when in reality these are sort of associated with this span and so we can set that information once and have it be associated with all of the events that come out of it. And we could also have a span out here. So I could say span level info main and I could guard is span.enter. And now you'll see if I run this we're inside of main and inside of main we're inside the span called file. So these can nest. Where this becomes really important is especially in things like concurrent or asynchronous programs where you don't necessarily do all of these things in order. So as an example, imagine that instead of looping over these serially, I actually wanted to loop over them in parallel. So I would do something like, you know, thread, spawn, move, you know, if I were to do something like this, then you can imagine that the output it requires a bunch of wiring to make this not do stupid things, but just conceptually if I spawn a thread for each of these then what you would end up with is a bunch of these events would just be interleaved and it would be hard to track which one was related to which file. Whereas with spans, that's not actually a problem because we have a span per file and the logging information, the events are associated with that span. And so for asynchronous programs this becomes so much more important. There are also helpers for, you know, getting rid of the level here. So there's like info span, for instance, that you can use here instead of this, they end up being equivalent. Now, going back to this. So as you saw here, you can additionally include additional attributes with spans and you can do the same thing with events. So I can say here, for example, it's a good example of something I might print here. I guess reading file, no parsing would be good. Would be like bytes is equal to, in this case, zero because we didn't actually read any bytes. And here it might be, you know, parsed is equal to a unit. It doesn't wanna do that. That's fine, let's do true. And so now you'll see that these additional attributes that I added to my, or fields that I added to my events are printed as part of that event. Now, this might not seem particularly interesting when we look at just the text output of this, right? Because it's really just printing, it's just appending it all together and then printing it out. But the reason why this is valuable is because subscribers are exposed to the full structure of this. So they are told there's a text part or there's a message, if you will, part of this event. But in addition, it also has these fields with these keys and these values. And the reason that is important is it means that you can have subscribers that use that richer piece of information in order to decide what to log or how to log it. For instance, you could have a subscriber that doesn't emit human readable text, but instead emits JSON objects where all of these fields are separate objects. So that after the fact, the sort of logging output that you get is actually structured and you can parse it and you can get these fields back out. Similarly, you can imagine something like, if there's a parsed field, then only include that field if the value is equal to true. The restriction on the keys here are mostly none. They need to be like valid identifiers, but they can also add dots in them. So you could say bytes.number, for instance, and tracing would be totally fine with that here, bytes.number equals zero. But in addition, you can put any value here that implements the value trait. So if you go back here to tracing, we scroll all the way down, you see there's a value trait. And the value trait here basically needs to be able to record its own information as a field. And it's implemented for a lot of the standard library types. In addition, crucially, it is implemented for anything that is an error and also for anything that implements debug or display through a little modifier. So let's say here that I have a struct foo and I'm gonna derive debug for it. And I have fields A, maybe a bool, and B, which is maybe a U32, it doesn't really matter. Then if I now here, let's say after parsing, I end up with a foo, true and 42. Then what I can do here is I can say, I want to have the value being printed out here B foo. And by putting a question mark in front of it, what that's telling tracing is when you log this or when you emit this event, use the debug implementation of foo. So turn it into a string essentially and then have that be the field that gets recorded. And so if I were to run this now, you would see that here I get out the debug representation of foo. And you can do the same thing with display using percentage. Foo doesn't implement that here, but if you add something else that did implement display, like for example, a path, right? So a stood path path where you call dot display and you get back a thing that implements display, you could then use that with percentage here to get the string representation out. Okay, let me pause there. I've talked for a while about attributes and fields and spans and events. Let's see if people are following whether there are things that are confusing in here. Okay, the span subscribes to info or do they both emit to the tracing subscriber? So the way this works is a subscriber, which we'll get into those way more later, but a subscriber is notified every time a span is opened, every time a span is closed. So basically every time a span is entered and exited. And it is also notified when a span is, it's informed that a span exists is the best way I can describe it. And again, we'll look at the interface from the subscriber side later. And then it's also notified whenever there's an event. And if there is an event, it's notified about the spans that are currently open or it has insight into which spans are open at the time of the event, right? Which spans have been entered. This ties into another question here around the guards. So it is indeed the case that when the guard is dropped, the span is exited. So an event that happens after the guard is dropped is not considered part of that event. And we can see that down here. Like if I, and it will be dropped automatically at the end of the scope, right? But if I drop the guard here and then I do a hello info log here, then you'll see that the hello is not part of file because the guard was dropped. But it is part of main because the main guard is still present. And it's important here that this is not just an underscore because underscore will drop the thing immediately. So it has to be assigned to an actual variable. And the reason we use the underscore here is because otherwise we would get a warning saying that this variable is unused. The underscore tells us that we're expecting it to be unused. What happens if you were to add a field to the parent span thinking along the lines of having a request ID? Yeah, so the file name here is a good example of that, right? We have a field on the parent span and that becomes an available piece of information for the subscriber for every event within that span. What happens if the span is a different level to the log? Okay, so this is a pretty common question which is what does the level of the span have to do with the level of the events? And we can try this out pretty easily. So let's say that I now make this a level worn and I say, this is also a worn. So let's just see what happens. You'll see that the nothing actually happened when the span became a worn but you'll see that the event that became a worn is emitted with sort of the warning level. And so you might wonder, well, why are the, why do the spans even have levels? And the answer to that comes into play when you start talking about how you can configure the subscribers. In particular, the formatting subscriber which is the one we're using here, the prints to console, you can configure it and you can configure any subscriber this way to only care or only be notified of events of a particular level or spans of a particular level. And so, for instance, if I were to make this, I'm gonna get rid of this little noise down here. If I make this a trace, for instance, and then run cargo run, you'll notice that the trace does not appear here. And that is because the default configuration for the format subscriber that we generated here within it is it only prints things at info level or higher. And that applies to both spans and to events but the two are independent. So if I now did, let's say that I make this span, I'm gonna turn this back into span and I make this a trace level span. What that means is that span disappears completely if the logging level we're using ignores things that are only emits things that are info or higher because that span for the all intents and purposes for that subscriber does not exist because its level is too high. But the events within that span are independent of the span, right? Like this event still happened. It just that when it looks up the stack, so to speak, it doesn't see the span because it never existed but it does see this span. And so this event is still emitted even though the span did not exist. The only thing that changes when you change the level of a span is just when is that contextual information recorded? It does not change whether the events within the span actually get emitted or get considered by the subscriber. And similarly, if we, let's say I made this also be trace. So now there are no spans at info level which is the default level. And then the result is we get all the events but we just don't get any spans for them. And this can be useful if for example, oops, level info. This can be useful so that you can change the amount of contextual information that's included for debugging purposes for example by changing the debug levels. So you don't have to actually change any of your events. You just wanna get more context for every event in your program than you can use the levels to achieve that. Okay, let's see here. Would it not make sense to have an enter macro? I don't know what you mean by an enter macro. I'm not sure what it would do but spans have other mechanisms than just guards like this. So one of the things you can do is you can call dot in scope. And what in scope does is that it takes a closure. And while you're in that closure, the span is entered. And when the closure finishes, the span is exited. So when we run this, we're gonna get the exact same output that we did when we brought out the guard. So there's just two different ways of doing the same thing. The reason I call it a guard, it's a common word to describe something that when you drop it, you lose access to something. So the guard is sort of a, it's standing on your behalf, right? It's standing with you and protecting you but only for the duration that it is alive. For something like user sessions, how do you open multiple spans that are not children of each other? Ah, so it's a great question. The, it's actually something where, oops, let me go back to the guard here. So let's say that we go back to our my threaded example here and in fact, let me just actually run this join handle is let's do vac new join handle dot push a little bit of extra noise that we just have to have here. I guess this should be join handles. When you spawn a thread, the program does not automatically wait for that thread to exit. So if we didn't have this, this additional step here of join. So joining each of the handles so we get back, then main would exit. It would loop, go through the loop, spawn a bunch of threads and then it would reach the end of main. The whole program would exit, which means all the threads would also exit. So we need to have this keeping track of the join handles and joining them so that we wait for all the threads to complete. If I run this now, you see that suddenly now these operations are emitted out of order, right? Like that they're in all interspersed because all these threads are running concurrently. And now these spans are coexisting, right? So you have an instance of the file span for each file and they are siblings, right? They're not, they have no connections to each other. They have to share the same span above them. Although if you look closely, and I'll get to this in a second, you'll see that here, main is not included in the span stack. I'll talk about that shortly. I just wanna address any additional questions on this part first before we talk about threads. Spans basically have a span ID and a span parent ID. Yeah, that's right. So the way to think about this is that spans know if they have a parent and events also know whether they have a parent and you can sort of walk the stack up there. In practice, it's not quite like that. In practice, what really happens is whether you enter a span or not could be a dynamic runtime decision. So it's not a static property of a span, whether or not it has a parent. The only thing that the subscriber gets to see and it gets to see whenever a span is entered and whenever a span is exited. And as a result, it could be the one execution of your program. This particular span gets open and then the event gets emitted. And in a different execution, that span is never opened in which case the event's parent ID is not set. So it's not actually encoded as a tree where the event has a pointer to its span. Instead, it's implicit by observing the sequence of enters and exits before the event is emitted. Can you put large things in a span or does it have to get cloned because of the thread safety or something? Ah, so this is also a very good question. If I here put like a blob is like a VEC with capacity, some giant capacity, right? Then, oh, there's a question mark. Blul, great. So is this gonna significantly slow down my program? The reality here is that the information that comes out of this is going to be tracked as part of the span, but does not get cloned for every event, at least not by tracing. Instead, what happens is when the span is entered, this information is conveyed to the subscriber and it can do whatever it wants with it. And then when the events are emitted, this information is not part of the call to the subscriber. So it's up to the subscriber whether this additional information should be kept around. Basically, the event, when the subscriber hears about the event, it can know which spans it's related to and it can know the current fields of those spans and get references to them, essentially, and then choose to do what it wants with them. If it just wants to print them, it doesn't need to clone them. Okay, let's see, what else do we have here of questions? Instead of having an underscore variable that we can enter, it can use a closure or something. Yeah, so that's the in-scope call that I showed earlier. Is it possible to configure the level at compilation time so that unnecessary of your Bose macros are discarded by the compiler? Yeah, so tracing is actually really smart about, let me get rid of this, about avoiding doing things if the levels indicate that no one is interested in that particular span. So you can do this at compile time if we go here and look at the feature flags. Where is my feature flags? No, that's not what I wanted. I want here. So you'll see that there's a bunch of features you can set on the crate that specify what the max level of events that should be emitted should be at compile time. And anything that is below that level, this is max level, right? So it is the level under which nothing should be emitted. So if you set, for example, max level worn as a feature of the crate, then anything that's below worn level will simply never happen. It will just be excluded at compile time at no cost. But even if you set max level trace, like you basically, you say that all of these could happen, tracing is quite good about eliminating early calls to something like trace. So I'm gonna give an example of this. One of the ways in which you can configure the subscriber is using something called an end filter. And we'll get a lot into layering subscribers and filters later, but you can often set rust log equals trace, for example, to, you see I set this environment variable rust log and here I set it to trace. You can set it to a lot of fancy things that we'll look at later to say that I want everything at trace level and above to be emitted. And now suddenly you see these trace calls also get emitted. So here there was no compile time exclusion of them because then evidently this would be impossible. I didn't change any compile time settings. So this was entirely determined at runtime, whether or not this should be emitted. But the cool thing is that if I do this, tracing is smart enough to have a, basically it has a very, very cheap check at every event where the macro is defined like the code that the macro expands to that checks whether that event's level is would actually be consumed by any subscriber. And if there are no subscribers that care about that level then nothing more happens. Like the fields do not get packaged up. They don't get shipped to the subscriber. The subscriber doesn't get called at all. It just eliminated super early. And so while you can set this at compile time as sort of a max level, it often is not necessary. The performance implications are usually not too bad of doing it dynamically. Okay, any tools to read the output easier? Yeah, there is. There is, for example, if I get rid of this for a second, just to get back these. There is a way in which you can get the tracing subscriber here to print basically a tree representation rather than a flat listing. So we go here, look at tracing subscriber. I wish that linked to the docs instead, but it does not. And then we go into format. Then I thought there was a way to configure this to say tree. Where's the subscriber builder? Or is it just a completely separate subscriber? I forget. Ah, pretty. Is it pretty that gives me a tree? I forget now. Yeah, I think it's pretty. So in that case, I need to go here. Version is this, features. Oh, the tree is separate. That's what I thought, okay. Yeah, because pretty is just prettier, but it's not the same. But it is called, is it tracing tree? Oh, there we go. Oh, I don't remember what it's called now. Well, it's not terribly important. There is a way where you can have a subscriber that instead of just printing a flat log, it will actually print a tree representations of the spans, which can be really nice. Okay, is it possible to create a span that isn't part of the current tree? How do you break free out of a parent? So let's say in here that you wanted this span, but you don't want it to be associated with main. There are ways to do this. So if we go look at the span macro here, and event has the same thing, so span, you'll see that there are a couple of things you can set. You can set target. We'll get back to target in a second. You can set parent, you can set the level and then you can set name and then these fields. And the parent here is the critical one. So the parent that you set parent is... So for the parent, you can specifically say, I don't want this to be associated with any given span as my sort of parent span here. And so if we look up here at... Where is the... Yeah, so if the target and parent span are not overwritten, they will default to the module path as the target and the current span is determined by the subscriber. And I believe you can set the parent to none, but I don't actually now remember what the syntax for that is. Maybe it's documented on event. I thought you could set it to unit, but maybe I am mistaken. I guess you can always set it to span empty or new root or something. Ah, span none. And this has to go before the level and span. Like so. So I can set the parent span of the span to not to be the none span, meaning it won't have a parent. And so when I now run this, you see all these files don't have a main associated with them anymore. You said the listener only gets the entering and exiting of spans, can it get confused with multi-threading? It's a great question that I'm about to answer. How do you efficiently get tracing arguments to include it in an event so they won't be fetched if the log level isn't to be printed? Ah, so if you have some field for a macro that's expensive to compute, right? So imagine you wanted to do, like foo is some expensive operation like this. And you don't want this to be computed if the level isn't used. Then we can actually go look at the trace macro here. And then we'll go look at the event part of that. Where's my macro rules event? And you'll see here in the definition of this macro, the fields in here are the actual field list that you specified. And down here, the value set, which is the thing that actually computes the fields is only expanded, that list of arguments is only expanded inside of this check for if enabled. So if the macro, if the level is not enabled, then the fields are not, they're not evaluated. And so therefore that the expensive thing would not be computed. So it's totally fine to have this kind of thing and the expensive operation would not be evaluated that expression would not be evaluated if the trace level was not enabled, including if it was dynamically enabled or disabled. How does this work in async functions? If I open up a span at the start of an async function, will it only be associated with events called in that same future? Also great question, also related to threading, which I'll get to in a second. Oh, you can do colon none. Interesting, I guess that works too, nice. Is there a way to hand off a span to some fire and forget background task while the main thread that started the span continues? Yes, so if you have a span, the span is just a, it's just a type. Like if we go here, like span is just a struct and it implements clone. And so if you create a span on some thread, you can then clone the span and hand it into another thread or a different future. You could send it on a channel so that that other thing that receives it can then resume emitting events within that span. The span is not constrained to the place that you created it. Can a tracing subscriber obtain a mutable reference to one of the values provided? No, I don't think so. Okay, so now let's go into this sort of async and threading, how does that work? So let me bring back this code, get rid of the parent stuff, bring back this and bring back this. Okay, so when we ran this code with threading, we noticed that the main span disappeared. And the reason why it does that is because when you enter a span, that information about what you entered is a thread local piece of information. So you cause the current thread to enter the span. This means that anything that happens on a different span, sorry on a different thread will not pick up the information from that span. It will not be aware that it's within that span. So even though we entered here, what we really did is we entered the span on the main thread. When we spawn these threads, those are different threads and they are not aware of the span that is currently being used on the main thread. So every thread gets its own current span information. And so that's why this information, this enter in here, affects all of the events within it and tracing does not get confused about like one event in one thread versus one event in another because the information about which span we're in is per thread. And that's also why this does not translate into this thread down here. Now there are ways in which we can make this do the right thing. So for instance, if we look at the methods on span, you'll see here that there is sorry, that's not the thing I wanted. What I wanted was because spans are clone, you can absolutely hear say, you know, span is span dot clone. And then here do let guard is span dot enter. So here we're re-entering the main span on this thread. And so the span can be entered on multiple threads at the same time. And now if you run this, you'll see that the main span here came back because now we have entered the span on this thread as well, on each thread as well. So that's one way to go about it, right? You just clone the span and you use it in all the places that derive from that span. The other way to do this is very often you don't really want to create your own spans this way. So let's try to move this logic over here into its own function. So I do on thread. And it's gonna take a file which is gonna be a string down here. And up here I'm going to do on thread of file. So what I've done now is I've moved this function into its own function. And now, first of all, I can get rid of this thing right here, this span right here, because tracing provides you with an instrument macro that you can use to automatically create spans on functions. So here I can say instrument and now tracing will automatically create a span for this function that includes all of its arguments as fields. So if I run this now you see it now prints on thread instead of printing file that we called it previously like a nameset after the function. But other than that includes the information of the arguments and that span is auto entered when that function is called. So that's neat, but it's still missing main here, right? And the reason for that is because this thread still does not know that it should be in the scope of the main span up here. When you're writing normal threading code there's not an easy way to work around this but there is a very convenient way to do it in async world. There is span. You know, we could do span is span.clone and then in here we could do span.inscope on thread. Right, so we're basically entering it within the thread as well. That's the most straightforward way to do it with threading. But I'll show you in a second how this interacts with async. All right, questions on this part before I move on. This is also applied to Tokyo task. I'll talk about futures in a second. Is this what span follows from is used for? No, so follows from is a little bit different so it's not a parent-child relationship. Follows from is more of a sort of hint to the subscriber that this span happened after some other span. And it's not an encapsulation relationship where the inner span's time is a part of the outer spans. Whether this gets used, I think depends entirely on the subscriber. I don't think this information is actually used by the formatting subscriber at least as far as I remember. Yeah, a sibling relationship, if you will, but it's specifically intended to communicate that one sort of happens before the after, right? Hence the name follows from. So it's usually used for things like you have one thread or one task that creates a bunch of other tasks and the span for each of those other tasks, you might say follows from the span of the thing that created those tasks in the first place. Okay, so now the question becomes, how does this translate to futures? So let's now go here and do cargo add Tokyo, features full, and so now our FN is gonna be async FN main with Tokyo main. And so now this is going to be Tokyo's spawn instead. I'm just sort of translating this to async code and I'll get rid of the little cheats that we did. And this is now an async FN, unused implementer of future. Right, and this says no wait. Okay, so this is now converted into async, right? And we still use the instrument macro and if I now run this, you'll see that actually still produces the same stuff, right? Like nothing actually changed and that's because the instrument macro here is aware of async functions and know how to treat them properly. But let's now try to go back to the way that we used to have this. So with manually opening our span like this. So if I run this, you'll actually see that it still produces reasonable outputs. But where this gets really awkward is that remember that these enters into spans are thread local. And Tokyo fundamentally is a work stealing executor which means that if you have a future it might run on one thread for a while and then if it yields like if an await call ends up doing having to wait, the future will be suspended and then be resumed on a different thread but therein lies the problem, right? The thread that just yielded control it doesn't know to drop the guard. So that thread is still gonna think that it's in the span even though some other future is gonna be run next. So that other future is now going to be potentially running on the other thread and it gets real confusing. And you might end up with events being associated with the wrong spans but also when the future eventually resumes on a different thread that other thread doesn't have the current span set because that other thread didn't run span.enter. And so suddenly the events in that when the future is resumed might not be associated with any span. So this just is completely wrong. We're not gonna see that here because there are no await points but if I for example here try to put in Tokyo task yield now, we might see it. If I run it just run a lot of yields now and see what happens. See if I can cause this to get disconnected. Let's have this also include file. Oh, this is a handy shortcut by the way instead of writing file equals percent file you can just write percent file and it'll do the same thing. The same works if the type directly implements value. So now that I'm adding the file field here, right? It should be the case that the file from the span always matches the file from the event. Let's see if that's indeed the case. Seems to be true here. So I might not be confusing it enough. Let's do a bunch more yields. See if I can make it confused. I really wanted to use other threads pick up the future here. Maybe instead I'll do sleep. And obviously now I don't wanna do this. See if I can now make it be confused. Yeah, so here for example, you see the span is for file name A, but the file in the event is B. So it got associated with the wrong span and you'll even see that there's some events that aren't associated with the span at all. And again, it's because of this problem that the guard is really kind of guarding some thread local state in here. When you call enter, you're making the current Tokyo worker executor thread be in that span. And when you exit down here, you're making the current Tokyo executor thread exit the span. And then all these events are whichever span the current Tokyo executor thread is in but because futures can move between threads this gets all wrong. And so that might make you wonder, okay, why did this work? Right, if I run this this is not going to be confused. So here you see C maps to C, B maps to B none of them are missing their span. I can run it again. You'll observe the same kind of output. And the reason for this is when you use the instrument macro like this the instrument macro will actually take the future that comes out of this function and make it so that every time the pole function is called on that future. So this is like the deeper mechanics of future basically every time the future is resumed it enters the span and every time the future yields it exits the span. And so that way rather than making the you're basically tying the parts only the parts where the future is actually executing only those parts do associate with the thread the worker thread with the span and not any other time. The other way you can get to this is if you if you go back to what we had here let's say that we still construct the span up here. So we don't want to use the instrument macro instead we want to have this we want to have the span created up here. Now this of course is going to have the same problem right the during the execution of this we might yield the thread we might get confused but there is another way to do this which is there's also the instrument trait in here and the instrument trait allows you to attach spans to a future. So here I can say on thread here returns a future it's an async function so I can do dot instrument and pass it a span and that will do the same thing as what the instrument annotation on this asynchronous function did earlier which is every time the future is resumed it'll enter the span and every time the future is about to yield it'll exit the span which then again has the same effect of the spans are not correctly attributed to every time you're within that future. Okay, that's a lot of threading and tasking questions. Does the use of instrument with recursive functions keep the span parents alive? Yeah, so if you have a recursive function you'll end up with a span for every invocation and those spans will be nested. So you'll end up with a potentially pretty deep nested set of spans for every level of recursion. What is the practical application of these spans for Rust users? So the point of the spans is that you can have events that are related to each other like all of the events that happened while processing this particular file or all of the events that happened while processing this particular user request or while interfacing with this particular TCP connection. So it lets you imagine something goes wrong like there's a crash of some kind and now you know that the crash happened while processing that HTTP request but your server is handling like thousands of requests a second, so your logs are super long. What you really want is you wanna extract just the events that happened for that request. Well, the association with spans will help you here because you can take the log and then you can prune it down to only the events that happened within the context of the span where the crash happened and everything else goes away. So what you're saying is that there should be task local variables. I mean, there are task local variables, right? This is the thing that exists and you could imagine that the guard went there. It gets more awkward to implement a library like tracing based on that but in theory, yes, it's possible. So the instrument, does the span get saved as part of the generated future? Yes, that's exactly right. So if you look at the instrument, the signature for the instrument method here, it returns an instrumented self, right? So the self here being the future and instrumented being a wrapper type that also implements future. And in fact, if we go look at it, the instrumented type that you get back from instrumented is really just a span plus an inner, which is the inner future. And if we look at the implementation of future for instrumented, what it does is it, well, this is pin stuff, but it calls span.enter and then it calls poll, right? Which is the way you resume a future. And when poll returns, then this poll will return which will drop this guard, which will exit the span. That's the entirety of instrumented. There's no more magic to it. Couldn't they have avoided all this by abusing the borrow checker, forcing you to pass the span to the macros? So you could do that, right? You could force the span and you can, right? Like there's the parent attribute that you can use for these events do allow you to specifically say what the span parent is. The downside of doing this is now you have to pass the span everywhere and it pollutes all your function calls because they all need to take a span parameter and it just, it gets really annoying. So the implicit state is usually nicer but it does have this one foot gun. Is instrument then only or mostly useful when working with futures? Sort of. So even in the threaded case, so when we weren't using async, having the instrument on a function is still useful because it gives you a sort of automatic span for that function. And if you tend to assume that functions are, bodies of related computation, then it kind of makes sense that you want to span for the function anyway. And the instrumented macro will create that for you rather than you have to write, let span equals span, set the fields and then enter the span. So I think it is still useful even in the non-async context. The instrument function, like the instrument trait that adds this helper method on futures, that one is only useful when you're using futures, only in async context. Is it okay for a parent span to go out of scope in terms of offloading them elsewhere? Yeah, I mean, parent scopes, parent spans can go out of scope, that's fine. So all that generally matters for, both for opening spans and for emitting events is which spans are currently entered. So the moment you have entered them, you can then exit the parent span. And now if you emit an event, that parent span will just not be considered one of the spans that are entered at the time. Is it possible to print the span, enter and exits to see the async mechanism clearly? I think there is a way to emit, to turn on the logging output of tracing itself and it shows you information like this, but I don't remember off the top of my head how you do that. Can you have an overarching span that can pierce through the inner asyncs, like a span that tracks a user session in a server request? Yeah, I mean, that's sort of what this is, right? You can imagine that instead of file, this like accepts new connections or something and it sets a span that is like, you know, user request and the user is, you know, some user ID and then handle user request, right? Of, you know, whatever the request is and instrument it with a span. And now any event within that future including nested futures is going to be associated with this span. How do you instrument every method globally? Are there global decorator macros? No, there's not a way to say every function should always get a span by default, not a thing. And it would be hard to even do in Rust because you don't really have a way to write code that is told about every function definition. It would have to be like a full text preprocessor. Even like proc macros too, require that there is actually an annotation on the function. What happens if a subscriber blocks when it's notified of an event that was produced in an async context? We'll talk about that when we get to subscribers. How not to include the parent span with the instrumented macro? If you use the instrument macro, let's go back here to the tracing docs. So if we look at instrument, you'll notice that you can set things like you can name the span, you can set the target, we'll get back to it in a little bit later. You can skip fields saying like, don't include this as one of the fields on the span. And I believe you can also set the parent. Yeah, parent equals none. To say I don't want this to be associated with whatever span is outside of here. I'll add one more thing here, which is let's say that I did this. Guard is span.enter. Because I had a bunch of code here that I wanted to run on. Then what do I do down here? Is there a way where I can still instrument this thing using the span? I can't pass span here because span is owned, right? And so I would need to do span clone. And you can do that or you can do in current span, which is also like a helper method on the instrumented trait that just looks at what the current span is, clones it, and then uses that as the instrumented thing. So this can be a handy way to combine these if you ever end up having to. How can tracing trace itself? Wouldn't it produce infinite tracing cycle? Tracing doesn't trace itself, but it has a way to basically emit just straight messages for debugging. So it's not really tracing tracing itself. Oh, hey, Steven. Visualizing entering and exiting span. You can make the subscriber print, the enter and exit events as well. Oh, maybe I can do that easily. Subscriber builder. Default. Init. So this is just, instead of using the init method directly, which in fact I can show you, the init method directly calls try init, try init calls subscriber, make a builder, and then adds a bunch of standard layers to it. We could replicate all of this and then have it also do subscriber builder.init. And then I would want to also replicate all of this code, which is a little bit annoying. I can do this. Tracing subscriber.init. Oh, what am I missing? Oh, is it try init? I need to like try init.unwrap. Why is it allowed to use crate? That's unfair. Oh, maybe I need to have tracing subscriber features and filter. Something else I'm missing here. Subscriber builder. Why? Oh, I might need .finish. What? It's confused somehow. .finish.tryinit. Why is it not letting me do that? Format subscriber. Oh, default then there's a max level of error, that's why. Which is why rust log equals trace, for example. Great. Okay, so now we're getting those outputs. And with this, I should be able to do with span events. Format span. Why is it being annoying about this? Full. So if I now run this, yeah, so here now you can see all of the enter and exit events. And also close events, which is when the last instance of a span goes out of scope. So you can see all of the little events on all the spans. Is there a way to compile the program to emit all tracing functionality? Yeah, so you can set max level off. So if you look here at this one, there's a max level off, which just turns off all tracing. And statically at compile time too. I do in current span before every await, is that necessary or am I misunderstanding what it does? So in current span, you should only ever need, this bit right here, you should only ever need if there is a span.enter that you want to capture. That's the only time that should really matter. Because if the span comes from something like instrument here or the span comes on like an in-current span that's in the future around you, that will take care of entering the span and so you won't need to do it as well. The exception to this is if you want to do something like Tokyo Spawn, because Tokyo Spawn is gonna run on a different task. And so now you, it's basically gonna run on a different task it's basically gonna construct a new top level feature. And so now there's no longer a future outside of you that's gonna enter the span on your behalf. So then you do need to instrument it at the time when you create the future. So for this we do have to use in current span but that's really the only case. And I wanna get rid of these again because those are annoying. Okay, so now we have a sense for how these events work. We know roughly how they relate to spans, how you open and close spans. So let's now go back to the docs here and look and see if there's anything we've particularly missed. We haven't talked about targets yet, which I'm aware of. So I'll touch on that in a second but let's see here. So we have events, we have spans, we have events, events of fields, they have levels. Subscribers we'll get to later. Spans can be entered, they can be instrumented. Events are within the context of a span. There are additional attributes like level and parent and target and name. Recording fields we've talked about. We've talked about debug and display. Okay, short-hand macros, those are fine. We've talked about those. Log compatibility, I think I'm gonna skip over or rather just mention briefly. So the tracing crate has support for compatibility with a log crate. And it has support for compatibility in both directions. So the log crate is a very commonly used logging library especially before tracing came around. So tracing can both have log events from log, from the log crate be emitted using a tracing subscriber. And it can also have tracing log invocations. So like tracing events be emitted into a log consumer. So both directions are possible. So this means both you could have a library that's written using tracing and if an application that uses log wants to use that crate it can still actually get events out through log. And similarly, if you have an application that uses tracing and you have a library you wanna use that uses log those situations can both work. You can usually not have both turned on at the same time because then you or at least you're not gonna want to because you end up with weird cycles where it's not actually a cycle but you end up with a double logging a lot of your things. Okay. Right, and then there's a, so you saw that I here instantiated a new tracing subscriber. That's only a thing that you should need to do in the place where you want to emit the output of tracing, right? Where you want to consume the events that are produced. So if you're writing a library for example you should almost certainly not have a subscriber in there. The library should only ever be emitting spans and events and not actually be consuming anything or instantiating your subscriber. You should leave that to the application. If you're an application author you do want to instantiate a subscriber maybe potentially multiple, we'll talk about that later but you're also free to emit your own tracing spans and events. Okay, that's log related crates. So these related crates are mostly about different kinds of subscribers which again we'll get to in a second. And it's about additional helpers for emitting certain types of events or events in certain contexts. So tracing futures for example allows not just attaching things to futures which you can do with the instrument but also to streams and executors and that kind of stuff. Most of these other ones are either subscribers or like for example AXM Insights and Tracing Actix Web are all crates that add tracing events and spans to existing frameworks. So that you can for instance plug and play in a middleware and AXM so that every request automatically gets its own tracing span. So it's that kind of integration. But those are all separate from the tracing crate itself which just provides a sort of mechanism for emitting these spans and events and tracking them and the subscriber machinery that we'll talk about in a second. Okay, so the last bit I then want to touch on before we go to subscribers is this notion of a target. Target is not particularly complicated. This is the reason I wanted to separate it because it just feels kind of disconnected from the rest. So every span and every event has an associated target and the target of a span or an event defaults to the module that the event or span occurs in. So if we look back here, we're in main of a crate named eventful and in that case the target is just gonna be eventful because we're in the root here. If I went in here and said, you know, mod foo and I put on thread inside of a mod foo and then here do foo on thread and I make this be pub super and then I guess I will use super. So if I now run this, then the target in here is going to be eventful colon colon foo because that is the path to where those events happen the module path and you'll see that here. It appears in the sort of grayed out bit in the middle and what target is useful for is mostly related to filtering. Basically the target is exposed to the subscriber as a sort of this is where the event happened and the reason this can be useful is that you can do things like eventful equals trace hyper equals info, right? So if I was using hyper in here what this would mean is that any event or span that happens inside of the hyper crates module which I don't have the hyper crate is not in use here so it would be nothing but anything that occurs under there should happen in only at info level and above whereas anything that's in my crates anything that's in eventful should be trace level. And so here I could imagine that for my own application I actually want to really trace deep into what's happening but I don't want to give this that I had before rust log equals trace because if I do that what I end up with is trace from all of the libraries that my code uses, right? It's trace all the way down and applies globally in the program whereas by using the targets I can scope these definitions to only where I need so imagine that I start debugging my application this produces a lot of information too so I might want to say well for eventful I want info level or maybe I want debug, right? Cause I'm debugging but for eventful colon colon foo I want trace and so now I get trace events from inside eventful foo but I only get debug level things for the rest of eventful and for hyper I would only get info and so this allows you to sort of scope out which events are relevant to you. The other reason that or the other cool thing about targets is that you can override them so imagine for instance that I wanted to keep metrics might be a good example here so I want something like target metric and I want name to be parsed and then I want to log bytes is 42 and maybe I don't even want a message for this one oh maybe there aren't maybe name has to come first macros are awkward beasts so what I'm doing here is I'm setting the target so instead I'm saying instead of using the module path here use this as the name of the target and here metric is an example but you could imagine for instance that you take all the metrics in your program and set them to have target metric and so that way people can turn on and off the metrics independently of where they're located because the metrics are their own target so here I could say you know what's level is this one so let's make this metric be debug so let's say the eventful I actually want info let's start there so eventful is info so that means I'm not gonna get this metric out because metric was a debug level thing so there's no debug levels in my output here but I can say metric equals debug and now you see I do get the debugs for the metrics here but if I made this also be debug so this one I'm not overriding the target for then you'll see for this one there's no the parsing output here there's no parsing message that has come out here because that's debug but it's not a metric so that's where tracing is useful sorry target is useful is for specifically saying this event or this span is like related to a different facet of the application almost it's almost like a different dimension compared to the sort of name of the span for instance okay if that made sense let's first check questions but if that all makes sense then we're gonna switch gears and start talking about subscribers sort of the other half of tracing okay let's then switch to the other half of tracing this can go away this can go away okay can you have multiple targets no every event and span needs to have only one target I wonder if tracing can access the token stream in case we want to log out line numbers and such we'll get to that in a second but no tracing does not expose token streams it is not in fact a procedural macro at all the in fact if you we did this earlier right but if I go to definition on trace it is a declarative macro with just a lot of branches and if I go to a macro rules event the entire event macro is also just a giant declarative macro and one of the primary reasons for this is declarative macros are way faster for compile times procedural macros tend to add quite a bit of delay because you need to compile a program to run over your program before you can compile it and that adds a non-trivial amount of latency but as a result it's not given access to the token stream however subscribers do get access to certain compile time information or static information about the events and we'll see that in a second all right let me drink some water so I don't die okay so back up here to subscribers so the core of the the core of subscribers is perhaps unsurprisingly the subscriber trait so if we go look at the subscriber trait it has a bunch of methods only some of them you need to implement and these are all of the things that a subscriber must handle in order to be used as the subscriber for a program in tracing you have two ways to set the subscriber there is and I'll show you this I don't want to do this down here so I find the module subscriber and you'll see that there are let's ignore set default for a second there is set global default and there is with default set global default is a method that will choose which subscriber is used everywhere in your program so it's not a thread local it's not local to a closure it sets it in a global static that every event every span will go check this global static to figure out what the subscriber is that they should send their information to when you set a global default subscriber that is the thing that everything will use if you call this method again with a different subscriber everything will switch to use that other subscriber instead so these do not stack there is only ever one subscriber in this setting there is also with default and what with default does is it takes a closure and during the execution of that closure the current thread and this is this is thread local the current thread will think that the global subscriber is the one that's passed in and this is why this doesn't actually use the word global it uses default right so the way to think about this is that when you emit an event or a span it goes to the default subscriber and the default subscriber is the one that is set for the current thread through with default or if no such subscriber is set the global default and so as a result from the perspective of any given event or span there is only ever a single subscriber there are never multiple subscribers to choose from there's only ever one and that is the one that receives information about the the spans in the events so if you now look at the subscriber trait what you'll see here is there's a function enabled and I think there's docs for this further down the docs here are pretty good as well enabled is is a method that will be called on the subscriber once for every call site so basically for every single appearance of span event info trace debug warn error and similarly for all the spans like basically all of the tracing event and span macros for every single one every single appearance of one in the in the source code enabled will be called once for the subscriber and the subscriber gets to choose whether that particular call site is enabled or not essentially do I care about that event and if the subscriber answers no if it returns a false here then that event will just never be triggered so we looked at the code for this earlier and I'll show you here again down here so this is the event macro which is what all like the info trace debug all of them expand to this macro you'll see that it constructs this call site thing which is a static and then it checks the crate level enabled is is checking the compile time flag for the maximum level and assuming it's not excluded by that then it will call interest which among other things is going to use is an call enabled on the subscriber to see whether the subscriber believes that this particular call site is enabled and if it is not like this whole code that expands the fields and everything just does not happen so it's a very easy way to exclude subsets of events completely and if we go back and look at what information enabled gets it gets one of these metadata things and metadata describes a span or event but it describes only the information that is known statically so here you'll see it gives the the name of the spanner event and the name should we go down here if the name is not set for an event let me go down here and find one where the name is not set um where is the fallback for these target parent level message aha so if the name is not set for an event then the name of the event is event space and then the file and the line so basically the the information about the exact location of the event is the name of an event unless you have overwritten it with something else but ignoring that for a second so you see it constructs this this set of static information which is the name of the event which is statically known the kind in this case its event could also be span the target which we specified the level which is also known statically right like it's written in the source code it's not determined at runtime and the set of fields and in particular what you'll notice here is that it emits um well this is actually handled by the the call side macro which we can go look at in a second it only extracts the names of the fields and the names of the fields are all known statically right so here bytes.number is in the source code it is written down it is statically known the value here might not be so if we look at something like this instruction right parsed here is statically known but the actual value of foo this might be a create foo function for all we know it's entirely determined at runtime dynamically and so it can't be known statically so the only thing that the subscriber gets in this metadata is the name the target the level and the names of the fields that are defined by the span of the event and of course whether it is an event and a span and in addition there are a couple of other pieces of information like the file in which the invocation occurs the line number in which the invocation occurs and the module pass in which the invocation occurs that may or may not be available and you'll see here that on that metadata this is what the subscriber has available to it to decide whether or not a given event or a given span is enabled should be is relevant to the subscriber and should be turned on and should emit events during the execution of the program and so you can you can from this seed that like pretty clearly you can implement something like only emit events where the level is at least this much because level is one of the things you get access to in the metadata and so if the level is lower than the lowest enabled level you just admit your return falls from enabled if every event has it's associated static metadata doesn't it greatly increase the final binary size it kind of does so this is an important point every single macro sorry every single event and span does have its own static here and the the size of that static is like you know it's the size of one of these metadata things so it's not tiny but at the same time the actual number of events and spans that you have is realistically probably pretty small and so this doesn't tend it does increase your binary size it's true but probably not enough that it really matters but it is true now the big advantage of doing this by having this static is that you can you can make the call to the subscriber once about whether it's interested in a given event and you can cache that information and use it to just not even call anything the next time or the next million times the event is emitted because you checked it once statically and so that ends up being a pretty huge performance boost for subscribers that are selective about what events they want so what you're trading is a little bit of binary size for a significant performance speed up I'm not going to cover hotel stuff no I'm going to mention hotel but that's probably the the extent of it okay so our subscriber gets access to this metadata to basically say whether or not a given span or event should be enabled in addition it's notified whenever a new span is created and for this it is given the set of attributes that were passed to the span and so the attributes here are the metadata of course like you always get access to the metadata for every event in every span because again they're statically known in addition here you now also get the values for the those fields of the span right because this happens at runtime this is a new span is actually being created a new instance of a span is being created so you now you are at runtime and you're given access to the values and you'll see that the the value set that you get back you can here you can visit all the fields in the value set and you'll notice this is a little weird right like it's not it's not a hash map where you can look it up by field or anything you have to pass in one of these visit things and this is similar to sort of the Serdi visitor pattern I mean this is a general pattern of visitors the Serdi also uses where you pass in something that implements this trait where it the the tracing code is going to walk the list of values and for each value it's going to call the appropriate method so for example if it encounters an f64 then it's going to call the f64 the record f64 method on the value you provide as part of this this record method on the value set and the reason it's done this way is because it means that we don't have to allocate anything right there's no allocation of a hash map needed because you statically know the list of fields so you can walk them and for each one you just call the appropriate method and so again no allocation is needed inside of tracing so it gives you a reference to the field the field being the sort of the name of the field that we're walking and the value being the actual value we came across and you'll see here that these are the the value types that are that implement the value trait so this is the reason why back here in this we could pass in for example bytes equals 42 because this is this implements the value trait and it would end up being a record u64 call in here but if you use something like a like down here like a question mark foo then it does record debug which is going to pass in you know the a reference to the thing that implements debug uh and and similarly for uh for errors for display so if i did this and foo did implement display well what it would actually do is it would um with the display i believe it would turn it into a string so it would actually allocate and then it would pass you the the reference to stir but for debug it just gives you a reference to the debug thing see if the display is actually mentioned here oh display value it might not yeah it might actually not do uh i see it does use record debug that's weird didn't debug i think it's lying oh i think what's going on here is that if something implements display it is wrapped in this type and this type implements debug by calling display that's my guess yeah okay so this implements debug by calling display and so therefore you can use the same record here for both types that implement display and types that implement debug because ultimately they're just a thing that you can give a format or two and they can emit themselves into the formatter why is the tracing value trait sealed like i can't create structs to use as values and have to flatten my structures by hand before logging um yeah so so as as uh david we have david barsky in chat who's one of the sort of main maintainers of tracing so if uh if i get stuck then he can he can give us the correct answers but but as he says like the the reason why you can't really implement value yourself if we go look at it you see it it has this um colon sealed which is a a trick you can use in the rest trait system to make it so that no one can implement this trait apart from yourself like in the current crate and the reason for that is because i think they want to allow themselves to implement value for more types but if they want to reserve that right then you have a problem because if you if you've opened up the value trait so anyone can implement it someone else could end up implementing it for the same type that we wanted to implement it for and then you run into problems so that's that's part one um and the the other one is because i think over time the goal is actually to use a different trait than value um there's a there's a crate called valuable question mark valuable uh yeah which is like a basically a more general purpose mechanism for the same thing the value does of like give me a way to visit a value of an arbitrary type and so they kind of want to use this type instead of the the value trait themselves and so sealing it is another way to ensure that people aren't relying too heavily on the value trait okay so this all stemmed for the information that you get when a new span is created you get the information that is available about that span which is both the static information and the dynamic runtime information and the thing you're expected to return is an id if we go look at the id here it's it's really just like a unique identifier um and you see you can create one from a u64 and the expectation is that it can be turned back into u64 the rule here is that this id needs to uniquely identify that span among all of the spans that currently exist and the reason why this matters is because you see here record record i'm gonna not talk about record right now because i haven't talked about placeholder fields and spans which i guess i will talk about shortly um but if we look at something like enter and exit right so enter and exit are called whenever a span is entered and whenever a span is exited and the only information the subscriber gets is the id of the span that was entered or exited and so as a result it has to be the case that every time a new span is created the id that it returns has to be unique among all of the spans that exist uh and then when you enter you know that like this id maps exactly to the one span that was created here and the reason i phrase it that way as opposed to saying it has to be globally unique is that after a span is dropped uh i forget whether it's drop or yeah it's close um so this close method is called whenever a span id has been dropped uh and it's supposed to return true if there are now zero id's that refer to that span and when that is the case it'll call this drop span uh and there's a little bit of deprecation going on here and some of the docs are a little hard to tune out but the basic idea is that at some point there are no more instances of a span like you know that that span will never be entered again and the moment that happens so basically whenever try close returns true um then it is actually safe to reuse that id because there are now no spans that have that id and so it is safe to give it to a new span because when you get that id from enter you know it must be the new span and not the old span because the old span didn't exist anywhere um so so hence the id does not actually need to be globally unique forever it just needs to be unique uh among all the currently active spans does it generate a random number or does it use some sync primitive to make them in a stack like pattern does it use something else well so notice that subscriber here is a trait it is not an implementation and actually writing a type that implements this trait is non trivial and what we'll see that when we get to the tracing subscriber crate which provides a lot of the mechanisms for trying to build your own subscriber um record follows from is is the sort of inverse implementation of the follows from method that we saw on on spans um event gets called whenever there's an event and event unsurprisingly the sort of uh value that's that's passed to event is a thing that holds a bunch of fields static metadata um is root i think it's just whether it has any spans above it um and record here is the way where you can give a visit to walk all the field values of that event uh and you see here you can also ask whether the event has an explicitly specified parent so again the event does not actually keep a parent pointer right it is up to the implementer of subscriber to keep track of which spans are currently entered whenever this method gets called um so this method is just if the if the event specifically has like parent colon some span uh that information comes in here but it's not a general purpose like what is your your span parent pointer and this is because it's not actually a requirement that spans are you know nested in a hierarchy they are allowed to move so sometimes a span might have a different parent than a different time when it's invoked and these uh these methods up here are mostly not used uh as in they're used by the macros that generate events but it's pretty rare that you'll be calling them directly yourself um okay so let me then talk briefly about record because i did not talk about it earlier so um if we read the docs for record you'll see it says record a set of values on a span this method will be invoked when a value is recorded on a span what does that mean well if we go back here we go to span you'll see that on a span actually maybe a better example is in the root here um if i go down to uh recording fields constant uh a span may declare fields with a special value of empty so you'll see here parting equals field colon colon empty which indicates that the value for that field does not currently exist but may be recorded later uh and so here you see i create a span there's no value for the parting field but later on i can say okay now this span that this the value for this field of the span is known and i can record it um now it's a little weird but the way to think about this is um imagine you want to span create a span as early as possible for something like a hdp connection and you know that every hdp connection is going to be associated with uh let's say some authorization token right and the authorization token maps to some unique like application id or something then the moment you get the hdp connection opened you don't know what the application id is yet because you haven't parsed the headers so you might open the span at that point and then start emitting events for things i'm going to parse the set of headers now and you want those events to be associated with the span and then when you know what the application id is then you can record it in the span so that the span from that point forward also includes that information and you don't want to create a new span because this is all one span which is this hdp connection you just want to sort of uh add some fidelity or add some extra information to the span that you already have so that's where record is is useful um and that is also what this uh record method does on subscriber is it tells you for this span the following values were just recorded uh by a call to the the record method on span um what if the subscriber just ignores the span info can it just ignore id's and always return zero or is uniqueness used by the tracing crate um the tracing crate does not enforce any uniqueness here on the id's so if you have a subscriber that just always returns zero for every new span tracing doesn't really care but what that means is the subscriber is not going to be able to understand which spans you're actually in because every every time a span is entered it's just going to be told while i entered span zero and it doesn't know which span that is because for every span like all of the spans have an id of zero um so that's a problem for the subscriber but i don't think it's a subscriber for uh i don't think it's a problem for tracing okay so how does one go about implementing this trait like if you want to have a subscriber what do you do oh that is not what i meant to do but luckily i can fix it uh and also right i'm tracing tracing subscriber uh so the tracing subscriber crate is a separate crate but also maintained by the tracing folks uh that provides utilities for and implementations of subscribers um it's sort of split into a couple of different segments so one of them is the uh we'll see this if you look at the set of modules so the format module is the the main thing that people use tracing subscriber for which is and we'll go look at it right now um it provides a subscriber for formatting and logging tracing data and so this is the thing that we've been using so far where uh it knows how to take event shaped things from tracing um and span shaped things from tracing and produce this kind of output and it has a couple of configuration options for like uh maybe you don't want the timestamps included or maybe you don't want colors to be used or bold to be used maybe you don't want span information or uh you know all of this integration with rust log all that is like part of uh of the the format subscriber it has all this built in you can configure it but ultimately it is a way to just sort of quickly get from events and spans to print me something to console and often that's all you need right like you you just want to use tracing as a logging library tracing format subscriber or the the subscriber from the format module of tracing subscriber is usually going to be basically all that you need is a super convenient way to get it set up which is you just call tracing subscriber format module the init method and it will create a subscriber a format subscriber with reasonable defaults and it will also call the method that we saw earlier um this uh set global default method on tracing to say to set that format subscriber as the global default so every event every span is going to emit their information to this format subscriber which is then going to print it um so that that's sort of the the most obvious part of tracing subscriber we're not going to spend too much time on this one because this one is fairly straightforward like it just prints to console and you have a bunch of configuration for like what syntax you want to use you want it to print jason do you want to like include levels targets thread ids thread names um you can do other things like if we go here to subscriber builder it has a bunch of methods for things like without time or with span events that we looked at earlier which shows you all the interests and exits but ultimately it's just like you're configuring a pretty printer for events um and so it's not super interesting from the perspective of understanding how tracing works where it is interesting is if we go back to here um is that you'll see if you sort of squint at the documentation that it talks about a couple of other modules like n filter um uh and down here it says composing with layers there's something about like n filter layers format layer okay so so there's clearly something else going on here which is that the format subscriber is not a monolith it's not a giant implementation that has like implementations of the subscriber and span tracking and how to parse environment variables and like all of these other bits it's really um uh a component that reuses a bunch of other bits and you can reuse those other bits for your own subscribers as well and that is where we get to the other parts of the tracing subscriber crate in particular filter and layer and registry uh let's look at register how do i want to do this um let's talk about layer first yeah we'll talk about layer first ah there's one thing i want to mention because the question came up earlier as well before we dive into layers which is on the subscriber trait what happens if uh inside of the implementation of subscriber you try to do something like write to a file or take a mutex right like something that might actually block is that a problem well this question came up a lot earlier too when we were originally looking at this uh asyn code up here and someone asked well if we're in asyn context here and then the subscriber when it gets this event calls some blocking code like some non-asyn code what happens and the answer is that tracing doesn't do anything special here like if you're in asyn context or not in asyn context it doesn't the subscriber isn't aware right the subscriber just sees this method call which is a blocking method call right as there's no asyn here and it's expected to do what it can do and so the question becomes what do you do in here if you need it to do something that takes a longer period of time well inside of function event you're allowed to write code that's slow you're allowed to write code that takes forever but that code is executed in line with the event invocation and we can see this actually if we go here to um if we go here to the event macro rules macro you'll see down here that it calls event child of if we go to event child of let me uh see if I can dig that up oh it's that's going to be annoying isn't it let's pick it up over here maybe it might be easier to look ah one important point if you ever go to the github of tracing the master branch is not the branch you want to be looking for or looking at if you're looking for the code that's actually on crates.io and I missed this yesterday there's a giant warning in the read me which is go look at this branch if you want to look at what's on crates.io so we're going to go to this branch um and then we'll go to tracing core which has the the the core bits of of tracing like the definition of event and span we'll look at event and then we'll go here to a new child of no that's not what I want to look at I want to look at uh yeah yeah here so child of um you'll see that it does it creates a new event and the say um dispatch is the the other method for this which is arguably the nicer one to look at it's one that's not a parent set um so dispatch will create a new event it will call get default which gets whatever is the current default subscriber so that could either be the thread local one or the global one and then it calls it takes that current right so current right here is the the subscriber a reference to the subscriber and it calls the event method there is no more magic to it it literally just calls the event method and as a result if that event method takes a long time to execute then this called the dispatch will take a long time to execute which means that this call right here to event child of which is really just dispatch and this thing which actually calls dispatch takes a long time to execute which means that the macro takes a long time to execute so there's no magic here uh and so as a result when you write a subscriber you want to think carefully about how you manage how long you take to dispatch an event so for example if you're writing a subscriber and you want to like asynchronously write to disk or something then you probably need some means to have a fast path for handling events that is not blocked on doing file access or network access usually this comes in the form of either something like a ring buffer where you're when you get in an event you're just like added to some lock free ring buffer somewhere and you have a different thread that walks that and writes it to disk or you could just use a channel a channel is also the most convenient way to bridge between synchronous and asynchronous code right so you could say your implementation of fn event is just you know package up the event into something that's owned right this is just a reference is something that's owned and then ship that over a channel and then you have some other background task that reads from that channel and emits to you know a network service or to disk or whatever and so that way your your actual event logic is going to be pretty fast while your you know the expensive operation is something you can batch in the background just be aware of that that the subscriber really is on the critical path of every single invocation of creating an event okay so with that warning behind us we can now talk about layer so as the the docs here say for layer the layer trait is a composable abstraction for building subscribers right as the name implies the idea is that you layer a bunch of things and collectively they are a subscriber and in our mental model this we can think of layers as like if an event comes in then it's going to invoke some method on the top layer and then that event is going to go to the next layer and the next layer and the next layer and the next layer and then when it's done going through the layers and the event has been handled right so it's sort of like a event multiplexer is one way to think about it now in reality the the fact that they are layers is actually pretty important but we'll see this in a little bit of a second but the let's look at the trait first so the trait here is generic over a subscriber which might strike you as a little weird like if our goal is to build a subscriber why does the layer already require a subscriber and the answer to that is if you look at what a layer gets a layer is more like a an event handler so it is told you know when a newsman was created it's told when a record happens it's told when an event happens it's told about an enter it's told about an exit but it's not expected to do state management you see all of these methods don't you don't return an id for example right for for something like on newspan the expectation is that there's some subscriber at the bottom that deals with all of that for you and you just have you just get to like observe the events as they go by and observe the spans as they go by and so that's what that inner subscriber is uh and that's why we go back here that's what this registry thing is so a registry is a implementation of the subscriber trait that really just does the state management it all it really does is keep track of span id's keep track of the values that are associated with each span and act as well a registry for spans so that down here you'll see that lookup span and subscriber so you see it implements the subscriber trait and then it also lets you so it's going to assign span id's on your behalf and make sure that like you know span id's are unique in the way that they need to be and you'll see that it also implements this mechanism where you can pass in an id to the registry so for example you know in your layers on enter all you get is an id well you can call the span data method on the registry to get back the data that is known about that span right so you could imagine the like in on enter or in on exit you actually want to look up some of the values of that span or the fields of that span or something and you can do that through this registry it keeps track of the data from new span on your behalf as an example and this allows the layers to actually be a fair bit simpler because all of the span tracking stuff which is sort of the would be the same for almost any implementation is taken care of for you so you'll see that for all these methods you get access to the same arguments that the the subscriber gets access to like you know the the values that have been recorded for an event for instance we also get access to this context and the context is really just a a reference to the subscriber so it gives you information about the the current span not just the subscriber but like the state tracked by the subscriber so which span we're currently in metadata about the event you can look up things like what is the current span where current span here is actually like what is the most what is the latest enter that i've seen so this gives you much more information like stateful information about where about the current state of events and spans and it can do that because the registry implements the state tracking for you if we look at the the subscriber trait again you'll notice that it's not really stateful at all right all the methods receive a shared reference to self and like in enter you don't get any information about what you're entering apart from the id so so all of that state tracking is handled by the registry for you okay so what does that mean what kind of layers might you actually implement well uh you could have layers to do all sorts of things the uh the most obvious kind of layer is one that will like write to disk right or well write to a network so you don't actually need the subscriber to do that you just need something along the way of the layers to observe an event and then decide to print it to disk and so if we go look at the format subscriber that we looked at earlier format uh layer so you see that there's the the format subscriber is really a collection of layers one of which is end filter which is we'll get to later and one of them is the layer that actually prints out to console and it's because the registry takes care of the state tracking and then this layer just does formatting and printing and so you could easily implement your own layer that you know emits in some other format or again this is where a lot of those other helper crates like you know someone mentioned hotel earlier so this is like open telemetry you could have an open telemetry layer that will you know look at the spans in the events decide how to encode them to conform to open telemetry and then send them over a network socket or something that would just be a layer and uh in the layer trait all you would have to implement is you see all of these methods are provided so you don't need to implement them you would only implement on event and inside of on event you would decide to emit you know open telemetry for that event maybe only if the target is equal to metric for instance okay there's a lot more to talk about layers but let me pause there after having introduced them how can i be sure the tracing events are not lost i'm guessing there's no delivery guarantees so things can get lost is there a way to prevent that also remember that the way that tracing dispatches an event like when when the event macro is used or any of its derivatives or the span macro is used or any of its derivatives it just calls the subscriber method you know new span or enter and event and it's entirely up to the subscriber what to do those calls are not lossy it's not like tracing will like you know you get so many seconds to execute or so many milliseconds to execute the the event method and then we'll just cut you off it just calls it blockingly and it's up to the subscriber the implementation of the subscriber what they do and so for instance there is a subscriber that basically implements like a ring buffer or a queue with a fixed size so if the subscriber starts falling behind it will just start dropping log events but you could also have a subscriber that doesn't do that that starts to slow down the code that emits the events whenever it detects that the uh the output doesn't keep up it will just slow down the code it'll just exert back pressure by blocking um so both of these are possible you could have a an infinite queue they just keep pushing to that's okay too tracing doesn't dictate what the subscriber does with the events or how it how it deals with things like a overloaded system um would structured logging take place in layers yes so as an example right so uh in the on event method of a layer you see here the event that you get you know you get a description of the event and you can walk all the fields of it so you have all the structured information right so you can call record or I guess this would be record um and it will then that that visitor will be invoked for every field like every field value pair and so this is how you would then emit structured logging out of that so yes that would entirely be a layer thanks David always helpful to have year okay uh so the nice thing of course with layers is that you can compose them so I can have you know layer one and layer two and I can put them on top of each other and now one will be called and then the other one will be called there are a couple of things to be aware of when you do that the first is if we look at the implementation of layer one of the methods you can override is enabled so you can say this layer uh is or is not enabled for a particular call site if we go here um and notice here so we can return true if the layer is interested in a span or event with the given metadata so remember the metadata sort of the static description of the event or span um and it's similar to the subscriber enable enabled method um and by default of course it always returns true because you want the subscriber to be allowed to do to choose whether to disable um what's interesting is that this method and hopefully that's actually kind of intuitive if you return false from this method the whole chain sort of stops right so if you return false from enabled that means that you've said this entire block of you know layers with a registry at the bottom is not interested in this event and so if any layer in the stack returns false then the whole stack like that represents everything below it in the stack and tracing will then assume okay so I should not emit this event so this is effectively a global enabling or disabling of a span or an event it is not just whether this layer cares it is this layer and all the ones below because again from the point of view of tracing there is only one subscriber and that subscriber is the the the sum total of the stack of layers and the registry and so returning false from enable means the subscriber does not care about this event and therefore tracing will just stop emitting it entirely there are ways to get per layer filtering and we'll talk about that in a second but but this enabled bit is a way to turn things completely on or off which then brings us to one of the most common layers that you'll see over here uh which is the end filter layer and we'll talk about why it's in the filter modules in a second filters are sort of special but the end filter layer is one that can be used for global filtering and we'll talk about per layer filtering later and the way that works is it's just going to be a layer in your stack of layers and its enabled method is determined by what is the level and target of the incoming event like the event I'm being asked whether is enabled and what is the value of the environment variable rust log and if the event that I'm seeing or the span that I'm seeing is um you know not included in the set set by rust log then I will return false otherwise I will return true and so that's how it ends up just globally enabling or disabling events and spans depending on that environment variable um and there's a bunch we can say about how end filter works uh the documentation here is really good you I already mentioned how you can do some like cool things where you can you know give uh different crates different targets with different levels but you can do a whole lot more with end filter things like spans like set the level for spans whose field of this name has a value of this like you can do really cool intricate patterns here to really nail down I want only exactly these spans and these events in my output that can be super useful but I don't think it's that useful for us to go through it here on stream because the documentation is really good for how you construct those those directives for what to enable or disable what events and spans to enable and disable when using the end filter layer and the nice thing about end filter being a separate layer is that if you write your own subscriber uh or you're using some subscriber that someone else has written like open telemetry then you can combine the open telemetry layer with the end filter layer and now it'll just work like if you set the rust log environment variable that will affect which events make it to the open telemetry layer which is exactly what you wanted or you know you can use per layer filtering which we'll get to a second to sort of fork where events go we'll talk about that soon uh so usually we only want to implement a layer and not the whole subscriber trait yes exactly right it is fairly rare that you want to implement subscriber directly there are a couple of cases where you really need to do like the the state tracking of spans yourself in which case you would implement the subscriber trait but usually the layer trait is the thing you want to implement okay so we've talked about how layers stack and the the enabled thing is sort of the most important thing to be aware of all of the other ones are pretty straightforward right like on new span it's going to be called all the way down the stack on record it's going to be called all the way like on every uh it will be called for every layer and also for the subscribers of the registry at the bottom uh similar for on event on exit etc um event enabled and enabled uh are global register call site we don't really need to talk about but this is basically um register call site is going to be called once for every single call site so we talked about call sites earlier they're basically every uh place where you have one of the tracing macros so the span uh macros or the event macros every single place where you have one of those um is a call site and for each one the register call side method will be called so that you as a layer are aware that that span or that event even exists so that is not like one instance of the event like if it was in a loop it would not the register call site will be called once not once per iteration of the loop it's just so that your your subscriber gets to know about the all the statically known locations in your code and the thing that this returns this interest method is just um it's like a a struct that is either never sometimes or always um and the idea here is that you can say when the call site is first registered you as a layer you can say i'm never interested in this event i'm sometimes interested in this event when sometimes we can ignore from now or i'm always interested and that that's sort of a a dual to enabled it has a very similar function to enabled and the exact distinctions are not worth digging into too much here okay uh you'll see this dispatch type mentioned a couple of times dispatch is really just a type erased subscriber so imagine you construct your construct your subscriber of whatever type and you want to record it or you want to set it as the the global default or the local default using with default the static the single static we have the tracks you know the current subscriber that static needs to have a type and that type can't be generic because it's a static and so that static actually has a holds a an arc arc dispatch or arc din arc din subscriber and dispatch is an instance of that and a dispatch really just is a subscriber that has been type erased so that there's no generics involved so you shouldn't need to think too much about dispatchers the main thing to know about a dispatch is that you can take a dispatch and you can call downcast ref to try to cast the dispatcher a reference to the dispatcher back into the subscriber type which is sometimes useful if you want to like access particular information about the current subscriber if you happen to know which concrete subscriber type it is okay so all of this is just sort of standard layering things where every layer is just invoked in sequence but there is one part here that is important to include which is this idea of with filter and we'll go back up here to per layer filtering for this so per layer filtering is a way for you to say you know actually don't want to do this first yeah before I just before I get into this imagine that you want to log both to the console and to a file and to hotel right you could do that by just having all of those layers in your stack there's nothing that says you can only one output layer right layers are just layers and you can stack them as much as you want and so there's nothing you can just stick all of them into your layer stack but this is where the tie into per layer filtering comes in because you could imagine that you know the hotel layer you only want to emit metrics the console layer you only want to emit like info level and above and the disc the to disk layer maybe you want to include debug but not trace and so what this really means is you want different filters for the different layers and when we talked about the enabled method on layer remember how I said if you return false from this the entire event is turned off it's like because the the stack is now saying we as a subscriber like the the subscriber that's made up of the layered stack does not care about this event so clearly that is not workable right because it would mean that if the hotel layer for example did not care about anything that's not a metric it would return false for enabled but that would disable all of the non metric events for every layer which is not what we want hence this idea of per layer filtering and the idea of per layer layer filtering is that you create a layer that is a filter and a separate layer stack and this is where I might have to draw and now let's let's see how well my drawing program is going to work in this I have not used it on this computer before I think at all so let's see see how my how much worse my drawing skills have gotten so and also whether it works it's over here it's working so far over here we have our subscriber so this whole thing is a subscriber and inside of the subscriber the way it actually sort of looks internally is a layer and this is a layer and this is a layer and this is a layer and this is a layer and down at the bottom we have the registry and and the way to think about this in terms of the types right is that the type here is you know a layer I don't know seven like let's say this the type of this thing is layer seven generic over registry right and remember that the layer trait is generic over an s where s implements registry so clearly this thing implements layer because this thing implements registry sorry implements a subscriber and that means this whole thing implements subscriber because layer implements subscriber when the s in the layer implements subscriber and so the type here is you know layer six of layer seven of registry terrible writing but this thing implements subscriber because this thing implements subscriber which is because of this and then then that sort of stacks all the way up here now the idea with per level per layer filtering is that for one of these layers what if we sort of expanded it and said that this is actually its own little subscriber its own little layer and what we want is to have this be internally should have a bunch of filters maybe up top here and then a bunch of layers and the idea is when a method call comes down here we want the method called to go in here and then down here and it might get filtered by one of these and then these layers will not be called but it should still proceed to the other layers after having gone through this one so that's the that's the basic thinking that the filters are sort of local to this whole thing but in the context of the whole stack this whole thing is just one layer in the in the outer bit and so as a result this filter right here for instance is not actually a filter for the whole stack it is just a filter for this sort of substack yeah i know i could have written bigger but you know such as life so that makes sense so the filter the filters that we add in here are sort of local to this mini layer or mini layer stack this small pancake if you will small small a short stack and and they're not a part of the big stack the tall stack and therefore will not affect the lower layers what this also means is that for some of the methods the the on like on event for example on event when it's called on a filter the filter will always pass through the the on event to the next layer down but it just might not pass it through the layers inside of the stack you might wonder well how does this work it looks really weird it does look really weird but crucially some methods like enabled will not be excluded if they don't pass through the filter so let's go look at what the code for this actually looks like because that might be instructive pancakes and all right i can have pancakes right now that's a safety um okay so let's go look at layer with filter like it's a filtered for now go look at filtered what does filtered look like okay it has a filter and a layer that's fine and whatever this magic pulse downcast marker is we're gonna ignore that for now let me see if i can find no i want the i want the impulse search maybe uh oh no it's gonna search on the wrong branch okay fine maybe i'll just go the others get clone uh tokyo rs tracing dot get tracing uh check out v zero one x cd tracing subscriber and then search whoops search for this thing um source filter layer filters mod rs line 703 okay so let's look here at so remember filtered has um oh my computer is going to be unhappy about this because they need to parse the entire workspace there we go so filtered this the struct that we get back when we construct one of these filtered layers it holds the filter and the layer separately and something like on register dispatch or on layer we just call into the inner layer and enable we're gonna ignore a little bit for now because it's a little complicated but if we look at something like uh on event uh did enable um how do i want to explain this i'm trying to think what the best way is to explain this in a way that's useful um actually maybe i do want to follow the docs here um yeah let's follow the docs first and then look at the code so so there are these two traits there's layer and filter and filter is a super straightforward one um if we look at here uh like end filter for example if we look at the methods on it you'll see that it implements the filter trait and the filter trait is mostly just the enabled method right which is you know it's a filter like does this filter the thing through or not is the only thing that you really need to do need to express if you are a filter and the idea is that a if you combine a filter with a layer then that layer and you know anything that lies below that layer will be subject to the results of that filter but if you then take that whole stack and you slot it into a larger stack then the the the next layer after the combined filter and layer layer uh that one will um uh that one will still pass through and ignore the filter um uh and you can construct filters from all sorts of things so it doesn't have to be like a fancy uh struct that implements the trait like you can have a filter function for example so the the filter module of tracing subscriber has a filter function method that just is given the metadata for a given you know the the statically known information about an event in a span and this is supposed to return true if that thing is interesting as part of the filter and false otherwise so in this case for example it checks whether the target is equal to htp access you could imagine a similar kind of uh filter for you know has targets set to metric and in fact i think they give an example of that but maybe not um and so here you see an example of how they might combine these kinds of layers so the info layers here are layer a layer b and those are filtered based on only things that have level info but that whole stack and this is the sort of thing i was drawing earlier that whole stack of layers you can insert as a single layer in the whole um the in the overall subscriber uh and similarly here you know layer c can have its own set of filters and that filter will only apply to the things inside of layer c uh just like this filter will only apply to these filters here they're inside that packaged layer and will not apply cross layers um and the way that it actually accomplishes this is uh and that this is the part i was looking for earlier uh is not that it is um seven oh three where's the method that calls layer um so on event for example it's just like did i enable this event if so then call the event on the layer right so this is the the filtering part of you know if it's if it's not filtered or if it is filtered then don't don't call on event amise versa but crucially uh the part where it actually constructs the layer on layer so this is where there's a little bit of magic this is this magic pulse downcast marker um i don't actually know what this thing does internally i think it just keeps track of what the real value for the filter is and it doesn't like type erasure but but the basic construction here is that you um the the layer oh oh i'm struggling to find the right way to convey this ah okay i know how to do this i'm not going to do it through the types because i don't think that's going to be helpful but i will do it through the drawing so here um i'm even going to switch color well i'm going to try anyway ah okay that's i want i want my color to change maybe now no can i go down here okay great uh let's do uh okay why why would not let me change colors well i guess then maybe it has to be yellow color palette sure let's do that color palette uh bright blue okay um so the key thing to remember here is that the the type here this type uh so this is the sort of type boundary here there's an implementation of a type here of layer and this one is allowed to not emit events but there's also a type for this overall thing and this overall thing is the thing the slots in here and that handles the outside calls and so this outside type can choose to call into the inner one and then call into the outer one because this is the filter and this is the next layer when the when the whole thing is stacked into the overall one um i don't know if that helps you but but the i think the mental model is clear which is if you insert a a stack of pancakes that has filters internally in it into this larger stack of pancakes then the filters apply only to the local stack of pancakes and not to the next layer in the larger stack and i'm going to not try to show you the code because i think you know one of the challenges with the tracing code base is because is that it is very optimized to um aggressively get rid of events and spans as early as possible if no one cares about them and so the code ends up being more complicated here uh than the sort of mental model that's needed to work with them uh as evidenced by you know types like this um and so i'm not going to try to dive into how it accomplishes this but just trust me that it does i guess um okay i'm gonna take questions there given that i rambled for a bit and see whether i can help clarify any of the things i rambled about um i guess one one clear question is um does the distinction between a global filter and a per-layer filter make sense is that distinction clear maybe hopefully i've not uh lost connection with chat no it's still there it's just everyone is super confused um um okay uh you can use the same filter type as a global one and a per-layer one yes so so so um it's actually um if you think about it you know i mentioned that you can attach a filter to a sort of local pancake stack right but the global stack is the same kind of type it is also just a stack of layers so if you put a anything that implements filter on top of the global stack then it filters all events for all layers and so you can actually construct these interesting hierarchies right where the the chain doesn't need to be only too deep there's like uh inception over here right so you can have this layer for example this layer could itself be a substack and that substack also has a bunch of layers and also has its own its own filter on top and that the red filter will apply to all of the layers in here but will not apply to the other blue layers and will not obviously apply to any of the yellow layers and and so you can you can stack them this way such that again if you imagine something like hotel versus console versus file right the the filter that you use over here you could uh this you know if this was the the hotel i should do that blue but that's fine if this was the hotel one then this might be a a thing that filters based on metrics being the target and then in here you might have a different one that filters on uh info and that is the one that goes to the format layer and similarly down here you could have one that filters on debug and goes to the uh file logger uh and inside hotel maybe you want like the the metrics that are marked info and higher to go out at a higher fidelity or something than the ones that are lower and so you could have sub filters uh under there as well so you can stack them all the way down uh can you modify some layer filter at runtime for example can you runtime change logging lever for some layer so kind of um and i'll show you this bit down here um and i think that's over in tracing it's called rebuild is it in here then rebuild so there is a method to basically say my subscriber has changed like i've changed the settings of it reevaluate the whether every event should be enabled or not uh and i'm just trying to find what that method is called but now of course i cannot find it i think it's over in subscriber so one option is you can call uh set global default uh apparently no set default no it's um it's not an internal method is it let me see if i can find it here tracing core call sites rebuilding cached interest this is the one i'm after um okay so this is in the call site module of tracing core i mentioned what call sites are um and there's a way where you can rebuild the sort of cached information about which events and which spans are enabled disabled like basically which one some subscriber is interested in um and it is by calling this rebuild interest cache method uh so if you modify your subscriber in such a way that it's let's say more restrictive or less restrictive uh then you can call this method in order for the i think you even have to call this method unless you go through a couple of other methods to do it automatically for you um so that all of the call sites are going to recognize that oh i was disabled so i was doing the shortcut for you know do nothing um but now i need to reconsider whether i'm enabled or not on the next time i call so calling this is quite expensive right it it um uh it recomputes a bunch of levels uh and it's like it's a it's a very expensive operation it basically needs to re re-evaluate every call site um so it's pretty expensive but but it is the method that you call if your subscriber configuration changes and i think this says here too like this function is standard for runtime reconfiguration of filters on traces where the filter recalculation is much less frequent than trace events are so basically it's rare that you change the configuration um if you have a case where your configuration actually changes very often you don't want to be calling this method because it's so expensive instead you want your subscriber to just not disable things so essentially you want it to indicate this interest sometimes rather than interest never and that way so this is the sort of distinction between interests that we talked about briefly and enabled so if interest is never then the call site is disabled entirely if interest is always then the enabled method is never called and if interest is sometimes then enabled is called for every event um and so for something like end filter it it it statically says you know the interest is never for things that don't meet the environment variable because it knows that the environment variable will not change over time but if you had something that was fully dynamically configured it would have to return interest sometimes uh so that the enabled method is called every time there's an event but of course now dispatching events is more expensive because each one needs to call this enabled method um and so it depends on how frequently you change the configuration whether you want it to be that the interest and the call to enable to be cached um and then call this rebuilt interest cash whenever the configuration changes or whether you want enabled just be called every time there's a reload module in tracing subscriber as well interesting where uh no this so this module is slightly different this is to basically allow a hot swappable layer so you can have a if you use this uh like for example for a level filter then you can swap out to the instance of the level filter dynamically at runtime now that in that particular case it has the same effect right because you're swapping a level filter or warrant a level filter info and when you do that you have to rebuild the interest cash but that is a a more specific case of the problem right where you have one instance of a layer and you just want to swap out that layer that doesn't necessarily mean that your filtering is more or less um is more or less restrictive right imagine you have a layer for instance that doesn't do any filtering it just like writes the disk whatever it gets then if you swap it out with something that writes to a different file for instance so this is going to be used for a rotational file logger then just because you swapped out the subscriber does not mean you need to rebuild the interest cash um so so reload is a more general purpose mechanism for just having uh layers where you can swap out the instance of that layer over time um okay let's see so i touched on that just on this just on that i talked about async talked about blocking talked about the level suspends and events layers filters subscribers i think i think that's all the things i wanted to cover but let me look through the tracing subscriber docs and see if there's anything particularly interesting that i missed um there's no student support which is nice um what do we have in utility that's not particularly interesting fields field visitors um uh i think the last thing i want to talk about is just a couple of maybe interesting subscribers but i'll leave that to the the very end but i i think i'm done on sort of tracing core topics uh how do you actually change the properties of the filter with the rebuild cash uh oh so if you can get access to a subscriber right so so you can get access to the subscriber by calling um here subscriber uh tracing dispatcher so again i mentioned when you set the subscriber it gets type erased into a dispatch uh and then the dispatch is what's stored in the static so you can call um the get default method inside of the dispatch module when you do that you get back or you you pass on a closure and that closure gets given a reference to the current dispatcher and then on the dispatcher you can call uh downcast in order to cast the dispatcher back into a reference to the subscriber type right so that would be you know the type of your whole little layering stack um and when you then have the type of your layering stack then uh over here when you have that layer stack uh and we look at the type like layered you'll see that layered in turn allows you to downcast into either the type of the like a layer is fundamentally you know the top and the rest right um and downcast ref will let you either downcast into the type of the head of the layer the top layer or it will call downcast ref on the rest as a result you can downcast into the type of any given layer and so that gives you then a reference to a particular layer in the stack and you can nest these right as if you have um if you have these sort of sub stacks that are injected in as batches of layers so ultimately you can always find your way from the dispatch all the way into an individual layer and then when you have that individual layer you only have a shared reference to it right because it's stored in a static um but if you have something like an atomic bool in there you could change that atomic bool or atomic use size using atomic operations in order to or you could be a mutex for that matter um in order to change the configurations of that layer although again like you you really and tracing does make this hard you really don't want to be changing the like a a layer that is a part of your subscriber at runtime very often um if you do chances are you either want something like reload like a swap the instance of this layer um or you know it's it's going to impact your performance if you if you require that kind of uh that kind of non-static setup like end filter can be extremely efficient even though it's not compile time because it can say once for every call site i am not interested in this call site and i never will be and so that allows it to be extremely efficient whereas if it had to check all the time because like the environment variable could change because it was stored in i don't know some mutex guarded string um then that end filter would be very expensive to compute uh so subscribers can have layers and layers can have their own layers not quite so subscribers don't really have layers the way to think about it is the subscriber trait is implemented for um any type where the top thing implements layer and the bottom thing implements subscriber that's the that's the whole deal so the subscriber trait is implemented for anything that is a layer plus a subscriber and because that applies recursively you can stack layers um but the and one instance of something that implements a layer is a stack of layers because they the the interface sort of um combines nicely so to recap inside all of these layer impulse you really should not block right they should send a message or write your ring buffer for file writing etc well i mean it depends on what you mean by block right like all cpu instructions take some amount of time and there's no hard rule for how many cpu instructions or how much wall clock time you're allowed to spend inside of event dispatching but all of the time you spend in there is going to be cost paid at every event site so how much you're willing to pay there is entirely up to you um usually you want it to be quite fast because there are a lot of events in a program and ideally you know people instrument your program with events all over the place so you really want it to be quite cheap if you start like blocking on file writes or re or i o that's probably too slow um can you talk about the usage of this crate like the frequency of tracing debug warrant etc how much do you rely on logging versus debugging um so on tracing versus debug versus info versus warn versus error there's no great answer to this usually the way i think about this is like tracing i use if i already know that there's a problem in this area of the code debug i use if um i'm trying to figure out whether there might be something weird with this part of the code info is um uh commonplace operations that are useful for understanding what the application is doing warn is something weird happened but it's not nothing's on fire nothing's wrong it's just something was weird uh and then error is something is wrong that's like roughly the the mental model that i have um and it's tempting to make a lot more things debug or a lot more things trace just so that they don't show up in your logs all the way but really what that's that's suggesting is you should be tuning your rust log environment variable more very often people just sort of run with the default rust log um environment variable value which is it's not set uh which defaults to info and so therefore logging things that info lever level in libraries for instance produces a bunch of output uh for applications that use that library and so the library sort of makes them debug instead so that applications don't have to hide it but but that means that libraries end up being sort of limited to just using debug and trace which feels weird and so my general model tends to be use all the levels and then the owners should be on application developers to set the levels such that they only get the logging the login that they they require um well when it comes to logging versus debugging it's a good answer like the the way it's a good question i think of logging as uh something that i use more after the fact right like something went wrong and i want to figure out how we got there if i'm actively debugging an application i'm more likely to just like insert my own print statements and stuff now it is true that if you have really good uh logging or tracing in your application you might not need print statements it might be sufficient just like enable trace for that module and everything's good usually though i find that there's always a little bit more that i want to dig out but enabling more verbose logging is often good enough and useful um if i had two subscribers one first stood out and one for a 2e how do i disable the default subscriber to standard out when i launch the 2e um oh i mean that one's easy so there is only ever one uh global subscriber and you can override the global dispatcher whenever you want so what you do is you set the when your application start you set the format subscriber the console logger to be your global subscriber and then when the 2e starts then you override the global dispatcher to be the the 2e dispatcher instead um how would you structure or separate between tracing for me while developing and logging for the user for programs that you ship to the user like a game server something not a service monitored by devs um there's there's not a really good answer to that right like levels don't communicate things that are intended for a user versus things that are intended for uh for a developer um the levels map a little bit to it like the user probably doesn't need debug and trace output but but i don't have a great answer for you here um the the closest i can get to is you could imagine that you have a field on events and spans that say user like user equals true and then you have a a filter that will um like in release mode that filter is set to um only allow through events that have the user field set to true and in debug mode it just passes through all events and so that way you can explicitly annotate like this event is user facing this event is user facing um and if you're in debug build then those attributes or those fields are just ignored but in a release build only those ones are emitted and so those are the only ones that users will ever see that that's my best guess for for how i did accomplish something like that okay so let's end then on the sort of list of interesting subscribers or things to use we've already talked about the format subscriber we've talked about registry which is a subscriber it just doesn't do anything um there are a bunch of others that you should be aware of so one of them is uh tracing logs so this is the one that provides compatibility with the log crate so it makes it so that every event you emit from tracing um actually produces a tracing log event sorry this is the one that goes the other way around this is the one where dependencies use logs so they use the log macros to log things um the tracing log allows those events to also be picked up by uh as tracing events by tracing subscribers there's one that's also the inverse uh that i can't immediately find now um tracing a pender is a subscriber the writes to file it supports both uh uh blocking writes the while the events go on and non block is using like a ring buffer type thing um there's also tracing open telemetry which supports writing out to open telemetry traces there's tracing timing which is one i wrote that basically produces histograms of the time spent between each two events uh within each span so like it can tell you you know across all uh hdp requests this is the time distribution of things spent in uh you know like let's say you have a part that's handling an hdp connection which is parsing the headers tracing timing is going to take the time between the start of the span and the finished parsing headers event and give you a histogram of how long how much time it took to execute that bit of code across all spans or across all hdp connections and it'll do the same between the parse headers event and whatever the next event is like uh you know the check authorization token right and i'll show you a histogram of that time and then the same for for every inter event region so that can be really helpful for trying to nail down where your performance problems or where your performance budget is going tracing honeycomb outputs to honeycomb by oh we talked a little bit about the sort of axom and actix web type integrations that automatically annotate spans and events for uh actix web and and axom applications um there's uh there's one more right there's sentry tracing of course uh and then there's this one which is the thing i was looking for earlier or tracing cloud watch which sends to cloud watch um but tracing forest uh no that's not the one i was thinking of i'm trying to find david's tree logger but now i cannot for the life of me find it oh is it is it is it just tracing tree why is that not in this list that's what i want to know ah so tracing tree is a subscriber that also just prints the console but it actually prints you like a tree like output showing you the the the sequence the sort of nested set of spans that you're in when a given event is uh is output and so it's it's a neat way to get a more structured look at the output it's probably not what you would use for like ongoing logging output but it can be really nice and i think i think that is all the things i wanted to talk about when it comes to tracing um are there any sort of questions at the end here of anything that's still unclear you're not sure how you do in tracing uh or any parts of the sort of pieces that um that you're curious about how fit together how does the tree react to multi-threading go find out you mean tracing tree right in that case i genuinely don't know i think you would have to you would have to go test it out i think it prints the tree for each event independently um and i think it probably takes a lock on the output but i'm not sure okay it doesn't look like there are any questions at the end here so i think i think that's it i think we did tracing finally it's been requested so many times and finally now we're through it well i hope this was useful i hope you found it interesting and i'll see you in a later video