Logging has become increasingly important for web application developers looking to take advantage of their data to better optimize their marketing and development efforts. Until recently I accepted the way that Rails wrote logs as gospel, not wanting to upset the Rails gods I left them alone in both production and development environments. Until recently….
My company has been using loggly for a while to observe behavior changes and events happening in, they provide a great interface for querying and filtering log data and allow you to view those queries with a large number of visualization options. Additionally they archive all logs to S3 for future analysis.
One feature of loggly’s that sets it apart from just storing logs is it’s ability to filter and correlate structured data. If you send your data to loggly as a json doc you can instantly filter on attributes and sub attributes as if they were columns in a database. This turns out to be hugely useful if you are trying to understand your application in aggregate.
Typical Rails logs do not output json, instead they output a fairly verbose string describing what happened. This is great for humans as it is fairly easy to read, but not particularly great for machines that handle structured data much better. JSON would be better in many cases, as it is immediately parseable by a huge number of code libraries.
Another gripe I have with default rails logging is that it’s very difficult to track all the data related to one particular request. The problem is that multiple processes write to the log at once leading to an overlap of log information in production.
Lastly, current_user tracking is an absolute must if you want your logging to double as an audit trail which is something we’ve always wanted at my company but up until this point have not had a great way of achieving. Taking all these requirements into consideration I decided to fix our logging to give us more of what we need and remove most of what we don’t in production. The following is the code we are using to make our logging much much better. I tried to comment the code where appropriate, but if you have questions feel free to comment and I can address any concerns.
So far the code above handles unique requestID’s, removal of old log format, and replacing with new JSON format. What we are missing is user tracking for future analytics and auditing needs. The following code should be added to the same initializer. The basic idea is that we need to improve our payload to hold additional data about the request being made. While we could use the Thread.current object, Rails gives a better way to handle this so I present the following solution.
This is what we run in production at Music Xray if you found this at all useful or take issue with the implementation, please feel free to leave a comment and we can debate about it.