Log4r for Ruby on Rails: Part I of “Scalable and Robust Logging for Web Applications” 14

Logging, monitoring and the collection of metrics, be it performance metrics or important business metrics, is usually a topic that is not often discussed when building and scaling an application from garage-hack to the startup on the front page of TechCrunch. It is essential to be be aware of the current situation of the system and the product performance to prevent FailWhales and maximize revenue and growth.

Having a good logging and monitoring system allows reacting to errors as quickly as possible, helps correlating data to track down issues, gives an overview over performance and allows to predict future performance. Business metrics allow tracking the impact of new features and help understanding users and customers.

Solutions like NewRelic are a good start at high-level monitoring of the application stack and help to detect failures and monitor overall performance. However the data is not detailed enough to help with debugging more complex errors or i.e. figuring out that the reason for the increased response time was a few really long running requests or something that resulted in every request taking longer, for example due to a failing database node.

The goal of this series is to develop a robust system for logging, monitoring and collection of metrics that can easily scale in terms of throughput – i.e. adding more application servers – but is also easy to expand to new types of log data – i.e. by adding a new database or importing external data sources – and makes it easy to modify and analyze the data exactly as needed.

(Subscribe via Email to get informed as soon as the next post in this series is published! Sign up now on top of the sidebar to your right!)

Scalable and Robust Logging for Web Applications

1. Log4r for Ruby on Rails
2. Log Transport and Distribution with Kafka
3. How to Pre-Process Logs with Logstash
4. Real Time Analytics with Storm
5. Server Monitoring with Sensu
6. Metrics with Graphite
7. Storing Metrics and Logs
8. Visualization

Rails’ standard logger

Ruby on Rails is great to build things fast. You have an idea today, you can launch next week. You grow to a million users in two months. But debugging errors in production is not always easy, especially when using the default logger.

(SQL log output example taken from StackOverflow)

So how can you work with these logs? One approach is just to ssh into the machine and do some shell scripting magic:

(The awk part is taken from logfile analysis with awk. Alternatives include more sophisticated gems like request-log-analyzer, however these also do not attack the root cause of the issues at hand – the log format is hard to parse for machines)

These simple metrics are doable via command line, but it still requires connecting to each server and execute these commands. It gets even worse for such simple information like “which URLs did result in 503s”? The url is at the top and the status at the end – in between are the view renderings and SQL queries – which makes it hard to get even to this simple piece of information.

The logfiles are becoming even harder to understand when using a server that spawns multiple instances of a rails app, like Unicorn, and logs all output to the same file. Worst case each thread could have written each line without a prefix. What belongs to which thread now?

Introducing Log4r

Log4r is modeled after the popular Java logging library log4j and allows a lot of customization and fine-tuning of your logging.

“Log4r is a comprehensive and flexible logging library for use in Ruby programs. It features a hierarchical logging system of any number of levels, custom level names, multiple output destinations per log event, custom formatting, and more”
( log4r project description ).

The official log4r website is a little outdated (v 1.1.7) but most of the content still applies to the latest version (1.1.10) that can be found here on github. The rest of the article will detail how to set up Log4r with Ruby on Rails 3.x and two common database adapters, ActiveRecord and mongoid.

Edit:

• Log4r seems to be no longer active. The Logging gem seems to be actively maintained and very close to Log4r, as pointed out in the HackerNews comments.
• Reportedly this article applies to Rails 4 as well.

Log4r Configuration

Basic Setup

Let’s get started with a plain new Ruby on Rails installation and change the default logging step by step to log4r:

The first step to set up Log4r is to create a config file at  config/log4r.yml . It describes the global log levels that the app supports and specifies a basic Outputter, a definition of how the log data is transferred out of the application.

This basic configuration writes all logs messages with loglevel DEBUG and above to the standard output, usually the console you started   rails server  in. The next step is initializing the logger in the application. This can be done in  config/application.rb . First add the log4r requirements below the existing ones and load the yaml configuration file inside the Application  class and set the new log4r logger as default rails logger.

Mongoid 3

In oder to direct the logging from mongoid to Log4r, use the following code in an initializer:

Loggers

Right now every log-message is handled through the same logger with the same loglevel. This does not allow for selectively changing the log level based on what has to be debugged. Maybe you want to optimize a mysql query but are not interested in seeing all the rails and mongo logs while you are working on this. Log4r allows you to use multiple loggers which can all be set to operate at a different loglevel.

Let’s create a separate logger for rails, mysql and mongoid:

Now you can set the loggers in your config/application.rb  like this:

Log Levels

Besides the standard log levels FATAL > ERROR > WARN > INFO > DEBUG log4r allows defining custom log levels on a global basis. Adding developer log-levels is a great way to debug new features and show partial results or log the current value of variables. In the following example the additional loglevels DEV0, PARAMS, DEV1 and EXCEPTION are added. They can be used like the standard loglevels and a call to logger.dev0 "Log this to dev0!"  will log the message with loglevel DEV0.

Warning:  Expensive calls, processing of data and database calls should be wrapped in a Proc, so that they are only evaluated when the loglevel is set to output the message.   logger.dev0 { Data.all.count() }

Custom Formatting

