Friday, November 6, 2009

Recipe 17.5. Adding Logging to Your Application










Recipe 17.5. Adding Logging to Your Application



Problem


You want to make your application log events or diagnostic data to a file or stream. You want verbose logging when your application is in development, and more taciturn logging when in production.




Solution


Use the
logger
library in the Ruby standard library. Use its
Logger
class to send logging data to a file or other output stream.


In most cases, you'll share a single
Logger
object throughout your application, as a global variable or module constant:



require '
logger'
$LOG = Logger.new($stderr)



You can then call the instance methods of Logger to send messages to the log at various levels of severity. From least to most severe, the instance methods are Logger#debug, Logger#info, Logger#warn, Logger#error, and Logger#fatal.


This code uses the application's logger to print a debugging message, and (at a higher severity) as part of error-handling code.



def divide(numerator, denominator)
$LOG.debug("Numerator: #{numerator}, denominator #{denominator}")
begin
result = numerator / denominator
rescue Exception => e
$LOG.error "Error in division!: #{e}"
result = nil
end
return result
end

divide(10, 2)
# D, [2006-03-31T19:35:01.043938 #18088] DEBUG -- : Numerator: 10, denominator 2
# => 5

divide(10, 0)
# D, [2006-03-31T19:35:01.045230 #18088] DEBUG -- : Numerator: 10, denominator 0
# E, [2006-03-31T19:35:01.045495 #18088] ERROR -- : Error in division!: divided by 0
# => nil



To change the log level, simply assign the appropriate constant to level:



$LOG.level = Logger::ERROR



Now our logger will ignore all log messages except those with severity ERROR or FATAL:



divide(10, 2)
# => 5

divide(10, 0)
# E, [2006-03-31T19:35:01.047861 #18088] ERROR -- : Error in division!: divided by 0
# => nil





Discussion


Ruby's standard logging system works like Java's oft-imitated Log4J. The Logger object centralizes all the decisions about whether a particular message is important enough to be written to the log. When you write code, you simply assume that all the messages will be logged. At runtime, you can get a more or a less verbose log by changing the log level. A production application usually has a log level of
Logger::INFO
or
Logger::WARN
.


The DEBUG log level is useful for step-by-step diagnostics of a complex task. The ERROR level is often used when handling exceptions: if the program can't solve a problem, it logs the exception rather than crash and expects a human administrator to deal with it. The FATAL level should only be used when the program cannot recover from a problem, and is about to crash or exit.


If your log is being stored in a file, you can have Logger rotate or replace the log file when it get too big, or once a certain amount of time has elapsed:



# Keep data for the current month only
Logger.new('this_month.log', 'monthly')

# Keep data for today and the past 20 days.
Logger.new('application.log', 20, 'daily')

# Start the log over whenever the log exceeds 100 megabytes in size.
Logger.new('application.log', 0, 100 * 1024 * 1024)



If the default log entries are too verbose for you, you have a couple of options. The simplest is to set datetime_format to a more concise date format. This code gets rid of the milliseconds:



$LOG.datetime_format = '%Y-%m-%d %H:%M:%S'
$LOG.error('This is a little shorter.')
# E, [2006-03-31T19:35:01#17339] ERROR -- : This is a little shorter.



If that's not enough for you, you can replace the call method that formats a message for the log:



class Logger
class Formatter
Format = "%s [%s] %s %s\n"
def call(severity, time, progname, msg)
Format % [severity, format_datetime(time), progname, msg]
end
end
end

$LOG.error('This is much shorter.')
# ERROR [2006-03-31T19:35:01.058646 ] This is much shorter.





See Also


  • The standard library documentation for the logger library













No comments:

Post a Comment