Logging Rethought 2
CC Attribution 3.0 Unported:
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.
Holtermann, Markus
We build services, potentially used by hundreds, thousands or even millions of people. And despite all the testing we do, some operations and interactions with these services will not work out the way we expect or hope. Wouldn’t it be great to be able to reconstruct what led to a problem? And then analyze if the same problem occurred at other times? In this talk, I want to look at structured logging. What are the benefits of it over plain-text logging? How can it be used effectively? Logging, by itself, can help to trace bugs. Structured logging adds additional, post-logging capabilities when used correctly. Because log events are structured data, they can be analyzed much more efficiently and effectively than plain text log messages. Furthermore, one can even build graphs and diagrams to visualize what’s happening in a service nicely.
 Can I get his slides on there? Ah, awesome. Thank you. All right. Good morning, everybody. Morning. Thanks for being here. Thanks for the organizers for running this event. Carlton, wherever you are, this was an amazing keynote. I'm sure you really inspire me. And also, when you give them a round of applause again, because this is just fabulous. Right. So today, can you hear me in your back? So today I want to talk to you about how we log information these days. How we store information or have information available when we run services in production. How we, how I think that we can prove upon that and how we can turn that into something where we can gain more information from what we currently do. And before we get into that, let me briefly introduce myself. I'm Marc Solterman. I'm a Django core contributor. Even though I've not contributed to the core components for a couple of years now, I tend to be more on the security team and the Django ops team these days. In my job, I work at Crate.io, which is the company behind a database called CrateDB, which is for IoT, satellite, data direction. So if you want to talk about that stuff, talk to me and find me. I'm here 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 the end. And then you 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 we have is what we currently, what's currently come. And 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 better. When we log stuff these days, it's probably going to look a bit like this. We import the logging framework from the Python standard library, we create a logger and then we have this text of, pro-text of what's happening. Like in this example, log in failed because a connection to an authentication provider something jumped out and then we pass on the authentication provider. And when this message ends up in the log files somewhere or in log service, it's going to be like this. Like for somebody who has decent enough 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 happened. And in this particular case, for example, the person, the engineer who looks at this message and sees this un-message, they can deduce that, well, somebody probably tried to log in using some maybe OALT provider, in this case, maybe Google, and something timed out because for whatever apparent reason, nobody has freaking clue at that point in time because there's no additional information about that. And yeah, this information already provides a lot of, or 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 going to get an answer on. What was the IP address of the host that this server that the log message was written on talked to? What was the, where did the server try to connect you? Or what was the timeout limit? 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 the provider? Was it an isolated incident, or was it something that happened for hundreds of users simultaneously? And there are even more important questions, I think, like where were there outgoing connections of other outgoing connections affected as well? Or was just this connection to this one service, which as an engineer could give you additional information about its main on their side, or is it something on your side, some routing that's broken? And were other servers affected? Was just this one server that failed? Or was it like your whole fleet of service? And I think this information we could actually add to those log messages. You can have this message that says authentication to host whatever at points, this failed with a timeout amount of whatever. And then you have a five kilometers long log message that nobody's able to comprehend because they have all the information that you could possibly want in there. At which point I think those post-all messages are just not going to cut it, and are not going to 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 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 string short string that provides the very necessary, the very specific meaning that's what's happening. And then you attach annotations or additional information attributes to this event. All the information you have at that point that you could remotely think that could be helpful. Like the provider name, the IP, the timeout, whatever you can come up with when you write the log message. And then 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. It looks obviously different than this text that we had before. It still contains the time, the error level, or log level. It contains the event and all the attributes that you said before. And it also contains the server because the way we configured the strat log added the server automatically. And you can 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 it used to do before. And I guess the most commonly used structured format these days in the modern world anyway, and like looking XML out because that's kind of like the old thing, is probably JSON. So we can have this structured thing log it as a JSON object into a file or into a slums and 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 elastic search, into a database like Mongo, or any of those that can deal with structured data but are not bound to necessary specifics, specific schema. 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. 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 idolanted incident? Well, you look at the graph and you can say, no, it's not because obviously for visually-appound reasons, there are more cases of that error message, of that log message, that event that failed, where something failed. And you can see that something one way or not the other way. And I think this is far more helpful than scrolling through a million lines of log messages. And a picture says more than a thousand words, because when you 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 and 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 ones follow the pattern that we had in the previous graph with three spikes, and that's fine, that's what you expected. And then the green graph, which stays pretty much at the bottom, has a few small spikes, which is common info log message noise, let's call it that. And that's fine, and then until the error messages on the kind of same level as green one, because it's not the best random dataset I generated here, the error messages, the error messages count kind of briefly inclined at 12 m. Now, that can have all kinds of reasons. Because what you could think about the other graph, that error happened like at this big spike, what could have happened here is that somebody started a stale stage world, and they ployed 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 that triggered the whole deployment to stop. And because it didn't stop that, it went to the second stage, which you can see here. It's increased again, but maybe it's still not enough for the whole thing to fall over to stop. So the deployment automation just went all ahead, deployed the code to everything, and well, there you are with your whole application failing and nothing working anymore. Now, this is something you can see. You look at this graph and see something is wrong. And you don't need to scroll through your million lines of log messages. This is knowledge engineer can gain by looking at something without spending hours of time on figuring out what's happening, especially when you have stuff like automation happen, having these visual insights in your software kind of provides a lot of valuable information. And this is not really possible, I mean, to some degree, sure, but it's not really possible to do with the old, like, pro-style messages. Now, all the things we've talked about right now were like 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. Think about the thousands of, or maybe not thousands, but thousands or hundreds of services that talk to each other. And this microservice framework, or make microservice architecture that you build because your boss thought that microservice were a cool idea and it's the best idea ever. Who of you think that the microservice architecture they have actually is like stable and they have services that when someone's service falls over, it doesn't make the whole thing blow up? Anybody? I see one hand up there in the back. Good on you. Because I think that a lot of the information that we currently have and that we currently do with logging is not giving us actually the information that we need in order to figure out why, when one service 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 a 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 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 this one thing a user did on your frontend? 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 plus sign before yet. And all of a sudden, your entire billing process dies because you have some broken error handling in there. If the service dies and you don't have any tracing in there, you're going to have a very, very, very interesting time figuring this out. And so the thing I want to propose here is to do something called event tracing. Essentially, the very first time you see a request come to your system, you give it a unique ID. Python's UI ID for example is quite sufficient for that. It's unique, it's pretty much globally unique. You attach it to the request the first time it comes in, and then every single time you log anything ever, you attach this trace ID to this log. And because you have structured logging, you can just add this attribute. And you can even go further because then you pass this trace ID onto the next service, onto the next, onto the next. You put it in the queue, the salary worker is going to figure this out, see, oh, there's a trace ID. I should probably attach that to all the log messages right 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 trace ID. And then you can see the whole flow of how your whole data flew through your entire architecture. With that, you can actually understand why some service failed because something happened somewhere else. And well, we are a Django console, I better show some codes related to Django. So we have the structure library, we have the logging frame, the structure docker. And this is a middleware for, but you just put as middleware in the first middleware 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, a trace ID, or it generates a new one. So if a request comes in from the outside world, and you do proper filtering on headers, like all the security nonsense, not nonsense, all the security things, you actually want to do, then you can assert that the trace ID is generated by yourself, or that when you talk to the service from other services in your backend, then you can assert that this actually is one of your trace IDs. So it's either a new one or some trace ID that comes from, because it's a request from one of your other services. You create a new logger here in the middleware, that's some struct log internals, it's a thread local behavior, I guess. And this one with this trace ID equals request, trace ID, you will assert that everything that happens within this request will have this trace ID attached to it, every single log message ever, until the request is terminated, or the next request rather comes in at which point it's going to have a new trace ID. And then similarly, you can put something after the authentication middleware, for example, and you bind the user ID on the logger. Everything from that point onwards will include the user ID of the currently logged in user, or no trace ID, or no user ID if the user is not authenticated. Now, we're in the EU, we have a whole bunch of interesting relations, and thinking about DrangoCon last year, there was this four letter thing called GDPR. So, logging data these days is actually pretty fun, or actually pretty something you really want to think about what you do. For example, you never ever want to log secrets. Hello Facebook, hello GitHub, hello Twitter. If you want to have your company's name next to that, please do that, and like, log user's password or something. I recommend you don't do that, it's bad practice actually, so I've heard. Also, you kind of don't want to accidentally expose all the logs that you log 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. Similarly to something called MongoDB, which is like one of those, I don't know why, but when you read certain newsletters, this is like every week there's somebody else who has a publicly accessible MongoDB. I mean, I never say never, but so far I've not had that. I think something fell over there. And then be explicit about what you log. I guess that's the more important part about the GDPR thing. So, don't do the first one, like, set explicit attributes that you want to 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. All it might not just work. Right, so with a bit less than 10 minutes left, who the heck is Frank Taylor, Jr.? Let me answer that with a slightly different question. Who here knows the movie, catch me if you can. Okay, everybody, let me give you a brief answer. It's the main character is a person called Frank William Abagnale and he figures out a bunch of cons, where he cons banks, airlines, airports, hotels, like all those 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 the reasons why nobody's able to trace him is because he figured out how, or he was smart enough to cover his tracks. And he figured out how to work around the US check routing system by forging checks and having them routed through the whole country. And the thing is that when you take this example from the real world and apply to something like Microsoft's 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 that we currently do in most cases, I think, we can gain far more information and can get 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, a lot of gain by going into a more structured logging approach. And at this point, I wanted to go with a more live demo but didn't actually have time to finish that. So also, I'm freeing a scale of live demos on stage and I promise myself I'll never do that. So I caught an example. There's a code on GitLab. If you want to run this thing, it's a Docker Compose setup. We essentially replace this catch me if you can thing a bit. You have an engine X startup page, engine index page that you can visit. It comes up with two banks that you can deposit money and wire checks and wire money from one person to another. 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 how this wire transfer from one bank to another flew through the system or how this check that you use to pay for this flight ended at this bank, but because that's a local bank and then needed to go through the other side of the country, all those events, this event tracing kind of being a bit mocked and abstracted here. And then you can also go and look at the raw database here and all the log events and have a look and see or play around. That's the example. Now I forgot what I wanted to do. I wanted to make this repositor public. I got to do that right after the talk. While you prepare for your question. Thank you. So, Marcus, do we have any questions? Hello, Marcus. Thanks for the interesting talk. In a typical stack, we not only have our jungle application, but also in Chinese, micro-wiz, pos-wiz. How would we go about sharing or correlating the logs, not only the trace ideas, but the time sense, the way of having the same name for the same fields all over. Are you aware of any standards or initiatives to have consistent naming scheme for structural logs or? I think it's highly dependent on how actually you build your Microsoft architecture. So, I think one team or maybe a few, very few teams that built a whole thing of 20 services, or is it like 50 individual teams that each have their own thing where they publish an API and that's about communication between them. In the former sense, you can probably go and set some standards. This is what we call these fields, or this is a best practice on how fields are called. For example, always include an underscore ID if it's the ID of an object. And, yeah, if it's the individual teams, I think it's much harder to... I mean, you still enforce certain things there, but also if you have individual teams, you don't want to take too much of the independence away from them. I guess it depends on the particular case of your organization. It sounds, and I guess, as the whole Internet community, if nothing exists, but you're aware of it. Yeah. To expand a little bit on the previous question, JSON and structured logging is like a little bit going in both directions because if you're saving JSON into a database, what kind of structure do you have? How can you still search with a while being performant? I mean, you said you don't want to impose too many rules, but on the other hand, if you have like 200 different log messages with different fields, how are you going to search in them? How are you going to find anything again? So the JSON output is more a thing to have a structured way to write it some way in a log file or something that's then being picked up by whatever, FU and D or a file B or something, as thrown into a more or less schema as a database, or a database that can handle dynamic schemas. As I said, I think it's highly dependent on the application, on the environment where you're building your system. You probably want to have some enforcement at some point anyway, but I think there's also just a bunch of best practices that just exist. Things like you call it what it is, not what you think it should be. If it's an ID, call it an ID. If it's milliseconds, call it milliseconds, it's not something arbitrary. I guess if you're thinking about it from a, when you look at the more ops perspective, like from this in that direction, they have a couple of best practices 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 dependent on the organization. Hi, Marcus. That was a very interesting talk. It's a bit of a continuation to the previous question. A lot of places where we use more than one server in parallel, even if it's not microservices, you use some sort of logging service. A lot of those are using the ELK stack. I was wondering if StructLog has any integration with that that can make it easier to use. StructLog plays more of the role of a, it's called a replacement for the Python standard library. And then you log it to a file and have Fulbid or whatever, 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 the data store as well when the request would just take too long. Do we have any questions from the internet, Russell? Okay, then that's it. Thank you, Marcus. Thank you very much. And we will now have a break until 11.50.
 Can I get his slides on there?  Ah, awesome.  Thank you.  All right.  Good morning, everybody.  Morning.  Thanks for being here.  Thanks for the organizers for running this event.  Carlton, wherever you are, this was an amazing keynote.  I'm sure you really inspire me.  And also, when you give them a round of applause again,  because this is just fabulous.  Right.  So today, can you hear me in your back?  So today I want to talk to you about how we log information these days.  How we store information or have information available  when we run services in production.  How we, how I think that we can prove upon that  and how we can turn that into something where we can gain more information  from what we currently do.  And before we get into that, let me briefly introduce myself.  I'm Marc Solterman.  I'm a Django core contributor.  Even though I've not contributed to the core components for a couple of years now,  I tend to be more on the security team and the Django ops team these days.  In my job, I work at Crate.io, which is the company behind a database called CrateDB,  which is for IoT, satellite, data direction.  So if you want to talk about that stuff, talk to me and find me.  I'm here 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 the end.  And then you 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 we have is what we currently, what's currently come.  And 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 better.  When we log stuff these days, it's probably going to look a bit like this.  We import the logging framework from the Python standard library,  we create a logger and then we have this text of, pro-text of what's happening.  Like in this example, log in failed because a connection to an authentication provider  something jumped out and then we pass on the authentication provider.  And when this message ends up in the log files somewhere or in log service,  it's going to be like this.  Like for somebody who has decent enough 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 happened.  And in this particular case, for example, the person, the engineer who looks at this message  and sees this un-message, they can deduce that, well, somebody probably tried to log in  using some maybe OALT provider, in this case, maybe Google,  and something timed out because for whatever apparent reason,  nobody has freaking clue at that point in time because there's no additional information about that.  And yeah, this information already provides a lot of,  or 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 going to get an answer on.  What was the IP address of the host that this server that the log message was written on talked to?  What was the, where did the server try to connect you?  Or what was the timeout limit?  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 the provider?  Was it an isolated incident, or was it something that happened for hundreds of users simultaneously?  And there are even more important questions, I think,  like where were there outgoing connections of other outgoing connections affected as well?  Or was just this connection to this one service,  which as an engineer could give you additional information about its main on their side,  or is it something on your side, some routing that's broken?  And were other servers affected?  Was just this one server that failed?  Or was it like your whole fleet of service?  And I think this information we could actually add to those log messages.  You can have this message that says authentication to host whatever at points,  this failed with a timeout amount of whatever.  And then you have a five kilometers long log message that nobody's able to comprehend  because they have all the information that you could possibly want in there.  At which point I think those post-all messages are just not going to cut it,  and are not going to 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 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 string short string that provides the very necessary,  the very specific meaning that's what's happening.  And then you attach annotations or additional information attributes to this event.  All the information you have at that point that you could remotely think that could be helpful.  Like the provider name, the IP, the timeout, whatever you can come up with when you write the log message.  And then 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.  It looks obviously different than this text that we had before.  It still contains the time, the error level, or log level.  It contains the event and all the attributes that you said before.  And it also contains the server because the way we configured the strat log added the server automatically.  And you can 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 it used to do before.  And I guess the most commonly used structured format these days in the modern world anyway, and like looking XML out because that's kind of like the old thing, is probably JSON.  So we can have this structured thing log it as a JSON object into a file or into a slums and 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 elastic search, into a database like Mongo,  or any of those that can deal with structured data but are not bound to necessary specifics, specific schema.  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.  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 idolanted incident?  Well, you look at the graph and you can say, no, it's not because obviously for visually-appound reasons,  there are more cases of that error message, of that log message, that event that failed, where something failed.  And you can see that something one way or not the other way.  And I think this is far more helpful than scrolling through a million lines of log messages.  And a picture says more than a thousand words, because when you 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 and 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 ones follow the pattern that we had in the previous graph with three spikes,  and that's fine, that's what you expected.  And then the green graph, which stays pretty much at the bottom, has a few small spikes,  which is common info log message noise, let's call it that.  And that's fine, and then until the error messages on the kind of same level as green one,  because it's not the best random dataset I generated here,  the error messages, the error messages count kind of briefly inclined at 12 m.  Now, that can have all kinds of reasons.  Because what you could think about the other graph, that error happened like at this big spike,  what could have happened here is that somebody started a stale stage world,  and they ployed 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  that triggered the whole deployment to stop.  And because it didn't stop that, it went to the second stage, which you can see here.  It's increased again, but maybe it's still not enough for the whole thing to fall over to stop.  So the deployment automation just went all ahead, deployed the code to everything,  and well, there you are with your whole application failing and nothing working anymore.  Now, this is something you can see. You look at this graph and see something is wrong.  And you don't need to scroll through your million lines of log messages.  This is knowledge engineer can gain by looking at something without spending hours of time  on figuring out what's happening, especially when you have stuff like automation happen,  having these visual insights in your software kind of provides a lot of valuable information.  And this is not really possible, I mean, to some degree, sure,  but it's not really possible to do with the old, like, pro-style messages.  Now, all the things we've talked about right now were like 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.  Think about the thousands of, or maybe not thousands, but thousands or hundreds of services that talk to each other.  And this microservice framework, or make microservice architecture that you build  because your boss thought that microservice were a cool idea and it's the best idea ever.  Who of you think that the microservice architecture they have actually is like stable  and they have services that when someone's service falls over, it doesn't make the whole thing blow up?  Anybody? I see one hand up there in the back.  Good on you.  Because I think that a lot of the information that we currently have and that we currently do with logging  is not giving us actually the information that we need in order to figure out why, when one service 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 a 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 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 this one thing a user did on your frontend?  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 plus sign before yet.  And all of a sudden, your entire billing process dies because you have some broken error handling in there.  If the service dies and you don't have any tracing in there, you're going to have a very, very, very interesting time figuring this out.  And so the thing I want to propose here is to do something called event tracing.  Essentially, the very first time you see a request come to your system, you give it a unique ID.  Python's UI ID for example is quite sufficient for that.  It's unique, it's pretty much globally unique.  You attach it to the request the first time it comes in, and then every single time you log anything ever,  you attach this trace ID to this log. And because you have structured logging, you can just add this attribute.  And you can even go further because then you pass this trace ID onto the next service, onto the next, onto the next.  You put it in the queue, the salary worker is going to figure this out, see, oh, there's a trace ID.  I should probably attach that to all the log messages right 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 trace ID.  And then you can see the whole flow of how your whole data flew through your entire architecture.  With that, you can actually understand why some service failed because something happened somewhere else.  And well, we are a Django console, I better show some codes related to Django.  So we have the structure library, we have the logging frame, the structure docker.  And this is a middleware for, but you just put as middleware in the first middleware 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, a trace ID, or it generates a new one.  So if a request comes in from the outside world, and you do proper filtering on headers,  like all the security nonsense, not nonsense, all the security things, you actually want to do,  then you can assert that the trace ID is generated by yourself, or that when you talk to the service from other services in your backend,  then you can assert that this actually is one of your trace IDs.  So it's either a new one or some trace ID that comes from, because it's a request from one of your other services.  You create a new logger here in the middleware, that's some struct log internals, it's a thread local behavior, I guess.  And this one with this trace ID equals request, trace ID, you will assert that everything that happens within this request  will have this trace ID attached to it, every single log message ever, until the request is terminated,  or the next request rather comes in at which point it's going to have a new trace ID.  And then similarly, you can put something after the authentication middleware, for example,  and you bind the user ID on the logger.  Everything from that point onwards will include the user ID of the currently logged in user,  or no trace ID, or no user ID if the user is not authenticated.  Now, we're in the EU, we have a whole bunch of interesting relations,  and thinking about DrangoCon last year, there was this four letter thing called GDPR.  So, logging data these days is actually pretty fun, or actually pretty something you really want to think about what you do.  For example, you never ever want to log secrets.  Hello Facebook, hello GitHub, hello Twitter.  If you want to have your company's name next to that, please do that, and like, log user's password or something.  I recommend you don't do that, it's bad practice actually, so I've heard.  Also, you kind of don't want to accidentally expose all the logs that you log 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.  Similarly to something called MongoDB, which is like one of those, I don't know why,  but when you read certain newsletters, this is like every week there's somebody else who has a publicly accessible MongoDB.  I mean, I never say never, but so far I've not had that.  I think something fell over there.  And then be explicit about what you log.  I guess that's the more important part about the GDPR thing.  So, don't do the first one, like, set explicit attributes that you want to 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.  All it might not just work.  Right, so with a bit less than 10 minutes left, who the heck is Frank Taylor, Jr.?  Let me answer that with a slightly different question.  Who here knows the movie, catch me if you can.  Okay, everybody, let me give you a brief answer.  It's the main character is a person called Frank William Abagnale and he figures out a bunch of cons,  where he cons banks, airlines, airports, hotels, like all those 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 the reasons why nobody's able to trace him is because he figured out how, or he was smart enough to cover his tracks.  And he figured out how to work around the US check routing system by forging checks and having them routed through the whole country.  And the thing is that when you take this example from the real world and apply to something like Microsoft's 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 that we currently do in most cases, I think,  we can gain far more information and can get 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, a lot of gain by going into a more structured logging approach.  And at this point, I wanted to go with a more live demo but didn't actually have time to finish that.  So also, I'm freeing a scale of live demos on stage and I promise myself I'll never do that.  So I caught an example.  There's a code on GitLab.  If you want to run this thing, it's a Docker Compose setup.  We essentially replace this catch me if you can thing a bit.  You have an engine X startup page, engine index page that you can visit.  It comes up with two banks that you can deposit money and wire checks and wire money from one person to another.  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 how this wire transfer from one bank to another  flew through the system or how this check that you use to pay for this flight ended at this bank,  but because that's a local bank and then needed to go through the other side of the country,  all those events, this event tracing kind of being a bit mocked and abstracted here.  And then you can also go and look at the raw database here and all the log events and have a look and see or play around.  That's the example.  Now I forgot what I wanted to do.  I wanted to make this repositor public.  I got to do that right after the talk.  While you prepare for your question.  Thank you.  So, Marcus, do we have any questions?  Hello, Marcus.  Thanks for the interesting talk.  In a typical stack, we not only have our jungle application, but also in Chinese, micro-wiz, pos-wiz.  How would we go about sharing or correlating the logs, not only the trace ideas, but the time sense,  the way of having the same name for the same fields all over.  Are you aware of any standards or initiatives to have consistent naming scheme for structural logs or?  I think it's highly dependent on how actually you build your Microsoft architecture.  So, I think one team or maybe a few, very few teams that built a whole thing of 20 services,  or is it like 50 individual teams that each have their own thing where they publish an API  and that's about communication between them.  In the former sense, you can probably go and set some standards.  This is what we call these fields, or this is a best practice on how fields are called.  For example, always include an underscore ID if it's the ID of an object.  And, yeah, if it's the individual teams, I think it's much harder to...  I mean, you still enforce certain things there, but also if you have individual teams,  you don't want to take too much of the independence away from them.  I guess it depends on the particular case of your organization.  It sounds, and I guess, as the whole Internet community, if nothing exists, but you're aware of it.  Yeah.  To expand a little bit on the previous question,  JSON and structured logging is like a little bit going in both directions  because if you're saving JSON into a database, what kind of structure do you have?  How can you still search with a while being performant?  I mean, you said you don't want to impose too many rules,  but on the other hand, if you have like 200 different log messages with different fields,  how are you going to search in them?  How are you going to find anything again?  So the JSON output is more a thing to have a structured way to write it some way in a log file or something  that's then being picked up by whatever, FU and D or a file B or something,  as thrown into a more or less schema as a database, or a database that can handle dynamic schemas.  As I said, I think it's highly dependent on the application,  on the environment where you're building your system.  You probably want to have some enforcement at some point anyway,  but I think there's also just a bunch of best practices that just exist.  Things like you call it what it is, not what you think it should be.  If it's an ID, call it an ID. If it's milliseconds, call it milliseconds, it's not something arbitrary.  I guess if you're thinking about it from a, when you look at the more ops perspective,  like from this in that direction, they have a couple of best practices 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 dependent on the organization.  Hi, Marcus. That was a very interesting talk.  It's a bit of a continuation to the previous question.  A lot of places where we use more than one server in parallel,  even if it's not microservices, you use some sort of logging service.  A lot of those are using the ELK stack.  I was wondering if StructLog has any integration with that that can make it easier to use.  StructLog plays more of the role of a,  it's called a replacement for the Python standard library.  And then you log it to a file and have Fulbid or whatever, 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 the data store as well when the request would just take too long.  Do we have any questions from the internet, Russell?  Okay, then that's it. Thank you, Marcus.  Thank you very much.  And we will now have a break until 11.50.
DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_0_707.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_708_7727.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_7728_7811.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_7812_10043.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_10044_13979.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_13980_14111.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_14112_22199.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_22200_24047.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_24048_24107.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_24108_24947.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_24948_25655.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_25656_25991.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_25992_26123.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_26124_26207.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_26208_29915.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_29916_31451.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_31452_36659.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_36660_36755.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_36756_37811.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_37812_38627.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_38628_38747.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_38748_39047.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_39048_39095.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_39096_39143.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_39144_39191.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_39192_40019.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_40020_40115.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_40116_40523.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_40524_40799.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_40800_42851.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_42852_43655.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_43656_43727.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_43728_44267.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_44268_46019.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_46020_46391.png DjangoCon_2019_-__Logging_Rethought_2__The_Actions_of_Frank_Taylor_Jr_46392_46501.png