025 RR Logging – I Do Not Think It Means What You Think It Means

I have recently put together some material related to logging. Streams of Data Part I - logging basics video: http://vimeo.com/30931422 notes: https://gist.github.com/1305172 Part II - event streams slide deck: http://dl.dropbox.com/u/1579953/talks/streams_of_data_2.pdf

Oh, look, the previous commenter suggested that as well. (=

Haven't finished listening to the episode yet, but someone asked a question about how to trace log messages related to one specific request, when you might have several Rails processes writing to the same file. Coincidentally, I was just listening to a Pivotal Labs tech talk the other day ("Magic Scaling Sprinkles", link) where Nick Kallen suggests generating a GUID for each request that comes in from outside, and then passing it around with every message. His point was that, as you start doing more SOA-type stuff, it's really hard to associate all the different little bits of work that got done to service one request; having a GUID gives you something to tie all that stuff together with. However, that could help in a Rails-only scenario as well. (Another thought: in a SOA environment, it might be desirable to have an appender that shoves messages on a queue or a pub/sub topic.)

Log levels should die in the horrible death they deserve. Here is my death sentence to them: 1. Don't use logs to display the state/performance of your program. Replace all those logs by application metrics. See https://github.com/johnewart/ruby-metrics . 2. Don't use logs to display application errors. Replace all those logs by an external notification system like airbrake (no, not email!) 3. Don't use logs to verify the correct execution of your code. Use unit tests, introduce #assert checks in your code and use #fail for execution paths that should not happen. By now, the remaining logs should all be trails of interaction with external services (SQL, HTTP, ...). If anything else, I'm curious to hear about them :) . Put them all on LOG_INFO level. Done. Bonus for HTTP services: create a rack adapter that creates a unique ID for each request and insert it in all log message with the PID of the process of the whole request/response round-trip. Bonus 2: instead of interpolating the values in your log message, create a log function that keeps the argument separated. You can always put them together later if a human needs to read them. In the mean time, you can also build tools more elaborate than grep to analyze them. Example: log("http request from {source_ip}, ...", :source_ip => env["X_REQUESTED_WITH"])