Tech

Structured logging in Rails

How we went about making Rails logs more contextual and less verbose.

Gojek

Aug 4, 2020 • 3 min read

By Tasdik Rahman

If you’ve worked on Rails, you would’ve noticed that the default Rails logs are true to the name: They run too long and are spread across multiple lines.

Even if the context of processing is just one simple controller action, the Rails logs generally tend to be verbose.

Read on to know how one can sanitise the logs without losing out on information and how additional information could be added for log lines to completely utilise the querying features of the logging platform.

Consider this example

A simple health check controller which you would add to make the health check pass for your Rails app deployed on Kubernetes.

The config (shown for the development environment for this example):

A simple route for the GET verb, to call the #ping action in the HealthCheckController :

This is what the logs would look like for the route ping:

Our observations

The logs are spread over multiple lines, adding to the complexity in debugging the whole request or response flow.
Given you would be pushing to your logging platform, let’s say EFK, which would allow full-text search, the configuration to have the request-id for each log would come in handy — which is better than not having anything at all. (Have a look at BaritoLog, our in house EFK platform).
If nothing is being pushed to any logging platform, then you would be debugging this by tailing the logs of the rails app somewhere. If deployed to Kubernetes, doing a kubetail or if on VMs, and you tail the logs of each and every application server instance. But then, the first step here would be to have centralized logging.
Extremely verbose logs which hinder debugging.
No clear way to parse the logs as the logs format is not standard (if you don’t add config.log_tags = [:request_id], which is not present by default).

Improving the Rails Logs

By using Lograge, we can make the log compact so it stays meaningful. There are a bunch of other alternatives like Semantic Logger and Logstasher. My reasoning behind going ahead with Lograge is that it has been around for some time now and has a larger adoption.

Now, add Lograge in your Gemfile:

...
gem 'lograge', '~> 0.11.2'
...

Do a $ bundle, after which you need to add setup the configuration as follows:

config.lograge.base_controller_class = ['ActionController::Base'] assumes that each controller will be inheriting from ActionController::Base. Any other controller which doesn’t inherit from the Base controller can be included, in order for Lograge to pick it up.

Do the following:

And check the logs of your Rails app:

Here, the whole log line captures a lot of metadata, so that each log line can be debugged. One of the keys present in the log line is request_id, which is a unique trace ID for a particular request. This can do a full text search on the logging platform, if it supports it.

To extend this further, capture the request_id, and pass it along the each controller’s flow. To capture it, you can simply do a request.request_id. Not that you have the request_id, if you are doing a Rails.logger.{info|debug} you can use it to log the request_id. This way, the request_ids generated would also be propagated to the custom logs which would be added to the application.

The biggest advantage here is this request_id can be added to every core flow which would be logged. Just put the request_id in the search param of the logging platform, and it will give all the logs which have this key in it.

Additional information like host, remote_ip, ip of the rails app servicing it would also be captured, by simply doing request.host, request.remote_ip, request.ip, request.request_id.

But remember, Lograge cannot be used for the custom logger because it doesn’t support this.

Adding structured logging for custom logs

A custom logger can be added for your application and initialised in the application config for the preferred environments.

The only thing that needs to be added is:

Initialise it in the application config (development, in this case):

And to test the above:

What will the logs look like after this?

As you can see, the logs from

the controller logs which the Lograge is showing
the Rails.logger.info is spitting

have…

logs in json format
log line has the request_id appended to it in the message key

Hoping this blog helps you make your Rails logs contextual and less voluble. 🖖

References

Thanks to Deepak, for his support, while we paired when we added structured logging to one of our services with the above approach.