Django Logging Demystified with Lee Trout

Speaker 1: Good morning everyone. Thank you very much for coming to my talk on Django Logging. Thank you to the conference chair and the conference committee for letting me come and have this opportunity to speak. I am very excited to be here and I apologize for my voice because for two years we've been in a pandemic and I've literally went nowhere. And this is my first trip leaving to go anywhere and I get a cold on the way. So I'm going to try to make it through. I've got some drinks. Bear with me as we we go through here. Here's a QR code, much like all the other speakers do. There's a GitHub URL, GitHub repo set up at that URL. The reason I have that up there is I want your help. I'm standing up here talking about logging today because I love logging.

Speaker 1: I'm not an expert in logging. I'm not an expert in Python or Django logging, I don't think, but I am very passionate about it. And so I'm sure there are more people in this room or at this conference or that watch online that can contribute back and help me learn more about logging too So please visit that URL, open the repo, star it, bookmark it. As I go through the talk, feel free to open an issue. As you go through the rest of the conference, if other talks inspire you, please remember to come back. Like somebody mentioned something about logging. I'm gonna go open an issue in Lee's repo. That would be great. I would like some interactivity through this talk. I'm pretty nervous. I hope my jokes don't fall flat. There's only a couple. But I will ask for a show of hands I will ask some questions. Even if you think the question is rhetorical, if you feel that you have an answer, shout it out.

Speaker 1: We're in the small room, which is great, so I should be able to hear you. So shout out those answers. Is everybody good with that? Hey, that was pretty good. Let's try one more time. I'll put you on the spot. Is everybody good with that? Alright. Thank you so much. You can find me on Twitter. I'm at the CodeWritesMe, because I don't write the code. The CodeWrites Me. On GitHub, I'm just my name, Lee Trout. And I enjoy behind-the-scenes work. I enjoy infrastructure work. I enjoy operations work. So this is no surprise I like logging. I've been working with Django on and off for the past 14 years, and there's times I'm on a treadmill. I learn something and then I forget it. And then I get bitten by something and I relearn it and I forget it Usually it is the ORM, but sometimes it's logging and logging configuration.

Speaker 1: And so the motivation for this talk is that I want to help other people feel like they're not stuck on this learning and forgetting and relearning, at least if you are at the point where you're learning or relearning. Here's yet another voice yelling into the wilderness. Logging is cool. Django logging is great. I think if I could do anything, I would just sit at this table and we would just totally nerd out about logging. Hopefully you have some opinions and ideas about logging. So I'm going to take questions at the end, and it'll be in here or in the hallway, depending on how the timing of this goes. This talk is not meant to be a tutorial. So I'm doing something a little different. I have some philosophical slides. I have things that I hope tease your brain, make you think about something. Maybe I present something you haven't seen before, and it makes you think, good or bad. Please find me, give me feedback.

Speaker 1: I'll be around the conference today and tomorrow. I'm in the Slack, so uh online folks. Any questions that come up through the talk, just at me in the Slack channel, the Salon Slack channel, and I'll respond to all those questions when the talk is over. I'll go find a quiet spot and respond to everything. Folks that are in the room, same thing, grab me on Slack anytime at the Valley Conference. This slides are about topics that I felt were important that you at least hear about it. I'm going to cover a broad range of topics. This may make you feel like I've left some things out. Or you may know something more in depth and you say, well, he's he's glossed over something important. Please call that out in a GitHub repo In an issue in the GitHub repo. The majority of the technical bits in the slides are going to be focused on two things.

Speaker 1: How the logging configuration in Django works And I'm going to spend most of the end of the talk talking about structured logging because I think most people can benefit from working on structured logging if you're not already. This is awesome. Like that keynote was awesome this morning. And there is an XKCD about not making fun of people or laughing at people when they don't know something. There's a good chance you again, I will say this repeatedly through the talk. There's a good chance you know something I don't know, and you know more about something as we go through this talk. Locking there covers so much territory. So maybe you're bored. That just means you're not one of today's lucky 10,000 people that are hearing about it for the first time. So keep that in mind. You know, that this slide's, you know, that slide that maybe bore you is for the person that it's their first time. But with that said, I do think there's something in here for everybody at all skill levels, at

Speaker 1: working on any kind of project, large or small, on teams, organizations, large and small. And my remote is on the Fridz. We'll see if it boots back up. Yes, there we go. So we're going to start with logging in Django. Title of the talk: Demystifying. Django logging. So logging in Django is just vanilla Python logging. So we just demystified the first part of Django logging. If you're done already, you can leave. That's it. It's demystified. Django logging is Python logging. The good news is, much like everything else in Django, it's very nice. I'm going to use the word they tell me to say, it's very good. It follows pragmatic Python. I don't want to say Pythonic, but it does follow pragmatic Python principles, and that's really good. Because it means if you know Django and you know Python, when you go to get to logging, yeah, there's some weird things we're going to talk about, but mostly you'll be able to find your way around.

