Stop using String Interpolation when Logging in .NET

hello everybody i'm nikki in this video i'm going to explain why you should not be using string interpolation when logging in.net now this video is part of my login video series and i will put those three other videos in the description down below so you can check them too i highly recommend you do because even though this video stands largely on its own it will help you put everything into perspective if you watch those other videos too and if you are using string interpolation right now when you're logging you will learn why it is bad not only from performance standpoint but also from a structured login perspective so let's dive straight into that if you like a lot of content and you want to see more make sure you subscribe or ring the sound notification bell and for more training check out nickjabstas.com so let me show you what i have here i made a simple api that still has all that weather stuff in here so we can call the weather endpoint provide a city and then this is passed down to a service and that service just has in-memory stuff so it doesn't really call a weather api it pretends to call a weather api to retrieve the weather and we're gonna use that as grounds to showcase the problem so as you can see here i have a logger call and i'm using the log information call to lock the city and how many days i requested the weather forecast for so if i run this api just to show you all that in action i will go to postman and i'm going to call that endpoint and as you can see i'm getting the weather and as you can see here i have this info something and then this text and this text is coming from here so retrieving weather for city for days days and as you can see i am not using string interpolation here i could but i explicitly decided not to and let's talk why is that you see when you're logging everything here from this url to this part of the line to this text over here this is not just unstructured text this is implementing something called structured logging or the idea of structured logging what does that mean in action well in order to make it extremely easier for you to understand the concept and exactly what's going on behind the scenes i'm going to actually use a different login framework than the built-in one called serilog which is the most popular one it's the one i'm using in production everywhere and it's great because it has tons of quality of life features and a rich ecosystem with third-party libraries so i'm gonna go and use that and it also implements the concept of syncs which is kind of like login providers so i can push logs into different providers because when you're logging you're not really just logging in the console and you know when you push the production you don't even log in the console you push your logs somewhere else because logging in the console is actually pretty expensive so let's go ahead and add serialog and put everything into perspective so i'm going to search for serverlog.extensions.logging and i'm going to add this nuget package over here and what this will do is it will allow me to go to the program.cs or startup.cs if you're using that and set up my logging over here by default cherrylog doesn't implement any means to log somewhere that's where the syncs come in so i'm going to say serilock.sync.console and this will allow me to log on the console and you can have multiple things so i've added that now and i can go up here at the top and i can say builder dot logging dot clear providers and this will clear any already registered providers in my web application then i'm going to go ahead and define an i logger but i want the siri log one not the built-in one so explicitly this one over here so i logger logger and i'm going to create a new logger configuration object over here and i'm going to say that i want this logger to write to the console which is added when we added that library and then i'm going to say create logger and this gives me my logger and i can say builder dot logging dot add siri log and i'm gonna pass down the logger and that's it and then i'm also gonna add it in the di container as a singleton for when i need it so logger goes here and that's it so now if i go ahead and press debug as you can see in the console logging looks different it's structured in a different way you still have information you still have the same log levels and everything and now you can see that it's a bit more visually pleasing it has the colors and as you can see here this is that log that we have in the weather service now notice how london is blue and five is magenta whatever you call that or like in the executed action you see how milliseconds are also magenta or like these other things are colored in different way this is part of structured logging because really these logs are not just text they are properties they have metadata attached to them you just see the message template that's replaced with the property but in reality you can think of it as a json object with a lot of data attached to it now if i stop this and i go ahead and i change this logging call and i use string interpolation instead so i do the thing that you probably might have in your service which is days here and city and i run this again now writer interestingly enough is warning me about the message template thing which i'm gonna talk in a second but let me show you that if i call that now i no longer have london be this bluish color and five being a magenta because now this thing over here is just a piece of text and it will be treated as a piece of text on any sync whether that's the console application insights cloud watch or kibana no matter what you use as a sync you lost the benefit of having structured login in place and just to show you a hint that rider has as you can see here it says that when i hover over this green dots type of thing it says the login message template should not vary between calls this is because even though it says message over here in this extension method this first parameter is not the message it is a message template and if i actually don't use the i logger which is now using sherlock behind the scenes and i say private read only ilogger and i add the serilog logger over here so i'm gonna go ahead comment out the old logger and i'm gonna use the serilog one straight away and do i logger here and logger then what happens let me just stop this quickly i no longer have a log information but i have an information call which is the same so if i hover over this method now this is called a message template and this is explicit as you can see even in the example in the documentation it's telling you that you should treat this as a static string that defines a specific format for that type of log and that's important because then your properties city and day can be properly parameterized and passed down to whatever sync we're using as a property and why it's not important because you can search on it you can filter on it you have tons of flexibility treating that log in a very specific way and you can also export it in data lakes or whatever for further analysis and you're making the life of those tools significantly easier and this logic the message templating logic is the same for the built-in logger as well this does not change between serilog and the microsoft one now because that concept might be quite abstract to you right now if you've never actually used a third-party provider for logging i'm going to use a third-party provider a sync to push my logs that allows me to visualize that logging filter on it and explain exactly what you're losing if you use string interpolation here and for that i am going to use is cloud watch which is a way i can push my logs somewhere and look at them filter them retain them and eventually archive them or delete them and this portion of the video will be sponsored by aws so just to show you how easy it is to add a sync in cellulog all i need to do is go here and say serilock.sync.aws cloudwatch and choose this nuget package and there's other things as well every login provider effectively has some sort of sync and once i do that i can have multiple right two methods here so you can have an amount of things so all i need to do is new line here and say write to amazon cloud watch and i will configure this a bit so the first thing i need even outside of that is a client which is the cloudwatch client so client equals new amazon cloudwatch logs client now if you want to preserve that and register it somewhere else in your di container you can in this case i want but i will need to pass it down to the method um so i need really three parameters here the first one is the log group which is a logical grouping of logs in this case i want to group by environment and application name so to do that i can simply say builder dot environment dot environment name and then for slash and then builder dot environment dot application name and that should be enough and then i need the log stream prefix parameter it can be whatever you want but it's good to have something that is orderable to make it easier for you in this case i'm using this format here and then i can also pass down the client so i can say a cloudwatch client and then client and that's all i need to do my pc is already authenticated against my aws account so i don't need to do anything all i need to do now is just run this and make a few calls so let's say london here let's also say paris let's also say paris but for days equals i don't know 10 this will allow me to get 10 days and that should be enough now i can go to the aws console and see those logs so the console is here and i can go to cloudwatch and i can search for log groups over here and i should be able to see my application here you go this is the log group name and you can see the log stream prefix over here at the bottom if i click that and as you can see those are all the logs that my application has sent from those calls and if i go and i find one of the executed ones like this one which is like the built-in application framework one as you can see it doesn't only have that it also has a properties object which also includes other custom parameters like action name elapsed milliseconds and that's a parameter source context request id connection id you have so many information to correlate details and do lots of cool stuff with all that information what cool stuff well let's say i want to get every request that took more than six milliseconds to complete so what i want to search for is properties elapsed milliseconds more than six but all i need to do is go in the filter and say do assign dot properties dot what is that elapsed milliseconds yeah here we go um more than six and if i press that i can get all the logs that have that property in that location now if i want to make it even more specific i can specify the template as well if i'm only interested in this message template for example i can also group that and say parenthesis here and then have the end symbol and then say dot message template equals that and if i have that in place and i send it i can filter my logs and get all the ones i want and here's where you really see the benefits so if i go back to the original view where i have my own logs over here retrieving weather for london as you can see there is nothing here that's captured as a property i lost all of the information because i used string interpolation now if i go back to my code and i update this code to use the non string interpolated version so just comment that one out and i run it again and i call it again a few times so power is for five days or a price for ten days price of five days and then london for five days and then i go back to the logs and it should be in a different log group now if i open that as you can see here the properties are now captured indeed so i can now use this message template in my filter and search for how many times paris was retrieved or how many times paris for more than seven days was retrieved it gives me so much flexibility which to do in the old way would be very expensive for technology that you're using and it's not flexible at all and any application that's doing any sort of reliable serious logging is working that way you are not just ditching those properties out of the way there is insane value in capturing them because what happens for example in this law group is it has a retention of one week i might have a job that listens to that deletion then pushes those things to some bi related tool um either within or outside of aws and they can be used for further analysis so there's so much benefit and you really do not want to lose that information so do not miss out on that huge huge advantage now off screen i added this logging folder and i'm not going to show you what's in there yet but what i will do is i will add an extra call over here so i'm gonna duplicate this one that's using string interpolation and i'm gonna comment out the proper one and instead of using the information method i'm gonna use the information f method which lives in that folder now this method is using string interpolation and we established that you will lose those properties if you use string interpolation right so i'm gonna go ahead and debug the application and i'm gonna go and call it a few times again london five days london 10 days and then paris 10 days whatever and we're gonna go back to aws or let's go back to log groups call that and then it's the newest one so like i said string interpolation you should never use it because you're gonna lose the parameters now i'm going to open this and as you can see here now i did use string interpolation but it did capture both the city and the days and it properly has them as properties how is that possible well this is where the string interpolated handlers video would be handy for you i recommend you check it out i'm going to put it on the top right corner of the screen i'm only going to give you a sneak peek of that because it's just an idea i've played around for a couple of hours yesterday it's the idea that you can create a string interpolated handler which will allow you to catch those properties and then replace them store them and when you eventually give back the the final string you behind the scenes for the user pass them down as an array to the behind the scenes information call and you preserve both the original template and also the parameters and this is possible by using the caller argument expression attribute i also have a dedicated video for that feature too so i highly recommend you check that out and this by the way is a pretty crude way of implementing it i'm still playing around with it but the reason why i'm making it public is because if anyone is interested in giving this a go or seeing how they can make it both efficient and a viable option then please go for it because i don't want to use it the biggest problems that this approach has is that anything can be color argument expression so for example if i went in that service and i had i don't know new string something this would literally capture the new string something here the whole text and obviously this is not a property that you would filter on it's of no use so ideally you'd want to have an analyzer that checks that the value passing down here is actually something that makes sense for your logging the other problem is that you need to find a very efficient way to store those parameters and because they can be of any type storing them as an object will box them and eventually you have to return them as an array um over here which will also allocate that new array so sure this can be optimized haven't really tried to optimize it at all but i think there is something there there's a use case here for a library i believe and if you want to play around with it then give it a go it's certainly possible but you need to limit how powerful it is in order for it to be viable bottom line is you should not be using string interpolation when logging if eventually there's a nuget package that makes it possible i will make a video on that but if you want to preserve your logs and use whatever technology you want to filter your logs archive your logs and index them efficiently do not use string interpolation when logging if you're using c sharp 9 and before or net 5 and before you also take a very significant performances which i covered in one of my other videos for logging i'm not going to dive into that for now because i do not think it's as important as literally losing data so that's all i have for you for this video thank you very much for watching special thanks to my patreon for making videos possible if you want to support us well you're going to find a link in the description down below leave a like if you like this video subscribe for more like this turning the bell as well and i'll see you in the next video keep coding

Channel: Nick Chapsas

Views: 74,508

Keywords: Elfocrash, elfo, coding, .netcore, dot net, core, C#, how to code, tutorial, development, software engineering, microsoft, microsoft mvp, .net core, nick chapsas, chapsas, dotnet, .net, logging in .net, string interpolated handler, interpolated string handler, C# 10 string interpolation, string interpolation logging, structured logging, logging in c#, structured logging c#, structured logging serilog, Stop using String Interpolation when Logging in .NET

Id: 6zoMd_FwSwQ

Length: 17min 29sec (1049 seconds)

Published: Mon Mar 14 2022