Django Logging for Wagtail

Speaker 1: Great, so I'm here to talk to you about logging. Oh sorry, hi, I'm Ryan. Uh Ryan Sullivan. I work at uh Wharton Research Data Services, a department at the Wharton School of Business, where you are. It's exciting if you want to wanna come work here talk to Tim. Um and uh we use uh Wagtail for our website. We use Django for a lot of uh different aspects of the War uh Wharton web presence and something that uh has been interesting to me is logging. Um I really love the idea of having a straightforward way to get all of the sort of console messages into a um a a controlled environment just so they're not just streaming across the console.

Speaker 1: And logging provides that, but I find that uh logging isn't used as often as I'd like for it to be. Uh I don't even use logging as lot as often as I'd like for it to be too. Um I too am a liar, sorry. And uh so I I decided a couple of months ago to start um really focusing on how can we use logging better uh at Words and um The result of that is that we have used logging to make our Wagtail lives easier and I wanted to show you. So There we go. Okay, so um logging. It is uh the process of cutting wood and taking it to a sawmill. Okay, it's also not this. Okay. So uh it's a means um of tracking events that happen in

Speaker 1: application. Um you could write print statements obviously, or you can uh use the login framework. One way to use the login framework is is to simply import logging and uh then type in logging. warning. And while that will work, it will only get your message out to the console. So it's better than typing print, but that is about as much That's about it. Beyond that, a better approach is to instantiate a logger object, which you do by calling logging. getlogger. uh and then with your logging object or your logger object then you uh you can call a number of methods um info, debug, warning, error, etc. And I'll just pause here to really point out this. Before I do, how many people here are familiar with logging?

Speaker 1: Excellent. So I don't have to do too much of this, but this I think is so important. These two lines should go at the top of every single method, or sorry, every single Python File that you write. And you'll import logging that will get you access to the logger. You'll create a logger and you'll create the logger by name. And by creating the logger by name, you will Have a logger that's named the same as the package name of your file and that way you don't have to uh overthink uh how to create your logger. There are two types of logging. There's uh audit and diagnostic logging, and then there are sort of metrics logging. Um audit and diagnostic is really the the

Speaker 1: area that the Python logger is um intended for. If you're looking at doing something like um metric logging or sort of tracking things that happen in a way that you can aggregate that information later. The Python logging framework isn't necessarily for you, although there are ways that you can do that through the logging framework Um why logging? Um it's better. I don't have a great I don't have a great um example of of I don't have a great uh talk about why you necessarily shouldn't be using print statements, but I can tell you that there's no way for your user to turn them off. So basically what you do if you're writing code and you're using print statements is at the end of writing your code, once you get everything working the way you want it to, your only option is to delete or comment out those print statements, and that means that nobody else can use them.

Speaker 1: So if you use logging, then you can just turn off the that level or raise the level of the logger for the statements that you wrote, the logging statements that you wrote when you go out to uh When you when you ship your code and that way other people can use your log messages to sort of sort of see what you were trying to understand as you're writing your code. So message formatting, it's really nice to be able to get context around your uh your log messages when you're reading them, and you have no access to that if you just use print. Whereas if you use logging, you have access to all the context that was uh there at the time that your log messages were written. I'm glossing over a lot, obviously. So just a quick met uh

Speaker 1: just a quick walkthrough of Python logging for anybody who didn't raise their hands. Of course, half the people here, this is an advantage. be very familiar so understood guilt good quickly. Loggers are your interface, the logging framework You get a logger by name. The logger's name generally matches the name of your package. That's very important. I just copied the text from Python's logging documentation because it's fantastic. You have logging levels. The various levels of logging are the way that you control uh at runtime or basically at runtime, uh what you will see in the console or what you'll see in your emails. or what you'll see in your log aggregation service and so forth.