Speaker 1: It's just Python. To effectively understand logging in Django means you have to understand Python logging. And you know, to add effective logging, I will say, um, you're going to have to learn Python logging. So I talked about this sort of philosophical slides, philosophical ideas. This is the part where I say if somebody wants to yell something out, what is logging? Does anybody have a definition in their head, a word or something? What is logging? Oh, tough crowd. Keeping track of what your app is doing on spot on. Well I didn't miss it. Something with print. Print with more features. Print with more features. Absolutely. Print with more features. So I'm going to share my philosophy on logging, and I'm going to start with this conceptual definition.

Speaker 1: This is going to anchor the rest of the talk that we have this concept. I think we all touched on it. We all know logging as a concept is about recording information. Generally we record this information in a way that we can reference it and we can look back on it. Are there any pilots or scuba divers in here? There's a couple. So pilots, scuba divers, anybody do any activities outside of work and programming where you keep a log, you keep a record. Maybe you cook your recipes. Yeah, so a few people. Not as many as I expected though. Okay, so a few people keep log books. But yeah, we write down events and things that matter. Pilots write in their logbooks. I took a flight. I took a flight from North Carolina to California. And they're going to write down their flight time and the flight conditions. You know, if I flew in clouds and weather and rain. That's important. We look back on that. And we look at the history of what we've been doing, how we got there.

Speaker 1: Logging and broadly observability are about recording those things that are happening within our systems, within our programmings. You know, an event is like something happened. You have this big batch import process. You start the import process on a cron job. So you may just log off, you know, import process started. That's just logging an event. You may log insights. You may say, okay, as I'm processing this huge batch import, I'm at, you know, item 250 of 500. And then if you're like me and you switch between Go and Python, you still forget that when you go back to Python, you cannot access members in a dictionary with thought notation. So your code gets riddled with attribute error. So you know you unexpected events get logged as well. This remote is on the fritz. We'll have to ditch the remote.

Speaker 1: So why do we invest in logging? Why do we log? We know what logging is. We want to capture these things. Why do we invest in it And who are the logs for? So I'm curious. Who wants to know? Why do you log? I heard in production you can't debug. Somebody over here was saying something. Oh did you already read the slides? Okay, so you don't know what happened. Say it again. Let me repeat it the right way. You don't know what happened until it happened. Yeah, you don't know what happens until it happens and you look at it later. That's spot on.

Speaker 1: So at the conceptual level, we're logging for understanding. And we're communicating when we log. Just like pull requests, just like commit messages. You get a lot more value out of those when you put a little more effort into them. The logs are for us. They're for everybody in this room. They're for people that aren't in this room. Logs are at a at a level, again this is the philosophical side, logs are about expressing assumptions. You're expressing your assumptions about what this program is doing. If you don't have an assumption of what your program is doing, your logging is not going to be as effective as it could be Yes, you can blindly log out swaths of data, but it's not going to be as effective as if you have some assumption. You can start to kind of laser focus and say, I want to log this specific thing. So logging is for the person writing the code.

Speaker 1: It's also for the person reading the code. A lot of people, there's you know controversy, oh don't document your code, document itself, code self-documenting. You know, comments get out of date. Logging is one way you kind of walk a middle line there because you're putting in something that's generally human-touched. You know, you have it your opinion, you're putting your fingerprints on this. And it's not a comment. It is hopefully going to stay, you know, up to date with the code. And the third person, because I'm in infrastructure and operations, it's for me, thank you, when I'm awake at 2 a. m. And pager duties went off, and I'm trying to understand what is going on. I have to start figuring out what the systems do and how is it behaving. You know, when you write these logs, when I write logs, especially for my own code, and I support my own code in production. then I try to remind myself I'm writing a log for me six months from now.

Speaker 1: So the gentleman in the back, thank you very much for how you identified logging because I'll say there's a quote from Maya Angelo. I'm going to paraphrase it Knowing where you've been helps you understand where you're going. And that's a key thing with logging. If you log your program's behavior in its state, you start to look at what it's doing. In some cases, and maybe this is more metrics and tracing, which we're about to talk about, but In some cases, you'll start to be able to predict where things are going. You'll start seeing a slowdown maybe. You start seeing more log lines showing up. It may tell you there's more load in the system. So, like I mentioned, this is broad topic, observability. How many people just subscribe to like observability? I do observability. Not that many people. This is great.