Rails and ActiveRecord are currently logging to stdout using Log4r. The logs do not look significantly different yet, except that they are now prefixed with the current time and the log level. Another advantage is that individual loggers can be set to different log levels. This is already an improvement over the standard rails logger. The next step is incorporating some of the advanced features of log4r to further improve the output.

Log4r

Log4r can prefix each log message using the PatternFormatter. Currently each log message is prepended with the time and the log level. However the time resolution is only one second and multiple processes that are writing to the same logfile cannot be distinguished. More useful information like hostname and application name can be added to make it easier to filter the logs down the road.

Let’s add another Outputter railsfile that writes the logs to a file, formats it and takes care of the limitations listed above:

The  type: FileOutputter defines that the logs should be written to the file specified through the  filename: attribute. The FileOutputter is thread-safe, so multiple processes can write to the same file as well as multiple loggers within one process.

The date format was appended with  %L to print milliseconds and %z  to log the timezone to allow easy synchronization of data points from data centers across the world.
The pattern  attribute supports some built-in variables of which the following were used in this example:

• %p : process id (pid)
• %d : the date
• %l : the log level
• %m : log message

You probably already noticed #{ENV} , #{EC2_INSTANCE}  and  #{APPNAME}. These are variables that can be defined before loading the configuration and will be substituted. In oder to use these variables, they must be defined in the log_cfg  variable in   application.rb before decoding the yaml.

Rails

Rails is still printing multiple lines per request. To change this, first turn off the default Rails logger.

Rails 3.0 introduced ActiveSupport::Notifications which allows subscribing to many events that happen throughout the lifecycle of a request and also supports sending your own notifications. The most important type of notification for logging is process_action.action_controller . It contains the information about the processing of the request, the time it took and every parameter associated with the request. A typical notification of this type looks like this:

The following example will output the most important facts of a request at the INFO log level and WARN on requests that take longer than 200ms or return a http status code different from 200 or 500. An ERROR will be logged when an exception is thrown or the request returned a status of 500. The DEBUG level will print the timings of view renderings and database calls and the parameters are printed at the PARAMS log level.

ActiveRecord

The same principle applies for ActiveRecord. This is just a simple example that prints all SQL queries with the time it took them to execute.
More complex filtering and formatting is possible, like assigning different log levels depending on how long the query took or the type of the query.

You can turn off the default logging of ActiveRecord by putting this into your config/application.rb :
ActiveRecord::Base.logger = Logger.new('/dev/null') 

Exceptions and Stack Traces

The  process_action.action_controller’s payload contains an exception message but no stack trace. To also be able to log stack traces, add this to the app/controllers/application_controller.rb 

and this to the  config/initializers/logger.rb

It is also possible to directly log in the ApplicationController and avoid sending a message if the exception log level is not active, however I decided to keep all the formatting in one place.

Changing Log Levels During Runtime

Most of the time logging everything is not necessary and slows down the application for no reason, therefore setting the log level to INFO or WARN is preferrable. However imagine you see strange behavior, customers are reporting issues and inconsistencies or the response times spike. In these times it is very helpful to see much more verbose logging and maybe even each SQL command and the results of it.

Changing the log level in rails requires a restart of the webserver in the best case – when the log level is set based on, for example, an environment variable – or redeploy the application in the worst case – the log levels are hard-coded into, i.e. in the production.rb .

Setting the log level via a request – for example http://mmlac.com/logs/set?level=DEBUG – is also not going to help because webservers like unicorn create a new process for each instance they run. These instances are isolated and do not propagate state between each other. This means the log level will only be changed at the rails process that this particular request was handled by.

One solution to this problem is saving the log level for each logger in a file and periodically check for changes. Doing this i.e. every 20 seconds does not impact performance and allows a reasonable response time to issues. Assuming the file $RAILS_ROOT/loglevels.txt  contains the log levels in JSON format, you can check and reset the log levels the following way in the logging initializer file config/initializers/logger.rb . Every time you call a logging function, like in  ActiveSupport.Notification.subscribe , call log_time_check  at the beginning to ensure the log levels are up to date.

Silencing Memcached

If you use memcached you may notice a lot of cache-miss logs that do not seem to go through log4r.

The reason for this is that the memcache gem – in this case dalli – is Rack middleware and therefore does not use the Rails logger but the Rack logger. To prevent the verbose Rack logger output, put the following into your development.rb  and production.rb :

Also add the command   Rails.cache.silence!   in an initializer.

Nginx Queueing Time

If you use nginx or another reverse proxy it is good to know how much time the request spent in the queue before the application server started processing it. Webservers like Unicorn have a central queue (the length of it can also be monitored separately) and assign each request to the next free worker available. Long queueing times are a sign that more application servers are needed to handle the current load.

In order to log the queuing duration, nginx has to set a header with the time it processed the request. The application can read out this header at the beginning and log the time elapsed. If you use NewRelic’s patched version of nginx, the format is slightly different. If you set the header yourself, use the $msec variable:

Then add the following code to the beginning of the process_action.action_controller subscription:

I hope this article gave you a good introduction into how to get started with improving your logging for Ruby on Rails using Log4R.

What do you think? Do you have any comments, improvements, questions or just enjoyed the read? Go write a comment below, at reddit or HackerNews and I try to respond as quickly as possible :)

Help others discover this article as well: Share it with your connections and upvote it on reddit and HackerNews!

Subscribe to the blog to get informed immediately when the next post in this series is published!