Speaker 1: So uh the levels uh go from not set, which nobody uses, Through debug up to critical, the ones that you'll generally find use most often are going to be debug info warning and error Um errors are things that stop your application. Warnings are things that people need to know when your application is running. So basically administrators that are running your code need to know when it's running. Info is just uh anything that is meaningful as the application is running but isn't necessarily a call to action or uh you know an alarm and then debug is only stuff that needs to be looked at when somebody's debugging or trying to figure out how your application is working or why it isn't working So log records. A log record is the object that's created when you call a method like logar. info or logger.

Speaker 1: debug. Formatters, they format your method, uh sorry, your log records and turn them into strings usually Here's an example of a formatter. You can get as crazy as you want. Obviously, there's a lot too much or there's way too much information there. So I don't recommend that. Handlers deliver messages to consumers. And your consumers can be, for example, Stream Handler, which writes the console , admin email handler, which is the reason that you get those annoying messages. just from Django when you mess up your code. Um take yourself off that email list. And then filters, you can't cover everything. But filters are interesting. So using logging in Wagtail information when you need it.

Speaker 1: So this is my code on screen part of the talk. The code is there on the screen. I probably should have muted. that while I was giving the first part of the talk. So the reason that I thought that um that logging was important is that There are frequently situations where I wanted to know more about what Wagtail was doing and I didn't necessarily have that information at my fingertips when I was writing the code. So I just wanted to show you a couple really just three examples of places where I used logging while I was writing Wagtail while I was developing with Wagtail. And so the this first place is going to be StreamBlocks So for example, here I am in a

Speaker 1: I'm just gonna restart the

Speaker 2: bigger

Speaker 1: absolutely

Speaker 2: Yes, thank you.

Speaker 1: Much better. Yeah, great. Um So here is a stream block. Let's see if I can uh Yeah. Um and so basically everything starts through this body block And uh so one thing you can do is override the render method. So here we're just defining the render method and then passing off to um the render method above us. And in between, grab go ahead and logging some information about this stream block. You can do this in any stream block, any stream field. it'll work because you're just overriding the render method and you can just stick logging information in there. So

Speaker 1: if you So here I'm writing logger. debug, some information about uh what's you know the the block that's being logged and the template that's going to be used, and if I go to the console And refresh the page, you'll see that nothing is logged. So the only thing you get here is the server log message coming out of Django. And that's because I have my logging level set to info at my uh at my package. So if I choose to make that big If I choose to change this to debug, now this log message at the debug level, when I view this page

Speaker 1: Will tell me. Well tell me That uh it was going to be uh begin rendering from a body block called body block using a template and the template was standards block screenfill. html That's a very simple example, but you can see how that would be powerful if you really need if you had a very complex body block or were doing some logic inside of the body blocks. This could be really helpful Another example of how you could use this for body blocks is actually a complete hack, but sometimes complete hacks are great. So if you've uh pip installed Django, you can just go straight

Speaker 1: into or sorry pip installed Widel you can go straight into the um into your virtual environment and go into your installed your uh site packages And then just go find the render method on blocks. base uh blocks base. Go ahead and add a debug statement there. And if you do that, and you choose they'll see those. And I'll wait for the server to restart itself this time. I think we should be ready. And render the page once more. Now you'll see that every single body block that was called in order was written out to the

Speaker 1: console and I find that to be incredibly useful because just by looking at this page I don't know which uh which stream blocks were were were called, what stream blocks were rendered. So this is my way of seeing exactly which blocks were rendered and when. And you can imagine that you could write more logging information to make that more powerful for you. Next up, I'll talk a little bit about template tags And in this situation, these are just general examples obviously. So in this situation, uh I'll we're I'm just gonna talk about breadcrumbs. Uh uh in our application, there is a breadcrumb at the top of the

Speaker 1: of the page. That's here And you can see that it says home support getting started ways to use words. And so if you, for example, wanted to know information about how that breadcrumb is being rendered, you could write a log message in your template tag. And then turn that template tags debug to or level to debug Takes a minute. At which point you would see nothing because the demo gods are against me.