Speaker 1: What is a great audience for this? So this is a huge broad topic. Logging is a part of observability. I will argue logging is the oldest form of observability. I think it's the most important form of observability. But if you want a complete understanding of your running, or more importantly, your crashing systems. Then you need all three of these things. You need to have the three pillars as they're called, logs, metrics, and traces. And where we're headed right now as an industry is that a lot of this is moving towards automated tracing. do you know sacrifice some CPU and performance to do this, but you are not going to manually go in your code and add traces. You will go into your code and add metrics as needed. And that's called instrumentation broadly. And logging can do that. So you can instrument with your logs.

Speaker 1: So I'm going to give you a really strong opinion here. Logging will get you most of the way there, and if you're doing nothing else today, the two pieces of advice. Start logging and think about your logging, especially if you're not doing any logging. That's really good because you've got a clean slate. Generally, and I'll mention this again later on the talk. Logs are like tests. By the time you realize you need them, it's a bit too late. So when you make that investment in logging, keyword, I'll keep saying that, invest in your logging, then you will come up with better logs. If you think you need metrics and traces or you're just getting started and you don't want to fool with logging, go get an APM tool that's application performance monitoring. You can look around for those popular ones are Century, Datadog, New Relic. But let's focus our talk back in on logging. So our conceptual definition, I'm going to repeat back out to the room what we talked about, and what I propose to you is that logging is a collection of events.

Speaker 1: for ourselves, both now and in the future, and our teammates, both now and in the future, to understand the state of a running system. Logging is a feature. I don't know. Does anybody on your teams at work? Does anybody consider logging a feature? A couple people. How about testing? Do you consider tests a feature? I see a lot of head nods. Observability is a capability. Logging is a feature. Features give your programs, your products, your systems a capability. So observability. My program, my software, my product has the capability of observability because I've invested in features. features. I've invested in logging and metrics and such. You have to invest in that. So first part of the talk, out of the way, what is logging?

Speaker 1: Let's dig into the logging setup. We're going to spend a bit of time here. To invest in logging in Django means you have to invest in logging in Python. Python logging might be a bit heavy compared to other things you'll encounter in the standard library. It was shock and awe for me when I first got into this. I'm like Okay, how many moving pieces and which does what? There's a few places in the standard library where you're going to get into this kind of complexity and it's like threading and concurrency. And certainly if you have a different opinion, find me later because I still think for anything that somebody's immediately going to reach for, logging is the easiest to get started and the most confusing when you try to do anything with it because it is all the same. event-driven paradigm. From a simplified view, what's going on in Python is that you have this thing called a logger.

Speaker 1: You have this object called a logger, and it creates log records. And log records get passed to handlers. So that's the event-driven nature of it. And then handlers use these things called formatters and they control what the output of your log data does in the final form. So if you're just putting lines in a file. That's a combination tag team of the handler and the formatter that make that happen. But I want to go into more detail because there's six primary components. It's not just those three. That's the overall flow. But I want to talk about each of these components in detail. Every one of these is used in Django logging and all of them except filters are effectively required for you to implement any logging in your application in Django. So let's go. Go through them in detail. I'm going to start with levels. Django

Speaker 1: uses Python logging. Python logging is a leveled logger. So level loggers means that every log record that you send out is going to have a numeric level associated with it. These help convey priority, urgency, relevance. And they're also instrumental in controlling how records flow through the logging system. They all have a name, and these names relate to constants that you can use when you reference different Let me back up. Let me just stick with this. If you look in the logging package, you can see that there's this mapping of numbers to names. You're going to access these names through constant variables. The same names will go into logger methods which we're going to talk about in just a second. So if you want to send an info message, there's an info method that'll do that for you.

Speaker 1: So you're rarely going to interface with the integers themselves, but there's what they are for each level. So as I mentioned, loggers generate records. You call get logger with an optional name to create a logger instance. If you do not supply a name, you get a special thing called the root logger. As I mentioned, so loggers have methods and they generate log records at a given level. This is primarily how you're going to log in any Python program. You can instantiate a logger, you're going to send an info message or a debug message or an error message, you're going to use those helpers. This talk does not get into the logger. exception method. So there is a logger. exception method that you can use inside an exception. And I didn't get into it because you get into A lot of complexity around tracebacks going out to your handlers.

