 Hello everyone. Well, first of all, thank you very much to your Python for hosting me. I think this is one of the hardest Conferences because you don't only have to compete with the rest of the speakers but as well with the beach I'm surprised to see I have that many people here So my name is Mario Carchero. I work at Bloomberg I'm a Python developer and I work in use automation if you want to speak about my company or Spain because I'm Spanish or the Python Spain or anything else I'll hang around afterwards So today we are going to speak about login We'll have a briefing direction on why why should you log? How logging works? How can you use it? How do you configure it? We'll do we'll try to do a little Code demo, so I'm gonna be jumping go and forth and then some sample use cases that you can implement on top of Login, and then we'll have some time. Well, we'll try to have some time for Q&A So first of all, well, we can do a full talk on why Logo matters but in brief I see you know I see documentation as the information you give to the rest of the developers when they are coding and I see Login as the information that you give to the developers and to see that mean when your application is running This this is one of the things that we usually don't don't care that much about right we put all kind of Login trash and then when we have an issue we really wish that we had the proper logs so about Why should you use login instead of? For example just printing blah blah blah around all your code First of all well some people actually say that if you have to use a debugger That's a smell that you are not using logging properly and I don't know if you want to go that extreme but Using login instead of printing it gives you a lot of benefits. It's much versatile and comfortable. It's really beautiful how it splits the how you log from the what you log and If you have a multi-thread environment It will work it compared to print which have some issues to it trying to come with all the notes I had in my slides So bear with me and there are more things I promise, but you can check the slides afterwards So how a login look how we're looking works in Python Python Well, is there any Java the poll developer in the room you can put your hands We're this is not the C++ conferences. We are gonna we are not gonna hit you and anything that we respect people This is Python around it. Okay, so if you're familiar with a log Apache log 4. Yeah, Python Was built the Python login model was built with that in mind following that standard So we're gonna see all different elements on on the login model So the first of all is on the login library We have loggers loggers are your main weapon to be able to log anything They just allow you to pass a string and whatever arguments you have with a category You know that this is gonna call the logger object and some log line is gonna go to a String I like to the console or a file, right? I'm going really quickly because I don't know what's next. Okay, so yeah, but it's not just like that So the login model is actually creating a login record Which is an object that is gonna shuffle everything in it and that object is actually what's gonna be locked And you might be wondering but okay, that's an object How is the object actually going to the console to the file? So that's where we use handlers, okay? So we have seen logger subject Like logger logger logger records logger objects. I know we're gonna you are seeing handler hander are the instances That the law are objects that allow you to print things to a file or to To a console and there are there are many loggers that there are many handlers already in the built-in Logging model for example, you can log to a file you can log to console you can look by HTTP You can send things to a socket you can send them via email And I know I'm missing one. It's in the notes check the slides So now we say we are gonna create the logger object We're gonna call info net or whatever category want to log on we pass all the information That's gonna call the the code that lives in the logger class Which is gonna create the log record and it's gonna pass it to the handler Which is gonna do its magic it's gonna emit it with its code and it's gonna transform it into You know, it's gonna shaft it's gonna put it into a file or into the screen And you might wonder but how does the handler knows how to put all this beautiful? Logger record information into a file so that's where we have for matters for matters are gonna mix all the information in that Do you have in the logger in the logger record and they are gonna give you back a string? Okay, so we said we have a logger object We call info or whatever category in it with all the information That's gonna go to the logger code the logger code is gonna create the logger record The logger record is gonna pass it to the handler the handle will call its for matter Which will give you back string and then you can pass it to a file or a function whatever, right? So we know how longer work how logger works on top of all this we have filters We just just spent 30 minutes 30 seconds of them filters are a way to be able to Is a really flexible tool to be able to filter logs in some predefined conditions By default I mean the default logger is not that much useful But you can create your own ones and it allows you to attach those ones to the to your logos hunting your handlers to Filter out some some logos. They do might not want to look So we said we create a logger we pass the information it goes to the code of the logger It checks the filters for if all the filters it turned through cool We we emit the log record that we just created it goes to the hunter the handle also have some filters If that passes then we format the log record we get by the string and we send it out to whatever we decide Great We also have the log hierarchy. Okay, so what is the log hierarchy? So we haven't seen so far. How do we actually create the logger? All the loggers are defined with that Factory function, which is called a get logger and it allows you to pass a string which is a dot-separated Main convention so for example here We can see we're creating parent dot child and what that means is that Here we are defining the child logger, which is a child of the parent logger and and so on if we were to create the Okay, so now we have the final word, right? So we create the logger we know how to and now we log something it goes to the logger Code it goes through the filters if it's all if it's all good Then we go to the handler section, which is we emit the log record goes to the hunters The law but then also if the logger has an attribute called propagate It will go to its parents and emit the emit the log record following again this same flow Will it execute the filter code? No, this is a great pitfall that I have fallen many times So it will just execute this part of the parents So when and what the hierarchy means is that once you have when you log when you call all your handlers You're gonna call the handlers of your parents. It's not that you're gonna call your parent It's just you're gonna call the partners of your parents Also another way that the hierarchy impacts is that if you don't set the level on the logger, it will use the parents one Okay, so we know how logger works right more or less. There is just two more two more conditions I promise this is the final one. Okay, so of that logger's can be enabled or disabled and you have the category Which is sold so on the handler, but this is more or less the whole workflow if you don't trust me You can go to the documentation which you have this this other one, which is it's kind of the same Okay, so we know we know how a logger works, right, but let's see how we use this this huge Implementation of this huge base code So here we can see how can we lock some stuff? This is how you as a developer. We just lock things. This is the what you lock not the how you log it. That's I think this is I Love this way of separating the concern of how you look things from what you like thing. You are usually fine separate them But so we just import login we get the logger we use the name So you can use the name of the model which it's it gets so name is It will give you the full path of the model that you're using. So for example, I said you have project one and then a folder called Folder one and then a file file one. This will be a project one if there are Python models folder one Sorry project one folder one file one So it gives you by default a really nice and bit of your hierarchy that follows your file hierarchy We do we log at the bug. So do we have different categories the bug info error and critical Will we have a debug log that we just usually want to see maybe in our tests or maybe now development server We do actually some execution we cut some exception. We could do a log exception. This is not a new category This is just error but passing X info and X info is gonna log all the information. It has Like all this trace back and the all information it has about the exception so We do this we can do the same with all the categories by just enforce forcing X info to be true and If you're wondering, oh my god, I love this trace back thing I want to see it as well in all the logs from Python 3.2. I believe don't quote me on that You have this stacking for attribute that you can pass when you log, which will also print all this time Okay, cool. Now some some things I wished I knew when I started things I should don't do with login is if you do this even if it's the bug is gonna Format and it's gonna use, you know, this has a competition Computational cost formatting the string even if you don't use it. So just pass the template and then Pass the argument that you want to put in the placeholders if you don't like this kind of string Notation the formatters have different types Half the minutes I have done the minutes Then more Wow, so really quickly If you're doing this, this is I don't know how many Sorry, okay. Thank you. Thank you. So if you're doing this, you probably will see errors like a terrible Terrible her has happened data. I don't know how many times have this I've seen this in in programs So quite quite you quite often you are captioned exception and log in that exception But what is happening is is logging the string representation of the exception which for key errors It's just the key that is missing. It's extremely frustrating So what you probably want to do is pass X info which we saw before and you're gonna see the full screen I'm gonna jump really quickly We spoke a little bit about this Now we know how to use it. How do we configure it? Isn't it beautiful? I'll leave you five seconds. This is how you can configure the whole login engine Isn't it great? So this is the basic. This is one of the ways you can configure it You have all those parameters my default is gonna print to to console But if you pass a file name, it's gonna it's gonna point to a file You can go over all the parameters But basically this gives you same defaults if you don't like the same defaults There are two of the ways to configure the login model Well, there are three you can configure it via code like just creating all the objects manually and wiring them you can also Configure it via a Configuration file, which I don't like so I won't show you and the third one is you can configure it using the dict config So the comfy allows you to pass a dictionary with all the options It can get even higher than this I don't know if you have seen the the login configuration on Django That's actually what you are doing behind the hoods. You're using the big config. I Usually use I personally prefer The comfy and I will put this config in a yaml file. I'll load the yaml file and then I pass it to the Cool, so here we can see we are we you can define all the the config for matters handlers and loggers and more in the documentation so I Want to show you That's all I've said is true And I have a demo Yes, because there are not enough technical difficulties, right? So And I have to type with one hand So we are going to just gonna see how how a log line is gonna go through all the code We we explained already so we are just gonna import logging. We do basic basic config We get the logger and we just print it and this is my cheat sheet So we use Python Python 2.4 I'm joking Python 3 Minus 10 pdb. Oh, you don't see that you probably want to see it There you are so Okay pop up on Okay, so what's the first thing we see we are gonna check if the logger is enabled for that level, right? It is because we we have it configure an info and then we go to the inner function underscore log Which has all the interesting stuff is getting the strike info source file pop up on Gets the color info and now we are creating this log record that we spoke about, right? So next next you can print with parentheses because it's Record so here you can see how does the log record looks like? Okay, so it has all the information that can capture around it and also the string and the parameters will be passed We go next have I gone inside? Sorry start again Mason Don't do demo with a single hand Bump bump bump bump bump Next next no, no So we go inside Next next next next next we create the logger the log record here Cool, and now we go into handle which is not the handle class But the handle method within the function and what do we check if the logo is enabled or not and we check all the Filters because they return true then we are gonna call all the handlers, and I'm gonna I'm running out of time This is really interesting. I recommend you do it afterwards I'm gonna put it in these lights, but there is still more content to go over and we have five minutes I promise it will go through all we spoke, but there is no time and I forgot that clicker okay So I see some use cases because this might be more interesting so I'm gonna jump over this one Basically, you can define Multiple handlers something I have on my web is I send to my to myself all the critical errors via email I have a single file with all the error logs because I may want to see in three months What actually happened with the error logs well for the info on the back only available in in in depth I will just rotate them every four days for example, so I keep only for the of looks You can print Jason where do where would we do the Jason formatting in the handler? No in the formatter, right? so this is how you could you could configure application to upload Jason because you know You are on the hype and you know that logs should not be human readable And you prefer to send it to some kind of post processing logs that will do a much better job if they take Jason There's code. I'll try to upload it and I don't have time to do the demo You seem filters to add context if you are over Python 3.2 there is now a factory method you can Configure to capture all the calls whenever a log record is created and you can add some extra context for information If you are before 3.2 Some kind of convention is you can use the field you can overuse the filters to add information So what is this doing? This is using a nice and global scary stuff that is gonna be passed to Like all the logs are gonna pass through here because we saw how the filters can be added to both loggers and handlers and You can enrich it with something and then put it in your formatter Where would you put it in the logger or in the handler if you want to do it for all the logs? Not everyone answering at the same time because I don't understand what you say In the handler we are right because if you do it in the logger it will only happen for the for the parent one right because we saw that With the hierarchy you're gonna call all your handlers and the handlers of your parents But you are not gonna execute the code of your parent okay More cool stuff buffering how many times you have an error you have logged an error And you wish you had only changed that debug log to info right? so this what this Smart buffer handler is gonna do is is is gonna have about it's gonna buffering The the the previews log in this case one and one of it detects an error is gonna not only log that error But also the previous info so you can do for example whenever there is an error print the last 20 Debug logs don't have time for them Okay, so they jump in case you have questions If you want to do if you want to let's say that you want to get only in depth some if some You want sorry you want to log the result of a function only in depth I don't know what you would do that because you might have for example What's called a hasten bug which is that a bug that only happens when you have your logs in the bug? You can use this kind of pattern which is that you create an object that will call your function only when you call a string and That's it take away stop illegal login in Amazon as that was the talk about But not really like the login model is I think it's amazing you can you can build on top of it as much as you want and It's really I love the way the what on the how is is is separated is it allows? All your parts of the system to collaborate on log in so for example Yes, you saw how we did before this thing of enriching the The context of the logger so something you can do if you do that It's not only that your log your logs are gonna log that global scary stuff. Is that also the library that you call are gonna log it So you're really you're really separating the what on the how And that's all we have two minutes for questions. That's my unique has some question Really a huge applause for Mario game because the middle of everything so we have a question here And it seems that the log in the model does a lot as you said what what is the performance impact? So you so actually something really scary is that if for example This is why I say that more or less you can split the the what on the how if you have sending an email This is it depends on the handler but co-op and is everything is happen happen synchronously So it's really gonna impact your your performance if you If you for example enable The bug logs and you're debugging something in a for loop It's really gonna go to the buffer and then to the file or every single duration. So Like don't don't just ignore it. Be careful with login. So it does happen back, but I haven't measured it in normal normal performance Forget the debugging or something. Yeah, so it depends on what you look right so you can see it depends on how much you look But it does have an impact how many milliseconds it's gonna take it depends on for example If you're doing if you're sending an email, it's gonna take longer if you look to if you look to a file How long it takes to look to a file it depends on your disk. So there's another question What's your opinion about to use decorators for for logging? Just like this thing where you put decorators On a function that thing will log when it gets in and when it gets out with all the yeah Cuz I heard that it's a great use case for decorators Logging yeah Yeah, I've seen that it might be I mean depends on your use case I'm worried You know, I really I I personally preferred to write my own logs because the decorators it feels more like I'm dumping this here. So then I'm gonna get the information when I did it whilst I Really like to think about my about my logs I really want to think on you know, I want the logs to tell me a story, right? I want to go to my log files and see I am doing this. I want to see value because When you do the decorator it worked great for today But in six months when you have a problem in production and you see this function name, which is do stuff What was this thing doing right you can still go to the code But if you can save that the person this is this is happening, which might not have any idea what's going on If you can save that step to him, that's really valuable Thank you Did you solve the problem with multi-processing logging because it's always an issue. Yeah, you can you cannot do it That's it I mean you can you would you would have to do like you cannot use the the normal you cannot use Something that is long into a file like you cannot use a Normal handler that will log to a file from two different process because they will share the the file descriptor, right? Yes, but for STD out not for example The problem is they will hmm. That might actually Meh, I mean what I thought that you should before and what I've done is I would log via TCP to another process Which is actually gonna collect all the login Sorry Yeah, so a lot of developers put just everything into a log in for right So just dumb the different variables and parameters. So what one of the approaches to solve this problem is to use? struct logs I don't know if you know the strike. Can you say that again? Struct log so structure running. Yeah, so how is your view on solving this problem so that developer just put everything in there? Do you use structure logging or? So this fragment where I'm logging Jason, it actually comes from there I was shuffling it and then you can propose it afterward and choose what you want to see how do you want to see it? Thing is I usually I'm still maybe old-school using log files not that I like it, but that my environment is what we have and At home at work for example, we just things like splanks a splank and more convenient thing so if you have the infrastructure to Do like strike the logging where you can log Jason and then parse it and accumulate it and whatever you want Go for it if you are gonna do an app at home that they are gonna log files Or even your company doesn't have that and you're still griping through log files You really don't want to read Jason, right? But I think I think it's cool I think if you know what we do today as well is we look into a file And then we parse it if you can if you can save that it makes still sense. Yeah And to your comment on them to your comment on Don't don't have a call that just says do stuff So one best practice I heard was always have at least enough hierarchical naming that you can see what object To your comment that don't just have a logging message that says do stuff a best practice I heard is preserve at least enough levels of hierarchical naming on the object that you can unambiguously see what called and when and I had a question for you and What is the guarantee you can format you can format millisecond resolution on timing? But what is your actual guarantee about the order and the accuracy? Platform level accuracy of the timing and logging messages, especially if it has to ripple up through multiple parents So did you ask if we please did you ask if it guarantees that? Things will go to the file in the same order that you log was that a question in Supposedly it's guaranteed that in a single threaded process you stuff is in order But the millisecond timings may still be inaccurate So what's your level of expectation about the actual accuracy of the millisecond timings? Should you you know what can you trust is it good to the nearest 10 millisecond or 100 or sorry? I'm not sure I understand the question. Did you ask? Maybe the mic Yeah, even if you don't mind you can Talk with him later. Okay, and thank you so much for everyone and another applause for Mario