lib/logger.rb

   1 # logger.rb - simple logging utility
   2 # Copyright (C) 2000-2003, 2005  NAKAMURA, Hiroshi <nakahiro@sarion.co.jp>.
   3
   4 require 'monitor'
   5
   6 # = logger.rb
   7 #
   8 # Simple logging utility.
   9 #
  10 # Author:: NAKAMURA, Hiroshi  <nakahiro@sarion.co.jp>
  11 # Documentation:: NAKAMURA, Hiroshi and Gavin Sinclair
  12 # License::
  13 #   You can redistribute it and/or modify it under the same terms of Ruby's
  14 #   license; either the dual license version in 2003, or any later version.
  15 # Revision:: $Id$
  16 #
  17 # See Logger for documentation.
  18 #
  19
  20
  21 #
  22 # == Description
  23 #
  24 # The Logger class provides a simple but sophisticated logging utility that
  25 # anyone can use because it's included in the Ruby 1.8.x standard library.
  26 #
  27 # The HOWTOs below give a code-based overview of Logger's usage, but the basic
  28 # concept is as follows.  You create a Logger object (output to a file or
  29 # elsewhere), and use it to log messages.  The messages will have varying
  30 # levels (+info+, +error+, etc), reflecting their varying importance.  The
  31 # levels, and their meanings, are:
  32 #
  33 # +FATAL+:: an unhandleable error that results in a program crash
  34 # +ERROR+:: a handleable error condition
  35 # +WARN+::  a warning
  36 # +INFO+::  generic (useful) information about system operation
  37 # +DEBUG+:: low-level information for developers
  38 #
  39 # So each message has a level, and the Logger itself has a level, which acts
  40 # as a filter, so you can control the amount of information emitted from the
  41 # logger without having to remove actual messages.
  42 #
  43 # For instance, in a production system, you may have your logger(s) set to
  44 # +INFO+ (or +WARN+ if you don't want the log files growing large with
  45 # repetitive information).  When you are developing it, though, you probably
  46 # want to know about the program's internal state, and would set them to
  47 # +DEBUG+.
  48 #
  49 # === Example
  50 #
  51 # A simple example demonstrates the above explanation:
  52 #
  53 #   log = Logger.new(STDOUT)
  54 #   log.level = Logger::WARN
  55 #
  56 #   log.debug("Created logger")
  57 #   log.info("Program started")
  58 #   log.warn("Nothing to do!")
  59 #
  60 #   begin
  61 #     File.each_line(path) do |line|
  62 #       unless line =~ /^(\w+) = (.*)$/
  63 #         log.error("Line in wrong format: #{line}")
  64 #       end
  65 #     end
  66 #   rescue => err
  67 #     log.fatal("Caught exception; exiting")
  68 #     log.fatal(err)
  69 #   end
  70 #
  71 # Because the Logger's level is set to +WARN+, only the warning, error, and
  72 # fatal messages are recorded.  The debug and info messages are silently
  73 # discarded.
  74 #
  75 # === Features
  76 #
  77 # There are several interesting features that Logger provides, like
  78 # auto-rolling of log files, setting the format of log messages, and
  79 # specifying a program name in conjunction with the message.  The next section
  80 # shows you how to achieve these things.
  81 #
  82 #
  83 # == HOWTOs
  84 #
  85 # === How to create a logger
  86 #
  87 # The options below give you various choices, in more or less increasing
  88 # complexity.
  89 #
  90 # 1. Create a logger which logs messages to STDERR/STDOUT.
  91 #
  92 #      logger = Logger.new(STDERR)
  93 #      logger = Logger.new(STDOUT)
  94 #
  95 # 2. Create a logger for the file which has the specified name.
  96 #
  97 #      logger = Logger.new('logfile.log')
  98 #
  99 # 3. Create a logger for the specified file.
 100 #
 101 #      file = File.open('foo.log', File::WRONLY | File::APPEND)
 102 #      # To create new (and to remove old) logfile, add File::CREAT like;
 103 #      #   file = open('foo.log', File::WRONLY | File::APPEND | File::CREAT)
 104 #      logger = Logger.new(file)
 105 #
 106 # 4. Create a logger which ages logfile once it reaches a certain size.  Leave
 107 #    10 "old log files" and each file is about 1,024,000 bytes.
 108 #
 109 #      logger = Logger.new('foo.log', 10, 1024000)
 110 #
 111 # 5. Create a logger which ages logfile daily/weekly/monthly.
 112 #
 113 #      logger = Logger.new('foo.log', 'daily')
 114 #      logger = Logger.new('foo.log', 'weekly')
 115 #      logger = Logger.new('foo.log', 'monthly')
 116 #
 117 # === How to log a message
 118 #
 119 # Notice the different methods (+fatal+, +error+, +info+) being used to log
 120 # messages of various levels.  Other methods in this family are +warn+ and
 121 # +debug+.  +add+ is used below to log a message of an arbitrary (perhaps
 122 # dynamic) level.
 123 #
 124 # 1. Message in block.
 125 #
 126 #      logger.fatal { "Argument 'foo' not given." }
 127 #
 128 # 2. Message as a string.
 129 #
 130 #      logger.error "Argument #{ @foo } mismatch."
 131 #
 132 # 3. With progname.
 133 #
 134 #      logger.info('initialize') { "Initializing..." }
 135 #
 136 # 4. With severity.
 137 #
 138 #      logger.add(Logger::FATAL) { 'Fatal error!' }
 139 #
 140 # === How to close a logger
 141 #
 142 #      logger.close
 143 #
 144 # === Setting severity threshold
 145 #
 146 # 1. Original interface.
 147 #
 148 #      logger.sev_threshold = Logger::WARN
 149 #
 150 # 2. Log4r (somewhat) compatible interface.
 151 #
 152 #      logger.level = Logger::INFO
 153 #
 154 #      DEBUG < INFO < WARN < ERROR < FATAL < UNKNOWN
 155 #
 156 #
 157 # == Format
 158 #
 159 # Log messages are rendered in the output stream in a certain format by
 160 # default.  The default format and a sample are shown below:
 161 #
 162 # Log format:
 163 #   SeverityID, [Date Time mSec #pid] SeverityLabel -- ProgName: message
 164 #
 165 # Log sample:
 166 #   I, [Wed Mar 03 02:34:24 JST 1999 895701 #19074]  INFO -- Main: info.
 167 #
 168 # You may change the date and time format in this manner:
 169 #
 170 #   logger.datetime_format = "%Y-%m-%d %H:%M:%S"
 171 #         # e.g. "2004-01-03 00:54:26"
 172 #
 173 # You may change the overall format with Logger#formatter= method.
 174 #
 175 #   logger.formatter = proc { |severity, datetime, progname, msg|
 176 #     "#{datetime}: #{msg}\n"
 177 #   }
 178 #         # e.g. "Thu Sep 22 08:51:08 GMT+9:00 2005: hello world"
 179 #
 180
 181
 182 class Logger
 183   VERSION = "1.2.6"
 184   /: (\S+),v (\S+)/ =~ %q$Id$
 185   ProgName = "#{$1}/#{$2}"
 186
 187   class Error < RuntimeError; end
 188   class ShiftingError < Error; end
 189
 190   # Logging severity.
 191   module Severity
 192     DEBUG = 0
 193     INFO = 1
 194     WARN = 2
 195     ERROR = 3
 196     FATAL = 4
 197     UNKNOWN = 5
 198   end
 199   include Severity
 200
 201   # Logging severity threshold (e.g. <tt>Logger::INFO</tt>).
 202   attr_accessor :level
 203
 204   # Logging program name.
 205   attr_accessor :progname
 206
 207   # Logging date-time format (string passed to +strftime+).
 208   def datetime_format=(datetime_format)
 209     @default_formatter.datetime_format = datetime_format
 210   end
 211
 212   def datetime_format
 213     @default_formatter.datetime_format
 214   end
 215
 216   # Logging formatter.  formatter#call is invoked with 4 arguments; severity,
 217   # time, progname and msg for each log.  Bear in mind that time is a Time and
 218   # msg is an Object that user passed and it could not be a String.  It is
 219   # expected to return a logdev#write-able Object.  Default formatter is used
 220   # when no formatter is set.
 221   attr_accessor :formatter
 222
 223   alias sev_threshold level
 224   alias sev_threshold= level=
 225
 226   # Returns +true+ iff the current severity level allows for the printing of
 227   # +DEBUG+ messages.
 228   def debug?; @level <= DEBUG; end
 229
 230   # Returns +true+ iff the current severity level allows for the printing of
 231   # +INFO+ messages.
 232   def info?; @level <= INFO; end
 233
 234   # Returns +true+ iff the current severity level allows for the printing of
 235   # +WARN+ messages.
 236   def warn?; @level <= WARN; end
 237
 238   # Returns +true+ iff the current severity level allows for the printing of
 239   # +ERROR+ messages.
 240   def error?; @level <= ERROR; end
 241
 242   # Returns +true+ iff the current severity level allows for the printing of
 243   # +FATAL+ messages.
 244   def fatal?; @level <= FATAL; end
 245
 246   #
 247   # === Synopsis
 248   #
 249   #   Logger.new(name, shift_age = 7, shift_size = 1048576)
 250   #   Logger.new(name, shift_age = 'weekly')
 251   #
 252   # === Args
 253   #
 254   # +logdev+::
 255   #   The log device.  This is a filename (String) or IO object (typically
 256   #   +STDOUT+, +STDERR+, or an open file).
 257   # +shift_age+::
 258   #   Number of old log files to keep, *or* frequency of rotation (+daily+,
 259   #   +weekly+ or +monthly+).
 260   # +shift_size+::
 261   #   Maximum logfile size (only applies when +shift_age+ is a number).
 262   #
 263   # === Description
 264   #
 265   # Create an instance.
 266   #
 267   def initialize(logdev, shift_age = 0, shift_size = 1048576)
 268     @progname = nil
 269     @level = DEBUG
 270     @default_formatter = Formatter.new
 271     @formatter = nil
 272     @logdev = nil
 273     if logdev
 274       @logdev = LogDevice.new(logdev, :shift_age => shift_age,
 275         :shift_size => shift_size)
 276     end
 277   end
 278
 279   #
 280   # === Synopsis
 281   #
 282   #   Logger#add(severity, message = nil, progname = nil) { ... }
 283   #
 284   # === Args
 285   #
 286   # +severity+::
 287   #   Severity.  Constants are defined in Logger namespace: +DEBUG+, +INFO+,
 288   #   +WARN+, +ERROR+, +FATAL+, or +UNKNOWN+.
 289   # +message+::
 290   #   The log message.  A String or Exception.
 291   # +progname+::
 292   #   Program name string.  Can be omitted.  Treated as a message if no +message+ and
 293   #   +block+ are given.
 294   # +block+::
 295   #   Can be omitted.  Called to get a message string if +message+ is nil.
 296   #
 297   # === Return
 298   #
 299   # +true+ if successful, +false+ otherwise.
 300   #
 301   # When the given severity is not high enough (for this particular logger), log
 302   # no message, and return +true+.
 303   #
 304   # === Description
 305   #
 306   # Log a message if the given severity is high enough.  This is the generic
 307   # logging method.  Users will be more inclined to use #debug, #info, #warn,
 308   # #error, and #fatal.
 309   #
 310   # <b>Message format</b>: +message+ can be any object, but it has to be
 311   # converted to a String in order to log it.  Generally, +inspect+ is used
 312   # if the given object is not a String.
 313   # A special case is an +Exception+ object, which will be printed in detail,
 314   # including message, class, and backtrace.  See #msg2str for the
 315   # implementation if required.
 316   #
 317   # === Bugs
 318   #
 319   # * Logfile is not locked.
 320   # * Append open does not need to lock file.
 321   # * But on the OS which supports multi I/O, records possibly be mixed.
 322   #
 323   def add(severity, message = nil, progname = nil, &block)
 324     severity ||= UNKNOWN
 325     if @logdev.nil? or severity < @level
 326       return true
 327     end
 328     progname ||= @progname
 329     if message.nil?
 330       if block_given?
 331         message = yield
 332       else
 333         message = progname
 334         progname = @progname
 335       end
 336     end
 337     @logdev.write(
 338       format_message(format_severity(severity), Time.now, progname, message))
 339     true
 340   end
 341   alias log add
 342
 343   #
 344   # Dump given message to the log device without any formatting.  If no log
 345   # device exists, return +nil+.
 346   #
 347   def <<(msg)
 348     unless @logdev.nil?
 349       @logdev.write(msg)
 350     end
 351   end
 352
 353   #
 354   # Log a +DEBUG+ message.
 355   #
 356   # See #info for more information.
 357   #
 358   def debug(progname = nil, &block)
 359     add(DEBUG, nil, progname, &block)
 360   end
 361
 362   #
 363   # Log an +INFO+ message.
 364   #
 365   # The message can come either from the +progname+ argument or the +block+.  If
 366   # both are provided, then the +block+ is used as the message, and +progname+
 367   # is used as the program name.
 368   #
 369   # === Examples
 370   #
 371   #   logger.info("MainApp") { "Received connection from #{ip}" }
 372   #   # ...
 373   #   logger.info "Waiting for input from user"
 374   #   # ...
 375   #   logger.info { "User typed #{input}" }
 376   #
 377   # You'll probably stick to the second form above, unless you want to provide a
 378   # program name (which you can do with <tt>Logger#progname=</tt> as well).
 379   #
 380   # === Return
 381   #
 382   # See #add.
 383   #
 384   def info(progname = nil, &block)
 385     add(INFO, nil, progname, &block)
 386   end
 387
 388   #
 389   # Log a +WARN+ message.
 390   #
 391   # See #info for more information.
 392   #
 393   def warn(progname = nil, &block)
 394     add(WARN, nil, progname, &block)
 395   end
 396
 397   #
 398   # Log an +ERROR+ message.
 399   #
 400   # See #info for more information.
 401   #
 402   def error(progname = nil, &block)
 403     add(ERROR, nil, progname, &block)
 404   end
 405
 406   #
 407   # Log a +FATAL+ message.
 408   #
 409   # See #info for more information.
 410   #
 411   def fatal(progname = nil, &block)
 412     add(FATAL, nil, progname, &block)
 413   end
 414
 415   #
 416   # Log an +UNKNOWN+ message.  This will be printed no matter what the logger
 417   # level.
 418   #
 419   # See #info for more information.
 420   #
 421   def unknown(progname = nil, &block)
 422     add(UNKNOWN, nil, progname, &block)
 423   end
 424
 425   #
 426   # Close the logging device.
 427   #
 428   def close
 429     @logdev.close if @logdev
 430   end
 431
 432 private
 433
 434   # Severity label for logging. (max 5 char)
 435   SEV_LABEL = %w(DEBUG INFO WARN ERROR FATAL ANY)
 436
 437   def format_severity(severity)
 438     SEV_LABEL[severity] || 'ANY'
 439   end
 440
 441   def format_message(severity, datetime, progname, msg)
 442     (@formatter || @default_formatter).call(severity, datetime, progname, msg)
 443   end
 444
 445
 446   class Formatter
 447     Format = "%s, [%s#%d] %5s -- %s: %s\n"
 448
 449     attr_accessor :datetime_format
 450
 451     def initialize
 452       @datetime_format = nil
 453     end
 454
 455     def call(severity, time, progname, msg)
 456       Format % [severity[0..0], format_datetime(time), $$, severity, progname,
 457         msg2str(msg)]
 458     end
 459
 460   private
 461
 462     def format_datetime(time)
 463       if @datetime_format.nil?
 464         time.strftime("%Y-%m-%dT%H:%M:%S.") << "%06d " % time.usec
 465       else
 466         time.strftime(@datetime_format)
 467       end
 468     end
 469
 470     def msg2str(msg)
 471       case msg
 472       when ::String
 473         msg
 474       when ::Exception
 475         "#{ msg.message } (#{ msg.class })\n" <<
 476           (msg.backtrace || []).join("\n")
 477       else
 478         msg.inspect
 479       end
 480     end
 481   end
 482
 483
 484   class LogDevice
 485     attr_reader :dev
 486     attr_reader :filename
 487
 488     class LogDeviceMutex
 489       include MonitorMixin
 490     end
 491
 492     def initialize(log = nil, opt = {})
 493       @dev = @filename = @shift_age = @shift_size = nil
 494       @mutex = LogDeviceMutex.new
 495       if log.respond_to?(:write) and log.respond_to?(:close)
 496         @dev = log
 497       else
 498         @dev = open_logfile(log)
 499         @dev.sync = true
 500         @filename = log
 501         @shift_age = opt[:shift_age] || 7
 502         @shift_size = opt[:shift_size] || 1048576
 503       end
 504     end
 505
 506     def write(message)
 507       @mutex.synchronize do
 508         if @shift_age and @dev.respond_to?(:stat)
 509           begin
 510             check_shift_log
 511           rescue
 512             raise Logger::ShiftingError.new("Shifting failed. #{$!}")
 513           end
 514         end
 515         @dev.write(message)
 516       end
 517     end
 518
 519     def close
 520       @mutex.synchronize do
 521         @dev.close
 522       end
 523     end
 524
 525   private
 526
 527     def open_logfile(filename)
 528       if (FileTest.exist?(filename))
 529         open(filename, (File::WRONLY | File::APPEND))
 530       else
 531         create_logfile(filename)
 532       end
 533     end
 534
 535     def create_logfile(filename)
 536       logdev = open(filename, (File::WRONLY | File::APPEND | File::CREAT))
 537       logdev.sync = true
 538       add_log_header(logdev)
 539       logdev
 540     end
 541
 542     def add_log_header(file)
 543       file.write(
 544         "# Logfile created on %s by %s\n" % [Time.now.to_s, Logger::ProgName]
 545     )
 546     end
 547
 548     SiD = 24 * 60 * 60
 549
 550     def check_shift_log
 551       if @shift_age.is_a?(Integer)
 552         # Note: always returns false if '0'.
 553         if @filename && (@shift_age > 0) && (@dev.stat.size > @shift_size)
 554           shift_log_age
 555         end
 556       else
 557         now = Time.now
 558         if @dev.stat.mtime <= previous_period_end(now)
 559           shift_log_period(now)
 560         end
 561       end
 562     end
 563
 564     def shift_log_age
 565       (@shift_age-3).downto(0) do |i|
 566         if FileTest.exist?("#{@filename}.#{i}")
 567           File.rename("#{@filename}.#{i}", "#{@filename}.#{i+1}")
 568         end
 569       end
 570       @dev.close
 571       File.rename("#{@filename}", "#{@filename}.0")
 572       @dev = create_logfile(@filename)
 573       return true
 574     end
 575
 576     def shift_log_period(now)
 577       postfix = previous_period_end(now).strftime("%Y%m%d")     # YYYYMMDD
 578       age_file = "#{@filename}.#{postfix}"
 579       if FileTest.exist?(age_file)
 580         raise RuntimeError.new("'#{ age_file }' already exists.")
 581       end
 582       @dev.close
 583       File.rename("#{@filename}", age_file)
 584       @dev = create_logfile(@filename)
 585       return true
 586     end
 587
 588     def previous_period_end(now)
 589       case @shift_age
 590       when /^daily$/
 591         eod(now - 1 * SiD)
 592       when /^weekly$/
 593         eod(now - ((now.wday + 1) * SiD))
 594       when /^monthly$/
 595         eod(now - now.mday * SiD)
 596       else
 597         now
 598       end
 599     end
 600
 601     def eod(t)
 602       Time.mktime(t.year, t.month, t.mday, 23, 59, 59)
 603     end
 604   end
 605
 606
 607   #
 608   # == Description
 609   #
 610   # Application -- Add logging support to your application.
 611   #
 612   # == Usage
 613   #
 614   # 1. Define your application class as a sub-class of this class.
 615   # 2. Override 'run' method in your class to do many things.
 616   # 3. Instantiate it and invoke 'start'.
 617   #
 618   # == Example
 619   #
 620   #   class FooApp < Application
 621   #     def initialize(foo_app, application_specific, arguments)
 622   #       super('FooApp') # Name of the application.
 623   #     end
 624   #
 625   #     def run
 626   #       ...
 627   #       log(WARN, 'warning', 'my_method1')
 628   #       ...
 629   #       @log.error('my_method2') { 'Error!' }
 630   #       ...
 631   #     end
 632   #   end
 633   #
 634   #   status = FooApp.new(....).start
 635   #
 636   class Application
 637     include Logger::Severity
 638
 639     # Name of the application given at initialize.
 640     attr_reader :appname
 641
 642     #
 643     # == Synopsis
 644     #
 645     #   Application.new(appname = '')
 646     #
 647     # == Args
 648     #
 649     # +appname+:: Name of the application.
 650     #
 651     # == Description
 652     #
 653     # Create an instance.  Log device is +STDERR+ by default.  This can be
 654     # changed with #set_log.
 655     #
 656     def initialize(appname = nil)
 657       @appname = appname
 658       @log = Logger.new(STDERR)
 659       @log.progname = @appname
 660       @level = @log.level
 661     end
 662
 663     #
 664     # Start the application.  Return the status code.
 665     #
 666     def start
 667       status = -1
 668       begin
 669         log(INFO, "Start of #{ @appname }.")
 670         status = run
 671       rescue
 672         log(FATAL, "Detected an exception. Stopping ... #{$!} (#{$!.class})\n" << $@.join("\n"))
 673       ensure
 674         log(INFO, "End of #{ @appname }. (status: #{ status.to_s })")
 675       end
 676       status
 677     end
 678
 679     # Logger for this application.  See the class Logger for an explanation.
 680     def logger
 681       @log
 682     end
 683
 684     #
 685     # Sets the logger for this application.  See the class Logger for an explanation.
 686     #
 687     def logger=(logger)
 688       @log = logger
 689     end
 690
 691     #
 692     # Sets the log device for this application.  See <tt>Logger.new</tt> for an explanation
 693     # of the arguments.
 694     #
 695     def set_log(logdev, shift_age = 0, shift_size = 1024000)
 696       @log = Logger.new(logdev, shift_age, shift_size)
 697       @log.progname = @appname
 698       @log.level = @level
 699     end
 700
 701     def log=(logdev)
 702       set_log(logdev)
 703     end
 704
 705     #
 706     # Set the logging threshold, just like <tt>Logger#level=</tt>.
 707     #
 708     def level=(level)
 709       @level = level
 710       @log.level = @level
 711     end
 712
 713     #
 714     # See Logger#add.  This application's +appname+ is used.
 715     #
 716     def log(severity, message = nil, &block)
 717       @log.add(severity, message, @appname, &block) if @log
 718     end
 719
 720   private
 721
 722     def run
 723       raise RuntimeError.new('Method run must be defined in the derived class.')
 724     end
 725   end
 726 end