Speaker 1: And so you can read more about that. So I'll call that out right now. I don't have that in here. Something to think about when you do log messages, you say logger. info. You should use string interpolation when you do that. Pylint, who uses Pylint? Who does any linting on their code? You have automated linting? Oh yeah, most of the room. That's great. How about formatters? Y'all use formatters? Whole room. Oh, that's great. So Pilot has a warning, it's warning W 1202, and it just tells you you should use string interpolation. Why this matters is that these make different types of log records. If you consider these two log statements and you're like me, you probably reach for the first one by default. I love the new F strings. I use them everywhere. How many people write logs like the top one?

Speaker 1: Who puts an F string in there? So the bottom one is better if you're using any third-party services that roll up your logs or group your logs or grab your logs, especially Century. Century, this matters a lot. The records that they generate, when you look at the two underlying records, there's an MSG attribute and these these hooks for these third-party libraries that touch on this and they They can access your raw records. They can group your messages because that context about how many items that are going through with your order, it's just percent D, right? So that means every log message looks the same to the underlying. Technology and tooling that's aggregating your logs. You can always get to the args too if you need them, but you you will not need to do that

Speaker 1: The other thing that's interesting about loggers, loggers are hierarchical. So I mentioned that special root logger. When you call get logger in Python, Python's maintaining this for you in memory. There's this whole hierarchy in tree. How many people already knew this? Uh not quite half. Okay, good. So this hierarchy uses dot notation just like import paths. That's super handy. We'll talk about a more in-depth example. But the important thing to know is that everything, every logger you grab will start as a descendant of the root logger. Loggers have a property called propagate. When you're configuring a logger, you can tell it propagate. true or false, if you set propagate to false, that means log messages will not pass up the chain because by default it's event driven. Things bubble up. So this will prevent log messages, is it propagate false, from passing up through these loggers

Speaker 1: Oh, let me go back. I will comment on one thing. This also means if you define two loggers as foo. bar and foo, and those have two different handlers attached to them, you will get duplicate log messages. So that's important too. Another weird thing that some people don't realize, loggers inherit their level, their default level, when you grab a logger. We talk about those levels, like is this an info level, you send the log record at a certain level, but your loggers are filtering those messages at a certain level. Loggers inherit at the default level from their parent By default, that will be the root logger. The root logger's default level is warning. So when you start logging and you see no logs, that's the first thing to check. Who's my root logger? What's my logger level? What's my handler? What's my handler's level? We're gonna get into all that. If you set the root logger level, all descendants, other

Speaker 1: root logger level will inherit that level. So that's really important to understand. Log records themselves contain all the information about your logging event. You generally do not instantiate these yourself. You can there's a make record, make log record helper, but generally you're gonna call the uh logger. info logger dot error and under the hood it's generating that log record object for you. Here's a representational string. I do a bunch of stuff in the IDE. or the REPL. I'm gonna tell you right now, if you all don't do that, you're missing an opportunity. That's my favorite way to play with all this stuff. If I'm wondering how does this work or I forget how something works, I open the REPL and I just start making objects and I play with them. So all these examples have just kind of the string repper of what is this thing. And so this is what a log record looks like.

Speaker 1: And what that's telling you is that I have a log record. It's generated on the foo logging channel. So I called get logger foo. That'll get that. That 20 means it's level 20, means it's info. You also get information about where this logging call happened, which is super handy. So this tells us that it's happened on line 22 in logging basic. py, and the message was hello. So log records have over 15 attributes that you can use to format log messages. You can use the keyword argument extra and you can supply your own extra data and that'll get put on the log record as an attribute. We'll talk about that a lot in structured logging, which is coming up. Handlers are used for setting levels, filtering, and formatting. Here's the default stream handler. So you just go grab a stream handler.

Speaker 1: It'll start any of the messages it gets will dump them out to standard error. There are multiple handlers built into the standard library and they'll help you output logs in various places. So you can use handlers to output logs to the console. to files, to cues, to emails, to syslog, to HTTP, and I think there's like four more. The important thing you should know is by default, handlers run in the main thread. They're running in the same thread that your program is running in, unless work has been done to explicitly avoid that. So be careful with that. You don't want to add delay in your request response cycle with Django applications. You don't want logging from your view to cause some two or three second delay. This is really important if handlers are shipping logs across the internet. it. But most third-party integrations that you would deal with, they handle that for you and you generally

Speaker 1: don't have to worry about it. Filters let you inspect and even mutate log records. The filter method on the filter instance is generally how you do this, but you can also just pass in a function. You can subclass filter, you don't have to. Any object with a filter method will work since I think Python 3. Filters can be added to both loggers and handlers. So if you remember my little simple diagram at the beginning, I had loggers and I said can filter and I have handlers and it says can filter. So what happens when people add logging and they start configuring logging? They'll lose messages later because they added a filter and they forget the interplay of how all these things work. So something to be aware of is that if you add a filter to

