How to enable distributed tracing in Ruby on Rails services

Nowadays almost every software company works with oriented service architecture. If not, you are either very lucky or missing something. When dealing with multiple services, debugging becomes more hard and hence a structured log messages filled with tracing id is a must.

Log messages structure

Let’s start the journey by having a look into the default Rails logger when we start a new Rails application:

It is not beautiful right ? As you can see it doesn’t give you any identifier about how to differentiate between each request. The good news is that Rails can keep track of a unique uuid for each request ActionDispatch::RequestId. So what we need to do is to enable Rails to print it.

We can enable this by adding the following line in your configuration to specific environment/environments/${env}.rb or the config/application.rb

config.log_tags = %i[uuid]

Then this is how the logs look like now:

Let’s say you have a log aggregator like Logstash that collects the logs from multiple backends and you would like to have an easy way to do some queries or analytics over the requests. One way to have this is to format the messages into JSON.

We can achieve this using the following snippet:

The is how the logs look like now

Another improvement we can do is to combine these 3 log messages into 1 and focus more about what is important. Luckily there is a nice gem we can use called lograge that can help us to format our log with less work.

let’s add it to the Gemfile and enable it in our config and enable JSON structure format in config/initializers/lograge.rb

Rails.application.configure do
  config.lograge.enabled = true
  config.lograge.formatter = Lograge::Formatters::Logstash.new
end

This is how the logs messages look like now:

Let’s enrich our log messages with more important data like request_id, params and the user agent.

config.lograge.custom_payload do |controller|
  {
    request_id: controller.request.uuid,
    params: controller.request.params,
    agent: controller.request.env[‘HTTP_USER_AGENT’]
  }
end

Now we have a well structured useful log messages that we can append more useful data that relevant to the application that can help us in debugging.

Correlate logs between Rails applications using RequestId

After having our logs structured, Let’s debug a request that spans over multiple backends. Our use case is a request that starts from the users backend then retrieves some information from the account backend.

Applying the mentioned tricks, we will end up by the following logs:

As you can see each request has its own id but eventually these two requests belong to each other. Imagine a situation where you want to know what the parameters send from the users service to accounts or what the latency for each part is.

Luckily Rails already can handle this issue easily. Actually Rails doesn’t generate a request id if it already exist in the request headers. Hence what we need to do is to provide the request id from the caller service(users) and our callee service(accounts) will log its messages using the same request id.

Let’s look about a small modification in the request structure that fixes this:

headers = {  'X-Request-Id' => request.env["action_dispatch.request_id"] }
response = HTTParty.get(url, headers: headers)

And this how logs look like now:

The next step is to wrap this into an API client that includes the request id for every outgoing request to an internal service.

Conclusion

When working with service oriented architecture, having structured logs and tracing ids is crucial to monitor your services and be able to know what went wrong and at which part of the system. Tracing id is the first step to improve your system observability and it gives you an overview of the request lifecycle in your ecosystem.