7 ms·
How To Write Good Log Messages
- slyphon 14y agofinally! someone needed to write this, if only to have something to point junior devs to. :)
- VikingCoder 14y agotime is expressed in seconds? My computer does about 3 billion things every second. I think milliseconds or preferably microseconds would be much better. Different domains have different needs, though, I'm sure. Also, I'd prefer the log specify the time zone it thinks it's in, rather than just convert to UTC automatically. pid - yes, knowing the process id is good, but knowing the thread is also useful. version - outputting this on every single log line is probably overkill. Ditto for host name.
- trotter_cashion 14y agoThanks for the feedback. I'm with you on the milliseconds and threads bits. As for hostname / version... how are you getting those into your logs? I've found having version in the logs very useful (and wished I had it when it wasn't there).
- pydave 14y agoCouldn't you output the host and version at the beginning of the log? Any tool that transforms the logs (splicing together logs from different servers) should include these bits in it's output. Also, why don't you use a sortable form for time? (With the most significant parts first.)
- trotter_cashion 14y agoMy issue with host and version at the beginning of the log is that they'll roll away when your logs rotate. If you've got a service that's rarely taken down, anything written to the front of the logs is likely long gone by the time you have a problem. That said, there may be a better way to handle these two. I certainly don't like repeating information if it's not necessary.
- nitrogen 14y agoYou could just print the version, etc. again when logrotate sends your daemon a SIGHUP.
- trotter_cashion 14y agoAhh... never thought of doing that. I like it.
- eru 14y ago> I certainly don't like repeating information if it's not necessary. On what grounds?
- dinkumthinkum 14y agoI don't think outputting the version is overkill at all. It's much easier and simpler to deal with it this way. Probably the nanosecond business is very much overkill, that only matters for a smaller subset of problem domains.
- mseebach 14y agoWhether the version is overkill depends on the frequency of version changes. If you're doing careful corporate releases with staging and QA on a two-month basis, it's definitely overkill - if you're doing continuous deployment with several releases daily and different systems running different versions concurrently, it's probably valuable.
- eru 14y ago> Also, I'd prefer the log specify the time zone it thinks it's in, rather than just convert to UTC automatically. But my computer thinks it's clock is in UTC, and it only converts to a timezone for human readable dates.
- pacaro 14y agoThis. UTC is not only unambiguous, but on some systems measurably faster to capture. My experience has taught me to work in UTC everywhere possible, local time is typically only relevant for direct human interaction.
- cluda01 14y agoA caveat here as well is you also need to make sure your various clocks in the data center are synched. This is one of those common but overlooked scenarios which lead to hilarious discussions about latency when really there was just a clock synch problem. Additionally the fallacies of distributed computing come into play here (namely, transport cost is 0) so you need to take extra care when looking at measurements across different systems and machines. Even machines in the same data center. The pipe that you are communicating across could be oversubscribed for example.
- eru 14y agoYes. But you get all those problems plus more, if you convert to local time first.
- philjr 14y agoThis link from a talk by Jordan Sissel has some great information on logging and information that's commonly missed in log files (even in some very large products) http://blip.tv/carolinacon/logstash-open-source-log-and-event-management-jordan-sissel-5123601 http://blip.tv/carolinacon/logstash-open-source-log-and-even...
- shell0x 14y agoI reviewed my some of my code and figured out that I'm one of this terrible persons, which haven't spent enough time to show an useful output. I should fix this now ;) A useful log output can be a real time saver. I also seen applications which just showed "an error occurred", so I had still no idea what causes this error message.
- memset 14y agoI personally have found a lot of difficulty with JSON-based logs, because tools like `grep` and `cut` don't suffice; I usually have to write a more complex regex with `sed` in order to extract useful information I want. Anyone have a good utility for managing JSON in log files?
- mgurlitz 14y agoMoving away from using regex to parse JSON, you can use Jsawk and Underscore-cli to manipulate JSON like Awk or JavaScript. https://github.com/micha/jsawk/ https://github.com/micha/jsawk/ https://github.com/ddopson/underscore-cli https://github.com/ddopson/underscore-cli
- gbog 14y agoBut the problem is speed. I found that if parsing logs is slow, bug hunting is far less efficient.
- robmil 14y agounderscore-cli is utterly brilliant for this, even better — dare I say it? — than traditional log files with cut/grep/awk. Being able to treat logs as a dataset that can be mapped/reduced/flattened/grouped/otherwise analysed is life-changingly good. About the strongest endorsement I can give is that it makes me wish more of my logs were in JSON format, rather than wishing that less were as I always had before.
- jcrites 14y agoRecordStream is a great solution for manipulating JSON log files: https://github.com/benbernard/RecordStream https://github.com/benbernard/RecordStream - makes it easy to perform relational-style operations, such as grouping, counting (recs-collate), and even joins (recs-join). It can also display and transform the logs in a variety of ways (recs-tocsv, recs-totable, recs-tognuplot for graphing). There are also tools to extract records from other data formats such as CSV or by querying a database. All in all, a fantastic tool for manipulating and querying complex data from the command line. I use it regularly.
- 14y ago
- 3amOpsGuy 14y agoOne of the hardest things in ops is trying to see what the app is doing without benefit of the code to review. I know what the app does, I know the process flows involved but 'failed to covert X at MyClass:44' doesn't have enough context for me. Also log levels - most developers over use warning and error levels and under uses debug and trace in my experience. It makes filtering out the noise harder. Rolling log files - roll on an event (new day, process bounced etc.) not on reaching a 10Mb limit or an equally arbitrary 1k lines limit. Use a header in the logfile, contain at least the version number of the code running, the user and host it is running on. Lastly stack traces, if they even have a use case at all in production, should not be in the main logfile.
- nitrogen 14y agoLastly stack traces, if they even have a use case at all in production, should not be in the main logfile. I would have to disagree with this one. There's no way to generate the stack trace after the fact if a particular bug is extremely rare; having a complete call chain makes fixing the problem much easier. Someone once said that removing error handling once the code is working is like removing the landing gear once a plane is airborne.
- Pfhreak 14y agoI always use warning to indicate something actionable for the developers. Some condition they should add to their next sprint, for example. An error is something actionable that needs to be responded to soon. You probably don't need to send a page, but an error is a serious condition. Stack traces are extraordinarily useful in your logs. When code breaks (and it will), you want as much information surrounding that event as possible.
- moe 14y agoroll on an event (new day, process bounced etc.) not on reaching a 10Mb limit Only applicable when you produce a small, predictable volume of logging. Not a good general guideline because often you don't know how big your system may grow in the future. When logging high volumes then fixed chunk sizes are usually preferable (e.g. so you know how many you can keep around without a disk running full). Large sites produce multiple gigabytes of logs per hour. Use a header in the logfile Disagree. Context should be provided directly in each individual line. Logs get sliced and diced in analysis, fetching an arbitrary header from the right file for a given context can be rather painful. Don't be afraid of long lines. Use field delimited formats (TSV) so they can be easily parsed (either via 'cut' or a small script). stack traces ... should not be in the main logfile Wrong. When a serious error occurs then as much context as feasible must be provided. Stack traces are usually very feasible and indispensable.
- jamesaguilar 14y agoMost important point: any log message that doesn't identify some property of the request that originated it (so that you can identify requests leading to erroneous conditions) is cause for immediate defenestration.
- sarabob 14y agoAgreed. We use mod_unique to add a header to each response and make sure it's included in each error log, back end access log and front end access log as well as being viewable via Charles/fiddler at the client. Being able to tie the various logs from different machines together has been invaluable.
- shazow 14y ago"08-08-2012-20:27:59" Which 08 is the day or the month? cut -d ' ' -f2- foo.log | sort Great, now it's sorted by (month, day, year) or (day, month, year). If my logs span multiple years, the sorting is useless. Please use YYYY-MM-DD. It's sortable and more intuitive for everyone outside of the USA. See also http://en.wikipedia.org/wiki/ISO_8601 http://en.wikipedia.org/wiki/ISO_8601
- deleted 14y ago[deleted]
- shazow 14y agoI'm not advocating internationalization. I'm advocating for using a well-known formatting standard used by almost every mature library which is unambiguous and useful for sorting.
- trotter_cashion 14y agoMore like the author was lazy and not thinking about correct ordering of the date there. It should absolutely be yyyy-mm-dd. I'll be updating the post w/ feedback from the comments sometime today or tomorrow. So expect to see that change.
- harshreality 14y agoPlease also use a T between date and time parts, per the standard. Making stuff up requires everyone parsing your timestamps to use custom parsing.
- Pfhreak 14y agoStill doesn't solve the sorting problem. YYYY-MM-DD produces sortable strings without needing to parse them.
- deleted 14y ago[deleted]
- 14y ago
- Jimbotron 14y agoIn my experience the measure of good logging is the ability for someone, either yourself or an operations engineer to be able to easily solve problems using only the logs. They shouldn't have to refer to the source code. Developers should be using this as the yardstick when asking questions about their log output.
- Pfhreak 14y agoUTC is great for timestamps, but he needs to make his times sortable (YYYY-MM-DD) Tab delimited fields are a problem, unless you escape the tabs inside the data you log. This format seems VERY similar to the Graylog Extended Log Format (or GELF) https://github.com/Graylog2/graylog2-docs/wiki/GELF https://github.com/Graylog2/graylog2-docs/wiki/GELF I'm a huge fan of JSON logs now, having just finished implementing them on a major work project. Every language out there can take JSON in and do work against it, and there are some really awesome tools for rendering filtered logs to a browser in realtime.
- mseebach 14y ago> Tab delimited fields are a problem, unless you escape the tabs. I don't understand this? A tab is a tab? > JSON Downside: File size. If you have any appreciable level of traffic/activity this matters.
- eru 14y agoThey should compress well.
- Pfhreak 14y agoIn fact, they compress to about a 3% of their size. Since they really only exist in text file form for a limited period of time before being moved on to a separate logging system, their exploded size isn't much of a concern.
- lost-theory 14y ago> I don't understand this? A tab is a tab? How do you differentiate between tabs that the logger generates, and tabs inside log messages? You need to escape the tabs inside messages. This problem exists with any character delimited format (e.g. csv).
- adamzochowski 14y ago> I don't understand this? A tab is a tab? I think the parent meant that a problem could be if data itself contains a tab character, causing an offset during parsing.
- gwillen 14y agoThis may be a bit out of scope for this post, but at Google I used to get a lot of mileage out of a system I worked on called Dapper: http://static.googleusercontent.com/external_content/untrusted_dlcp/research.google.com/en/us/pubs/archive/36356.pdf http://static.googleusercontent.com/external_content/untrust... It uses thread-local storage and RPC library instrumentation to thread a fixed request-id through every RPC call and thread handling a particular user request. Then you can do things like automatically adding the request ID to log messages, transparently to the request-handling code. And when you visualize logged RPCs, you can include (some subset of) the logged messages in your visualization.
- emmelaich 14y agoDapper looks fantastic. It reminded me somewhat of the ancient ARM (1996) http://en.wikipedia.org/wiki/Application_Response_Measurement http://en.wikipedia.org/wiki/Application_Response_Measuremen... which I thought had died. I was pleasantly surprised to see that there's a module for Apache in the works.
- gwillen 14y agoWow, that's cool. The two systems are very similar, and I wouldn't be shocked if ARM was the inspiration for Dapper.
- roryokane 14y agoSo how do you implement this? In your Rails apps, what kind of library do you use to write log messages in this format? Is it an open-source library or one you wrote just for your company?
- arockwell 14y agoLook at the ruby libraries for syslog. Iirc, there is a ruby standard library for syslog.