STOP Passing State For Logging: A Practical Example of Logging Scopes

In this video, we're going to be looking at structured logging with Sarah log. But in particular, I wanted to talk about this idea where I think traditionally, at least for me, historically, I would create functions and have logging. And I would reach this point where I'm like, I need this information to add into my log message. So, I have to start passing it down in methods. And I'm like, I'm only passing this for logging. It feels pretty gross. And there's, of course, a better way. Okay, so in the previous video that I put out, we talked about sort of the basics of begin scope in structured logging. So we can have scope added to our logs. And I just wanted to walk through a different example in this video where we can see sort of what I would call the old way of doing it. And then when you leverage scope, how you can sort of invert what you're trying to do. That might sound kind of weird. So let's jump into Visual Studio and talk about it. at the beginning of this class that we have pulled up on the screen here. This is just setting up Sarah log. I don't want to focus too much time on that. If you haven't watched the previous video, you can check it out right up here. Come right back to this one after, but it walks through some of the basics. We look at the Nougat packages that you have to pull in for this, but it's just going to be Sarah log with the Serogg console sync. So, what we're going to be doing is looking at starting right here, we have a couple of fields that we're interested in. Okay, so I want you to think about something like a user ID, a correlation ID. If you're thinking about some web application you have that's maybe processing a request for a user, you might have some other pieces of information. And the idea that I want to walk through is that we're having a method call that has another method call that has another method call. And at some point in the depths of our call stack, we're like, well, we want to log this information out. So, we need the user ID and the correlation ID and whatever other data. You kind of need to make sure that it gets passed down to where you want to log the information. But like I said, there is a better way. But I just want to walk through what this looks like. To kick things off, we have this do operation method. And it's literally on line 18. We're calling it. It's declared on line 20 through 23 here. And if we just look at it, right? So we're taking the logger itself, the user ID and the correlation ID and then we're just using sort of it's not um it's not string interpolation but it is going to be structured logging. It will do the formatting for you. Right? So string interpolation is if I would have put this dollar sign out the front and then I used the proper variable names here. Right? So I'm just changing this so you can see what I'm talking about. This would be string interpolation, but that's not what's actually happening here cuz the formatting happens under the hood for us. But the reality is we still have to pass this information into the log message, right? So, not only do we need to pass it in here, but it means that this method needs to have access to it, right? And then if we look a little lower, we have this other method we're going to call after. So, we're calling do operation. Then, it's going to call process data. And that's also going to need to pass in the same parameters because we also wanted to do some logging and have that information passed into the log message. Okay. And we're going to repeat this pattern one more time. I'm going to stop after this many times so that you don't get totally bored of this. But the idea is that, you know, as we get into the depths of our call hierarchy, we still want to log out information and we're interested in the user ID and the correlation ID. for this example. Of course, in your real applications, there's going to be more complexity. You're probably fetching data from a database or putting data into a database. There's probably some type of processing and manipulation in between, and you might have more complicated things going on that you want to log information about. But the point is that as you get deeper into your code and you want to log things out, you kind of don't like if you're not using scopes, you don't really have a choice except to pass that information in so that when you call this log line just like this, which this one is the deepest one we have in our example. We need to have the user ID and correlation ID passed in between each method call so that we can finally get it down here. Not so bad in this example, but you can probably see how this creates a bit of a crappy pattern. Especially especially if the only reason that you're passing these things in is because you want to log them. So, for example, maybe we need the user ID for saving results. Maybe we need that because we need to use the user ID to reference it in the database or do something with it. But the correlation ID, maybe we don't need that at all except that it's handy for us to log out at this point. Right? So we end up passing this information in just for diagnostics and it feels kind of gross, but you're like whatever, I got to do it cuz I need it for the logs and it's going to help with diagnosibility, so we'll do it. But when you keep making this trade across your codebase, it kind of creates this pattern that keeps perpetuating and you're sort of stuck with having this all over the map. So there's a better way and that's going to be with scopes. So I just wanted to show you this but I want to run it first so you can see the output and you can see when we go to change it it will be similar different but similar and then it's going to accomplish the same thing without having to get so messy. And I am using the wrong project. So give me one sec. We'll set this one as the startup. I'll do this right here and we'll rock and roll. So we have this output here, right? So starting the operation and you can see that it did the formatting for us. So the user ID is passed in that's in this magenta color. The correlation ID is this gooid here. And then we go into the next method call and then we go into the next one. Right? So this last one is sort of the deepest level that we have and it's not really that complicated. Right? These three log lines, nothing too fancy. So now what I want to do is walk through how we can leverage a scope and then how we can clean a lot of this up so that we don't have to keep passing this stuff in. Again, you can pass in parameters into methods if you need to use them. But if you're just doing it for logging, we can leverage scopes in this case. So what I want to do is I'm feel like co-pilot's probably going to complete this for me, but we'll try. So I'm going to do I disposable so we can get Okay. So it's kind of uh starting to guess at it. Um so I want to call it scope is logger begin scope. So it's going to do it for us. Um it's not exactly how I was thinking about formatting it, but I was going to do a new is it going to finish it for me? Copilot new dictionary. Sure. We'll use the dictionary format for this. I like this because to me it's um from a readability perspective I like the organization of this. But the idea here is that we're going to have this scope and every log entry that we have in the scope of this scope. That sounds kind of funny. The scope of this logging scope, every log entry will have this information added on to it without us having to format the message. Okay, so we have this scope. It is disposable. So, I'm just going to put a using uh out the front here. You can use a using block. So, if you change this, you could have the structure so that it's within these, but we're not going to be doing that. I'm just going to have every log line that comes after is going to be part of the scope. We're going to think about this call hierarchy, and this is labeled the old way, and we're going to make the new way of doing it. Okay, so the order of operations we have is do operation which calls process data which calls save results. Again, we're not actually doing these things. We're just kind of simulating something that's happening. So I'm going to have this. I'm just going to copy and paste it. Okay. And this is going to be new way. And what I'm trying to get across here is that we do not need to pass this stuff in if it was only for diagnosibility. Okay, so we have the logger. We don't need to pass this in on the log message. And this is worth calling out like your log messages will change as a result of this, right? So starting operation for user. Notice how the message is not going to have the user ID or the correlation ID added onto it. Just a constant string like this. Okay. And then we're going to say new way to process data. And I am not going to pass in these two other parameters. You can see that so far in the old way we had to keep passing data into the methods. Again, I'm just going to keep reiterating. If you need those parameters for actually performing your operation or saving results, you got to pass them along. But if you're just doing it to log, this is where you don't need to do that. So we need the next one now. So we had do operation. We're going to do process data. So we'll put that here. I'm just copying and pasting it. Right? So new way process data. We don't need those parameters, which means we don't need any of this. And we're going to say processing data for user. And then we're going to do one more final level. So again, you can see on line 34, I'm just using a constant string here. I am not using a message that has parameters passed into it. Okay. And then the final one we had was this. So it's save results. Again, just copying and pasting it. New way to save results. We don't need these two parameters passed in. Saving results for user. And then you can see here. Boom. Okay. So all of these in the new way, none of them take anything to do with these two parameters for the user ID and the correlation ID. Okay. So none of these log lines on 28, on 34 or on line 41, none of them are requiring that we pass the user ID and the correlation ID throughout our call hierarchy. Okay, so that's the important part I wanted to get across and I will say one final time if you need the user ID at this final stage here, right? If you needed it. So what did I declare it as? The user ID is a well I used var. Okay, so let's just call it int. So if we needed an int here, right? Because so if you actually need the user ID to save it out, then yeah, you're going to have to go back up this call stack and pass it through. Okay, if you actually need it. So I'm just going to take that out. And now we have these three new methods. We need to call it. So, new way, I think Copilot already had it for me. New way for do operation. And because of how our using is set up, the scope for this log scope is going to be until we reach the end of the file, which is technically after this line executes. Okay. So, I'm going to leave both of these in here. And what I'm just going to do is do um let's just do console.right line. I just wanted to put something on the screen so we can see the difference. By the way, this begin scope has a squiggly here because I believe that this is technically able to return null. So you could do that. I'm just not going to do that. So let's go ahead and run this. And what we're looking for is that the first set of log lines will be unchanged. Of course, we didn't touch that code. The log messages in those will still have the values. our new way, we will have all of that data in our structured log, but the messages themselves, like those individual messages will just be constant strings. We still have the data and we didn't have to pass it into the methods. So, let's go ahead and run it. And then we can see, right? So, everything above this line is the same way that we had it before, completely untouched. So, every message has the values passed in. Everything below this right every message is you know not including the data but every sort of log entry has these properties. Okay so we have the user ID available we have the user ID available here in the correlation ID. We have it down on this final one in the depths of our code. I mean it's three methods deep. It's not really that deep but I think you get the idea right. So, we're able to use a scope at the top level where we have access to some of this information. We can begin the scope and all of the logs below that will now have this information attached to it without you having to pass in this information into those method calls. So, this is just a really simple walkthrough to explain this because I have personally found myself cleaning up a lot of my code where I went, wait a second, you know, I'm refactoring something. Why am I like why do I need this thing here? And I delete it and it doesn't compile and I go, "Oh man, like it's just because I have this log entry." So this information was helpful to diagnose something, but I'm passing it in just so that I can have it available on some log message. So instead of that, I can have a scope higher up and that means lower in the code as it's executing, I will be able to have that context attached to the log line. So, I hope you found that helpful. Lots of stuff to consider when you're playing around with scopes and stuff like this, but it can be a great way to enhance the ability to diagnose and debug the stuff that you have going on in your application. So, thank you so much for watching and I will see you in the next video.