Logging Rethought 2: The Actions of Frank Taylor Jr.

Speaker 1: Can I get his slides on there? Ah, awesome. Thank you. All right. Good morning, everybody. Um morning. Thanks for being here. Thanks for the organizers for running this event. Carlton, wherever you are, this was an amazing keynote. Thank you. Really inspiring. There you are. Um and also the venue, give them a round of applause again because this is just fabulous. Right, so today can you hear me in the back? Good. So today I want to talk to you about um how we log information these days. How we store information or have a information available when the run

Speaker 1: services in production and yeah how we How I think that we can prove upon that and how we can turn that into something where we can ma gain more information from what we currently do. And uh Before we get into that, let me briefly introduce myself. I'm Mark Solterman, I'm a Django core contributor, even though I've not contributed to the core components for a couple of years now. I'm tend to be more on the security team and the Django ops team these days. In my day job I work at Crate. io, which is the company behind a database called CrateDB, which is for IoT sensor data direction. So if you want to talk about that stuff, talk to me and fund me. I'm here

Speaker 1: until the end of the sprints. So let me talk about logging and the problems we are facing today. We have applications that are run by or used by hundreds, thousands, maybe even millions of people. And Things are usually going smoothly and are usually fine until they aren't. And then have problems and you have engineers who need to figure out what is happening there and what is going wrong. And well one of the things they do is they look at log messages and they look at what actually happened there. And the log message that that we have is what we currently what's I guess currently common. And

Speaker 1: the current state of logging I think is okay and I think there's a lot of good stuff happening there. But there's also a lot of stuff that we can approve and that we can make b better. And when we log stuff these days, it's probably gonna look look a bit like this. We import the logging framework from Python standard library, we create a logger, and then we have this text of Protext of what's happening. Like in this example, logging failed because uh login failed because in connection to an authentication provider something uh timed out. And then we pass on the authentication provider And when this message ends up in the log files somewhere or in

Speaker 1: log service, it's gonna read like this. Like for somebody who has decent enough English skill in English skills, they can make assumptions and have an understanding of what's happening. But it's up to them to actually understand what's happening at that time. And because we look at log messages after the fact, after something has happened. Maybe hours later because we didn't realize it in time, it's really really hard to actually figure out what went wrong and what had what happened. And in this particular case, for example, the person, the engineer who looks at this message and sees this unmessage, um, they can deduce that's well somebody probably tried to log in using some

Speaker 1: Maybe OAuth provider in this case, maybe Google probably Google, and something timed out because for whatever apparent reason nobody has freaking clue at that at that point in time. because there's no additional information about that. And yeah, this app transformation already provides a lot of or this this log message already provides a lot of context and information, but it's not actually really helpful I think because I think that's at this point our logging is broken. And our logging is broken because when I see this log message, there's a bunch of questions that I would like to ask. We're just not gonna get an answer on. What was the IP address of the host that this

Speaker 1: server that the log message was written on talk to? What was the where did the c did the server try to connect to? Or what was the timeout limit? Was it five milliseconds? Five minutes? Five milliseconds for something external is probably far too short. Maybe it was a configuration mistake. Or how many other attempts were there that were made to talk to that provider? As in was it an isolated incident or was it something that's like happened for hundreds of users simultaneously. And even more important questions I think like stuff like were were there outgoing connections of other outgoing connections affected as well? Or was it just this connection to this one service, which

Speaker 1: as an engineer could give you additional information about Um if it's maybe on their side or is it something on your side? Is there some routing um that's broken? And were other servers affected? Was it just this one server that failed or was it s like your whole fleet of servers And I think this information we could actually add to those log messages. Like you can have this message that says authentication to prov um to host whatever at point this failed with like time uh time out amount of whatever And then you have a five kilometers long log message that nobody's able to comprehend because you have all the information that you cost could possibly want in there.

Speaker 1: At which point I think those pro stall messages are just not gonna cut it and are not gonna help. And are not really the thing we should be using these days anyway. And instead, I think we should look into something that's more structured. We should should add structure to the log or to the log messages that we have these days. For example, look at this. Instead of using Python's framework or logging library, we use a library called struct log, which is structured logging. And we create a logger similar to before, and then instead of having this long text, we have event. This event is a

Speaker 1: string, short string, that's provides the n very necess or the the very specific meaning that this that that what about what's happening and then you attach annotations or additional information attributes to this event all the information you had to have at that point that you could remotely remo or think that could be helpful. Like the provider name, the IP, the timeout, like whatever you can come up with when you lock write the log message. And at a later stage when you realize, oh actually this value would have been helpful at all, start logging it as well. It's easy to just add another value there. And then in the log messages that you see on your laptop, it might look like this.

