Log for Machines(journal.paul.querna.org)
journal.paul.querna.org
Log for Machines
http://journal.paul.querna.org/articles/2011/12/26/log-for-machines-in-json/
11 comments
>Here's the thing: I can do anything with a human
>readable text log. I can scan it visually and look for
>anomalies; I can use my favorite text editor with it; I
>can grep it; I can cobble together some magic
>incantation on a command line to munge it to death
>until it cries out in mercy and gives me exactly what I'm looking for.
>But if I ever open up a server log and get blasted by a jillion
>lines of JSON that make it a thousand times harder for me to figure
>out how something broke I'm going to go on a shooting spree.
>host.com:80 w.x.y.z - - [25/Dec/2011:06:07:42 -0600] "POST /page/open HTTP/1.1"
>200 1200 "-" "Mozilla/5.0 (Windows NT 5.1; rv:8.0) Gecko/20100101 Firefox/8.0"
>{'host':'host.com', 'timestamp':'2011-12-25 06:07:42', 'method': 'POST',
>'path':'/page/open', 'protocol':'HTTP 1/1", 'response_code':200,
>'content_length':1200, 'user_agent': 'Mozilla/5.0 (Windows NT 5.1; rv:8.0) Gecko/20100101 Firefox/8.0'}
>{'host':'host.com', 'timestamp':'2011-12-25 06:07:42', 'method': 'POST', 'path':'/page/open',
>'db_time':0.157, 'app_time':0.43, 'protocol':'HTTP 1/1", 'response_code':200,
>'content_length':1200, 'user_agent': 'Mozilla/5.0 (Windows NT 5.1; rv:8.0) Gecko/20100101 Firefox/8.0'}> ...isn't all garbagy like XML...
I don't think it's fair to take something that isn't garbagy at all and then say that the proposed alternative isn't bad because it's not as garbagy as one of the garbagiest things ever invented. :-)
JSON may not be as garbagy as XML, but it's still garbagy. With logs in their current format, often my very first tool in log analysis is the scroll wheel on my mouse. It's so lovely because all the lines are unbroken, the columns line up so neatly, and the data in the columns are so distinct from each-other. JSON dicks all that up.
Now, OK, I'll admit it wouldn't be very hard for me to whip up something that will take a JSON-formatted log and turn it into something I actually want to read. And in fact that's exactly what I'd end up doing.
But, logs are already getting big enough that some companies are doing very stupid things to them. (Bluehost, by default, logs only the last 24 hours for all hosted sites; if you turn on their "extended" logs feature, their logs still have huge gaps in them.) JSON makes that problem a lot worse for those companies. And, if their log rotation isn't set up correctly -- and if they're doing vhosting I'll bet you a donut it's not -- then what would have been a silly amount of data to process now becomes nearly impossible to process.
I don't think it's fair to take something that isn't garbagy at all and then say that the proposed alternative isn't bad because it's not as garbagy as one of the garbagiest things ever invented. :-)
JSON may not be as garbagy as XML, but it's still garbagy. With logs in their current format, often my very first tool in log analysis is the scroll wheel on my mouse. It's so lovely because all the lines are unbroken, the columns line up so neatly, and the data in the columns are so distinct from each-other. JSON dicks all that up.
Now, OK, I'll admit it wouldn't be very hard for me to whip up something that will take a JSON-formatted log and turn it into something I actually want to read. And in fact that's exactly what I'd end up doing.
But, logs are already getting big enough that some companies are doing very stupid things to them. (Bluehost, by default, logs only the last 24 hours for all hosted sites; if you turn on their "extended" logs feature, their logs still have huge gaps in them.) JSON makes that problem a lot worse for those companies. And, if their log rotation isn't set up correctly -- and if they're doing vhosting I'll bet you a donut it's not -- then what would have been a silly amount of data to process now becomes nearly impossible to process.
>> ...isn't all garbagy like XML...
>I don't think it's fair to take something that isn't garbagy at all
>and then say that the proposed alternative isn't bad because it's not as
>garbagy as one of the garbagiest things ever invented. :-)
EDIT: hey, I ignored most of your reply and that's rude:
My first tool for debugging Apache is 'less', so I would be screaming and yelling if JSON logs were harder to read than non-JSON logs.
Agreed about the size of the logs, but JSON logging seems to only change the caliber of the handgun used to shoot yourself in the foot, not turn it into a Howitzer.
RFC-5424 describes a format to log structured data via syslog, so why do we need JSON again? (five years ago, I bet this proposal would have used XML for encoding)
as a big data guy, every time i see structured data written in an unstructured, non standard, and possibly ambiguous and unparseable format i get the same urges. i think the best solution is separate logs for human consumption and machine consumption. if someone logs data that they want analyzed in some goofy format then they can also write and maintain their own damn parsers for it, i don't have time for that shit and the solution is so simple.
Yeah, I can grok that. I think that the needs of big data are a bit different from the needs of troubleshooters. For example, I usually just need to sift through the data to quickly find the few bits that are interesting to me; you probably need to do aggregation and derive patterns and all kinds of other magic.
I would only counterpoint that what I wrote was not at all a defense of badly-formatted logs.
I'm also not at all opposed to people generate separate logs for humans and separate logs for machines. In fact, I think that's a great idea. I just really really do not want to see machine logs taking the place of human-readable logs.
I would only counterpoint that what I wrote was not at all a defense of badly-formatted logs.
I'm also not at all opposed to people generate separate logs for humans and separate logs for machines. In fact, I think that's a great idea. I just really really do not want to see machine logs taking the place of human-readable logs.
You could easily make a small unix filter that takes the json logs in, and spits out strings with "%date : %short_message" from them - enabling you to use them just like all of your other one-line-per-entry unixy plain logs.
Machine-readable logs are a win. JSON is very close to providing the holy grail, machine _and_ human readable.
tail -f logfile | grep blah
tail -f logfile | json2line | grep blah
Machine-readable logs are a win. JSON is very close to providing the holy grail, machine _and_ human readable.
In what format should that filter output? Which fields should it show? Should it be specific for the application or should it be generic? What parameters should it accept in this case?
Do you see where I'm going with this?
We have been using text-based logs and text-based pipes on unix for decades, even though it has always been inefficient to parse (especially on ancient machines). The thing is: it's much more efficient for humans.
I understand the kind of cognitive dissonance this causes in programmers, I feel it myself. However, I've also been a sysadmin for a few years now and understand just how having plain text makes my life (much) easier.
Do you see where I'm going with this?
We have been using text-based logs and text-based pipes on unix for decades, even though it has always been inefficient to parse (especially on ancient machines). The thing is: it's much more efficient for humans.
I understand the kind of cognitive dissonance this causes in programmers, I feel it myself. However, I've also been a sysadmin for a few years now and understand just how having plain text makes my life (much) easier.
Fine, then:
(To answer your question directly: The filter should be generic, and should allow you to specify simple format strings to be yanked out of top-level json fields.)
tail -f logfile | json2line '%date %name %level %shortmsg' | grep expr
(To answer your question directly: The filter should be generic, and should allow you to specify simple format strings to be yanked out of top-level json fields.)
I often find myself troubleshooting applications for which I know little about, or that I don't have to troubleshoot often enough (fortunately). I don't want to have to look what fields are available in the log to prepare the proper format string with the fields that I want because... I do not know what I want.
I want to go to "/var/log/application" or whatever place the application stores its logs, and cat/tail whatever it is there and seems remotely related to the problem at hand.
This is one of the reasons it is painful to troubleshoot problems in Windows using PowerShell, where what you suggested is more or less what needs to be done to parse the event log in a more intelligent way that filtering stuff using the Event Viewer.
This shows in the speed and efficiency in solving issues with unix vs. windows systems.
But you can say that's just my anecdotal evidence.
I want to go to "/var/log/application" or whatever place the application stores its logs, and cat/tail whatever it is there and seems remotely related to the problem at hand.
This is one of the reasons it is painful to troubleshoot problems in Windows using PowerShell, where what you suggested is more or less what needs to be done to parse the event log in a more intelligent way that filtering stuff using the Event Viewer.
This shows in the speed and efficiency in solving issues with unix vs. windows systems.
But you can say that's just my anecdotal evidence.
This falls under "good intention, but not well planned out" IMO. Single line logs are MUCH easier to process with text-oriented tools, which is why they've stuck around for so long.
This solves the encoding problem, but not the "how do I read/search it" problem, which is kicked down the line to other tools. And having a different format for every daemon is just a new problem.
I'd look at how others have dealt with the problem - for example, Logstash, which is a log parsing and movement engine:
http://logstash.net/docs/1.0.17/learn
Also, timestamps aren't recommended for storing time data - they're not human readable, and convey less information than something like ISO8601 which covers more edge cases.
This solves the encoding problem, but not the "how do I read/search it" problem, which is kicked down the line to other tools. And having a different format for every daemon is just a new problem.
I'd look at how others have dealt with the problem - for example, Logstash, which is a log parsing and movement engine:
http://logstash.net/docs/1.0.17/learn
Also, timestamps aren't recommended for storing time data - they're not human readable, and convey less information than something like ISO8601 which covers more edge cases.
Not this again...
There may be any number of automated agents consuming the log, so a human isn't the largest consumer of log messages (in volume), but it is the first consumer of log messages as it is a human that ultimately will need them to troubleshoot issues.
Programmers are not the ones who "debug" issues in production environments.
Both of these are just symptoms of the same base misconception about how systems administrators go about their work. The same misconception that brought us XML configuration files.
When troubleshooting production issues I want to be able to grep for specific strings or regular expressions. I want to be able to tail the log. I do not want to have to parse structure (programatically or mentally), I do not want multi-line log entries. I do not want to be forced to use a tool just to transform the log from whatever format into something I can read.
Going even further: often production issues arise when only people less familiar with the system are available locally. In these cases I don't want to explain log structure over the phone.
* The first level consumer of a log message is a human.
* The programer knows what information is needed to debug an issue.
I believe these presumptions are no longer correct in server side software.
There may be any number of automated agents consuming the log, so a human isn't the largest consumer of log messages (in volume), but it is the first consumer of log messages as it is a human that ultimately will need them to troubleshoot issues.
Programmers are not the ones who "debug" issues in production environments.
Both of these are just symptoms of the same base misconception about how systems administrators go about their work. The same misconception that brought us XML configuration files.
When troubleshooting production issues I want to be able to grep for specific strings or regular expressions. I want to be able to tail the log. I do not want to have to parse structure (programatically or mentally), I do not want multi-line log entries. I do not want to be forced to use a tool just to transform the log from whatever format into something I can read.
Going even further: often production issues arise when only people less familiar with the system are available locally. In these cases I don't want to explain log structure over the phone.
There's actually a plan to replace syslog with something that's easier to create tools for.
https://docs.google.com/document/pub?id=1IC9yOXj7j6cdLLxWEBA...
https://docs.google.com/document/pub?id=1IC9yOXj7j6cdLLxWEBA...
I wonder if we need text logs at all anymore. It seems silly to expect people to be able to read millions of log entries from tens, hundreds or even thousands of servers. Maybe binary logs using protocol buffers or thrift are the way of the future.
Maybe.
Protobuffers or Thrift can definitely be smaller in byte size, which does matter somewhat, but JSON right now is just more easily accessible.
I think in a few years, assuming JSON logging really takes off, you'll see people using these other RPC formats in order to optimize and reduce the size of their messages.
I view 'better' RPC formats as a performance optimization of the same basic idea though: Easily add new fields, and use a format designed for computers to consume.
Protobuffers or Thrift can definitely be smaller in byte size, which does matter somewhat, but JSON right now is just more easily accessible.
I think in a few years, assuming JSON logging really takes off, you'll see people using these other RPC formats in order to optimize and reduce the size of their messages.
I view 'better' RPC formats as a performance optimization of the same basic idea though: Easily add new fields, and use a format designed for computers to consume.
JSON lends itself pretty well to compression as well so a binary format might not buy you as much as you think.
What would be binary data? The only possible thing I could think of would be the timestamp. Everything else would most likely be text, ASCII for English speakers, UTF-8 otherwise.
Regardless of the syntax for encoding a server event, having a request id (txnId in the post) is an often overlooked detail. See how Google do this in their systems: http://highscalability.com/blog/2010/4/27/paper-dapper-googl...
Before tea, standard sysadmin response: NO
After tea and some thought: No thanks
After tea and some thought: No thanks
Apache Flume also xfers things in json.
s,JSON,BSON,g
These logs are for machines, and should be compact -- why use JSON at all?
These logs are for machines, and should be compact -- why use JSON at all?
Two reasons:
Easily read by human *and* by machine;
Highly compressible since it's full of repeating strings.
One could imagine a "bzoncat" utility which simply reads bson objects on stdin and emits formatted json objects on stdout. I don't know, the difference probably doesn't matter.
Oh christ. I'm pretty sure my sysadmin friends would murder anyone that tried this on their boxen. As an engineer, while I appreciate the amount of shiny going on here, I doubt that adding yet another layer of tooling requirements to dealing with logs is the right answer--this could lead to serious ax-sharpening of picking the best JSON-to-readable scripts, and you can bet your ass that'll be different on every machine, install, site, etc. etc.
All that being said, I could see this being hilariously useful in game development. Having little JSON crumbs dribble out during playtesting and QA would be really handy, and that is an area where data mining is actually quite useful. Having a trivial way of sorting through crumbs by issue or tester, and then being able to, say, project the bugs into an HTML5/WebGL-based tool for devs to use would be really nifty.
All that being said, I could see this being hilariously useful in game development. Having little JSON crumbs dribble out during playtesting and QA would be really handy, and that is an area where data mining is actually quite useful. Having a trivial way of sorting through crumbs by issue or tester, and then being able to, say, project the bugs into an HTML5/WebGL-based tool for devs to use would be really nifty.
Social games has been doing this for 2+ years already, with JSON log files scraped into various databases and viewed using web tools for everything from A/B test impressions to virality to monetization to error logging (especially useful when you can't get the error to reproduce locally).
I spend all day every day troubleshooting broken things. Human readable logs are the very last thing that I have left that leaves me with any energy to keep troubleshooting things. If you take that away from me too, I swear I'm going to shoot somebody. (If I have any sense left when I go 'round the bend, I'll target a software engineer that thought it would be a good idea to fix what wasn't broke.)
Here's the thing: I can do anything with a human readable text log. I can scan it visually and look for anomalies; I can use my favorite text editor with it; I can grep it; I can cobble together some magic incantation on a command line to munge it to death until it cries out in mercy and gives me exactly what I'm looking for.
If I have to use somebody's special web-based woo-widget to view and search the contents of a log, if I'm restricted to the limits of their imagination when it comes to trying to get useful information out of the log, if I have to debug their dumbass invention while somebody's time-critical server is flopping around on the floor before I can even begin to figure out what in the heck is actually wrong with the server, I'm going to be stupid not to give up completely on support.
If you want to log information which is useful to you, you can do that without hardly any trouble at all without replacing perfectly good, reliable logging facilities which are the way they are for damned good reasons. Just write a Ruby whatchamacallit or a Python thingamajig or a PHP flibbedyfloo and log it to your MySQL database or your Postgres database or your no-sql nuh-uh-it's-not-a-database. I don't care.
But if I ever open up a server log and get blasted by a jillion lines of JSON that make it a thousand times harder for me to figure out how something broke I'm going to go on a shooting spree.