Beginner's Guide To Structured Logging in C#: Logging Scopes

All right. So, I wanted to make this video on scopes with structured logging because I think for probably too long as a developer myself, I wasn't really leveraging this. I kind of had some patterns I was using from, you know, years and years and years ago. And I figured it's time to show other people in case you're in the same situation I was for a really long time. We're going to jump over to Visual Studio. We're going to be using Sarah log for structured logging. But we're going to be talking about logging scopes, just the basics, and we can see how to leverage a scope, what that does for us, and then kind of compare and contrast it with sort of like what I would call the old way. So, let's jump over to Visual Studio and check it out. I have a sample program pulled up here, but what I'm going to start with is just showing you that we have some Nougat packages here. So, like I mentioned, we are going to be using Serogg. I'm using three different Serogg packages. The first one is just Sarah log itself. I have this one for extensions and syncs. So this one here lets us write to the console. This is Sarah log itself. And this is just so that I can get some extension methods for wiring up Sarah log to the Microsoft logger. And then this is also so we get some extension methods for Microsoft logging. So this stuff will be available on my GitHub. I try to I don't do it super regularly. So, if you're looking for, you know, some code from a video and it's not there yet on my GitHub, comment on a video. I'll see if I still have it and I'll publish it. This one will go up, but it's just basic code, right? So, if you're following along, you can see which packages I'm using. Otherwise, you can check out the repository, but it's these four packages. Now, if we jump over to the program.cs file, I'm just going to walk through some of the setup so that you understand where we're starting from. I don't want that to be the focus of this video. I want to show you how the scopes work. So if you want to jump ahead a little bit, feel free to do that. But the top we're just creating the seral log logger. I did mention that we're going to be using the console one. So that's why we had that sync for console. And then I just have this uh formatted message here. So you can see, I know it's kind of uh way too long across the the screen here, but this is just because we need to be able to format the log lines. And there's going to be some extra details or extra content going in because if you look right here, this is the message, this is the timestamp, and this is the level, right? But there's properties, and there's also exception. You know, if you're logging an exception, that probably makes sense. But there's this thing called properties, which is kind of interesting. But this is just going to be sort of the the template or the shape of the log line. From there, you can see that I'm using a logger factory. I'm adding Sarah log. And then we're creating a logger. Um you can make typed loggers. So this one's for program. We're in the program.cs file. So this is why uh this is just a little bit of extra boiler plate. You don't necessarily have to do it this way. But if we hover over here, um we do have an I logger. So this is the one coming from the Microsoft extensions or the Microsoft abstractions for logging this logger here. So just to write it out it's it might complain. Yeah, it's going to complain because Sarah log also has one. But if I fully qualify it, it is this logger, right? Just as a heads up. So we have a logger and that's just the setup. But what I really want to focus on is some of the code that we have down here. Traditionally or like before we start talking about structured logging and all of that kind of stuff usually what we would do is we would have something like a log line right so in this case starting application right we're just log information and then a message and the information you have here so so there's log there's critical debug error information trace warning blah blah blah these are your log level and then of course this is the message and if you had an exception uh you put your exception here, right? And then you can log an exception as well as the message. But I think the way that I used to do this kind of thing again before structured logging is we would have like you could use string format or string interpolation and then you could do this kind of thing where you have uh variables that you can pass in. Okay. So I could put like string uh my name is Nick, right? So I could do this and then I could put my name in here. And so this uses string interpolation like this. But this is already not going to be the focus. Uh because we have this other thing we can do where it's not string interpolation. And I wonder if this is already trying to recommend that I don't. But you can do this thing where you're not using string interpolation. You can actually pass in these named properties. Okay. So you can do this kind of thing and the logging framework will take care of this for you. It kind of does the interpolation if you will or the formatting for you. So instead of you doing the formatting yourself and putting the dollar sign here and passing in the variable, what you can actually do is take my name in this case, right? So one of the variables and that will get assigned to the first named property that we have here. And then I could do some other thing here, right? So I can just put some garbage here. And then if I wanted to, I could do another thing, right? So thing two. And then you would just pass in You can see if I don't, by the way, I just want to show you. You can see that it has uh an analyzer that's running and saying, "Hey, look, like there's something going on here. Not only is this variable not being used, that's why it's got a a squiggly, but something's going on here. like we don't have enough parameters. So if I go put in blah blah here, not only does this squiggly go away on line 19, but line 21, that squiggly goes away because we are passing in blah blah for thing two. So so far we're still not using scopes. But what I wanted to talk about is that in some of the applications I was building, even though we had this ability to not rely on string interpolation, I found myself every time I wanted to write a log line, I'm like, I got to pass these variables around so I can have the right information to go put into the the log line, right? So I have, you know, uh, in Brand Ghost, which is one of the products that I'm building on the side of work, I need to be able to have like a user ID or know which social platform I'm posting to. So a lot of the log lines that were being created, I need to pass this information around and then it would kind of look like this where I'm passing in the parameters for each log line that I have like this. Now, there is a super nice way to sort of get away from this if you have a lot of log lines that are repeating this same type of information over and over. Before I do that though, I just wanted to show you how this can look. So, let me get rid of some of this garbage that I added in here. I just wanted to show you the logging output so you can see what it actually looks like. So, let's get rid of that. So what I had before, we're going to be looking at these two different variables that I have here. So we're going to start an application. This is all pretend obviously. We'll start an application. We're going to say that we're processing. We're going to log some information while we're pretending to process. And then we're going to say that we finished processing. So the old way that I used to do this is I might say logger log information. Okay. Well, thanks C-Pilot for just making up stuff for me. So I could do something like this, right? And we get the two things added in here. So, this is exactly like that silly log line that I wrote before when I was putting my name in there, right? Just different variables, different message. Can we do another one? Come on, co-pilot. No, you're going to make me come up with something. Okay, so logger. Okay, so great. We can do another one. I just wanted to simulate a couple of log lines. We're going to go run this and it's not going to be that exciting. we're going to see the template, but I just wanted to show you that we get this information populated in and we can see what the format looks like in the console. So, I'll press play. Okay, so this is the my log lines based on the template I'm using. They're each three lines long. So, we have the timestamp and the level. Then, we have this source context. So you'll notice that the first couple log lines like starting application, they don't have any other things added to them, but the context is program. And why is it program? It's because this up here, right? We said we're going to create a logger for program. We have that. And then you'll notice that if we go down a little bit lower, each one of these also has source context of program, right? Each one of these has the same thing. But you will notice that I also have user is 42 and 42's got a cool color with it, right? It's got this magenta color. So it did insert 42, right? So user ID on line 26 where my cursor is that got replaced by 42. And then we have the correlation ID which is this gooid here that got inserted into the message as well. We have a log of warning, right? And we had user 42 as well. And the last line doesn't have any information added to it. So, so far we're still not talking about scopes yet, but this is where we can start to leverage scopes. And I think this is super interesting. I wish that I just knew about this sooner cuz it feels kind of silly that I didn't know about it for so long. So, what we're able to do with scopes is essentially say from this point on or while we're using this scope, using is a keyword that we're going to talk about in a moment. while we're using a particular scope, every log line we want to have additional information added to it. And the real cool benefit of that is that we don't have to start passing in these parameters over and over again, passing them between methods and making sure that we have the user ID and the correlation ID available to us. We can actually begin a scope and every log message that we do within that scope will also have that information attached to it. So, I have that code in here. I'm probably just going to try writing it out myself. So, this is going to be like the sort of the old way. And then we're going to do it with a scope. So, because it is a scope, it's going to be disposable. So, I'm just going to do I disposable. Okay. I mean, co-pilot's completely cheating for us. So, there we go. [laughter] We're going to have this here. And then we can put it into a using block as well. So, I think I can do it all on one line. You know what? Let's um That might be kind of messy, but let's just see if we can do it to um There we go. Okay. So, inside of here is where we're going to be able to use the scope. What I'm going to show you after is we're going to get rid of this block scope where we have it all inside here. And um anything that we log inside of these two curly braces between line 38 and 40, they will have this information attached to it, which is cool. We don't have to add it to the log message. Now, log information at the bottom on line 43 is outside of that block. So, it's not going to get the scope attached to it. But if we do sort of like air quotes here the wrong thing with this using statement on line 33, we'll see that we end up getting this information attached down here. That might be what you want. But in this case, I'm just going to show you that there is a difference. And that's just because of how the using statement works here. Here we had these two messages. I'm just going to copy and paste them. We don't need to have these two parameters passed in. Okay. So I'm going to say user initiated a request. Okay. So simple log line. Okay. And then potential issue detected for user. I'm just going to get rid of the extra data that we're passing in. And the idea here is that we still will have the information from the scope with these two log lines. The messages. Yes, they are going to be formatted differently, but the information that we're looking for will be attached to them. In fact, there is a subtle difference in that this second log line, this one that says potential issue detected for user, it had the user ID. You'll notice that up here from 29 to 31, it never had the correlation ID. This one down here will also have the correlation ID because the scope is the same between the lines 39 and 40 log lines. Okay, so let's go run this. I'm going to comment out these two so that it's not totally noisy. Okay, and then this is trying to tell me that begin scope is technically nullable if we put an exclamation mark here. Makes the squiggly go away. I'm just going to leave it. I just wanted to let you know that's why there's a squiggly. So let's go run this and we'll talk about the output. Okay, so it's already finished. You'll notice that it's similar, but it is different. So we have the first couple of lines. They're the same. And these two are the ones that changed, but they only changed slightly. You'll notice that here we now have with this object for the properties, we have the user ID inside and we have the correlation ID in here as well. The message is just the constant string that we have in the new log line. But essentially we have the information available to us here. And if we look at the second one, it's the same idea. We have both the user ID and the correlation ID available to us. And we just have this constant string here for this warning log message. So the cool part about this in my opinion is that we can simplify a lot of our logging. So we don't have to pass in the parameters across every log message. We can just say here's a scope of logging for the log messages in this scope. We want this extra amount of detail. Okay? And then every log line that we have in that scope will then get that extra detail. We don't have to format it into the message. This might seem like a very subtle minimal thing. If you are building applications and you need uh the ability to diagnose them, especially if it's a you know web application, if it's a distributed application, I can't tell you how many times I'm like trying to debug something and it's like okay well what happened, right? And if you're relying on a user to tell you that they can't see what's happening with your server, you might have written the code and you might not know exactly what's happening with your server. So having log lines really gives you a clear picture of what's going on step by step. So when you start adding this observability in right this traceability observability into your application you're looking at log lines and you start writing a bunch of stuff like this what I'm highlighting works. It's just that it starts to be a pain in the butt over time. So having things like scopes could be really beneficial. But I did tell you that I wanted to show you what happens if we get um rid of this as a block scope. So, let's go put this here. I mean, the way I formatted it might make it even more obvious, but basically these three lines are all going to fall in the same scope because the way that this using statement is now is that it won't call the dispose method until we're at the end of the program. So, in the previous run, we saw two lines that have the extra information. We should see the last three lines have that information. And that is the case. If you look at finish processing, right, we're still inside of that scope even though we're at the end of the program. And that's because this using will not dispose until we're going out of scope. So hopefully that makes sense. The one other thing that I wanted to talk about with begin scope is sort of the usability of this in a simple application like you know this kind of dummy one that I put together here in this console app. This is fine from a performance perspective. If you were going to write some code and have a hot path or have something in a tight loop, what I would recommend you don't do is try to put begin scope into a tight loop because that's going to be probably a performance hit for you. Obviously, benchmark this stuff maybe for what you're doing. You know, your loop is two iterations and who cares? But if you're doing stuff and it's performance critical and you're trying to log and you have begin scope inside of that loop, that could be a lot of extra work. So something to consider. it's probably worthwhile to pull, you know, something like this outside of a loop so that you're not trying to begin a scope like that, like I said, inside of a tight loop. So, something to consider. Begin scope is not free. It is relatively lightweight, but I would not recommend you put that into a critical path where you're trying to constantly make new scopes. So, something to consider. And the final thing is, of course, we've already touched on the fact that it's disposable, but it is disposable, right? So, like with all things that are disposable, make sure that you understand how to manage the life cycle of these things. You do want to make sure you're disposing them. This is just general advice for disposables. But especially with log scopes, if you're not thinking about that, the example that I was trying to show you here is that if you only wanted it on, you know, these two lines, make sure that you're using the right scope and how you're thinking about it. It's probably the last thing I want to touch on for this. However, I did want to walk through a more sort of abstract uh scenario talking about some some calling patterns. So, in this next video, which I'll link right up here, you can check that out and we'll walk through how you can have a couple different variations of this and how scopes can really help. So, thanks so much for watching. I'll see you in the next one.