Speaker 1: a logger, not a handler, add a filter to a logger, Its descendants will not inherit that filter. So if you start configuring other loggers in descendant namespaces, you will not have that filter. It's another point of confusion. I run into that all the time. The last piece we'll talk about is formatters. Like I said, formatters work in concert with handlers to give you that final output to get your log records out in the format that they need. That's generally a string, but that's not always the case. Brief snippet from Django's server formatter here. This is where the record is mutated to ensure that there's a server time attribute that can be used in the formatted string output. We're gonna go through Django's log in a second and you'll see that. But the most important thing, I was this is my favorite slide in the whole deck. Loggers, handlers, filters, formatters, and levels, by your powers combined, you get Python logging.

Speaker 1: Thank you very much. All this complexity is actually really great though. Um and I do think it's complex. Other people may say that it's not that complex. I think it's very complex, but it's it's great. And it's by design and it gives us a really good benefit. We get this separation of concern that code generating logs does not have to care at all about where it's going. And code that cares a lot about where logs go does not have to care about how it gets its log messages. This is really important. You think kind of like this worst case scenario that can happen is that you grab some library off the internet and put it in your application and start using it, and you don't know, but that library author doesn't know all this. They actually configure log handling inside their library. This is a bad idea. If you're making a library to ship around, you just want to send log messages. Let the consumer deal with where they go. You start running this on your web server, maybe they're logging to a file handler

Speaker 1: and they don't use a rotating file handler, and so they start filling up your disk space with junk logs. Ask me how I know this can happen. Now it's been a decade ago, but this is important. So it's a great separation of concerns and it's a good design. So configuring logging, and I'm a little bit behind time, so I'm going to speed up. Um configuring logging, all this logging has to be configured, and I think the important part of D demystifying Django logging is understanding how Django configures its logging and how you would interface with that configuration. As with everything, the Django docs are fantastic. Logging is no exception. There's three main sections of Django Logging, they're in that GitHub repo. You can find information on oops the overview of logging in Django, the how-to guide for configuring and using logging, and there is a logging API reference which talks about what kinds of log records you can

Speaker 1: operate on and understand the kind of logging namespace of what's inside Django. I'll offer you some advice that I take myself and I recommend to everybody else when you take your first steps with this. Copy the default login configuration out of the Django source code. It's in Django utils logs. Default login config. Copy that and put that in your settings in the login key. And people say leak, the docs explain how to extend the configuration. They don't say copy the configuration. I personally find it easy uh easier to manage all my logging configuration in one place and I want Django to do my full logging setup and I prefer to see everything there. I'm also really lazy and Django has great defaults and it already has a console handler and I reuse that on like all my stuff. So grabbing that default uh logging setup is super handy. Um and there's examples in the docs

Speaker 1: of all this. So as we move through here, I'm going to do a deeper dive really quick on this default configuration so you understand what's going on in it. It's a giant dictionary In this dictionary, it's the the dict config format, and this is built into Python. So this is your standard Python configuration helper. What's really great about this is it lets you configure all of your logging in one place at one time. You don't have to, but that's what it can do, and that's how I recommend most people use it, especially when you're just getting started. Um it's extremely powerful. Because it's just loading it in your settings file, you can actually pass your logging configuration around as JSON. So you can load JSON out of an environment variable if needed. You can load it from a file on disk if needed. So you can dynamically load your logging configuration and pass that around. It's in my opinion much cleaner to do that than litter

Speaker 1: your logging configuration if you needed to load something out of an environment variable. So the flexibility in the config comes at a small cost of its this unusual syntax and unusual resolver as it parses these dictionaries. It has some rules. You always have to go and kind of refer to the documentation to remember that. This is an example straight out of Python docs. You put this block inside your formatters section in this special key with the parentheses that's saying go load this class. Works a lot like Django settings. When it sees a dotted path, it will go and load this class, instantiate it. And then those extra um dictionary elements, those extra items, are actually passed as keyword arguments into your constructor for that formatter. So Django's logging configs copied into our settings file.

Speaker 1: Let's understand what it's doing. When you start running Django in production, the most important logging behavior is that logs at the error level and above are emailed to the admins, assuming you have admins configured and you have a way to get the email off the server. That exceptions are logged at the error level, so exceptions will come out as well. When you're running Django locally or in debug mode, info level and above are reported to your console. And that's anything inside Django. This includes access logs for local development server, which I'm sure you've seen when you do run server. And we can see all this in the default configuration when we walk through that. So if you copy to that over and you put it in your settings file, this is what you're going to see The only thing Django changes from the default is that it does uh set disable existing loggers to false. And that's important because that will keep the Django configuration from potentially stomping on any other

