Python Logging Like Your Job Depends on It
This is a modal window.
The media could not be loaded, either because the server or network failed or because the format is not supported.
Formal Metadata
| Title |
| |
| Subtitle |
| |
| Title of Series | ||
| Number of Parts | 542 | |
| Author | ||
| License | CC Attribution 2.0 Belgium: You are free to use, adapt and copy, distribute and transmit the work or content in adapted or unchanged form for any legal purpose as long as the work is attributed to the author in the manner specified by the author or licensor. | |
| Identifiers | 10.5446/62031 (DOI) | |
| Publisher | ||
| Release Date | ||
| Language |
Content Metadata
| Subject Area | ||
| Genre | ||
| Abstract |
|
00:00
Open setNetwork topologyLink (knot theory)Software developerOpen sourceGoodness of fitCartesian coordinate systemPresentation of a groupArithmetic meanPoint (geometry)SoftwareRight angleQR codeLink (knot theory)Software developerOpen setConfiguration spaceComputer clusterProduct (business)Network topologyGroup actionBlogComputer animation
02:19
LoginGastropod shellDemo (music)Data typeRevision controlVideo game consoleError messageLetterpress printingGame theoryFile formatMessage passingHoaxInformationBlogLevel (video gaming)Computer fileInformationRadical (chemistry)Context awarenessSet (mathematics)Right angleCore dumpFunction (mathematics)Filter <Stochastik>Video game consoleResolvent formalismMechanism designNumberRotationCASE <Informatik>Cartesian coordinate systemCodeGreatest elementPlastikkarte2 (number)Multiplication signGod
09:11
Video game consoleQueue (abstract data type)World Wide Web ConsortiumLoginOpen setGame theoryMessage passingInformationMessage passingServer (computing)BlogQueue (abstract data type)InformationInformation securityOpen setError messageBoom (sailing)Key (cryptography)Level (video gaming)SpacetimeComputer fileSampling (statistics)2 (number)Cartesian coordinate systemSoftware testingRow (database)EmailElasticity (physics)Boss CorporationModule (mathematics)Integrated development environmentConfiguration spaceEvelyn PinchingSoftwareFile formatBitLibrary (computing)Multiplication signClient (computing)Virtual machineThread (computing)World Wide Web ConsortiumWeb pageShared memoryProduct (business)Moment (mathematics)ImplementationSource code
16:03
Physical systemPasswordSystem administratorOpen setSoftware bugQuery languageTraffic reportingBlogData managementInformation securityPrice indexObject (grammar)Stack (abstract data type)Mobile appMenu (computing)Information securityLocal ringPasswordOpen setSystem administratorData managementSubject indexingStack (abstract data type)Computer animation
16:29
Video game consoleOpen setExecution unitPrice indexPattern languageWeb pageDefault (computer science)Object (grammar)Physical systemInclusion mapSource codeFile formatData typeCore dumpField (computer science)Texture mappingType theoryDigital filterString (computer science)Uniform resource locatorTraffic reportingMessage passingModule (mathematics)Game theorySubject indexingMultiplication signPattern languageDifferent (Kate Ryan album)Field (computer science)Point (geometry)Open setType theoryProcess (computing)Presentation of a groupGroup actionVisualization (computer graphics)1 (number)SoftwareInformationMappingPanel paintingComputer animation
18:44
InformationExecutive information systemVideo game consoleOpen setServer (computing)Configuration spaceBlogOpen setFile formatLastteilungDirect numerical simulationReverse engineeringBeat (acoustics)Computer architectureOnline chatWeb serviceComputer virusGodPresentation of a groupCartesian coordinate systemFile systemWordSearch engine (computing)Product (business)Server (computing)Visualization (computer graphics)BitMechanism designMobile appContext awarenessFunctional (mathematics)InformationComputer animation
24:39
Program flowchart
Transcript: English(auto-generated)
00:06
This is the largest room I've ever given a presentation to, so thank you for showing up. Also, let's see. How many of you are using logging right now in your job? Wow, OK, that's a lot of you.
00:21
This is the wrong talk. No, I'm just kidding. How many of you would say you're doing Python logging well? Yeah, that's what I thought. Well, it's OK. You're in the right conversation because we're going to tell you all about how you get started with Python logging and all the wonderful things that's oh, hold on.
00:40
It's my boss, hold on. Hey, yeah, I'm in the middle of a presentation right now. What's up? He deployed on a Saturday? Are you kidding me? What do you mean production's broken? Yeah, tell me you checked the logs. He's not logging. Oh my goodness. Well, please don't fire him.
01:01
Tell him to tune into my talk. We're going to go over the basics of logging, and then we're going to get all the way down into some more advanced logging configurations. Yeah, ciao. So nobody wants to be in that situation. Honestly, that went over way better than I thought it would.
01:22
Nobody wants to be in that situation. So before we get too deep, though, I'm going to just say hi. I'm David. I'm a developer advocate for Open Search. Thanks to the Open Search group for letting me come here. Open Search is commonly used as a log store, so it fits in nice with Python logging. Previous to this, I'd worked as a data engineer, network
01:42
automation engineer, DevOps engineer. I've done a lot of engineering, and all of them had one thing in common, and it was I needed a lot of logs. You have to understand what was going on at any point in my application. So you might want to get your phones out at this point. I have lots of QR codes. Just kidding. There are only three. And we're going to go to code right after this one.
02:01
So that's my link tree if you want to connect with me and hear more about Open Search, because I'll talk your ear off, I promise. So with that, you can follow along. There's a gist for this whole presentation. It can all run for the most part. I was working on it last night till very late today. And we're going to go ahead and get started.
02:20
So as with anything, we're going to import logging off to the races. And now you can check off your JIRA card and put it on the backlog. Just kidding. We all know that logging is a lot more than just importing logging. So we're going to start with the logger. Logger is kind of the core concept of Python logging. And all loggers start with a name.
02:42
So we're going to do underscore, underscore, name. Does anyone know what underscore, underscore, name actually will resolve to in this instance? Any guesses? It's underscore, underscore, name. Come on, guys. So we create a logger. We give it a name. And fun fact of the day, that logger is global.
03:01
I can import Python logging and do get logger, of course, from anywhere and use this logger. Can you make it bigger? It's too small. Yes. There we go. Try not to delete code while I'm at it. There we go. We're going to make this smaller.
03:21
We're going to make this up here. So as we know, with logging, there are several different levels you can set. These levels are a filtering mechanism for Python logging. Fun fact of the day, though, most people don't know this, is these levels actually resolve to numbers. And those numbers are used to do filtering.
03:40
And fun fact of the day, you can actually make your own log levels as if five, six, six log levels, seven log levels isn't enough. You could add more potentially if you needed that. So we're going to go ahead and send this to the terminal. And we're going to take a look at all those log levels. Here we are.
04:00
As we can see, they resolve to 10, 20, 30, 30, 30, 30, 40, and 50. So warn and warning both resolve to the same log level. So they're both there in case you need two log levels that have the same level. And these levels, again, are used for filtering. So as you are sending out logs, they're used to filter out logs
04:21
that maybe are less important. So the lower the number, the lower the importance of the log. So let's talk about emitting a log. Here we're going to go ahead and send a log with logger.info. So that's going to emit a log from the logger with the info level attached to it.
04:40
Lowercase info is for sending logs. Uppercase info is the level. And nothing actually happens. It just gets sent to the terminal and nothing happens. And the reason why nothing happens is because we've not told it where it needs to go. We need log handlers. So that is what we do.
05:01
We're going to build a simple syslog handler for, sorry, streaming handler for sending to standard out now. So handlers receive logs from the logger. It's pretty straightforward. I'm going to go ahead and create this real quick. We're going to set the level of our handler. Remember, our levels are our wonderful filtering mechanism.
05:24
Set the level to warning. And the top one will not show up, but the bottom one should because it is greater than warning. And there it is, this will. That's pretty dull. Nobody really wants a log that says this will. That tells us nothing.
05:42
You have no clue what's going on in your application. What time did this will? What time will it won't? So we need to add some context. And the way we get context is, of course, with log formatters. And I've jumped ahead too far in my presentation. We're just going to take a quick back step real quick.
06:02
We're going to talk about some of the other handlers that are built in. So there's the rotating file handle. This one's particularly useful if you have too many logs and your file gets too large. It can actually automatically rotate that file every x amount of size into a new file. And then you can specify for it to delete logs
06:21
after a certain amount of time or a certain amount of files. We have the syslog handler. Syslog is a standard for logging. HTTP lets you send logs to arbitrary HTTP endpoints. Timed rotating file handler, believe it or not, is a timed rotation of your log files, whether it be every day, every minute, or please,
06:41
God forbid, every second. Do not do that. You will end up with thousands of files. I did actually every hour once, and that was a huge mistake. I ended up with like 15,000 files after a little bit. And the SMTP handler, if you are masochistic. Now we'll talk about formatters.
07:00
OK. So let's go ahead. We're going to set our console handle to the info level. We're going to create a formatter. The formatter is going to include the date and time, the name of the logger, which, again, if you're using underscore underscore name, that's going to be the name of your module, whether that's like search.util.whatever.
07:20
And then the level name that it was emitted at, and a message. Pretty straightforward. Then we set the formatter. Formatter gets attached to handlers again, and logger.info. Look at my pretty log. Well, just kidding. There's no log there. Is it because I have a bug?
07:42
Because I wrote this way too late at night? Probably. Or more likely, because there was something I actually tricked you on earlier. The truth is, the reason our first log wasn't emitted wasn't because there wasn't a handler attached to it, but it's because Python's logging library, by default, sets loggers and handlers to the warning level
08:01
right out of the gate, and we emitted at the warning level. So fun fact, you actually need to set the level for both the logger and your handlers. So we'll go ahead and do that. We'll set the logger level. And we're off to the races. Let's look at this pretty log. Man, that is so beautiful.
08:21
Now I know exactly when I had a pretty log. I know exactly where it happened in the main. I know what level it was at. It was informational log. So we've talked about a lot so far. We've talked about loggers, handlers. So let's do a top to bottom just real quick to make sure we're all talking about the same thing.
08:43
So we have loggers. Loggers emit a log at some level. They also filter out logs at some level. So if your logger is set to filter out warning logs and you send it an info, it's never going to get to the handler. Handlers receive logs and then send them
09:01
to some specified output, whatever that may be. And then formatters attach to handlers and they enrich the output. So they add context. And there's a bunch of other contexts. That's not mentioned here. It's in the Python Logging Library. Ooh. Ooh. I guess it's like at a certain time in the presentation, it just decides it wants to do that.
09:23
So these are all wonderful. Wait a minute. I'm getting there. Logging, yes. All right, here we go. We're just going to scroll on. Oh yes, here we go. So setting up logs in each individual module is a pain.
09:43
So you can actually pre-create loggers ahead of time with a dictionary config or a YAML config file, because I know all of us just love creating YAML configs and having them everywhere. So with this, you can create as many logs as you want
10:01
and specify them with dictionary config. One other really important thing to mention, and I probably should have hit it when I was talking about loggers at the get-go, there's a specific reason why you can set it at the logger level and at the handler level. So handlers give you very fine-tuned access over what you're looking at. So where it's going, which output.
10:21
So a lot of times, people will specify certain levels for handlers. And then they will use their global debug level to set their loggers. So say, for example, you're debugging an application locally. You're going to set that to debug, of course. But when you push it to production, you don't want that. So a lot of people will have a production logging
10:43
config and a development environment logging config. So with that, there is actually one other slight challenge with loggers, and that is they're blocking operations. So like I said earlier, if you're a masochist and you like the SMTP log handler,
11:03
you could be in a real pinch. So say, for example, I'm on your application. You have this nice web server. And all of a sudden, it hits a critical error. It sends a message to your SMTP server. And your SMTP server is slow. It's chugging. So you're taking five to 10 seconds for it
11:22
to register that and send a response. Do you think I'm going to stay on your web page for five to 10 seconds while it sends an error log? Heck, no. I'm closing out and I'm going to somewhere else. Amazon.com to buy whatever I needed. So we have to handle this. We have to understand that, hey, this could potentially block.
11:41
So how do we unblock our applications? Well, it's by making our applications simpler, obviously, and using multi-threading. That was a joke. You can laugh. So with this, we can actually import queues. And what happens is there's a queue handler and a queue listener. So the queue is the shared memory space
12:02
that can be accessed by both the handler and the listener. You create the handler. The handler receives all the logs and then distributes them to the queue. The queue listener starts up on its own independent thread. And it's going to listen to the log queue and then distribute it to any of the handlers
12:21
that you specified it should. So let's go through that end to end again. We've got queue handlers, receive the logs, place them on a queue. The queue hands it over to the queue listener, which then hands it on to your other loggers. Now your application's unblocked. It drops that log on the queue, and then it's off to the races.
12:41
You can use SMTPlib if you really wanted to. So let's talk about pulling this all together now, right? So we have these logs. They sit on our local machines. And that's fine. But if you are a large organization, you might have hundreds of servers.
13:03
Take a second to breathe. You might have hundreds of servers, hundreds of network devices or whatever. And I'll give a real example of when I use this or could have used this. So when I was a network automation engineer, we had a particular log that my boss found on some of the servers or routers, switches, et cetera.
13:23
And I spent the next three hours logging into each individual one. We had thousands of network devices. So I logged into enough of them, wrote down the logs, and then correlated. I said, oh, look. Every Thursday and Saturday at the exact same time
13:42
this log happens. One email later finds out security team is pen testing against us, and we don't need to worry about it. Again, three hours just trying to correlate what log was happening, where, when. So this is exactly what you can avoid by using something like Open Search or Elastic Search low key
14:03
to aggregate your logs. And again, if you do want to follow along with this later, this just is a Docker Compose file that will let you spin up some sample containers with Open Search. So we'll import logging in our Open Search library,
14:21
create an Open Search client. And this is where I'm going to break for just a moment and talk about custom handlers. So we mentioned handlers are where you send your logs. You can implement custom handlers, believe it or not. All you need to do is, I was going to say,
14:40
inherit from, there we go, that's probably the right word, logging dot handler. Then you create an emit definition, and that needs to have self and record, and that will send the record wherever you specify. So in our case, we have, it's going to take and it's going to format created time.
15:01
Also, I did not implement the formatting library because I wanted to send it as a dictionary to Open Search just because that's what it works with. You can also use something like fluent bit or fluentd log stash to parse out your logs later. And we'll talk about that just briefly. So we've got our created time.
15:20
We've created this wonderful record, open search client dot index. We'll send that log to Open Search. Do, do, do, do, do. There we go. And then we'll set it up. So we're going to create our logger named log. We're going to set the logger's level to info so that we get the info records.
15:40
We're going to create the Open Search handler and add logging dot info, set that level, and add our handler. And we're off to the races. Boom. Well, that was kind of anticlimactic. You can't actually see it going into Open Search. But I promise you, it chugged along and it went into Open Search and, huzzah,
16:03
let's go into Open Search. And this is actually Open Search dashboards. So again, if you do this on your local machine, password's admin, username's admin. Very secure. We're actually looking to change that, but that is coming soon. So we go here and we're going to go into Stack Management.
16:25
Hang with me for just a second. So we created a custom index with this. And that index is named based off of the logger that sent it. So we've got logger name, which was log, and then with the date time so
16:42
that we can roll those off after a certain amount of days. We're going to create an index pattern. And we are going to say absolutely nothing because this is the problem with doing things live. Oh, just kidding. I just don't know how to use Open Search. Here we go. It's only my job.
17:01
Don't worry. Boss, I swear if you're watching this. No, I'm just kidding. So there we go. So we have these two indexes that have been created because I was testing yesterday and today. So log star just says, hey, any index that looks like log with anything after it, group them together. Ask for a time field, which is our created field.
17:22
And create index pattern. There we go. Open Search auto detects all of these different files, types, et cetera. You can actually specify mappings. And I actually really recommend that because different visualizations require different types of mappings. But that is not what we're talking about today. We're talking about Python logs, darn it.
17:41
So we're going to go over to discover. And go into our logs. And we are going to make sure we're looking at today's logs. Actually, let's look at this week. Here we go. And we have three hits. There we are. These are our logs. Look ma, I'm logging. And you can actually see the exact point in time
18:01
when I switch from this is my log to look ma, I'm logging. So that was, yeah, I had 2.37 PM. So anyhow, with this, you can actually go ahead and then visualize spikes, peaks, valleys, when this is happening. You can enrich it with device information. So you can say, hey, when was this log sent?
18:21
Is there a particular device that's having a lot of issues? So now instead of logging into all of your servers, you can go and bounce the correct ones. And if you saw Doton's presentation yesterday, you'll know you can use this for monitoring anything, whether it's the ICD pipelines, Python logs, network logs, et cetera.
18:43
So let's see. Look at that. You're doing more logging now than 99% of the population. So congratulations. Clap of hands for yourselves. So I'm going to talk real quick about just a very simple, common logging architecture for capturing distributed logs
19:05
and why you would want to do that. So more often than not, you're probably actually going to want to log your doop ba ba. You're going to want to put your logs locally on the file system. And the reason why is because your file system is not
19:21
going to go down, and god forbid if it goes down, there's no hope for that log getting out anyways. Your service remotely could disconnect because whether you're doing an upgrade or something along those lines. So it acts as a little bit of a caching mechanism. And then you'll normally have it logged to a file. And then you could use something like fluent bit or beats.
19:40
And those will ship your logs out. And the wonderful thing about this architecture is, again, if open search was to go down because you're doing an update or if something was to happen critical with your Python app, it can quickly write that log out. And you can also do enrichment. So I talked about getting which server sent that log.
20:04
So fluent b, sorry, fluent d, data prepper, and log stash all can take and enrich your logs with the context information that came with them. So say, for example, it says, I received this log from x, y, and z server, 10, 20, 90, 2, 83,
20:22
or something like that. Then it can go and do a reverse DNS lookup and say, hey, which service is assigned to that? And then it can add that information in and then push it into open search. So now you've all of a sudden gone from having a log that says, hello world, to or got here, please, please, do not.
20:43
And you can have it pushed into open search, know what service is causing the issues, and visualize on dashboards. With that, I'm finished. Please scan, look at open search if you're curious. It is open source, Apache 2 licensed. All of our features are being developed in the open.
21:01
And with that, I want to ask it, does anyone have any questions? Yeah. Thank you. Hello.
21:21
OK. How would you, I'm mostly familiar with Sentry. And I'm very curious how would you compare this to that. Because as far as my friend has told me, they're pretty different products, but they do similar stuff. Yeah, I think Sentry is more of an APM, isn't it? Is that word familiar? OK, so open search has some APM capabilities, which is app,
21:41
oh, I don't remember the word for it. But it's for app monitoring and specific to the application. So this has some APM capabilities. It might not go as deep as some of your auto configurations for other APM tools, though. But it can ingest APM logs. So it's a good question. Thank you.
22:01
We had two async questions from the chat. The first one is, what about fstrings and logging? Because I wrote this presentation in a couple hours. And yeah, so I'm trying to modernize. But again, it's old habits die hard. So I'm still using fstrings. Please don't get on me.
22:23
What was the next one? Sorry. And the second question is, what about structured logging and in particular, struct log? I'm not actually familiar with struct log. So I'm actually moving myself more towards using OpenTelemetry instead of logging, or alongside logging, we'll say.
22:40
So OpenTelemetry gives you a trace, actually, which can tell you the full stack of what happened during your application. So everything down from which function was called to which load balancer sent the information over. So you get an end-to-end trace of what happened, which in my opinion, I think is a little bit more handy than just logs.
23:03
I think we have one more question in the middle. Just a quick question from the discussion I'm having with the co-worker. So we're thinking about moving our logs to JSON format because it's easy to understand for non-Python people and searchable.
23:23
If we were to switch to open search, and I really like the presentation, do you think it's still feasible to make logs searchable in and of itself? Or is open search that stable and usable? And from your experience, there's no need to search on your logs?
23:41
Yeah, no, that's a great question. You do need to search your logs. Open search is a search engine at its core. And that is why it is as good as it is with logs. As for JSON versus other formats, I think there's no particular preference. But open search is certainly stable. We have 150 million downloads. So we are here to stay.
24:01
It's been adopted by a lot of companies such as Oracle, Ivan, Instacluster, Opster, Amazon Web Services, of course, because I work there, and many others. So I would say it is very stable, production ready to use. And yeah, it's a really great way to search your logs. In fact, I have a lightning talk at 1655 in another room.
24:23
So I think it's a Kubernetes room. So if you want to talk more about searching your logs, I'm going to be talking about search relevance for logs. Thank you. And thank you online people. Thanks a lot.