Speaker 1: Uh I think this has something to do with template tag with the way that template tags are loaded by um run server and I believe that it means they need to restart run servers. So I'm just going to go ahead and do that. And I have one more example of template tags to show you that's a little bit more interesting If this one doesn't work , doesn't. So what we're going to do then is change the entire CMS package and everything below it to debug. And once we do that, and we're going to go look at this example page. This example page is um Using another template tag

Speaker 1: and this template tag sort of does a whole lot, but it's very simple. It's called the variable picker tag. It actually just makes a call out to uh Thank you. Uh makes a call out to the ORM, grabs some results, and then it's going to log those messages back to the console. And so when I refresh this page, hopefully this will be a better example of template. tags working. And so here you can see, oh look, our breadcrumbs are now our template tag breadcrumb log messages coming out. So you can see our ancestors were a query set, and above it was uh a data page, AHA test page six. And so if we look up here, we'll see data and then AJ

Speaker 1: test page six. And then finally , we're about to look for columns. For a table, and then we got 418 columns back, and that's why we have this table here. It's 418 rows long. We call those rows columns. I'm sorry, we're weird My final example is hooks. One of the most one of the funnest things about putting this talk together was I really just got to spend like a good hour on Google Image Search finding log images. It was a lot of fun. This is called a cant hook. It's like a cantilever hook. It's for rolling logs when you're inspecting them. I don't know. Learned a lot about logging. Um Wagtail Hooks.

Speaker 1: I am honestly afraid to to show you this demo. Oh no, I'm not afraid. I I will show it to you because it's running in development. So this um because I don't want to mess with the production uh uh Zindesk um instance. So here we basically have an integration with Zendesk. Um I know I showed you all these contrived examples. Here's a real one. So here we have this integration with Zendesk, uh, and the integration with Zendesk is itself a um Uh where do we do this? Here we go. So we have these after page create, after page edit, after page copy, after page Delete and uh we're calling this uh this method to integrate with Zendesk, and then through this method we make a whole bunch of API calls in order to synchronize our NOS

Speaker 1: -based articles to Zendesk. And so if you go to one of our editor pages, you'll see, whoa, that's big. Uh there we go. You'll see that we have a knowledge base tab here. And if you go into the knowledge base knowledge base tab, you can see that you can you can basically turn any page into a knowledge base article and the act of saving it will sync it to Zendesk so that if you go to our support portal you'll see all of our support article, all of our knowledge base articles in the Zendesk support interface. So when you save an article here, we want to push that information out to Zendesk. And so So, you know, I'm just stuff.

Speaker 1: And basically what I want to do is I want to save this. So I'm just going to publish it. And if you go back over to the log, you'll see that. So here I have the log message that was written by um By my wagtail hook says start of method, end of method, and that's because I have log messages here called the say start of method. End of method. And the reason that you don't see any other information here that all this is missing

Speaker 1: Because this is dev and I'm not gonna go messing up depth. Anyhow, that's gonna take forever to load, so we're just not even gonna bother. So Django logging. Um how am I doing on time? So Django logging. Basically all of this sits on top of Wagtail's sorry Python's login framework. You get access to Python's logging framework. Really when you're running Django through Django log through the way that Django uses logging. And uh I think it's a it's sort of uh important thing to understand. It's actually um it's incredibly simple, but I feel like it's simple once you understand it. So I just figure I'll give a quick high level of how Django actually implements logging

Speaker 1: and and and why it's interesting. Django by default logs uh creates logging this way so it configures um uh Python's logging interface by using this default logging configuration and it'll give you some interesting things like Setting up the stream handler so that your stuff goes out to the console, setting up this em admin email handler so that you get those annoying emails And then it'll kindly set up for you that no log messages will be displayed to you except for if they're coming from Django or Django server. So if you want slightly more than that You can set up some custom logging.

Speaker 1: And if you set up custom your custom logging on top of Django's logging, you can set up a root logger so that you have control over all of the log messages that are generated by the entire application You can choose to log, you know, specifically from your packages, which is of course what I've done here. I've said I want to log from CMS, CMS being the name of the package and which Uh the the those log messages were coming from. You can have more information about your log messages so forth. I'm going to go straight into this wall of code. This is our login configuration. Here it is in a less terrible format. And so you can see what we've really done here is I've created my own formatter. Um