Speaker 1: previously configured logging. So the first piece and you'll see in this dictionary are formatters. Django uses a custom formatter for the development server access logs. We talked about that. We looked at that code example. So you can see they reference server time in the formats. So we can do that because that custom server formatter ensures that server time is available. This is what those formatted records look like in your unrun server. Uh filters is the next piece. Django has two filters, require debug true, require debug false. You can use those filters on loggers and handlers. Uh Django uses them on their handlers and it just prevents things like mail admins from sending email if you're not in production. So if debug is false, it will actually send emails. When you get into the handlers, it's where you'll see these referenced. Django currently has three handlers,

Speaker 1: console, Django. server, and mail admins. Each of these handlers is responsible for controlling the flow of the log records out of the system, and that works in both production and development. This is where you start to tie together levels, filters, and formatters. The most important part we get to is logging. Django uses two logger definitions to control the flow of log records across different channels or namespaces. The logger covering all Django namespaces uses both the console and the mail admin's handlers, and it can do that because of the filtering. Django server uses only the Django server handler. It'll send anything at or above the info level, but importantly it says propagate to false. So that's only going to go to that one and not go out. This is something important about loggers. The keys in the other mappings are just IDs that let you reference that object definition.

Speaker 1: The keys in the logger dictionary are actually the logger names that are going to be instantiated. This is very important. The key is going to be the logger. So when we see loggers Django, this is the equivalent code, logging. getlogger Django. Adding a logging configuration at the debug level for Django DB backends will let you see that SQL generated by the ORM. This is super handy if you don't have debug information available. At some point you may find yourself seeing too many logs or no logs at all. There's a good bit of complexity at play as your configuration grows. It's easy to get overwhelmed if you're new to configuring logging, or if you're like me and you set it up a year ago and you forgot and you come back to it and you start working on it again.

Speaker 1: But you know, I know you can't read this, it's kind of small. Just know that there is a really nice flowchar in the Python docs, and that'll help you debug like what's going on with your logs. Explains how a logging flow works. And if nothing else, drop a print statement in your code. See if your code's actually being reached. I actually prefer raise an exception because I use the uh run server plus, so I throw an exception and in my browser I get that really nice interactive console. You can always drop in a breakpoint. Python 3. 6 or older, you will need to do the import PDB and set trace dance. And the last thing I'll do when I'm debugging logs, if something's not working the way I expect, I'll start doing incremental log changes. So I'll go into my logger and I'll put a very specific logger definition in there And so I may say, you know, Django backends, DB, or Django DB backends and get more specific in Postgres

Speaker 1: and see if I can find a backend namespace. But contextualizing these examples around some software to run a pizza restaurant, you know, when you set up a Django app, either way I set mine up, I have a project. Here's an example project called Pizza Pro. I've got an app called Core, it's got some views. When I go add logging to my views, I import logging, I instantiate a logger, and I use the special double underscore name. How many people have seen this pattern? Okay, great. So that's all the room basically. That's wonderful. So we do that because we're getting our module name. So it's great that we all already know that. It's really great to do that because that means when you go to configure logger definition, you can start at the highest level, the most broad scope, and you can grab any logs out of your Django project. Here we're instantiating a logger at the Pizza Pro level, and we're configuring

Speaker 1: that so there'll be project level logging. Reminder, if you do something like this, you will get duplicate logs. So you can't have Pizza Pro and PizzaPro. apps without putting propagate false on PizzaPro. pro apps. So I see all of a sudden things duplicate. That's why. So just a quick recap. When you create a logger, it's great to use the module's name attribute. Beware this will cause problems if your module is an entry point. You'll run into this with Heroku and other platforms where you need to run a cron job and your entry point, your script runs as entry point. Now name is main and doesn't help with your logs. So in that case, just namespace it for your project. So the last thing I wanted to talk about, and I know I'm going fast and I warned you, it's like I'm covering a broad thing, is you have this underlying configuration.

Speaker 1: Python configuration, the Django configuration, how the interplay works. You're actually going to start writing logs. I think structured logging is a great way to start writing those logs. How many here already do structured logging? So it's about a quarter of the room, would be my guess. How many people that are doing structured logging? Do you use a third-party library? Do you use struct log? Something like that? Yeah. So half of that half about use struct log. With regular logging, you just toss out a log message. This is a great place to start. Uh I I got a pizza order for two large pizzas with cheese and pepperoni. And there'd probably be some interpolation operators in there, but you just log this message. this thing happened. With structured logging, we take a different approach. Start structuring your log messages and the contextual data that you send to support the log message.

