Structured logging - what is it, why is it useful and how do we do it in Asp.Net Core

hey there and welcome back to the code wrinkles channel for a brand new video this time we will talk about structured logging and this is a topic that unfortunately or at least in the way that i have researched it you find very very few tutorials or learning points on it and though when it comes to production applications structured logging is really vital because it not only allows us to simply just log things but also to be able to query for laws to to to construct complex search criteria for logs that that actually match a certain criteria that you are searching for and this is really vital when you're troubleshooting or when you try to to fix bugs or find out exactly what happens in a certain sequence of events when something's uh gets wrong or is wrong in your application so it is really really vital and it's also not very complicated it's actually very very easy to achieve at least in asp.net core or generally in dot net core so before we get started with visual studio let me just briefly explain you why actually structured logging is very important now the problem that we have usually with log files is that they are unstructured text data so it's just really some text there that is written and when you really want to do complex queries and try to actually search for something it's very very very difficult to achieve that let's simply imagine for instance like we have done in our previous videos that we just logged to a txt log file now when you try to actually find a problem in your code and you know there there should be some locks there regarding that specific problem now it's very difficult to search for of course you could use tools that are a little bit more complex than than a notepad or noted plus plus but still the same problems remain because it's just text it is not structured at all so therefore the goal for structured logging is simply to solve this problem by actually making the logs queryable so that you can query logs for certain criteria and in order to achieve this what we actually need to do well we need to make this log files machine readable which is very very easy because nowadays what does this even mean that something or a log file should be or generally a text should be easily or should be readable by a machine very very easy and it's it's the answer to that is actually very easy and we use it day by day the data needs to be in kind of like a structured format nowadays we usually use json in previous years maybe 10 years back we used to use a lot of xml but still also xml is a structured format like it is json and we use json every day and what do we do with json well we usually have different type of application configurations that we read in our application so they are machine readable well this means that the the core concept or the core idea of this structured logging is that we should actually create our logs in a format that is machine readable and therefore nowadays mostly in json unfortunately this is really not very complicated especially when it comes to asp.net core because the microsoft extensions logging library supports structured logging by default and more than that most of the third-party logging providers and we have looked in the series of videos here on the codeniko's channel on for instance serilog well sirilog is one of these providers that actually supports structured logging out of the box what this actually means for us as dotnet developers well it means that we can simply use structured logging out of the box we just have to stick to certain conditions or well to certain conventions i would rather say and that's exactly what we will do right now by jumping over into our visual studio solution that we have previously also used for all the other logging videos so this might already be very familiar to you now the core thing that we want to achieve right now in this video we want actually to make these logs machine readable so that so we want to use structured logging now in order to do that i have set up a few things here that are really really important because here we can see how powerful or in order to see how powerful actually structured logging is and how useful it is when it comes to debugging or searching for problems in real production uh applications and what i have done here i have installed locally seek and seek is actually a logging sync so or a log file destination where you simply could send your log files and then where you can aggregate logs you can query logs and things similar to that and it's useful to to have such a tool for instance because well in a txt file even if you write json we cannot really do a lot of things so seek is also free you can google for it and you will find it you can simply install it on your local machine it runs like a web server so it is exposed through uh through a url and you can just use logging to simply send your logs to seek of course if you want to could use other third party or other tools like maybe microsoft azure log analytics or other tools that are especially designed for getting logs and offering this great opportunity to query logs to search or do advanced searches for logs and things similar to that but for simplicity we will use sig because it's really very easy to get started with it you don't need any subscriptions any keys you just need to install it and that is then done so nothing more than that now the second thing that we have already done here is we have added actually to our project a new package which is a serilog sync for the seek log server so you see it we have installed it here and the other thing that we have done is of course we have configured a very basic seek provider for serilog so that we are able to actually send our logs also to seek not only to a log file and to the console and in fact we have added this as a using here in the serial configuration and then we have added it as a right to target and that's pretty much everything that we have done to actually set up all that we need for for for this video so now we'll go here back to our weather forecast controller and get actually started with what actual uh structures logging means and how it works so it's actually very very easy but before we really do our structured logs let me just take these exceptions that we have here and let's move them somewhere at the bottom so that we can log different things here uh up now let's for instance see how this could be useful and we also let's assume you would also like to to keep track of how long actually this service takes to perform the task so let's do this in a very very uh well old-fashioned way not the best one but it's actually uh useful to just get started and understand why this structured logging is or could be so important so here we just want to use a stopwatch and we just need to add the using for that and let's call it uh sw and this would be a new stopwatch so we will use this in order to exact uh see how much time it elapses until this service actually performs its job but before we actually do that let's let's actually try to add our first structured log and the way we do this in asp.net core so we can already use the i logger that we have so nothing more than that the only convention that we have to actually take care about is that we when we write our string let's for instance let's say here request received by controller and we want to specify the name of the controller and here comes the first convention when you want to use placeholders for the end result that would be actually a json log you would have to use this curly braces and then you would have to specify the property name and in my case the property name will also be controller so we have added this and then we can say for instance action because we want to see exactly also which action was executed and then once again this convention we put these curly braces and here we should put the name of the property that we actually want to have as a property in our structured log so in this case we will also use action or let's use controller action you actually can name these properties really the way you want the only important thing is that you are consistent so if you start to to name your actions controller actions instructor logging and it might be useful to really stick to that because then when you want to to do a query or an advanced search as said for instance in seek you need to have reliable results for that and what we can even also say is and let's let's go here on a new line and we specify that it will receive on a date time and here once again we place these curly brackets and we want to have a property which is called this time and that's basically it now the second part of this convention when it comes to structured logging in asp.net core is that after you have provided a string you have to provide actually an object array that would actually specify uh the values for the placeholder that you have here and let's let's start this and uh let's say new object array and here in this new object array you have to specify the values for the placeholders that we have here in this exact order so the first value that we would have to specify in this array would have to correspond to this controller so we want to have the name of the weather forecast controller so we use here a name of weather forecast controller then the second thing that we want to have is the controller action so this means that the second thing that we would need to provide here is the name of the action and here it would be the name of the action is get in this case and then the third thing that we have here as a placeholder is a date time so what we can do here is simply use the date time but now and dot to string and that would actually record exactly the time when this request actually came in but now after we actually do this let's maybe all add this other log here that we already have but we just change a little bit of text and we will also change uh we will also use here of course structure structured logging because the next thing that i would like to achieve and that i want to actually be able to search for when i have thousands of vlogs is for instance uh which exactly service was called in order to well get the forecasts in in our case so what we could do here is we can simply say here dispatching dispatching to service and then we have here a placeholder for the service but here we don't need to use string interpolation okay and then what do we need to do we need to stick to the convention and the next thing that we want to provide here is a new object array and here in this object array uh sorry you we can initialize it and we just need to provide the name of the service so in this case it will be named of weather forecast service okay um so we should be good to go i guess that should work just fine so right after we have done this we can just start our stopwatch start it's cool and now we get for instance we run the service and then after we run the service uh let's hey let's have this stopwatch stop and here for instance after this we can just uh log some information so let's have here logger log information just like we had before once again we will however use structured logging and here for instance we can say that for instance the service and once again we specified service so we need a placeholder for that and that would also once again by convention be the property name or the json property name uh that will be actually placed uh in the json log that will be generated and then let's maybe generated a response in and then let's have here for instance maybe ellipse time you can even call this ellipse time this property but that would be it and then maybe just add this milliseconds at the end so that everybody knows what this is about and for the second part of the convention for structure logging once again we just need a new object array and here in this new object array we would have to specify at the first place the value for the service so it would be once again name off and whether forecast service and then we would just have to specify an object for the elapsed time so in that case it would be uh stopwatch dot elapsed milliseconds and that should actually do it so now we log this information now we log the other information which is the count and i guess everything else we can leave it the same of course we could add some structure logging for the warning or for the exception like to include the name of the controller but i guess that you've got the main idea how structured logging works we just have to stick to this convention so just use for instance displaceholder where we put the json property names that we want to have in our logs and then we have to provide an object array in which we have to be careful to provide to provide the values in the exact order in which we have these placeholders here otherwise you would get a mismatch between what you would expect here and what you really get so that's actually the only thing that we have or that we would need to be careful about anything else is i said handled already by microsoft extensions logging and in our case by serilog as we are using stereolog as a third-party provider now let's run the application and make a request so that we will be able to see then why actually this idea of structured logging is so important so let's run the application i guess it just takes a few seconds but it should start so we also have here this swagger now let's just run right out execute and that's it and that's everything we need actually we don't need anything else we can close down the application now we can switch over to seek and let's do a refresh here and as we did this refresh we see that we have here a lot of information now a lot of the information was logged by sirilog already because we have said that we actually want to look different things when we have configured siri log but what we can do here is we can take a look here is the first information that we log and already by the color you see that you did that this weather forecast controller is colored differently this get is car is colored differently and this date time is is uh colored differently so if we expand this and here is the where you actually see how powerful structure logging is because you see that besides the text itself that we write we also get here a bunch of key value pairs that correspond to the json properties that microsoft extensions logging and serilog have uh have have generated for us now here we can see that we have this controller property which was the name that we have used and here we see that we have this weather forecast controller then we have this controller action that we actually um have created and we have this date time for instance uh so everything that we have added to our logs or to our text we can see that we have it here as properties and for instance we can see then dispatching the service to the weather forecast service and in this case you can see that we have the service name that was already added here and then we have some logs that that come directly from the service itself so we haven't implemented structured logging there yet so in this case you see that the text is really just wide but then comes the other log when we actually measure the time that it took and once again we have the text but besides the text we have all these kind of like properties where we have this for instance ellipse time where we have for instance uh once again uh the action name and we have the service so these are the things that we actually uh have have added by ourselves and this is actually very very nice because uh let's maybe just run the application again to just have a little bit more logs in there and show you exactly what why this structured logging is actually important so let's run the application again okay it starts let's execute this execute we have our results we can just close it we don't need it anymore so we can just switch over to seek again and let's do refresh and we see that once again we have some other type of information and in this case we see that for instance we have this ellipse time which is 5 milliseconds and now for instance let's see how this actually works because we have here the option in seek and in virtually all tools that would help you with log aggregation you have this option to like write queries to just filter some specific log logs that you are very uh interested in and let's see for instance that i would like to well see a little bit uh how the timings of of my service is and i would be or i would say that um well maybe four milliseconds for the service would be okay but everything that's more than four milliseconds it's actually not okay anymore so i want to get any logs to see if there were any cases when the service took more than four milliseconds and this is actually very easy to do now that we have structured logging and that we have all our properties that we have added actually here in our json that is readable by the machine we can simply say here elapsed time we have here ellipse time i want it to be greater than four and let's run this again and you see that right now i just have only one log because we had only one single instance where this uh service took more than four milliseconds and this is really a very very simple query and this video should really not be about how to make such a complex queries or create more complex or advanced queries for seek that's something that uh well we can do when we will have more complex applications but this already shows us how important actually this structured logging is because once we have our properties and when we log in a structured format that is machine readable in our tools that we use to actually aggregate logs and search logs we can then create such criteria in which we can for instance pinpoint in a very very uh granular way exactly the logs that are of interest for us and without structured logging this would for sure not be possible and once again this is why structured logging is really vital for each application that goes live and it's really important that you log correctly that you log really the important steps that might uh interest you when you're trying to when you try to debug something and that you use structured logging because it will really help you to search to do extensive searches and very very clear um or very on the point searches for exactly the things that are of interest for you in that moment yeah that's kind of it about structured logging as i said it is really not complicated for us in the dot net ecosystem because at least in asp.net core as said the microsoft extensions login already supports out-of-the-box structured logging and most of the third-party logging providers also support structured logging so the only thing that we need to do as developers is just to stick to these conventions where we specify here our property names in curly braces and then we have to actually provide an object array and we have to provide objects that would be actually the values for the placeholders that we have defined previously in this exact order and this is really important to note we have to stick to that order that we have used here in this text we should also for instance use here when we provide the values and that should be it if you enjoyed this video please feel free to share it with your colleagues with your friends on your social on your social networks wherever you might think it might be useful or reach at least people that might be interested in this topic because as i said from my point of view for production applications this structured logging concept is totally vital you you can't really uh well maintain an application without having proper structure logging also hit the thumbs up button if you enjoyed that that would also really help others to also discover this video as soon as possible and if you didn't subscribe to the code wrinkles channel then please do because we try to create really content as often as possible at least twice a week so if you want to keep up to keep or to be up to date with everything that that we create here new uh mostly on the dotnet ecosystem then um just subscribe and make sure to also hit the notification bell that you get notified whenever we create something new and if you have any questions if you just want to also jump into a discussion don't be shy and use the comment section below i would be more than glad to get in touch with you and really start the chats there so that would be also very very appreciated and awesome if you if we can really get to talk to each other once again this being said thank you very very much for watching and until the next time i wish you the very best

Channel: Codewrinkles

Views: 1,776

Keywords:

Id: 8rRQzcbn36o

Length: 24min 49sec (1489 seconds)

Published: Wed Nov 24 2021