Speaker 1: and then for the most part everything else is standard except for in loggers I've created this root handler. So this root handler says anything that's not otherwise handled comes in at the info level. And if I change this to uh debug, then I would get uh any debug messages that are generated by any code running in this application. I don't know what's going on there. I don't and finally you can control um your custom uh packages. So here are some tips. If you're going into production, what I like to do is develop uh with debug levels set for all the codes uh packages that I'm working on when you go into production Just set everything to info or warning because you really don't want to see it in production. Rollbar is amazing, or Sentry, or Airbreak, or Elastic

Speaker 1: Stack, or wherever you want to send your log messages to, you can aggregate them. I'm happy to talk about this in more detail if anybody wants to wants to talk about it. But effectively Rollbar becomes a handler in your logging framework and as a result all of your log messages will be created will be s sent up to rollbar and there you can actually do some aggregation and uh and start looking at metrics and for some of your log messages or exceptions, you can send any level of log messages as much as you're willing to pay for. Make your own formatter. I wanted hostname in the uh in the console and I found the best way to get hostname into the console because it doesn't come out automatically from Python's logging is to just uh create a formatter and then use it And so this format is incredibly simple. All it does is uh grabs the record, gets the hostname, puts the host name

Speaker 1: if the hostnames can be gotten, otherwise it just says this exception getting the hosting, puts it on the record, and then lets the uh the message move on. And then the format that I showed you earlier This format, you'll see the very the very first uh format string is host name, so it's using that that attribute of the log. record. Lastly, in WISGI , send your stream to or set your stream to standard air. This way when you go to production. Yep. When you set when you go to production, because you're gonna use Runserver in Dev, once you go to production, you're gonna be using WISGE and this way because you probably already have log rotation set up on your uh standard error or

Speaker 1: on your error log in uh uh in Apache or an Internet or whatever. Uh this way you are getting all of your Python log messages going into that same log and it is automatically rotated in here. handled for you. It's incredibly simple, it's one line of code. Debuggers are actually better than loggers from almost all the examples that I showed you. Debugger, uh using the debugger is actually probably a more efficient way of getting the information. However, using the logger is a way for you to have that information always available to you every time you run the application, whereas with the debugger you clearly have to fire up your debugger every time. So please still log. Here are some resources, Python, Django, and uh uh some

Speaker 1: documents on articles on logging. This one is particularly awesome and I strongly encourage everybody to read it. It's by Peter Baumgartner. He set up, he created Lincoln Loop. Um he says Django logging the right way, and he really does a great job of explaining all of the details of Django logging that you wish you knew um uh when you start. And uh this is a article on logging in the Wagtail framework. Uh sorry, an issue on logging in the webtail framework. called Make Logging Better. I'm hoping to sprint on this a little bit in the coming days because it was proposed a couple years back that logging and Bagtail be made better. More information about what's going on when

Speaker 1: it happens and then more information being tracked sort of as metrics or as events that show changes that were made by users over time that can be sort of audited. There is uh a lot of people have agreed that this is something that we should work on uh as a community and um then there are production priorities and this doesn't get addressed, so maybe we can spend some time on this uh and coming days. And finally, here's a video for you. Um

Speaker 1: We're gonna get this working, I promise. Is there is there time for a one-minute video, Tim? Awesome

Speaker 3: Hey, kid, you want a toy? Uh-huh, uh-huh. How about a bike? No. A video game. Well, okay. You pick a toy.

Speaker 4: Hmm, I want Log! Boy, oh boy!

Speaker 3: Yes, Log All kids love log.

Speaker 2: Log rolls bad stairs, owner in pairs, fits over your neighbor's dog. It's ready for a snack that fits on your back. It's long, long, long, it's long, long, it's big, it's heavy, it's wood, it's long, long, it's better than hell It's good. Everyone wants a log. You're gonna love it long. Come on, get your log. Everyone needs a law.

Speaker 3: From Blamo

Speaker 1: Um I don't