Speaker 1: So now we send an order received and items and the kind of the item was a pizza. Structured logs let you express concise events with explicit context to generate log records. These log records generally are easier to transform when they're sending and received, faster to parse when they're received. I think every major logging and analysis platform is going to work fine with struck logs , structured logs. Watch out for sensitive data, too many unique attributes or large payloads. If you start sending all kinds of unique attributes and you're using Elkstack and Kabbana, there's like a thousand uh attribute limit. I forget what how it plays with Kibana, but you will blow out your cardinality if you send all kinds of stuff in there and you'll have to go tweak it. Or talk to your elk stack admin. So be aware of that. One minor caveat when you use the extra keywords, is

Speaker 1: you're like walk out of this talk like Lee said you structured logging. This is going to be great. So now order. received. And I'll put some data in there. You go in there and you go and make a log record and I'll show you what's on this log record, you get this default set of attributes. You have to create something like this extra formatter if you are going to see those attributes. So you start seeing all that logging out, you're not going to see anything but those logging events and you've sent all this extra data. So this extra formatter can pull those attributes off the log record. It's kind of one thing. All that extra information just becomes attributes on the log record. So what happens is before you see things like order. received, but you don't see the information, the context around That. You put that in play or a handler like that, and then you'll see after order received, and the way I you know make my little handlers is just to dump that information out.

Speaker 1: Now you see order received, and the context goes with that. So I'll give you some advice on structured logging and some experiments I've been doing in previous teams and some things to think about. You kind of look holistically at the be behaviors of your entire tech stack and what you can do with logging. Define your events up front, and this is really important with like working with a team. Create a rule for how you'll format these messages. For example, you might choose subject. behavior. Or noun dot verb, so we ordered dot received. You can be consistent about these kinds of events too. You can classify common actions or behaviors. Remember I was talking about you do this big import process, so you can have like a state on the end of this or a suffix. Depending on your logging system, it may be easier to do a prefix, a state or prefix on the front. front. But if I was doing the suffix and I'm processing a hundred orders and I want to know progress and I'm logging out progress, I'm going to send something like orders.

Speaker 1: items. progress. And I'm going to talk to my team and I'm going to say, hey everybody. Everything that ends in dot progress is going to have this schema payload with it. It's always going to have a total count and a current count. And I may have things where can I order progress? And so there's an example that looks like extra just to get some order ID, obviously more context is very helpful. You could even say that as explicitly order ID and not just ID. So these are things to keep in mind as you put your your logging records together. Duration is something that you might want to do. Keep in mind that may work better in a tracing library. On my team, I would document duration events, something like this. Please, for all of your operations people, when you log things with numbers, if it has a unit, please put the unit on the key. Please and thank you. There is nothing worse than looking at log records as

Speaker 1: duration two. Okay? Two milliseconds, two microseconds, two seconds, two days, two hours. I don't know. But two milliseconds, please and thank you. This is an example of what this would look like with iOS format or ISO formatting. And I don't know, you could argue, you know, things you think, Lee, well maybe start time should have UTC on the end of it too. So just things to think about to make your life a little easier. You can start to exploit a consistency to your logging. And it's super helpful. Another interesting pattern, I don't know if anybody does this, the people that use TruckLog probably do this, is that you can let your loggers own the context. That means? It means you can bind data to loggers with a facade class. So you can have this facade that wraps over a logger and just passes through anything that looks like a logger method. So you can bind data on your logger. And you start to get into

Speaker 1: more kind of like functional programming and you do some dependency injection or inversion of control. It may not be dependency injection, but you can have something where I have this bound logger, this example of like a thing I I made up. I have this binding logger. But it lets me take a logger and capture it and then bind some piece of contextual data to it. So now I have a bound logger that will always log a job ID. And then this bound logger, when I call dot info on it, I can say job. started and I know job ID is already in there. And this is in struct log. If you use the struct log library, they have a concept of this and wrapping log. But then what you can do is you can pass logger methods around. So you can write logging helpers that help you maintain this consistency in your logging by just passing in a logger function. And so if I want to log the duration, I just log, I just pass into that uh bound logger info and the name of the event that I'm logging, the x.

Speaker 1: duration. And then you know managing this on the other side is super easy. Since it's already bound, I only have to care about inside these helpers the extra information being the relevant context. So a duration helper, I only have to care about putting my duration milliseconds, my star and end. time in there. So I talked about logging being a feature. How many people test their logs? Two three. Four. Maybe, yeah. Super important. If you make this investment in your logs, test your logs. You can do this with facilities that are in the standard library on unit test. Test case has a cert logs context manager. that you can use. There's also a great third-party library called test fixtures, and they have a great log capture context manager here. And that's fantastic for being able to see that it will pull all the attributes off your log record

