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