lib/logger.rb

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