Logging: Getting the Information You Need

Keeping track of your application’s health has many different facets and different layers of information. Logging is the most basic tool, but can often be the most difficult to understand.  While we strive to convey information by dashboard and graphical outputs as much as possible, sometimes there is nothing better than an old fashioned trip through the logs to get a good grip on the situation.

On the development side, we can use the Logger class in Ruby applications.  It is part of the Ruby standard library and therefore easily accessible.  The purpose behind Logger is to send log messages to some stream for review or to write logs directly to a file for retrieval at a later time. The following code shows an example of setting up Logger for use:

require ‘logger’
Logger.new (‘log.txt’)

Messages from Logger can also be assigned flags to determine how severe an issue is.  These messages can then be limited so that only messages above or below a certain threshold will be sent.  This code shows an example of a message in the logs that has been marked as a “warning” level event:

log = Logger.new (‘log.txt’)
log.level = Logger::WARN

log.debug “This can be ignored”
log.error “This is an issue, please take action”

In general, production applications have log levels of Logger::INFO or Logger::Warn, but the there is a range of severities, listed here in order:

Logger.debug

Logger.info

Logger.warn

Logger.error

Logger.fatal

One of the key features of Logger is the ability to rotate the logs.  While logs can be helpful, they are only pertinent for brief periods of time and should therefore be overwritten once they are no longer of value.  The following code takes a look at different ways of creating logs that are rotated periodically:

require ‘logger’
# Keep a daily log
Logger.new (‘daily_log.log’, ‘daily’)
# Keep data for the past 10 days
Logger.new (‘application.log’, 10, ‘daily’)
# Keep data for the current month
Logger.new (‘monthly_log.log’, ‘monthly’)

Logging is a key feature to debugging any Ruby application in order to get everything in place and get the application production ready.  Using Logger is the easiest way to get the feedback necessary to find issue and fix them and get the app out into the world.

In Production

Once all the bugs are worked out and your application is working optimally, it’s time to put it out into the world.  Most people know Engine Yard makes this easy, many aren’t aware of the various logging and reporting features available for your application once it’s been deployed.

The first logs we look at when troubleshooting is the deploy logs.  To find your deploy logs, assuming you aren’t using the dashboard, SSH into your application master instance and do the following:

$ cat home/deploy/#{app_name}-deploy.log

Here we can find, hopefully, logs showing the most recent successful deploy, complete with Chef run information and what gems have been installed or might be soon deprecated.  If the situation that lead to the deploy logs was a failed deploy, you may see something more along the lines of:

+    03s  ~> Deploying revision fatal: bad object 648b1bcf3269de8df657c1280980189a9d880290
$ git checkout -f  '648b1bcf3269de8df657c1280980189a9d880290'
fatal: reference is not a tree: 648b1bcf3269de8df657c1280980189a9d880290
$ git reset --hard  '648b1bcf3269de8df657c1280980189a9d880290'
fatal: Could not parse object '648b1bcf3269de8df657c1280980189a9d880290'.
+    05s  !> FATAL: git checkout 648b1bcf3269de8df657c1280980189a9d880290 failed.

This is a glimpse of particular issues you may encounter in the deploy logs.  In this case, there was an error contacting Github to deploy the code.  This could indicate a bad reference to the branch being deployed or an issue on the Github side, but it’s fairly explicit and clear where the action needs to be taken.  If everything deploys as planned but there are still issue, it may be necessary to check other logs, such as nginx logs.

Logs specifically geared toward following nginx can often be helpful but tricky to navigate.  It is necessary to have some idea of some of the facets of systems administration and devops to understand messages like the following:

ip-10-144-150-196 log # more /var/log/chef.main.log
/usr/local/ey_resin/ruby/lib/ruby/site_ruby/1.9.1/rubygems/custom_require.rb:36:
in `require': iconv will be deprecated in the future, use String#encode instead.
[2013-08-28T20:01:25+00:00] INFO: *** Chef 10.16.4 ***
[2013-08-28T20:01:36+00:00] INFO: Setting the run_list to "recipe[ey-base]" from
JSON
[2013-08-28T20:01:36+00:00] INFO: Run List is [recipe[ey-base]]
[2013-08-28T20:01:36+00:00] INFO: Run List expands to [ey-base]
[2013-08-28T20:01:36+00:00] INFO: Starting Chef Run for i-76d2f915
[2013-08-28T20:01:36+00:00] INFO: Running start handlers
[2013-08-28T20:01:36+00:00] INFO: Start handlers complete.
[2013-08-28T20:01:36+00:00] WARN: Setting attributes without specifying a preced
ence is deprecated and will be
removed in Chef 11.0. To set attributes at normal precedence, change code like:
`node["key"] = "value"` # Not this
to:
`node.set["key"] = "value"` # This

Here we see some of the deprecation errors we are familiar with, some information from our chef run, and things more in depth than our original deploy logs.  If these logs seem confusing and aren’t helping you to diagnose the situation, you’re left with two choices: call Support, or use something like AppFirst to graphically represent your logs.

Logs are a key component to application success.  Whether tracking latency, minding resources, or just tracking bugs in development, using the logs is the fastest and easiest way to ensure a solid app and better experiences for your users.  If there is ever doubt, the Engine Yard App Support team is standing by to help.