Speaker 1: so makes it super easy to test them. How many people are doing type hints in your Python code? About half there , maybe more than half. Fantastic. That's awesome. How many people type your logs? I maybe like one person, me and the other person. That's great. So you can type your logs. You can use a typed dictionary. You could use a data class. The problem is. Yep. And we're almost out of time and so we may have to do questions outside. The important thing is you have to write helper functions if you want MyPy and friends to help you with your logging because the type checking will have to happen on the receiver And so you have to write receivers. Now my team, we experimented with this and was actually pretty good because we use Copilot or we use Tab 9. If you write everything in a predictable pattern, it will just generate all of your things for you.

Speaker 1: So you go to add a new, when I have log progress, you go to add a new log. log foo, it'll automatically fill in log foo, uh foo log context. So everything was very predictable. When you go to use your logs, I don't have to speed up and go fast. You're going to run into stuff where exceptions show up in Century. I just want to touch on what you'll see when you use common software as exception in Century. But I go look in Century at my exception. My logs are captured as breadcrumbs. structured logging data will be pulled off of that by default. So this just happens out of the box with Sentry. That's great. If you're using uh something in the Elk stack or logs. io or honeycomb, what you'll see when your logs get passed over is generally those attributes will all show up as part of the log record. And it's really nice because you're not having to do any uh data extraction on the receiving side. So you've already named.

Speaker 1: I can look at this and say, oh yeah, what was passed into this? Well message was in order progress. Everybody in the room, what do we know about progress events in Lee's code? They all have a current count and a total count. So immediately I can just go ahead, I don't even have to like look at what's on the records, I can just go ahead and type in current count, total count. So this is a great way to exploit consistency in your logging. And I think struct log or structure logging helps you do that. So again, I know I went super fast. The whole point of this was like I said a bunch of stuff, my slides are in that GitHub repo. You can come in here, check out the slides, open an issue, open a pull request, but I've given you something to like kind of tickle your brain, give you something to think about to go and research later. Remember, the best logs are the logs that you have So

Speaker 1: thank you very much.

Speaker 2: Hi, thank you. Great talk. Uh when you're sending out structured logs, um you need something on the other end to like collate and visualize them and make that interactive. I've used paid services that do this really well, like Logly, but are there any good open source alternatives

Speaker 1: Cygnaws is the new one, I think, and I think they're all open source, self-hosted. I think they're moving to use ClickHouse from the underlying data store. Other than that, I mean it would be like running. the elk stack locally. But I don't know of any like lightweight local options that do that. Good question. Thank you. I guess I should repeat that for folks online. His question was like how do you analyze your logs and look at your logs without using a paid service? And reminder for folks online that are watching, questions in Slack, tag my name, I'll go answer them after the talk. Thank you.

Speaker 3: Um, so I'm really new to this obviously. So do you how do you like um what do you call it? Log rotate?

Speaker 1: Okay, yeah. So I went super fast. I didn't get into tactical like using logging. There is a talk from three years ago. Ryan J. Sullivan gave a talk at DjangoCon. Oh, you're sitting over there. Actually, yeah, I see. He gave a talk in twenty nineteen and he gets into all the tactical stuff. He doesn't get into the philosophy. He saw this tactical stuff. But I don't remember. Did you do rotating? You did file handler, but did you do rotating file handler? I don't remember. It's on YouTube. Check that out. But yeah, use a rotating file handler. So that sort of behavior is built into handlers.

Speaker 4: Maybe one more? If anyone has one?

Speaker 5: Yeah, so speaking of sizes, what if um you by mistake you log too much, how do you protect against that maybe through your tests or whatever? Um

Speaker 1: give me a better example. I'm not sure how to answer that.

Speaker 5: And suddenly your granularity is such that you

Speaker 1: The easiest thing to do there is if you set up your levels and your logging. uh effectively then you change a level somewhere like as a as a band-aid fix raise your you know assuming all that sent at info raise your login config and production hopefully you have a way to do that easily raise your login config and production up to error level or higher level immediately, so that's the band-aid fix. And then the longer fix is then to go in and add more specific logging and there's uh more specific handlers and there's some libraries out there that will help you do sampling. And so you can sample your logs in a handler. So everything shows up to the handler and the handler then samples and only forwards a sample of things. Thank you. Those were great questions.

Speaker 4: All right. Lee, thanks again. Once again, everyone, please help me. Thank you.