Standardize Rails log output
Currently my team is working on an application which intensively communicates with external APIs and writes to log files a lot of information about received/processed/failed/sent requests. Log messages in the app are popping up from nested subscribers, publishers, services classes, they are inconsistent and don’t have any common structure.
The log itself was pretty noisy and was painful to read and analyze it with the naked eye.
At some point it was decided to switch to a centralized log management tool (Splunk in our case) in order to allow our support team to search/filter log entries on their own and in a more convenient way than less. Therefore we had to standardize all the log entries. The desired log entry format looks like
timestamp={time} level={severity} source_class={class_name} user_id={email} message={log_message} tag=#{tag}Moreover there’s also a standard Rails log output which needs to be casted to this uniform format as well. There’re plenty of gems which do logs formatting, but after a quick investigation it turned out that it’s easy to adjust Rails logging without external libraries. And none of the gems was offering the required log format out-of-the-box anyway.
First of all, we’ll need a dedicated log formatter class, which has to respond to call(severity, time, progname, msg) method with this exact signature. severity stands for the level of message ‘importance’. time and msg arguments are more or less obvious, and progname is the name of the program which uses the logger class, it’s usually used by gems with built-in logging (Ruby docs).
Now let’s “plug” it into Rails. It was decided to keep default Rails TaggedLogging wrapper.
Yeah, that’s easy! Now our brand new log formatter is in place. Except it still misses some of desired attributes, i.e. source_class and user_id, they’re a bit trickier to implement, but let’s do it.
Our app has multiple event processing classes and it’d be neat to show within the log entry which of them produce this exact output. There’re a few possible options: manually add a class name to the logger message wherever we need it, or detect the caller class automatically on the fly. The second one sounds fun, so I decided to give it a shot first.
Ruby’s Kernel includes caller method which returns the current execution stack represented as an array of strings with files/methods names (Ruby Docs). It’s troublesome to build source_class detection based on this method solely. Still, we can achieve the same in an easier and a more performant way — by using binding_of_caller gem. It’s written in C and does exactly what we need — detects the class name flawlessly.
STACK_LEVEL is 7 as it goes through 6 methods in the logger stack before it gets into the log formatter.
Sadly, the gem’s author asks to not use it in production applications. Well ok, since we’re mostly interested in our internal classes output analysis we can go for explicit argument passing.
I didn’t want to monkey patch Logger class to make it accept additional arguments or to create a separate logger. Hooray due to dynamic typing it’s not necessary. We can use the next logger calls notation:
logger.info('Info message')# orlogger.info(message: 'Info message', source_class: class_name, user_id: user.email)
It’s still the same single first method argument, but in the first example it’s a string, and in the second one — a hash. All we need to do is to allow the log formatter to work with hashes and to manually add source_class and/or user_id values to logger calls in the app wherever we need them to be in place.
The next log formatter version:
That could be enough in case we don’t use ActiveSupport::TaggedLogging. But we do, and this module casts all messages to string concatenating it with the tags. We have to add support for hash messages as well.
And that’s it, now let’s check it on a few examples.
Progname:
logger.info('MyApp') { 'Received a new package' }=> timestamp='2018-09-03 19:50:39 +0000' level=INFO progname='MyApp' message='Received a new package'
Message as a hash:
logger.info(message: 'Message', user_id: 'admin@example.com', foo: 'Bar')=> timestamp='2018-09-03 19:54:56 +0000' level=INFO message='Message' user_id='admin@example.com' foo='Bar'
Tagged logs:
logger.tagged('Records') do
logger.debug message: 'Finding records...',
source_class: 'ClassName'
end=> timestamp='2018-09-03 20:04:49 +0000' level=DEBUG message='Finding records...' source_class='ClassName' tag='[Records]'
Regular log message:
logger.warn('Warning')=> timestamp='2018-09-03 20:09:19 +0000' level=WARN message='Warning'
Thanks for reading!
If you have any questions or feedback please feel free to reach me on twitter. Cheers!