Introduction to Logging

with Ruby on Rails

A crucial part of software development, logging is a process of record keeping an application’s runtime behavior such as processes, data input, data output, errors and warnings. While the primary usage is to debug, test and statistic analyze, it is also useful in assessing users’ preference when using the program.

Logging is an important part of life — Pileated Woodpecker

Ruby provides you with a tool to accomplish this task: the Logger class: “a simple, but sophisticated logging utility that you can use to output messages”. You can have one logger object for each type of log, or one for each class, or any other combination that your application would require. The link above provides a very comprehensive introduction to using Logger in a simple Ruby application.

Typically, complex programs in which logging is invaluable, would be best written on a framework. Therefore, Ruby on Rails has its own way of data logging using ActiveSupport::Logger class as part of initialization and uses it for logging to standard output.

By default, each log is created under #{Rails.root}/log/ and the log file is named after the environment in which the application is running. Here is a snippet of an app in development’s log file:

Code snippet of an application’s log file in development environment

These messages log what has been happening in the application. In order to gain more insights, we can customize Rails Logger to have more context. This is where Log Levels come in.

Log Levels

include: :debug, :info, :warn, :error, :fatal and :unknown, corresponding to the log level numbers from 0 up to 5, respectively. The default Rails log level is debug in all environments. We can log a message at any one of these levels by calling the associated method from within a controller, model, or mailer:

Typically, you’d want more fine-grained logging in environments where you’d be actively developing and testing. Production might not benefit from all the debug statements unless there is an actual issue. When logging messages to yourself or your team, it is important to log at the correct level. It simplifies debugging and help reduce log pollution when things are logged at too high a level.

1. Debug: used by developers or system admins who need as much detail as possible about what exactly happened during an issue.
2. Info: provides information regarding normal application processing, such as services starting and stopping, or application metrics.
3. Warn: warnings indicate something is wrong. It might not be a current error since the application might have recovered. It informs us nonetheless of a rare scenario that would be in our best interest to track.
4. Error: something has failed. The application might still functions, but things are not working properly.
5. Fatal: used when something happens that causes the application to crash. This type of error may need support or intervention from the development team. It is not to be used for general business errors.
6. Unknown: This logging level will catch anything that does not have a known level. It is a catch-all for anything that might sneak through.

Lazy loggers’ memo

Tagged Logging

another great feature of Rails logger, tagged logging help categorize different logs for different use cases. Especially when you are running multi-user, multi-account applications, it is exceptionally useful to be able to filter the logs using some custom rules: stamping log lines with subdomains, request ids, and anything else to aid debugging.

logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
logger.tagged(“BCX”) { logger.info “Stuff” } # Logs “[BCX] Stuff”
logger.tagged(“BCX”, “Jason”) { logger.info “Stuff” } # Logs “[BCX] [Jason] Stuff”
logger.tagged(“BCX”) { logger.tagged(“Jason”) { logger.info “Stuff” } } # Logs “[BCX] [Jason] Stuff”

ActiveSupport::TaggedLogging is used to wrap any standard logger instance to add “tags” to a log statement. This means we can invoke an ActiveSupport::TaggedLogging instance’s tagged method with an argument of the “tag” we want to apply, and a block containing the call to the standard logger’s appropriate severity-level method.

Data that provide relevant metrics

We want logs that help troubleshoot issues with requests. We also want to include the data that provides the relevant metrics. Here is a list any developer or support teammate would like to see:

• Date/Time
• Request ID — a unique identifier for this request that gets used throughout the call stack
• Client ID
• HTTP method
• URL path
• Response status or failed requests
• Error message
• Request parameters
• Relevant variables within the application
• Call stack

There are many more other important metrics and values that as you continue on your developer’s journey, it will become more relevant and valuable. Your logs, in fact, are code, too. Despite that, often not much thought is put into logging. It only occurs to us when things have already started breaking and we realize how much it would have been useful to start the development with good logging.

Logging’s best practices

Sources:

1. https://stackify.com/rails-logger-and-rails-logging-best-practices/
2. https://thegreatcodeadventure.com/building-a-custom-logger-in-rails/
3. https://guides.rubyonrails.org/debugging_rails_applications.html
4. https://www.papertrail.com/blog/introduction-to-logging-in-ruby-on-rails/
5. https://www.scalyr.com/blog/rails-logger/