Speaker 1: It looks obviously different than this text that we had before. It still but still contains the time, the error level or log level. It contains the event and like all the attributes that you said before. And this case also the server because the way we configured strut log added the server automatically. And you can do have do other things automatically add automatically. And now that we have some kind of structured data, we can actually think about reusing that in some slightly different way than used to do before. So the c I guess the most commonly used structured format these days, in the modern world anyway and like leaving XML out because that's kind of like the all

Speaker 1: thing, is probably JSON so we can have this structured thing log it as a JSON object into a file or into s l some log service or whatnot. And then when we have structured data, we can reuse that and throw it into a database like Create, into a database like Elasticsearch, into a database like Mongo, or any of those. That can deal with structured data but are not bound to necessarily specifics uh specific schemas. And then with that We can do something far more helpful than what we have when we look at a million records or million lines of log messages. We can visualize what happens in our systems.

Speaker 1: And when you think about that, what you see is what you understand. And thinking about this message that we had before, let's show this graph. Have a brief look at it. The green lines with the three spikes are the successful authentication provider communications, and the yellow ones are the ones that failed Now the log message that we saw before is about at this point. Now can you guess what now happened? Or can you think about some of the questions that I asked earlier? Stuff like was it an isolated incident? Well you look at the graph and you can say nope it's not

Speaker 1: because Obviously for visually apparent reasons there are more cases of that error message, of that that lock message, that event. It failed, where something failed. And you can see that something one way or not the other way. And I think this is often far more helpful than scrolling through a million lines of log messages. And a picture says more than a thousand words. Because when we now correlate this graph with a different one, for example this one. then as an engineer you might who has understanding of the environment, you might have a better understanding of the entire setup.

Speaker 1: And a of have a can have a good idea of what's happening on a larger scale. Now these graphs show the total amount of log messages for a given log level So the blue lines are the debug messages, green is info, and red is error. Now the blue la b blue ones kind of follow the pattern that we had for the green ra uh the f in the previous graph with three sparks. And that's fine, that is kind of like I guess what you expected. And then the green graph, which stays pretty much at the bottom, has a few small spikes. Which is like common info log message noise. Let's call it that. And that's fine. And then until

Speaker 1: the the error messages on the kind of on the same level as green one, because it's a um Not the best uh random data set I generated here. Um the red um error mess or the error messages, the error message count kind of briefly at inclined at 12 pm. Now that can have all kinds of reasons. Because what you could when you think about the other graph, that error happened like about at this big spike What could have happened here is that somebody started a stole stage drawload and deployed the application on the configuration change. to a set of servers, a small set. And that set of servers raised a couple of errors, but possibly not enough

Speaker 1: that triggered the whole deployment to stop. And because it didn't stop that, it went to a second stage, which you can see here. It's increased again, but maybe still not enough for the whole thing to fall over and to stop. So the deployment automation just went all ahead, deployed the code to everything, and well there you are with like your whole application failing and nothing working anymore. Now this is something you can see. You look at this graph and then see something is wrong. You don't need to scroll through your million lines of block messages. This is knowledge an engineer can gain by looking at something without spending hours of time on figuring out what's happening.

Speaker 1: Especially when you have stuff like automation happen, having these visual insights in your software kind of provides a lot of valuable information. I think And this is not really possible. I mean to some degree sure, but it's not really possible to do with like to mod the the good old like pro style messages. Now all the things we've talked about right now were like this this system where you have your one application maybe running on multiple servers that Bust things. Now think about the micro or microservice infrastructure that you have. I think about the thousands of or

Speaker 1: maybe not thousands, but dozens or hundreds of services that talk to each other. And this this microservice framework Or make Microsoft architecture that you build because your boss th th thought that uh like Microsoft is very cool idea and it's like the best idea ever Who of you think that the microservices they or microservice or microservice architecture they have actually is like stable and they have Like services that when s one service falls over it doesn't like make the whole thing blow away blow up. Anybody? I see one hand up there in the back. Good on good on you, look at you. Um because I th I think that um A lot of the information that we currently

Speaker 1: have and that we currently do with logging is not giving us actually the information that we need in order to figure out wh why when runsters falls over Why it actually falls over. Because you have this one service that talks to another, that talks to another, that puts something in your queue, that's done then worked on by some workers that do then something else. If anything in this chain fails, how does the services depend that depend on that actually are able to deal with that? And I think a very big part of that is not being certain how the events that happen in our systems actually correlate to each other. So are you able to trace that

