 We're good to start No, all right. Hey everyone. My name is Michael I know it's like last last election of the day. I know you probably must be tired. So I'm going to try and keep it short and well, I don't know about entertained but with high energy so as I said My name is Michael. I work in the conference SRV team back in Sydney, Atlassian And I want to talk to you talk with you about logging But first of all just I kind of want to get like the feel of my crowd Is there anyone here who never used logging before and I mean like the standard of library logging model It's like sort of like Okay, no, no anyone here that Tried using log log in and just going to stack overflow and like Copy and paste until it works. Yeah, okay. I got one. I got two and three cool and Again, I guess some of you also like fall back to print when it stops working as well So my My goal today is not to try and cause you to stop using print I think like print there like there is space to use it And especially if your application is like focused on outputting data to you to your user through the terminal but whenever you start writing any demon services or applications that run in background and you need some kind of a Feedback either for you or for your developers. You probably want to start thinking about logging So Again, this is like this is why why do why do I care and why should you should you care as well? I I'm not a developer. I'm I define myself as a system administrator operations guy basically SRE is like a glorified the system admin in my opinion and When problems strikes in production Logging is my first go-to, right? It's usually that usually I have only login in place and debugging problems Good logs and bad logs make a world of difference basically So I care deeply about this and I think that you as an application developer you should care about the deeply as well because Essentially your application is not only what it does like the thing but also how easy to operate how easy to to observe what it does and if you only I don't log stack traces when problems break when things break I have really Tough time to try to debug it So unless I don't know maybe somebody here within the embedded world, which is like makes this much more trickier I think everybody should should think well about their login and how they Make the job of person who actually debugs the problem a bit more easier So Obviously, can't be just use print. So like I said, I'm not saying you shouldn't use print but Whenever you need to let's say you need like a different verbosity level So you have like a CLI tool and you need to have like dash dash debug or dash dash verbose Logging makes it much more easier than writing your own customizing your customizing your output format And actually making it customizable by your user login makes it much more easier Contextual logging so let's say you have a web server like I don't know something like fast And you have a request coming in and now this request causes like three or four different log events with login You can add like a context to each log. So it will bind your Your log event with the actual request so you can understand the context of your log and It supports multiple destinations as well. So let's say you want to log your errors to your error file And you want to log your regular? I don't know access logs to your access log file Again logging makes it much more much more easier and it provides pretty awesome Configuration mechanism not only for your stuff, but also for your dependency stuff. So I will show it as we go But it's something like which is always kind of people miss miss this point So Like I said, Python standard library. It's pretty mature since 2003. I never used by simple three before So it's pretty mature. It's inspired by look for Jay from Java I say inspired not not just copy copy pasted. It's much more compact I think it's maybe three files and like three thousand lines or something like that It's thread safe. So basically if you walk from different say different threads They won't overlap each other it provides common interface for configuration and that's we'll see it as we go and often been blamed for being too complex non-pointonic and a lot of staccato flow questions Why why doesn't log white log twice and so on and so forth? So there's three parts. I'm gonna talk about the basics the I guess they just like the basic steps that you need to Just start logging and then I'm going to talk about How do you log if your library or application have multiple models and in the end? I'll also include the more advanced stuff that I think is like where is Logging really shines and presents itself So everything starts with logger But I say logger. I mean logger object You can think about logos as those channels where you put your information in and in the end They will emit some kind of Amid that information to some destination to define and this is a simplified view of your of your loggers there is a on the top there is some kind of a basic level Filter and there is a bunch of handlers that you can attach to it all of those components are Optional so it's totally possible that the logger will be completely naked without filter and without handler And I'll I'll talk about what happens in that case a bit further on So sorry about that Okay, yeah, so this is a basic snippet of how you Initialize logger and start logging Just for wines. I guess you import logging you use the get logger call to get your logo your channel You give it a name in my case. It's my app you set some kind of a level to it and At the handler and that's it. You're ready to walk. So logger exposes Those I guess interfaces to log in there is a number of built-in levels debug info warning error critical exception And you can define your own but I think it's very rare. I never actually saw anyone define their own There is also if you if you see in the logger.info call there is like Templating built in into the logger calls. You can use your own like format call or you can do that This is a bit more optimized because the formatting will actually be done only if if the level is Is just right so you will kind of you save few CPU cycles The levels themselves are thresholds Okay, so they're not so if you set your logger to be Debug level it doesn't mean that you it will only walk debug it means it will log debug and above and Like if you set it to error, it means that it will only log error and above so this is like one point that kind of sometimes people miss now handlers Handlers are what it's basically what makes Your it what it meets your messages to different destinations And oh by the way, I totally forgot if you guys have any question, please raise your hand You help me because I totally forgot. Sorry Nervous, so any question keep like no problem at all So This is the handler Again, it's a simplified view. I'm meeting few details Handler have a level as well just like just like a logger, but it's a completely independent level, okay It has a formatter, which I'll explain above Next and it has some magic this magic can be anything from writing stuff to a file writing writing stuff over network to your I don't know some syslog server Sending emails Sending stuff to console and so on so And the format the format errors are what defines like the format of your output to that destination So if you think about okay, I'm going to I'm going to write stuff to file Formatter is what actually will define that format of of the information that will be emitted to file So you can just you can just define something like some simple line format Or you can go crazy and maybe do stuff in Jason for example, right? So format errors are the way where you're going to define how this information is going to be serialized The format error itself If you can see it uses again uses a templating Format and the The attributes that I use that there are you actually attributes that Exists in the Logger in the log object. So basically the log object is what created when you call your logger with info dot error And so on there are plenty of other attributes I'm not going to show them but everything that I explained is in the dog. So you can take a pic In my case level name is your logging level. So if you do Logger dot info that will be info here Name is our logger name. So in my case, it will be my app and message is the message that we passed And also if you don't default define your format error, there will be always a default one, which will be pretty ugly Right and Python comes with Plenty of built-ins built-in handlers I'm going to just focus on those four I think those are the most important one Others they do have in my opinion, they have a place But if your application is like I don't know running in real production environment You probably already have some kind of a logging pipeline set up You probably have some I don't know log-stache agents running or Some log shipper that takes your files and shifts them to some place else and you don't really want to Slow down your app with rotating files or sending emails probably not sending emails So in my case in our case trim handler is basically for your console standard standard error standard out file handler for writing to file files now Handler is a special handler which just drops everything and we'll see why it's important and I'll mention q-handler and q-listener in the end So with that knowledge, I guess in mind we are ready to I guess use multiple handlers and It's it's a bit a long example, but there's really nothing to it. It's just like I doubled everything We still have one logger in in the beginning We have two handlers So we have a file and we have a stream handler, which will log to our standard output We have some kind of a basic formatter which I use in both handlers and then I set I set levels But if you notice I set my levels I set my logger level as debug, but my handler level as error Right and then I just add at both of those handlers to to my logger So what happens here is that my console will get all of my info of my messages But only my file my error dot errors dot log will get my errors messages And this is already kind of kind of cool because now you can you can you can have your errors log and When you when you need to like your your user reports to you a I got a problem Ask him to send you to send errors look for example issue error errors are very are very useful in that of course so Very very easy to implement if you're going to try to implement it without talking probably will take some try and effort So that's that's basic basically. This is the basic part Second part of it is yo, yeah Yeah, of course Yeah If you only have stream So the question is if you have your logger set to debug and you have only one handler and that handler set to info Does it makes the debug messages go away? Yes Yes, if you only have one handler, yes I'm going to go back to this There's a slight edge case why I thought for it for a second There's a slight edge case what happens if you have no handlers and I'm gonna come back to it in the end Yes, oh Yeah, so so that that yes, I don't set the logging level for STD out So basically if the handler does not have any any level everything everything goes in so It's just accept everything. That's a good point. Thanks So multiple files I guess so one thing that is super like I Think I think it's not The dogs don't put enough attention on this little is that logging is is basically have a manager it It create when you use it and you create your loggers You basically you register it to a common manager that Share states between all of the all of your models and under the same process So what it means is that let's say you have a main py and your I don't know api py and Main py is your entry point, right? It's your I don't know This is where your command line comes from if you define your loggers in main py and then you're going to call Get logger from some other file with the same name. You'll get the same object Okay, so You don't need to pass loggers between between your models. You can just call it like this right, so this is one point that We need to keep in mind as we go forward But yeah, just if you take anything from my my presentation, I just take this Logger hierarchy so we can easily replicate our Our model structure by using this common pattern. This is this is what is recommended in the documentation So dunder name and you'll get if you do logger get logger dunder name in every model of your library You'll get basically a nice structure where every logger actually I guess Goes together so basically we'll get something like this, right? So this is the the blue boxes are all loggers and we have our files and we're going to replicate our package This is not only for for aesthetics. There is actually some power behind it But before I go into this one small caveat that you need to remember Dunder name can be dunder dunder name can be equals dunder main if your if your file is your entry point Keep that in mind because sometimes you suddenly like you will change how you execute Your programs so for example, we saw nice nice presentation about entry points when you will use entry points Everything will work just fine because name will be actually your model but if you if you're going to If you're going to call your program with just Python and your model name This will change to main and suddenly you won't see your logs. Okay, so keep that in mind if you use this This pattern your log suddenly can just go away and like what's going on This so this is the reason So like I said, this is our structure. It's all nice and cool What this structure actually allows us is to a feature called Propagation, okay, so basically what happens is if we have our my app dot cli logger And we do and we submit submit some kind of message to it This message is actually going to traverse the entire tree of the loggers Okay It's a it's a it's a nice feature, but it will probably be responsible for I don't know Maybe 60% of the question on stack overflow and the reason is because a lot of times We set handlers on multiple loggers in the in the tree in the Propagation tree and this is why we have multiple multiple lines of output in our logs in console and stuff like that and This is because of propagation. It is possible to disable it. I don't think you should but there is a Parameter called propagate equals true false you can disable it but The real like I think what you really should do is you should set all of your settings on your base logger and Just keep it there and this what what it will mean is that your your log message here So we won't have any handlers defined here and your message is going to bounce down It will get some kind of handler that is applied on my app will emit your information to learn a console to your file and Go go on and usually root doesn't have any any handlers. So you shouldn't see anything here This is This is the most I guess Powerful thing because now you can you can Set different Settings different filters and I'll get the filters in the in the end on on per per module I guess granularity But you usually you only want to set it on your base logger, which in our case is my app So this is propagation And there's another interesting effect, which is the like okay, what happens if you don't if you don't set levels Right So let's say you have a you have a logger level, which is debug on your base my app logger and you have No level set which basically is called no set You have no level set on your my app CLI So basically what happens is that the logging library will traverse the tree until it find the first level And this is will be your effective level in this example its output is 10 because internally the Level level 10 is debug in logging. So this if you combine both of those Both of those properties. This is what you need to remember if you do use this pattern of thunder name You should usually set your loggers on your base logger of your application Unless you have really good reasons to also add some other handlers on on your I guess children the children logs So That's that's that's what you should do when you have multiple logs multiple models and you and you want to do not really nice login and The last the last part is about basically mixing everything up together and seeing What else we can get from logging. So this is an example of how you can also control Logs of your dependencies. So let's say that everybody uses a request nowadays I think request underneath uses your a lib your a lib free to to do a lot of the stuff and Let's say in our case. I want to see what's going on when I do When I do request that get to google.com If I if I'll if I Configure your web your a lib free logger to level debug and just set some nice format or do it It's very easy to see Okay, so I see there's like for That I actually I actually see the logger name. So the left most column is your a web connection pool This is the model where the Where the action is being done. I have my level which is debug and I have some kind of a message string which Pretty much explains to me what's going on This is super super super nice because let's say you're walking with stuff. I cast you alchemy or I don't know bottle or any other big library and You're hitting wall and you don't know you don't say what's going on this can this can help you understand What's going on and not only like you don't need to even do it in code because you can actually Give this interface of configuration to your users I'm not going to show example how but if you look for logging dot config, which is the configuration model which allows like more File-based configuration to your logging you can pretty much Have your sysad means or whatever whoever runs your applications to enable logging of Dependencies that you never gave gave possibility to do it. So this is super super cool and and And you should definitely take use of it now if you want if you want to enable your your Library users to do the same thing. It's very simple. Just use log logging and Document document your base logger name. So let's say again if you go to my app Let's say your your application. It's called my app put it in your documentation under the login section Hey, if you want to use my logging, this is the this is my logger name and and and maybe like a snippet of how to enable debal go logging and you're you're good The other thing that you should definitely do is to attach this special now handler to your base logger The reason that you should do it is because Python has the logging model has a very special Special behavior when it comes to what happens is there is no Handler set at all. Okay, it it changes between Python 2 and 3 and oh by the way, I totally forgot This all other examples here are Python 3 Python 2 is kind of dead to me, but it's not It's not There's no there's no breaking conflict breaking Compatibility change just free is a bit more nicer to use but everything I did you can adjust to Python 2 so What happens if? There is no handler set at all and you're trying to log will change in Python 2 You will get this cryptic message saying no handler set blah blah blah And in Python 3 there's two options if you if you if your log message is info or debug you just won't see it and in if it's warning or above you will see it in in In your in your standard error with just the default form order so if you're a library author and you want to give the the power of like Setting loggers and seeing your seeing your internal debug logging make sure you always set no handler on your base base base logger And obviously you shouldn't like you shouldn't enforce anything else like don't try to Log on default because they're just not they're just not nice So and last last thing I want to talk to you about is filters filters are a bit of a confusing term because they are much more powerful powerful than just filtering filters are available in both handlers and loggers and They basically they have two options either they allow you to create a more fine grained Logging so let's say you want let's say you want to have debug and info log messages in standard standard out and Warning and above in your standard error with With the current tools you can't do that because you basically because it's threshold base system you will your Your standard out will include both errors and and the regular messages so filter allows you to create those kind of rules and also they Because the way they work they actually receive the entire log record so they can manipulate it so Here's the actual how logger and handler looks so we also have this another layer of filters So it can be one or it can be a couple and the same thing for handlers And here's a quick like simple filter right it can be a callable it gets the record And in our case basically this filter if you attach it to your logger or handler It will pretty much just drop everything but info messages But the more important like the more nicer use case is I guess this and I'm sorry like I Try to bring better example, but this is what I had in mind. I had to share it if anyone here use flask Okay, five six people cool so fast has the concept of context request context Basically, you can store variables in the context which I Connected to the same request incoming request so using this functionality and using logging you can you can do basic contextual logging so in my case We just check are we in a flask context Box so basically do we have do we have context if we do we try to get Request ID from the context, okay If there is great if there is no we generated one we generate one and we store it in the context And in the end the most like important part is we store the the request ID inside of the record Okay, so this this Gives us basically if we format it correctly We will get in our logs also the request ID of our of our log So we can connect between the error in the actual request that we had and this is This is very powerful because if you have like a hundred request minute and you have an error Okay, well like which which request was was the because of that So this is this is the coolness of filters Do I have few more minutes I guess I'm already like 30 minutes now so Yeah, so I need just like two more minutes. I guess just few few words on performance There is this nice method code is enabled for Use it if you have some kind of an expensive logging So let's say this expensive function will take I don't know five seconds and you only want it in debug This is the two you should probably like this is the gate you should use to to stop it from Do this expensive commutation Don't try and create Logger for far no every request or some unbounded unbounded number of things like I don't know Logger for every user or logger for every request or something like this because they are stored in this gen in this global state They won't ever be garbage collected because of that. So you just run out of memory Handlers they I think all of them except for the Q and list and Q hand on Q listener all of them are blocking So let's say you decide to send email message from your logs For some reason you have a network issue and the SMTP server never respond your app will block Sometimes it's good. Think about I don't know your your logging Auditing stuff you're logging like user purchasing or registration. You want your system to fail because of auditors So you want to block until you actually write it to this for something If you want to unblock it you need to probably check into Q-hander and Q listener. There is a very nice couple of examples of how to use it so you basically create a queue and you Send your messages into that queue instead of doing some blocking call And yeah, and that's that's pretty much it free resources that you should probably be aware of The last two this is like the Python Python docs. They got Much much better in the last few I don't know years I guess but it's it's worth taking a look especially the the cookbook and the tutorials the first one is actually the blog of Vinay Sajib. I hope I say his name correctly. He's the creator of logging He got some really good logging blog posts about like decisions behind why they made stuff this and there and And that and if you're curious you should definitely check it and Yeah, that's it. I'm think I'm done. You guys got any questions? Yeah, you like you mean in In your app so my prefer yeah, my preferable way is to is to is to raise The right I guess level to my to my problem. So I I try to throw errors when it's really an error so It's very easy to get in situation when you have like, I don't know your erog is full of errors and Exceptions and those are like normal exceptions, but for me Exception is not normal. Like it's an exception. It's by definition shouldn't be something that my log is like full of them so I use I use the levels in very Cautious way. So if if tomorrow I'm going to Say, okay, I'm gonna log only errors. I want I really want my my logs to be clean of them Okay, so I don't I don't run Production in debug mode for that say debug mode for me is for the development local development and I don't know warning and above or my own Critical or sorry error and above is for for pro Is that the answer to your question? Oh, you mean you mean you mean the okay? Okay, you mean the warnings the warnings model, right? Okay. Sorry warnings model I think are really good to like if you want to mark something as It's going away or it's not going to be supported in the next version or like because then you actually like it pops up into your console whenever you start using that so like This is this is my use of warnings, but to be honest, I never really used it. I never like again. I'm not coming from the Writing code for for living a more of the person who operates that code So I never had actually used warnings in myself, but this is this is from my experience. This is how I saw it used So, yeah Yes, oh, sorry. Yes I didn't like just for the video the the last question was about the warnings and the how they compare to the login model Yeah, you mentioned log shipping before I I guess when you you wanted to sort of write out to a file and then and then You know use log stash or something like that to actually go and ship it What's your view on like it seems a bit wrong to actually go and format the file out and then you gotta I'm past that thing back in to sort of get it off to elastic or something like that Yeah, it's like a structured thing. So what's your so I when I prepared my slides? I really wanted to talk about structured logs Sadly just like too much information to cram. I definitely so Okay, there is the thing like there is no like perfect solution I don't want to say. Oh, this is the way you should definitely do it Okay, if your application is like, I don't know your personal script that you run on some VPC Obviously, you're not going to run work such for it. So I don't judge anyone who does other stuff but usually in prod you You want your logs to be already structured like we have in the last five years. We have So many awesome tools to process log Log stash all the elk stacks or elastic search log stash kibana if if nobody if somebody never heard about them You should definitely Google those crazy crazy powerful pay tools like Splunk and Dozens of SAS products that helps you with that. So you should probably Your logs should already be in some structure like Jason or I don't know If you want to optimize probably some kind of a crazy protobuf Usually Jason and then you get like two benefits. First of all, your log is already kind of like self-documented. So Let's say you have wine this request failed blah blah blah if you if you input if you output it instead as Jason and you say, okay success falls URL this URL error code 400 When when you read it when you read it, you can actually like understand what's going on and you don't need to do any regs parsing for it and You know crazy stuff like that because you have number of different developers that work on on that application they They they they put crazy for they put like different formats like to different errors and trying to like figure that out after it It's really hard. So you should really you should really output your logs as structure But only when the time is right. Don't do it like for your Script, but you use a formatted for that thing. Yeah, yeah, I would just I would just use like a Jason for matter There is no there is no built-in Jason for matter, but if you like search github you Find the dozens of implementations This is more of a comment than a question But you can also because the Python logger is global you can actually One of our applications We set up an admin panel where you could actually it parsed through the loggers and you could actually change the logging level Dynamically as it was running so that if you're having a particular issue You could actually switch on debugging for particular parts of the application and then once you've got enough You can actually switch it back off again. So it's just something to be aware of that you actually can do this sort of thing with the logging module And it's really powerful. I Yeah, I only learned about it like last week I was reading the logs because you know when you prepare the slides you want to like really know yourself and yeah, apparently That's true. And that's that's awesome I want one more thing I guess is worth looking for there is a memory handler Which I didn't speak about but it's kind of can be useful as well If you if you just tweak it a bit you can create let's say you can create Logs where you add debugging for only only whenever error happened And they never been reading as log if everything is okay So there is some like it's I know that it exists in the log for J2 or maybe one as well It doesn't exist built-in in the in Python But it's something really cool that you if you like you want extra debugging phone error You should definitely check my more handler and adjust it Yes, just asking about the file handler in past lives Sorry, so in terms of the file handler Do you know if Python keeps like an open file pointer or if it keeps a position in the file or if you can muck around and cheat and do things like truncate or empty the file out from under it and Will it you know get up seat at you. I have no idea Sorry You caught me so maybe just to expand on that then if if because you said it's better to use the file handler rather than the Rotating file handler because they block and performance. I just don't want to risk it, right? I mean, yeah So how do you manage the size of that? I like okay in Unix you have so many small tools to like do the actual rotating like I Sorry, I have like a brain freeze right now But you have like a dedicated facilities from the operation system to handle those like log rotate exactly or Usually a lot of times like if you in system D if you use it You can you can just stream the logs to standard error standard output It will take care of your logs or rotate them It will take care So usually I just leave it to the operation system of some kind of a demon that runs and do it for me just because I don't want to burden my application with this babysitting of logs So is there any valid use case to set up the root logger handler? So I Guess if you like if you want to see everything Like let's say you have like now application. You don't know your logger names, right? You didn't find them in documentation if you're too lazy You can just set handler on your root logging you'll get everything it can be scary But then you can start like if you set your format error and you like set the logger the actual logger names Then you can see okay. I see I have this and this in these loggers. I can now Make them more Fine-grained I guess so I think this Valid use case another valid use case I Usually to to deal with some kind of Misconfiguration I think so if you if you have a library that didn't configure now handler and They now they have like let's say critical errors critical logs And you want to stop them and you don't know what is the like logger? You can just go to the root handler and just kill everything right? This is another but usually I Don't I don't see reason Except maybe if you have like a basic very basic application and you don't want to deal with all this madness You just want to start logging you can just start using root without Like without giving names without anything and this is another valid case. I guess so it's it's really I don't think there's like a The right way it's just depends on your case case by case I guess awesome. Thank you Thank you very much from you guys if Like if I have any feedback Please like tell me good stuff and especially the bad stuff because like this what helps me Get better. So thanks