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!)

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.

(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:

Set up a new rails project

Shell

1

2

3

4

5

6

7

8

$rails newtestApp

...

$cdtestApp

$echo"gem 'log4r', '1.1.10'">>Gemfile

$bundle install

...

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.

config/log4r.yml

YAML

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

log4r_config:

# define all loggers:

loggers:

- name: rails

level: DEBUG

trace: 'true'

outputters:

-console

# define all outputters (incl. formatters)

outputters:

- type: StdoutOutputter

name: console

formatter:

date_pattern: '%H:%M:%S'

pattern: '%d %l: %m'

type: PatternFormatter

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:

config/initializers/logging.rb

Ruby

1

2

3

4

Mongoid.logger=Log4r::Logger['rails']

Moped.logger=Log4r::Logger['rails']

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:

YAML

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22

23

24

25

26

27

28

29

30

31

log4r_config:

# define all loggers:

loggers:

- name: rails

level: DEBUG

trace: 'false'

outputters:

-console

- name: mysql

level: DEBUG

trace: 'false'

outputters:

-console

- name: mongoid

level: DEBUG

trace: 'false'

outputters:

-console

# define all outputters (incl. formatters)

outputters:

- type: StdoutOutputter

name: console

formatter:

date_pattern: '%H:%M:%S'

pattern: '%d %l: %m'

type: PatternFormatter

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

config/application.rb

Ruby

1

2

3

4

5

6

7

8

#no change to log4r loading code necessary

config.logger=Log4r::Logger['rails']

config.log_level=DEBUG

ActiveRecord::Base.logger=Log4r::Logger['mysql']

Mongoid.logger=Log4r::Logger['mongoid']

Moped.logger=Log4r::Logger['mongoid']

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()}

config/log4r.yml

YAML

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

log4r_config:

pre_config:

custom_levels:

-DEV0

-DEBUG

-PARAMS

-DEV1

-INFO

-WARN

-ERROR

-EXCEPTION

-FATAL

# define all loggers ...

loggers:

...

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:

config/log4r.yml

YAML

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22

23

24

25

26

27

28

29

30

log4r_config:

# define all loggers:

loggers:

- name: rails

level: DEBUG

trace: 'true'

outputters:

-console

-railsfile

# ...

# define all outputters (incl. formatters)

outputters:

- type: StdoutOutputter

name: console

formatter:

date_pattern: '%H:%M:%S'

pattern: '%d %l: %m'

type: PatternFormatter

- type: FileOutputter

name: railsfile

filename: "log/#{ENV}.log"# notice the file extension is needed!

trunc: false

formatter:

date_pattern: '%Y %m %d %H:%M:%S.%L %z'

pattern: '[#{EC2_INSTANCE}][%p][#{APPNAME}]|[RAILS][%d][%l]: %m '

type: PatternFormatter

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.

config/application.rb

Ruby

1

2

3

4

# disable standard Rails logging

config.log_level=:unknown

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.

1

2

3

4

5

6

7

8

INFO:GET200/object/2434.59ms

WARN:POST200/object/25450.22ms

ERROR:GET500/breakme30.0msEXCEPTION:

ERROR:GET403/object/notThere24.4msEXCEPTION:"The Object could not be found in the Database"

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.

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

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 :

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:

The issue is that DelayedJob expects the logger to be Rails::Logger and makes calls to it that log4r does not support. In this article the logger variable is overwritten to use Log4r::Logger, which does not support the .add call as intended. Unlike in Java there are no packages to determine which logger class to use or slf4j that unites different loggers to a standard interface.

There is no simple solution to this issue. On the one hand you can overwrite the affected parts of delayedJob. On the other hand you can prevent loading the log4r when delayedJob is running rails, i.e. by using a custom environment:

development

production

delayedJob

This is also not guaranteed to work everywhere (anything that checks the rails env == “production” will have issues).

Another way is to use environment variables and check those in the application.rb:if (ENV["log4rlogger"] == "true") config.logger = Log4r::Logger["rails"]

Meet me at…

May2018

Categories

About the Author

Markus Lachinger is an entrepreneur, product manager and full-stack software engineer with a Masters in Software Management from Carnegie Mellon University. He is based in Mountain View, CA and blogs mainly about Ruby, Scala and Scalable Infrastructure. Find out more