Speaker 1: this one thing a user did on their on your front end actually are you able to figure out that this thing caused this thing to not work in the back end? somewhere. Maybe because they entered some value some weird email address with a whatever a plus sign in the f before the ad Um and all of a sudden your entire billing process dies because you have some broken error handling area. Like if you if the service dies and you don't have any tracing in there, it's you got you're gonna have a very, very, very interesting time figuring this out And so the the thing I'm um I want to propose here is to do something called um event tracing. So essentially

Speaker 1: the very first time you see a request come to your system, you give it a unique ID Python's UUID uh for for example is s is quite sufficient for that. It's unique, it's pretty much globally unique. You attach it to this first the request the first time it comes in, and then every single time you lock anything. ever you attach this trace id to this log. And because you have structured logging, you can just add this attribute. Um And you can even go further because then you pass this face ID on to the next service, onto the next, onto the next, you put it in the queue. the your salary

Speaker 1: worker is going to figure this out for see oh there's a trace ID. I should probably attach that to all the log messages alright as well. And then when you see this one thing failing, you see trace ID and then you can go and Look at all log messages that have this trade study. And then you can see the whole flow of how your whole data flow through your entire architecture. And with that you can actually understand why some service failed because somebody something happened somewhere else. And well we are Django con, so I better show some codes related to Django. Um so we have the structural library, we have uh the logging frame uh the structure dogger, and this is a middleware for

Speaker 1: That you just put as middleware in the first middleware in your um in your settings. And what it does, it attaches the trace ID to a request, to the request object And it either takes the request ID from a header, xtrace ID, or it generates new one. So if s a request comes in from the outside world And you do proper filtering on headers and like all the security s nonsense you not not nonsense, not the security things you actually wanna do. Um Then you um then you can s ascertain that this log m that the trace ID is generated by you by yourself or that when you talk to the service um from other services in your backend, then you can

Speaker 1: ascertain that this actually is one of your trace IDs. So it's either a new one or some uh trace ID that comes from because it's a request from one of your own other services. You create a new um logger here in in um In uh the middleware, that's some um struct log internals, it's uh threat local um behavior, I guess. Um and this one with this Trace ID equals request trace ID here, you will ascertain that everything that happens within this request. will have this log this trace ID attached to it. Every single log message ever until the requester is terminated or the next request rather comes in at which point it's gonna have a new trace ID

Speaker 1: And then similarly you can put something after the um authentication middleware, for example, and you bind the user ID. on the logger. So everything from that point onwards will include the current the user ID of the currently logged in user. Or no trace ID at all, or no user ID if um the user is not authenticated. Now Uh we're in the EU, we have a whole bunch of interesting relations and think about DjangoCon last year. There was this four-letter thing called GDPR. So um Logging data these days is actually pretty fun or actually pretty s something you really want to think about what you do. For example, you never ever want to log secrets.

Speaker 1: Hello Facebook, hello GitHub, hello Twitter. Um if you won't have your company's name next to that, please do that and like lock user's password or something. Um I recommend you do don't do that. It's Bad practice actually. That's uh so I've heard. Um also you kind of don't wanna accidentally expose all the locks that you lock to your to the outside world Like stuff like S3 buckets are very, very good at being publicly readable or possibly even writable. It's a really great idea to have that. um similarly to something called MongoDB, um which is like one of those I don't know why, but when you read certain newsletters this is

Speaker 1: like every week there's somebody else who had the publicly accessible MongoDB. Um I mean and never say never, but so far I've not had that. I think something fell over there. Um And then yeah be explicit about what you log. I guess that's the more important part about the um the GDPR thing. Don't do uh do the first one like set Explicit attributes that you wanna have that you wanna log to your log files and you have end up in your log system. Don't do the latter because you have no freaking idea what's actually on this object. It might not just work. Um right, so with a bit less than ten minutes left, who the heck is Frank Taylor Jr. Um

Speaker 1: let me answer that with a slightly different question. Who here knows the movie Cat Me If You Can? Okay, not everybody. Let me give you a brief runto. It's uh the main character is a person called Frank William Abignell. and figures out a bunch of cons. Where he cons banks, airlines, airports, hotels, like all those like interesting companies and organizations where you can make money or can save money rather And the problem is that nobody's actually really able to trace him until some point. And one of that uh reason is that he why he's n nobody's able to trace him is because he figured out how

Speaker 1: Or he was smart enough to to cover his checks and he figured out how to like work around the US um k check routing your system by forging checks and having them routed through the whole country. And The thing is that when you th take this like example from the real world and apply to something to some like microservice architecture maybe Then if you are able to trace events across your entire system, you can actually figure out who did what and what happened and why And I think the key here is that with proper logging and more smarter logging

