Making the Most of Your Logs in Rails

Most people only realize the necessity of logs when they need them the most. But when your application breaks, user complaints start flooding in, and you have no clue how to fix it, it's too late to add some log messages that might have helped.

Good logs pay for themselves tenfold. They make it a breeze to diagnose those tricky bugs, and if you do logs right, they can alert you of issues even before your users notice. But what does it mean to 'do logging right'?

Logging is easy to start with but hard to master. In this post, we'll dive into how you can use your Rails application's logs to their full potential.

Logging in Rails

Let's talk about the basics first. When you start a new Rails application, logging is already set up for you. Rails will initialize a new instance of ActiveSupport::Logger that you can use anywhere within your application.

Rails.logger.debug('Hello logs!')

I, [2019-01-04 05:14:33 #123] INFO -- Main: Hello Logs!

The Rails logger writes to the standard output or log/<environment>.log and will automatically log incoming requests or executed queries in addition to any log messages you write explicitly.

There are numerous ways in which you can configure Rails logs, as outlined excellently in the documentation for Rails.

To make the most of our logs, we are especially interested in setting log levels as well as log formatting.

But before tackling that, let's talk about why we should write logs.

Good Logging, Bad Logging

The purpose of logs is to inform you about system events so you can react to them. For example, when an error happens, a log message should tell you about it in a way you can understand.

How well you understand a log message depends on how descriptive and contextual it is. A descriptive log message provides relevant information about what happened. A contextual log message includes information about a system's state when the system wrote it.

Let's consider a simple example to see why we need both. Here is some code that calls an external API and returns its response when a user performs a request.

def call_external_api(user_id, payload)
  Rails.logger.info('Method entered')
  client = Client.new(user_id)
  response = client.request(payload)
  if response.ok?
    Rails.logger.info('Response success')
    return response
  else
    Rails.logger.info('Response failure')
    return response
  end
  rescue ClientError => e
    logger.debug('An error occurred)
end

Now let's imagine a situation where a customer reports an issue, and you look into the logs for help. This is what you might see:

I, [2022-07-10T10:40:34.827604 #100038]  INFO -- : [42f2e074-d53f-41e4-adca-13f59c6383ec] Processing by UserController#action as HTML
I, [2022-07-10T10:40:34.828084 #100038]  INFO -- : [42f2e074-d53f-41e4-adca-13f59c6383ec] Method entered
I, [2022-07-10T10:40:34.933263 #100038]  INFO -- : [42f2e074-d53f-41e4-adca-13f59c6383ec] Response success
I, [2022-07-10T10:40:34.933803 #100038]  INFO -- : [42f2e074-d53f-41e4-adca-13f59c6383ec] Completed 200 OK in 106ms (Views: 0.2ms | Allocations: 2135)
I, [2022-07-10T10:40:35.959454 #100038]  INFO -- : [458a209f-6b0e-4d29-a9b0-449d6ff3d29a] Started GET "/action" for 127.0.0.1 at 2022-07-10 10:40:35 +0200
I, [2022-07-10T10:40:35.959975 #100038]  INFO -- : [458a209f-6b0e-4d29-a9b0-449d6ff3d29a] Processing by UserController#action as HTML
I, [2022-07-10T10:40:35.960081 #100038]  INFO -- : [458a209f-6b0e-4d29-a9b0-449d6ff3d29a] Method entered
I, [2022-07-10T10:40:36.043971 #100038]  INFO -- : [458a209f-6b0e-4d29-a9b0-449d6ff3d29a] Response failure
I, [2022-07-10T10:40:36.044316 #100038]  INFO -- : [458a209f-6b0e-4d29-a9b0-449d6ff3d29a] Completed 200 OK in 84ms (Views: 0.1ms | Allocations: 1297)
I, [2022-07-10T10:42:49.701879 #103892]  INFO -- : [e02c3a8f-c081-40aa-90fb-9d1474126403] Started GET "/action" for 127.0.0.1 at 2022-07-10 10:42:49 +0200
I, [2022-07-10T10:42:49.703400 #103892]  INFO -- : [e02c3a8f-c081-40aa-90fb-9d1474126403] Processing by UserController#action as HTML
I, [2022-07-10T10:42:49.703745 #103892]  INFO -- : [e02c3a8f-c081-40aa-90fb-9d1474126403] Method entered
I, [2022-07-10T10:42:49.775846 #103892]  INFO -- : [e02c3a8f-c081-40aa-90fb-9d1474126403] An error occurred

These log messages provide some information, but not nearly enough. We are no closer to finding out what's responsible for the error the customer has reported. These log messages lack descriptiveness and context. They are noise. How can we improve them?

Log Levels in Rails

The default Rails logger provides the log levels DEBUG, INFO, WARN, and ERROR. Using them, you can group log messages into different categories of relevance. This not only helps you filter log messages, but also provides some context.

It can be challenging to decide when to use which log level. Here are some rules of thumb:

• DEBUG: Use this log level for detailed information about actions happening within the system. You may use debug statements when methods are entered or exited, or anywhere you think it may add value during debugging.
• INFO: Whenever your system changes its state, or some relevant event occurs, reach for the INFO level. Examples of common info messages in the context of Rails applications are received requests, requests sent to external APIs, or jobs starting and finishing.
• WARN: Use this log to signify that something unexpected has happened. It's not a problem yet (because your application can handle it), but if it keeps happening, it might warrant your attention.
• ERROR: Use this log level when an error happens. Errors are invalid application states that you must resolve as soon as possible.

You can change the kinds of log messages your application writes by modifying the respective environment file. Normally, Rails will discard DEBUG messages in production, but you can change that.

# config/production.rb
Rails.logger.level = :debug

Let's apply the log-level suggestions above to our code sample.

def call_external_api(user_id, payload)
  Rails.logger.debug('Method entered')
  client = Client.new(user_id)
  response = client.request(payload)
  if response.ok?
    Rails.logger.info('Response success')
    return response
  else
    Rails.logger.warn('Response failure')
    return response
  end
  rescue ClientError => e
    logger.error('An error occurred')
end

When debugging, we can now identify root causes for issues by looking into WARN and ERROR messages. Sadly, our log messages haven't gotten any more descriptive.

Descriptive Log Messages

Descriptive log messages leave no room for interpretation. They provide the details necessary to give the reader instant knowledge about what happened.

When you read messages such as 'An error occurred', you are left wondering what the error is. You want to avoid such confusion when writing your log messages. The most important thing when writing descriptive log messages is to put yourself in the shoes of the log reader. Will they get all the information they need when reading your logs?

Let's change the message 'An error occurred' to the error itself, including its message.

logger.error { "#{e}: #{e.message}" }

That's an improvement. Let's check the other log messages in our example. 'Method entered' doesn't tell us which method was called, 'Response success' leaves out the actual response, and 'Response failure' provides no information about the nature of the failure. Let's change that.

def call_external_api(user_id, payload)
  Rails.logger.debug('Calling external api')
  client = Client.new(user_id)
  response = client.request(payload)
  if response.ok?
    Rails.logger.info { "Request success, received #{response.body}" }
    return response
  else
    Rails.logger.warn { "Request returned #{response.code}, #{response.body}" }
    return response
  end
  rescue ClientError => e
    logger.error { "#{e}: #{e.message}" }
end

Note: You might have noticed we use the block syntax when performing string interpolation with our logs. Using it avoids unnecessary computation when the application's log level is higher than the log messages' level. For example, log.debug("Some #{concatenation}") will always perform the string concatenation, but log.debug { "Some #{concatenation}" } will only do so when the log level is set to debug.

I, [2022-07-30T11:19:13.742108 #122944]  INFO -- : [29d1ced1-3d05-4fbf-8b75-2a50e87ad749] Started GET "/users" for 127.0.0.1 at 2022-07-30 11:19:13 +0200
I, [2022-07-30T11:19:13.743058 #122944]  INFO -- : [29d1ced1-3d05-4fbf-8b75-2a50e87ad749] Processing by UsersController#index as HTML
D, [2022-07-30T11:19:13.743248 #122944] DEBUG -- : [29d1ced1-3d05-4fbf-8b75-2a50e87ad749] Calling external api, user 1, payload {:search=>"name"}
I, [2022-07-30T11:19:13.844355 #122944]  INFO -- : [29d1ced1-3d05-4fbf-8b75-2a50e87ad749] Request completed. Received {"userId"=>1, "id"=>1, "title"=>"title", "completed"=>false}
I, [2022-07-30T11:19:13.844836 #122944]  INFO -- : [29d1ced1-3d05-4fbf-8b75-2a50e87ad749] Completed 200 OK in 102ms (Views: 0.2ms | Allocations: 2195)
I, [2022-07-30T11:20:09.501016 #123422]  INFO -- : [598eb218-d3c9-4e92-9236-13281cc660af] Started GET "/users" for 127.0.0.1 at 2022-07-30 11:20:09 +0200
I, [2022-07-30T11:20:09.502518 #123422]  INFO -- : [598eb218-d3c9-4e92-9236-13281cc660af] Processing by UsersController#index as HTML
D, [2022-07-30T11:20:09.502848 #123422] DEBUG -- : [598eb218-d3c9-4e92-9236-13281cc660af] Calling external api, user 1, payload {:search=>""}
W, [2022-07-30T11:20:09.574884 #123422]  WARN -- : [598eb218-d3c9-4e92-9236-13281cc660af] Request failed with 400: Empty search
I, [2022-07-30T11:20:09.575415 #123422]  INFO -- : [598eb218-d3c9-4e92-9236-13281cc660af] Completed 200 OK in 73ms (Views: 0.2ms | Allocations: 2106)
I, [2022-07-30T11:20:41.229494 #125518]  INFO -- : [77b70a25-268c-43ea-a3da-8788086165f2] Started GET "/users" for 127.0.0.1 at 2022-07-30 11:20:41 +0200
I, [2022-07-30T11:20:41.230735 #125518]  INFO -- : [77b70a25-268c-43ea-a3da-8788086165f2] Processing by UsersController#index as HTML
D, [2022-07-30T11:20:41.231039 #125518] DEBUG -- : [77b70a25-268c-43ea-a3da-8788086165f2] Calling external api, user 1, payload {:search=>"long name"}
E, [2022-07-30T11:20:41.301237 #125518] ERROR -- : [77b70a25-268c-43ea-a3da-8788086165f2] Request timeout exceeded
I, [2022-07-30T11:20:41.301878 #125518]  INFO -- : [77b70a25-268c-43ea-a3da-8788086165f2] Completed 200 OK in 71ms (Views: 0.3ms | Allocations: 2085)

Our logs read much better now. There is little doubt about what each log message signifies.

Further Context for Log Messages

Our new log messages provide a clear picture of what happened. Because this is a simple example, we also have a good understanding of why certain things happened. In reality, it's usually not that easy.

Providing additional information about the context in which the system wrote each message can significantly help with debugging.

For example, when logging requests or responses, it may be helpful to know who performed the request. Attaching a stack trace for errors might be useful so we can gather additional information about why the error occurred.

def call_external_api(user_id, payload)
  Rails.logger.debug { "Calling external API. user_id: #{user_id}, payload: #{payload}" }
  client = Client.new(user_id)
  response = client.request(payload)
  if response.ok?
    Rails.logger.info { "Request completed. Received #{response.parsed_response}. user_id: #{user_id}, payload: #{payload}" }
    return response
  else
    Rails.logger.warn { "Request failed with #{response.code}: #{response.parsed_response}. user_id: #{user_id}, payload: #{payload}" }
    return response
  end
  rescue ClientError => e
  logger.error("#{e.message} (#{e.class}), #{ e.backtrace.drop(1).map { |s| "\t#{s}" } }")
end

Note: You have likely noticed that creating log messages with contextual information can be cumbersome when you use Rails' default logger. Luckily, custom loggers such as Ougai or MrLogaLoga make this a lot easier.

Structured Logging

Once you've made your logs readable for humans, you are ready to take things to the next level. You now need to make your logs readable by machines so you can use them for monitoring and data analysis.

My go-to format is JSON, but depending on which tools you use, you may prefer other log formats such as Logstash. You can change the format of your log messages by creating a custom log formatter.

# lib/json_log_formatter.rb
class JsonLogFormatter < ::Logger::Formatter
  def call(severity, time, progname, msg)
    json = { time: time, progname: progname, severity: severity, message: msg2str(msg) }
      .compact_blank
      .to_json
    "#{json}\n"
  end
end

# application.rb
config.log_formatter = JsonLogFormatter.new

{"time":"2022-08-07T18:57:20.261+02:00","severity":"INFO","message":"Request completed" }

Rather than writing custom formatters yourself, you can use one of the many gems that provide custom log formatters. I recommend Lograge, which not only offers out-of-the-box formatting but also cleans up Rails' somewhat verbose request formatting so it's much easier to read.

Rails Logging with AppSignal

Now that your logs are nice and readable, it would be nice to make them more accessible. After all, you don't want to SSH into some machine and tail or grep the logs there, right?

Luckily, AppSignal has recently launched a logging feature in beta! This allows you to inspect and analyze Rails logs directly in the AppSignal web interface.

You can access our logging beta through the 'Logging' tab in the left-hand side menu:

If you follow the steps in our Ruby logging docs, you can configure the Rails Logger to use the AppSignal::Logger class by placing the code below in the config/environment.rb file before initialization:

# Use AppSignal's logger
Rails.logger = Appsignal::Logger.new("rails")

# Initialize the Rails application.
Rails.application.initialize!

You can also ingest structured logs in JSON format or with Lograge.

Once you've set everything up, you should see your Rails logs show up on AppSignal!

Logging and Error Reporting

You're reading this on the AppSignal blog, so you might wonder: why should I care about logging if I'm already using a nice error reporting platform?

It's a good question. Error tracking tools provide detailed information about application errors. They capture the full stack trace of any application error and provide lots of contextual information out of the box.

However, while most tools allow you to capture events other than errors, sending these tools an arbitrary amount of messages is generally infeasible. You won't be able to replace the detailed, historical information that well-written logs provide.

In reality, well-written logs augment and support error tracking tools. You should likely use both.

Wrap Up

In this post, we looked into how you can get the most out of your logs. We saw that getting started with logging in Rails is easy, but writing useful
logs can be challenging.

Logs that lack descriptiveness or context will end up just filling up your disk while providing little value. However, logs that use the correct log levels and provide readers with the information they need are a great asset.

Once you've mastered writing great log messages, you can take things further and format them in a way that allows for log analysis and easy filtering.

We also explored how you can use AppSignal's new logging feature to access your logs easily. Finally, we touched on how logs should augment error tracking tools rather than replace them.

Happy logging!

P.S. If you'd like to read Ruby Magic posts as soon as they get off the press, subscribe to our Ruby Magic newsletter and never miss a single post!