Speaker 1: than we currently do in most cases, I think. um we can gain far more information and can get uh much yeah get m much more intelligence about our users about how our system is being used about the resilience of our services. And yeah, this is I think there's a lot of gain by going into a more structured logging approach. And at this point I wanted to go with a like I guess a more live demo, but didn't actually have time to finish that. So also I'm f freaking scared of live demos on stage and I promised myself never do that. So I caught it an example.

Speaker 1: There's a code on GitLab. If you want to run this thing, it's a Docker compost setup Um which essentially replays this this um catch me if you can thing a bit. You have an ND Nginx startup page, index page that you can visit there comes up with a there's a there's two banks that you can uh deposit money and wire shacks and wire tra wire money from one person to another. Um there's an airline where you can book flights. There's a Grafana dashboard where you can then see all the events that happen in the system with like how this wire transfer from one bank to another flew through the system or how this check that us

Speaker 1: used to pay for this flight ended up at this bank but because that's a local bank and then needed to go through the other side of the country and then make all those events, this event tracing kind of be a bit mocked and like it's like abstracted here and then you can also go and like look at the raw database here and like all the log raw log events and um yeah have a look and see or play around and yeah That's the example. Um now I forgot what I wanted to do. I actually wanted to make this repository public. I can do that right after the talk. Um while you prepare for a question.

Speaker 1: Thank you.

Speaker 2: Thank you, Marcus. Do we have any questions? Again, please line up at the microphone. Hello

Speaker 3: Marcus. Thanks for the interesting talk. In a typical stack, we not only have our Jung application, but also Nginx, MicroWiski, Postgres. How would we go about sharing or correlating the logs not only the trace ideas but the time stamps the way of Having the same name for the same fields all over. Are you aware of any standards or initiatives to have a consistent naming scheme for uh structured logs or

Speaker 1: I think it d highly depends on how actually you build your microservice architecture. Is it like one team or maybe a few very few teams that built a whole thing of twenty services? Or is it like fifty individual teams that each have their own thing that where they publish an API and that's about it the about the communication between them. In the former sense you can probably go and like set some standards. This is what we call these fields, or this is a best practice on how how fields are called. Um for example always include an underscore ID if it's the ID of an object. And um yeah if it's uh the individual teams I think it's much harder to f I mean you still you could

Speaker 1: still enforce certain things there, but um Also if you have individual teams you don't want to take too much of the um uh independency of um away from them. So this is I guess it depends a bit on the particular case there um of your organization. Um

Speaker 4: to expand a little bit on the previous question, uh JSON and structured logging is like Uh a little bit going in both directions. Because if you're saving Jason into a database, what kind of structure do you have? How can you still search in it with uh while being um performant? I mean You said you don't want to impose too many rules. But on the other hand, if you have like um two hundred different log messages with different feeds, how are you going to search in them? How are you going to find anything again?

Speaker 1: Um so the the JSON output is more a thing to have a structured way to write it somewhere in the so in a log file or something that's then being picked up by a f whatever fluent D or a F or something and thrown into a more or less schema less database or a database that can handle dynamic schemas. I think it's uh highly depend on on the application on on the environment where you build in with your system. You probably wanna have some enforcements. Um at sir at the some point anyway. But um Th I think there's also just a bunch of best practices that just exist that m like you things like

Speaker 1: Um you call if it you you call it what it is, not what you think it should be. Like if it's if it's an ID call it an ID. If it's milliseconds, call it milliseconds and not something arbitrary. Like um I guess it's if you think about it from a when you look at the more ops perspective, like Prometheus in that direction, they have a couple of best practices on theirs um on their page. how to name metrics. Like include a base unit, for example. This is probably something that a good recommendation that you can do. But yeah, it depends on I guess highly depends on the organization. Hi

Speaker 5: Marcus, that was a very interesting talk. It's a bit of a continuation to the previous question. Uh a lot of places we are where we use wo more than one server in parallel, even if it's not uh microservices. Uh you use some sort of logging service. A lot of those are using the ELK uh stack and um I was wondering if if struct log has any integration with that that can make it uh easier to use.

Speaker 1: So struct struct log more plays more the role of a That's called a replacement for the start Python standard library. And then you log it to a file and have Felbeat or whatever does uh fluent D and throw that in whatever data store you have. You wouldn't do that within the request, for example. You wouldn't handle like this right into a data store as well in the request. It would just take a lot.

Speaker 2: Do we have any questions from the internet, Russell? Okay. And that's it. Thank you, Marcus. And we will now have a break until eleven fifteen