2008-06-04 05:37:38 -04:00
|
|
|
# logger.rb - simple logging utility
|
2011-01-18 01:11:41 -05:00
|
|
|
# Copyright (C) 2000-2003, 2005, 2008, 2011 NAKAMURA, Hiroshi <nahi@ruby-lang.org>.
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# Documentation:: NAKAMURA, Hiroshi and Gavin Sinclair
|
|
|
|
# License::
|
2004-01-06 06:55:08 -05:00
|
|
|
# You can redistribute it and/or modify it under the same terms of Ruby's
|
|
|
|
# license; either the dual license version in 2003, or any later version.
|
2004-01-05 08:33:48 -05:00
|
|
|
# Revision:: $Id$
|
2007-05-16 08:52:52 -04:00
|
|
|
#
|
2011-05-16 17:43:20 -04:00
|
|
|
# A simple system for logging messages. See Logger for more documentation.
|
2007-05-16 08:52:52 -04:00
|
|
|
|
2009-10-20 11:08:38 -04:00
|
|
|
require 'monitor'
|
|
|
|
|
2004-01-05 08:33:48 -05:00
|
|
|
# == Description
|
|
|
|
#
|
|
|
|
# The Logger class provides a simple but sophisticated logging utility that
|
2011-05-16 17:43:20 -04:00
|
|
|
# you can use to output messages.
|
|
|
|
#
|
|
|
|
# The messages have associated levels, such as +INFO+ or +ERROR+ that indicate
|
|
|
|
# their importance. You can then give the Logger a level, and only messages
|
2012-07-17 20:27:04 -04:00
|
|
|
# at that level or higher will be printed.
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
2011-05-16 17:43:20 -04:00
|
|
|
# The levels are:
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# +UNKNOWN+:: An unknown message that should always be logged.
|
|
|
|
# +FATAL+:: An unhandleable error that results in a program crash.
|
|
|
|
# +ERROR+:: A handleable error condition.
|
|
|
|
# +WARN+:: A warning.
|
|
|
|
# +INFO+:: Generic (useful) information about system operation.
|
|
|
|
# +DEBUG+:: Low-level information for developers.
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
2011-05-16 17:43:20 -04:00
|
|
|
# For instance, in a production system, you may have your Logger set to
|
2012-07-17 20:27:04 -04:00
|
|
|
# +INFO+ or even +WARN+.
|
2011-05-16 17:43:20 -04:00
|
|
|
# When you are developing the system, however, you probably
|
|
|
|
# want to know about the program's internal state, and would set the Logger to
|
2004-01-05 08:33:48 -05:00
|
|
|
# +DEBUG+.
|
|
|
|
#
|
2011-05-16 17:43:20 -04:00
|
|
|
# *Note*: Logger does not escape or sanitize any messages passed to it.
|
2011-01-18 01:11:41 -05:00
|
|
|
# Developers should be aware of when potentially malicious data (user-input)
|
|
|
|
# is passed to Logger, and manually escape the untrusted data:
|
|
|
|
#
|
|
|
|
# logger.info("User-input: #{input.dump}")
|
|
|
|
# logger.info("User-input: %p" % input)
|
|
|
|
#
|
2011-05-16 17:43:20 -04:00
|
|
|
# You can use #formatter= for escaping all data.
|
2011-01-18 01:11:41 -05:00
|
|
|
#
|
|
|
|
# original_formatter = Logger::Formatter.new
|
|
|
|
# logger.formatter = proc { |severity, datetime, progname, msg|
|
|
|
|
# original_formatter.call(severity, datetime, progname, msg.dump)
|
|
|
|
# }
|
|
|
|
# logger.info(input)
|
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# === Example
|
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# This creates a Logger that outputs to the standard output stream, with a
|
|
|
|
# level of +WARN+:
|
|
|
|
#
|
|
|
|
# require 'logger'
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
2012-07-20 19:41:51 -04:00
|
|
|
# logger = Logger.new(STDOUT)
|
|
|
|
# logger.level = Logger::WARN
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
2012-07-20 19:41:51 -04:00
|
|
|
# logger.debug("Created logger")
|
|
|
|
# logger.info("Program started")
|
|
|
|
# logger.warn("Nothing to do!")
|
|
|
|
#
|
|
|
|
# path = "a_non_existent_file"
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# begin
|
2012-07-20 19:41:51 -04:00
|
|
|
# File.foreach(path) do |line|
|
2004-01-05 08:33:48 -05:00
|
|
|
# unless line =~ /^(\w+) = (.*)$/
|
2012-07-20 19:41:51 -04:00
|
|
|
# logger.error("Line in wrong format: #{line.chomp}")
|
2004-01-05 08:33:48 -05:00
|
|
|
# end
|
|
|
|
# end
|
|
|
|
# rescue => err
|
2012-07-20 19:41:51 -04:00
|
|
|
# logger.fatal("Caught exception; exiting")
|
|
|
|
# logger.fatal(err)
|
2004-01-05 08:33:48 -05:00
|
|
|
# end
|
|
|
|
#
|
|
|
|
# Because the Logger's level is set to +WARN+, only the warning, error, and
|
|
|
|
# fatal messages are recorded. The debug and info messages are silently
|
|
|
|
# discarded.
|
|
|
|
#
|
|
|
|
# === Features
|
|
|
|
#
|
|
|
|
# There are several interesting features that Logger provides, like
|
|
|
|
# auto-rolling of log files, setting the format of log messages, and
|
|
|
|
# specifying a program name in conjunction with the message. The next section
|
|
|
|
# shows you how to achieve these things.
|
|
|
|
#
|
|
|
|
#
|
|
|
|
# == HOWTOs
|
|
|
|
#
|
|
|
|
# === How to create a logger
|
|
|
|
#
|
|
|
|
# The options below give you various choices, in more or less increasing
|
|
|
|
# complexity.
|
|
|
|
#
|
|
|
|
# 1. Create a logger which logs messages to STDERR/STDOUT.
|
|
|
|
#
|
|
|
|
# logger = Logger.new(STDERR)
|
|
|
|
# logger = Logger.new(STDOUT)
|
|
|
|
#
|
|
|
|
# 2. Create a logger for the file which has the specified name.
|
|
|
|
#
|
|
|
|
# logger = Logger.new('logfile.log')
|
|
|
|
#
|
|
|
|
# 3. Create a logger for the specified file.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# file = File.open('foo.log', File::WRONLY | File::APPEND)
|
2012-07-17 20:27:04 -04:00
|
|
|
# # To create new (and to remove old) logfile, add File::CREAT like:
|
|
|
|
# # file = File.open('foo.log', File::WRONLY | File::APPEND | File::CREAT)
|
2004-01-05 08:33:48 -05:00
|
|
|
# logger = Logger.new(file)
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# 4. Create a logger which ages the logfile once it reaches a certain size.
|
|
|
|
# Leave 10 "old" log files where each file is about 1,024,000 bytes.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# logger = Logger.new('foo.log', 10, 1024000)
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# 5. Create a logger which ages the logfile daily/weekly/monthly.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# logger = Logger.new('foo.log', 'daily')
|
|
|
|
# logger = Logger.new('foo.log', 'weekly')
|
|
|
|
# logger = Logger.new('foo.log', 'monthly')
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# === How to log a message
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# Notice the different methods (+fatal+, +error+, +info+) being used to log
|
2011-05-16 17:43:20 -04:00
|
|
|
# messages of various levels? Other methods in this family are +warn+ and
|
2004-01-05 08:33:48 -05:00
|
|
|
# +debug+. +add+ is used below to log a message of an arbitrary (perhaps
|
|
|
|
# dynamic) level.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# 1. Message in a block.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# logger.fatal { "Argument 'foo' not given." }
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# 2. Message as a string.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# logger.error "Argument #{@foo} mismatch."
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# 3. With progname.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# logger.info('initialize') { "Initializing..." }
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# 4. With severity.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# logger.add(Logger::FATAL) { 'Fatal error!' }
|
2011-05-18 10:09:38 -04:00
|
|
|
#
|
2011-05-16 17:43:20 -04:00
|
|
|
# The block form allows you to create potentially complex log messages,
|
|
|
|
# but to delay their evaluation until and unless the message is
|
|
|
|
# logged. For example, if we have the following:
|
|
|
|
#
|
|
|
|
# logger.debug { "This is a " + potentially + " expensive operation" }
|
|
|
|
#
|
|
|
|
# If the logger's level is +INFO+ or higher, no debug messages will be logged,
|
|
|
|
# and the entire block will not even be evaluated. Compare to this:
|
|
|
|
#
|
|
|
|
# logger.debug("This is a " + potentially + " expensive operation")
|
|
|
|
#
|
|
|
|
# Here, the string concatenation is done every time, even if the log
|
|
|
|
# level is not set to show the debug message.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# === How to close a logger
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# logger.close
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# === Setting severity threshold
|
|
|
|
#
|
|
|
|
# 1. Original interface.
|
|
|
|
#
|
2005-07-16 01:14:23 -04:00
|
|
|
# logger.sev_threshold = Logger::WARN
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# 2. Log4r (somewhat) compatible interface.
|
|
|
|
#
|
|
|
|
# logger.level = Logger::INFO
|
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# # DEBUG < INFO < WARN < ERROR < FATAL < UNKNOWN
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# == Format
|
|
|
|
#
|
2007-05-16 08:52:52 -04:00
|
|
|
# Log messages are rendered in the output stream in a certain format by
|
|
|
|
# default. The default format and a sample are shown below:
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# Log format:
|
2012-07-17 20:27:04 -04:00
|
|
|
# SeverityID, [DateTime #pid] SeverityLabel -- ProgName: message
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# Log sample:
|
2012-07-17 20:27:04 -04:00
|
|
|
# I, [1999-03-03T02:34:24.895701 #19074] INFO -- Main: info.
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# You may change the date and time format via #datetime_format=.
|
2004-03-26 11:47:16 -05:00
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# logger.datetime_format = '%Y-%m-%d %H:%M:%S'
|
2004-01-05 08:33:48 -05:00
|
|
|
# # e.g. "2004-01-03 00:54:26"
|
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# Or, you may change the overall format via the #formatter= method.
|
2007-05-16 08:52:52 -04:00
|
|
|
#
|
2011-05-16 17:43:20 -04:00
|
|
|
# logger.formatter = proc do |severity, datetime, progname, msg|
|
2007-05-16 08:52:52 -04:00
|
|
|
# "#{datetime}: #{msg}\n"
|
2011-05-16 17:43:20 -04:00
|
|
|
# end
|
2012-07-17 20:27:04 -04:00
|
|
|
# # e.g. "2005-09-22 08:51:08 +0900: hello world"
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
|
|
|
class Logger
|
2009-10-20 11:08:38 -04:00
|
|
|
VERSION = "1.2.7"
|
2010-07-11 12:59:10 -04:00
|
|
|
_, name, rev = %w$Id$
|
2008-11-19 17:35:40 -05:00
|
|
|
if name
|
|
|
|
name = name.chomp(",v")
|
|
|
|
else
|
|
|
|
name = File.basename(__FILE__)
|
|
|
|
end
|
|
|
|
rev ||= "v#{VERSION}"
|
2015-10-26 10:51:04 -04:00
|
|
|
ProgName = "#{name}/#{rev}".freeze
|
2003-09-18 02:31:25 -04:00
|
|
|
|
2011-05-16 17:43:20 -04:00
|
|
|
class Error < RuntimeError # :nodoc:
|
|
|
|
end
|
|
|
|
# not used after 1.2.7. just for compat.
|
|
|
|
class ShiftingError < Error # :nodoc:
|
2011-05-18 10:09:38 -04:00
|
|
|
end
|
2003-09-18 02:31:25 -04:00
|
|
|
|
|
|
|
# Logging severity.
|
|
|
|
module Severity
|
2012-07-17 20:27:04 -04:00
|
|
|
# Low-level information, mostly for developers.
|
2003-09-18 02:31:25 -04:00
|
|
|
DEBUG = 0
|
2012-07-17 20:27:04 -04:00
|
|
|
# Generic (useful) information about system operation.
|
2003-09-18 02:31:25 -04:00
|
|
|
INFO = 1
|
2012-07-17 20:27:04 -04:00
|
|
|
# A warning.
|
2003-09-18 02:31:25 -04:00
|
|
|
WARN = 2
|
2012-07-17 20:27:04 -04:00
|
|
|
# A handleable error condition.
|
2003-09-18 02:31:25 -04:00
|
|
|
ERROR = 3
|
2012-07-17 20:27:04 -04:00
|
|
|
# An unhandleable error that results in a program crash.
|
2003-09-18 02:31:25 -04:00
|
|
|
FATAL = 4
|
2012-07-17 20:27:04 -04:00
|
|
|
# An unknown message that should always be logged.
|
2003-09-18 02:31:25 -04:00
|
|
|
UNKNOWN = 5
|
|
|
|
end
|
|
|
|
include Severity
|
|
|
|
|
2004-01-05 08:33:48 -05:00
|
|
|
# Logging severity threshold (e.g. <tt>Logger::INFO</tt>).
|
2003-09-18 02:31:25 -04:00
|
|
|
attr_accessor :level
|
|
|
|
|
2012-07-17 20:27:04 -04:00
|
|
|
# Program name to include in log messages.
|
2003-09-18 02:31:25 -04:00
|
|
|
attr_accessor :progname
|
|
|
|
|
2011-05-16 17:43:20 -04:00
|
|
|
# Set date-time format.
|
|
|
|
#
|
|
|
|
# +datetime_format+:: A string suitable for passing to +strftime+.
|
2005-09-13 09:13:41 -04:00
|
|
|
def datetime_format=(datetime_format)
|
|
|
|
@default_formatter.datetime_format = datetime_format
|
|
|
|
end
|
|
|
|
|
2011-05-16 17:43:20 -04:00
|
|
|
# Returns the date format being used. See #datetime_format=
|
2005-09-13 09:13:41 -04:00
|
|
|
def datetime_format
|
|
|
|
@default_formatter.datetime_format
|
|
|
|
end
|
|
|
|
|
2011-05-16 17:43:20 -04:00
|
|
|
# Logging formatter, as a +Proc+ that will take four arguments and
|
|
|
|
# return the formatted message. The arguments are:
|
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# +severity+:: The Severity of the log message.
|
|
|
|
# +time+:: A Time instance representing when the message was logged.
|
|
|
|
# +progname+:: The #progname configured, or passed to the logger method.
|
2011-05-16 17:43:20 -04:00
|
|
|
# +msg+:: The _Object_ the user passed to the log message; not necessarily a
|
|
|
|
# String.
|
|
|
|
#
|
|
|
|
# The block should return an Object that can be written to the logging
|
|
|
|
# device via +write+. The default formatter is used when no formatter is
|
|
|
|
# set.
|
2005-09-13 09:13:41 -04:00
|
|
|
attr_accessor :formatter
|
2003-09-18 02:31:25 -04:00
|
|
|
|
|
|
|
alias sev_threshold level
|
|
|
|
alias sev_threshold= level=
|
|
|
|
|
2011-05-18 20:07:25 -04:00
|
|
|
# Returns +true+ iff the current severity level allows for the printing of
|
|
|
|
# +DEBUG+ messages.
|
|
|
|
def debug?; @level <= DEBUG; end
|
2004-01-05 08:33:48 -05:00
|
|
|
|
|
|
|
# Returns +true+ iff the current severity level allows for the printing of
|
|
|
|
# +INFO+ messages.
|
2003-09-18 02:31:25 -04:00
|
|
|
def info?; @level <= INFO; end
|
2004-01-05 08:33:48 -05:00
|
|
|
|
|
|
|
# Returns +true+ iff the current severity level allows for the printing of
|
|
|
|
# +WARN+ messages.
|
2003-09-18 02:31:25 -04:00
|
|
|
def warn?; @level <= WARN; end
|
2004-01-05 08:33:48 -05:00
|
|
|
|
|
|
|
# Returns +true+ iff the current severity level allows for the printing of
|
|
|
|
# +ERROR+ messages.
|
2003-09-18 02:31:25 -04:00
|
|
|
def error?; @level <= ERROR; end
|
2004-01-05 08:33:48 -05:00
|
|
|
|
|
|
|
# Returns +true+ iff the current severity level allows for the printing of
|
|
|
|
# +FATAL+ messages.
|
2003-09-19 22:51:06 -04:00
|
|
|
def fatal?; @level <= FATAL; end
|
2003-09-18 02:31:25 -04:00
|
|
|
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
2013-07-10 10:30:12 -04:00
|
|
|
# :call-seq:
|
2014-02-10 19:10:13 -05:00
|
|
|
# Logger.new(logdev, shift_age = 7, shift_size = 1048576)
|
|
|
|
# Logger.new(logdev, shift_age = 'weekly')
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# === Args
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# +logdev+::
|
|
|
|
# The log device. This is a filename (String) or IO object (typically
|
|
|
|
# +STDOUT+, +STDERR+, or an open file).
|
|
|
|
# +shift_age+::
|
|
|
|
# Number of old log files to keep, *or* frequency of rotation (+daily+,
|
|
|
|
# +weekly+ or +monthly+).
|
|
|
|
# +shift_size+::
|
|
|
|
# Maximum logfile size (only applies when +shift_age+ is a number).
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# === Description
|
|
|
|
#
|
2005-09-13 09:13:41 -04:00
|
|
|
# Create an instance.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
|
|
|
def initialize(logdev, shift_age = 0, shift_size = 1048576)
|
|
|
|
@progname = nil
|
|
|
|
@level = DEBUG
|
2005-09-13 09:13:41 -04:00
|
|
|
@default_formatter = Formatter.new
|
|
|
|
@formatter = nil
|
2003-09-19 22:51:06 -04:00
|
|
|
@logdev = nil
|
|
|
|
if logdev
|
2005-09-13 09:13:41 -04:00
|
|
|
@logdev = LogDevice.new(logdev, :shift_age => shift_age,
|
2011-05-18 20:07:25 -04:00
|
|
|
:shift_size => shift_size)
|
2003-09-19 22:51:06 -04:00
|
|
|
end
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
|
|
|
|
#
|
2013-07-10 10:30:12 -04:00
|
|
|
# :call-seq:
|
2004-01-05 08:33:48 -05:00
|
|
|
# Logger#add(severity, message = nil, progname = nil) { ... }
|
|
|
|
#
|
|
|
|
# === Args
|
|
|
|
#
|
|
|
|
# +severity+::
|
|
|
|
# Severity. Constants are defined in Logger namespace: +DEBUG+, +INFO+,
|
|
|
|
# +WARN+, +ERROR+, +FATAL+, or +UNKNOWN+.
|
|
|
|
# +message+::
|
|
|
|
# The log message. A String or Exception.
|
|
|
|
# +progname+::
|
2011-05-13 08:54:57 -04:00
|
|
|
# Program name string. Can be omitted. Treated as a message if no
|
|
|
|
# +message+ and +block+ are given.
|
2004-01-05 08:33:48 -05:00
|
|
|
# +block+::
|
|
|
|
# Can be omitted. Called to get a message string if +message+ is nil.
|
|
|
|
#
|
|
|
|
# === Return
|
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# When the given severity is not high enough (for this particular logger),
|
|
|
|
# log no message, and return +true+.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# === Description
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# Log a message if the given severity is high enough. This is the generic
|
|
|
|
# logging method. Users will be more inclined to use #debug, #info, #warn,
|
|
|
|
# #error, and #fatal.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# <b>Message format</b>: +message+ can be any object, but it has to be
|
2004-01-06 06:55:08 -05:00
|
|
|
# converted to a String in order to log it. Generally, +inspect+ is used
|
|
|
|
# if the given object is not a String.
|
2004-01-05 08:33:48 -05:00
|
|
|
# A special case is an +Exception+ object, which will be printed in detail,
|
|
|
|
# including message, class, and backtrace. See #msg2str for the
|
|
|
|
# implementation if required.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# === Bugs
|
|
|
|
#
|
|
|
|
# * Logfile is not locked.
|
|
|
|
# * Append open does not need to lock file.
|
2012-07-17 20:27:04 -04:00
|
|
|
# * If the OS supports multi I/O, records possibly may be mixed.
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
def add(severity, message = nil, progname = nil, &block)
|
2003-09-18 02:31:25 -04:00
|
|
|
severity ||= UNKNOWN
|
|
|
|
if @logdev.nil? or severity < @level
|
|
|
|
return true
|
|
|
|
end
|
|
|
|
progname ||= @progname
|
2004-01-05 08:33:48 -05:00
|
|
|
if message.nil?
|
2003-09-18 02:31:25 -04:00
|
|
|
if block_given?
|
2009-10-20 11:08:38 -04:00
|
|
|
message = yield
|
2003-09-18 02:31:25 -04:00
|
|
|
else
|
2009-10-20 11:08:38 -04:00
|
|
|
message = progname
|
|
|
|
progname = @progname
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
end
|
|
|
|
@logdev.write(
|
2005-09-13 09:13:41 -04:00
|
|
|
format_message(format_severity(severity), Time.now, progname, message))
|
2011-05-18 20:07:25 -04:00
|
|
|
true
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
alias log add
|
|
|
|
|
2003-09-23 10:12:42 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# Dump given message to the log device without any formatting. If no log
|
|
|
|
# device exists, return +nil+.
|
2003-09-23 10:12:42 -04:00
|
|
|
#
|
|
|
|
def <<(msg)
|
|
|
|
unless @logdev.nil?
|
|
|
|
@logdev.write(msg)
|
|
|
|
end
|
|
|
|
end
|
|
|
|
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# Log a +DEBUG+ message.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# See #info for more information.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
|
|
|
def debug(progname = nil, &block)
|
|
|
|
add(DEBUG, nil, progname, &block)
|
|
|
|
end
|
|
|
|
|
2011-05-16 17:43:20 -04:00
|
|
|
#
|
|
|
|
# :call-seq:
|
|
|
|
# info(message)
|
2012-07-17 20:27:04 -04:00
|
|
|
# info(progname, &block)
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# Log an +INFO+ message.
|
|
|
|
#
|
2012-07-17 20:27:04 -04:00
|
|
|
# +message+:: The message to log; does not need to be a String.
|
|
|
|
# +progname+:: In the block form, this is the #progname to use in the
|
|
|
|
# log message. The default can be set with #progname=.
|
|
|
|
# +block+:: Evaluates to the message to log. This is not evaluated unless
|
|
|
|
# the logger's level is sufficient to log the message. This
|
|
|
|
# allows you to create potentially expensive logging messages that
|
|
|
|
# are only called when the logger is configured to show them.
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# === Examples
|
|
|
|
#
|
2004-03-26 11:47:16 -05:00
|
|
|
# logger.info("MainApp") { "Received connection from #{ip}" }
|
2004-01-05 08:33:48 -05:00
|
|
|
# # ...
|
|
|
|
# logger.info "Waiting for input from user"
|
|
|
|
# # ...
|
|
|
|
# logger.info { "User typed #{input}" }
|
|
|
|
#
|
|
|
|
# You'll probably stick to the second form above, unless you want to provide a
|
2011-05-16 17:43:20 -04:00
|
|
|
# program name (which you can do with #progname= as well).
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# === Return
|
|
|
|
#
|
2004-03-26 11:47:16 -05:00
|
|
|
# See #add.
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
2003-09-18 02:31:25 -04:00
|
|
|
def info(progname = nil, &block)
|
|
|
|
add(INFO, nil, progname, &block)
|
|
|
|
end
|
|
|
|
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# Log a +WARN+ message.
|
|
|
|
#
|
|
|
|
# See #info for more information.
|
|
|
|
#
|
2003-09-18 02:31:25 -04:00
|
|
|
def warn(progname = nil, &block)
|
|
|
|
add(WARN, nil, progname, &block)
|
|
|
|
end
|
|
|
|
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# Log an +ERROR+ message.
|
|
|
|
#
|
|
|
|
# See #info for more information.
|
|
|
|
#
|
2003-09-18 02:31:25 -04:00
|
|
|
def error(progname = nil, &block)
|
|
|
|
add(ERROR, nil, progname, &block)
|
|
|
|
end
|
|
|
|
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# Log a +FATAL+ message.
|
|
|
|
#
|
|
|
|
# See #info for more information.
|
|
|
|
#
|
2003-09-18 02:31:25 -04:00
|
|
|
def fatal(progname = nil, &block)
|
|
|
|
add(FATAL, nil, progname, &block)
|
|
|
|
end
|
|
|
|
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
2011-05-16 17:43:20 -04:00
|
|
|
# Log an +UNKNOWN+ message. This will be printed no matter what the logger's
|
2012-07-17 20:27:04 -04:00
|
|
|
# level is.
|
2004-01-05 08:33:48 -05:00
|
|
|
#
|
|
|
|
# See #info for more information.
|
|
|
|
#
|
2003-09-18 02:31:25 -04:00
|
|
|
def unknown(progname = nil, &block)
|
|
|
|
add(UNKNOWN, nil, progname, &block)
|
|
|
|
end
|
|
|
|
|
|
|
|
#
|
2004-01-05 08:33:48 -05:00
|
|
|
# Close the logging device.
|
2003-09-18 02:31:25 -04:00
|
|
|
#
|
|
|
|
def close
|
|
|
|
@logdev.close if @logdev
|
|
|
|
end
|
|
|
|
|
2011-05-18 20:07:25 -04:00
|
|
|
private
|
2003-09-18 02:31:25 -04:00
|
|
|
|
2012-07-17 20:27:04 -04:00
|
|
|
# Severity label for logging (max 5 chars).
|
2015-10-26 10:51:04 -04:00
|
|
|
SEV_LABEL = %w(DEBUG INFO WARN ERROR FATAL ANY).each(&:freeze).freeze
|
2003-09-18 02:31:25 -04:00
|
|
|
|
|
|
|
def format_severity(severity)
|
2003-09-19 22:51:06 -04:00
|
|
|
SEV_LABEL[severity] || 'ANY'
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
|
2005-09-13 09:13:41 -04:00
|
|
|
def format_message(severity, datetime, progname, msg)
|
|
|
|
(@formatter || @default_formatter).call(severity, datetime, progname, msg)
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
|
|
|
|
|
2012-07-17 20:27:04 -04:00
|
|
|
# Default formatter for log messages.
|
2005-09-13 09:13:41 -04:00
|
|
|
class Formatter
|
2015-10-26 10:51:04 -04:00
|
|
|
Format = "%s, [%s#%d] %5s -- %s: %s\n".freeze
|
2005-09-13 09:13:41 -04:00
|
|
|
|
|
|
|
attr_accessor :datetime_format
|
|
|
|
|
|
|
|
def initialize
|
|
|
|
@datetime_format = nil
|
|
|
|
end
|
|
|
|
|
|
|
|
def call(severity, time, progname, msg)
|
|
|
|
Format % [severity[0..0], format_datetime(time), $$, severity, progname,
|
|
|
|
msg2str(msg)]
|
|
|
|
end
|
|
|
|
|
2011-05-18 20:07:25 -04:00
|
|
|
private
|
2005-09-13 09:13:41 -04:00
|
|
|
|
|
|
|
def format_datetime(time)
|
2014-08-25 00:03:33 -04:00
|
|
|
time.strftime(@datetime_format || "%Y-%m-%dT%H:%M:%S.%6N ".freeze)
|
2005-09-13 09:13:41 -04:00
|
|
|
end
|
|
|
|
|
|
|
|
def msg2str(msg)
|
|
|
|
case msg
|
|
|
|
when ::String
|
|
|
|
msg
|
|
|
|
when ::Exception
|
|
|
|
"#{ msg.message } (#{ msg.class })\n" <<
|
2011-05-18 20:07:25 -04:00
|
|
|
(msg.backtrace || []).join("\n")
|
2005-09-13 09:13:41 -04:00
|
|
|
else
|
|
|
|
msg.inspect
|
|
|
|
end
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
end
|
|
|
|
|
2014-05-24 19:54:17 -04:00
|
|
|
module Period
|
|
|
|
module_function
|
|
|
|
|
|
|
|
SiD = 24 * 60 * 60
|
|
|
|
|
|
|
|
def next_rotate_time(now, shift_age)
|
|
|
|
case shift_age
|
2015-10-26 10:51:39 -04:00
|
|
|
when 'daily'
|
2014-05-24 19:54:17 -04:00
|
|
|
t = Time.mktime(now.year, now.month, now.mday) + SiD
|
2015-10-26 10:51:39 -04:00
|
|
|
when 'weekly'
|
2014-05-24 19:54:17 -04:00
|
|
|
t = Time.mktime(now.year, now.month, now.mday) + SiD * (7 - now.wday)
|
2015-10-26 10:51:39 -04:00
|
|
|
when 'monthly'
|
2014-05-24 19:54:17 -04:00
|
|
|
t = Time.mktime(now.year, now.month, 1) + SiD * 31
|
2015-10-26 23:00:38 -04:00
|
|
|
return Time.mktime(t.year, t.month, 1) if t.mday > 1
|
2014-05-24 19:54:17 -04:00
|
|
|
else
|
|
|
|
return now
|
|
|
|
end
|
2015-10-26 23:00:38 -04:00
|
|
|
if t.hour.nonzero? or t.min.nonzero? or t.sec.nonzero?
|
|
|
|
hour = t.hour
|
|
|
|
t = Time.mktime(t.year, t.month, t.mday)
|
|
|
|
t += SiD if hour > 12
|
2014-05-24 19:54:17 -04:00
|
|
|
end
|
|
|
|
t
|
|
|
|
end
|
|
|
|
|
|
|
|
def previous_period_end(now, shift_age)
|
|
|
|
case shift_age
|
2015-10-26 10:51:39 -04:00
|
|
|
when 'daily'
|
2014-05-24 19:54:17 -04:00
|
|
|
t = Time.mktime(now.year, now.month, now.mday) - SiD / 2
|
2015-10-26 10:51:39 -04:00
|
|
|
when 'weekly'
|
2015-10-27 03:18:14 -04:00
|
|
|
t = Time.mktime(now.year, now.month, now.mday) - (SiD * now.wday + SiD / 2)
|
2015-10-26 10:51:39 -04:00
|
|
|
when 'monthly'
|
2014-05-24 19:54:17 -04:00
|
|
|
t = Time.mktime(now.year, now.month, 1) - SiD / 2
|
|
|
|
else
|
|
|
|
return now
|
|
|
|
end
|
|
|
|
Time.mktime(t.year, t.month, t.mday, 23, 59, 59)
|
|
|
|
end
|
|
|
|
end
|
2003-09-18 02:31:25 -04:00
|
|
|
|
2011-05-16 17:43:20 -04:00
|
|
|
# Device used for logging messages.
|
2003-09-18 02:31:25 -04:00
|
|
|
class LogDevice
|
2014-05-24 19:54:17 -04:00
|
|
|
include Period
|
|
|
|
|
2003-09-18 02:31:25 -04:00
|
|
|
attr_reader :dev
|
|
|
|
attr_reader :filename
|
|
|
|
|
2005-09-13 09:13:41 -04:00
|
|
|
class LogDeviceMutex
|
|
|
|
include MonitorMixin
|
|
|
|
end
|
|
|
|
|
2003-09-18 02:31:25 -04:00
|
|
|
def initialize(log = nil, opt = {})
|
|
|
|
@dev = @filename = @shift_age = @shift_size = nil
|
2005-09-13 09:13:41 -04:00
|
|
|
@mutex = LogDeviceMutex.new
|
2003-09-29 03:27:57 -04:00
|
|
|
if log.respond_to?(:write) and log.respond_to?(:close)
|
2009-10-20 11:08:38 -04:00
|
|
|
@dev = log
|
2004-01-06 06:55:08 -05:00
|
|
|
else
|
2009-10-20 11:08:38 -04:00
|
|
|
@dev = open_logfile(log)
|
|
|
|
@dev.sync = true
|
|
|
|
@filename = log
|
|
|
|
@shift_age = opt[:shift_age] || 7
|
|
|
|
@shift_size = opt[:shift_size] || 1048576
|
2014-02-21 02:11:03 -05:00
|
|
|
@next_rotate_time = next_rotate_time(Time.now, @shift_age) unless @shift_age.is_a?(Integer)
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
end
|
|
|
|
|
|
|
|
def write(message)
|
2009-10-20 11:08:38 -04:00
|
|
|
begin
|
|
|
|
@mutex.synchronize do
|
|
|
|
if @shift_age and @dev.respond_to?(:stat)
|
|
|
|
begin
|
|
|
|
check_shift_log
|
|
|
|
rescue
|
|
|
|
warn("log shifting failed. #{$!}")
|
|
|
|
end
|
|
|
|
end
|
2005-08-20 09:43:46 -04:00
|
|
|
begin
|
2009-10-20 11:08:38 -04:00
|
|
|
@dev.write(message)
|
2005-08-20 09:43:46 -04:00
|
|
|
rescue
|
2009-10-20 11:08:38 -04:00
|
|
|
warn("log writing failed. #{$!}")
|
2005-08-20 09:43:46 -04:00
|
|
|
end
|
|
|
|
end
|
2009-10-20 11:08:38 -04:00
|
|
|
rescue Exception => ignored
|
|
|
|
warn("log writing failed. #{ignored}")
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
end
|
|
|
|
|
|
|
|
def close
|
2009-10-20 11:08:38 -04:00
|
|
|
begin
|
|
|
|
@mutex.synchronize do
|
|
|
|
@dev.close rescue nil
|
|
|
|
end
|
2010-07-11 12:59:10 -04:00
|
|
|
rescue Exception
|
2009-10-20 11:08:38 -04:00
|
|
|
@dev.close rescue nil
|
2005-08-20 09:43:46 -04:00
|
|
|
end
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
|
2011-05-18 20:07:25 -04:00
|
|
|
private
|
2003-09-18 02:31:25 -04:00
|
|
|
|
|
|
|
def open_logfile(filename)
|
2013-11-01 18:14:42 -04:00
|
|
|
begin
|
2009-10-20 11:08:38 -04:00
|
|
|
open(filename, (File::WRONLY | File::APPEND))
|
2013-11-01 18:14:42 -04:00
|
|
|
rescue Errno::ENOENT
|
2009-10-20 11:08:38 -04:00
|
|
|
create_logfile(filename)
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
end
|
|
|
|
|
|
|
|
def create_logfile(filename)
|
2013-11-01 18:14:42 -04:00
|
|
|
begin
|
|
|
|
logdev = open(filename, (File::WRONLY | File::APPEND | File::CREAT | File::EXCL))
|
|
|
|
logdev.flock(File::LOCK_EX)
|
|
|
|
logdev.sync = true
|
|
|
|
add_log_header(logdev)
|
|
|
|
logdev.flock(File::LOCK_UN)
|
|
|
|
rescue Errno::EEXIST
|
|
|
|
# file is created by another process
|
|
|
|
logdev = open_logfile(filename)
|
|
|
|
logdev.sync = true
|
|
|
|
end
|
2003-09-18 02:31:25 -04:00
|
|
|
logdev
|
|
|
|
end
|
|
|
|
|
|
|
|
def add_log_header(file)
|
|
|
|
file.write(
|
2009-10-20 11:08:38 -04:00
|
|
|
"# Logfile created on %s by %s\n" % [Time.now.to_s, Logger::ProgName]
|
2013-11-01 18:14:42 -04:00
|
|
|
) if file.size == 0
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
|
2005-08-20 09:43:46 -04:00
|
|
|
def check_shift_log
|
|
|
|
if @shift_age.is_a?(Integer)
|
|
|
|
# Note: always returns false if '0'.
|
|
|
|
if @filename && (@shift_age > 0) && (@dev.stat.size > @shift_size)
|
2013-11-01 18:14:42 -04:00
|
|
|
lock_shift_log { shift_log_age }
|
2005-08-20 09:43:46 -04:00
|
|
|
end
|
2003-09-18 02:31:25 -04:00
|
|
|
else
|
2005-08-20 09:43:46 -04:00
|
|
|
now = Time.now
|
2014-02-21 02:11:03 -05:00
|
|
|
if now >= @next_rotate_time
|
|
|
|
@next_rotate_time = next_rotate_time(now, @shift_age)
|
|
|
|
lock_shift_log { shift_log_period(previous_period_end(now, @shift_age)) }
|
2013-11-01 18:14:42 -04:00
|
|
|
end
|
|
|
|
end
|
|
|
|
end
|
|
|
|
|
2013-11-02 02:15:02 -04:00
|
|
|
if /mswin|mingw/ =~ RUBY_PLATFORM
|
|
|
|
def lock_shift_log
|
|
|
|
yield
|
|
|
|
end
|
|
|
|
else
|
|
|
|
def lock_shift_log
|
2013-11-01 18:14:42 -04:00
|
|
|
retry_limit = 8
|
|
|
|
retry_sleep = 0.1
|
|
|
|
begin
|
|
|
|
File.open(@filename, File::WRONLY | File::APPEND) do |lock|
|
|
|
|
lock.flock(File::LOCK_EX) # inter-process locking. will be unlocked at closing file
|
2013-12-14 00:43:01 -05:00
|
|
|
if File.identical?(@filename, lock) and File.identical?(lock, @dev)
|
2013-11-01 18:14:42 -04:00
|
|
|
yield # log shifting
|
|
|
|
else
|
|
|
|
# log shifted by another process (i-node before locking and i-node after locking are different)
|
|
|
|
@dev.close rescue nil
|
|
|
|
@dev = open_logfile(@filename)
|
|
|
|
@dev.sync = true
|
|
|
|
end
|
|
|
|
end
|
|
|
|
rescue Errno::ENOENT
|
|
|
|
# @filename file would not exist right after #rename and before #create_logfile
|
|
|
|
if retry_limit <= 0
|
|
|
|
warn("log rotation inter-process lock failed. #{$!}")
|
|
|
|
else
|
|
|
|
sleep retry_sleep
|
|
|
|
retry_limit -= 1
|
|
|
|
retry_sleep *= 2
|
|
|
|
retry
|
|
|
|
end
|
2005-08-20 09:43:46 -04:00
|
|
|
end
|
2013-11-01 18:14:42 -04:00
|
|
|
rescue
|
|
|
|
warn("log rotation inter-process lock failed. #{$!}")
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
|
|
|
end
|
|
|
|
|
2005-08-20 09:43:46 -04:00
|
|
|
def shift_log_age
|
|
|
|
(@shift_age-3).downto(0) do |i|
|
|
|
|
if FileTest.exist?("#{@filename}.#{i}")
|
|
|
|
File.rename("#{@filename}.#{i}", "#{@filename}.#{i+1}")
|
|
|
|
end
|
2003-09-18 02:31:25 -04:00
|
|
|
end
|
2009-10-20 11:08:38 -04:00
|
|
|
@dev.close rescue nil
|
2005-08-20 09:43:46 -04:00
|
|
|
File.rename("#{@filename}", "#{@filename}.0")
|
|
|
|
@dev = create_logfile(@filename)
|
|
|
|
return true
|
|
|
|
end
|
2003-09-18 02:31:25 -04:00
|
|
|
|
2009-10-20 11:08:38 -04:00
|
|
|
def shift_log_period(period_end)
|
|
|
|
postfix = period_end.strftime("%Y%m%d") # YYYYMMDD
|
2005-08-20 09:43:46 -04:00
|
|
|
age_file = "#{@filename}.#{postfix}"
|
|
|
|
if FileTest.exist?(age_file)
|
2009-10-20 11:08:38 -04:00
|
|
|
# try to avoid filename crash caused by Timestamp change.
|
|
|
|
idx = 0
|
2011-05-11 06:22:16 -04:00
|
|
|
# .99 can be overridden; avoid too much file search with 'loop do'
|
2009-10-20 11:08:38 -04:00
|
|
|
while idx < 100
|
|
|
|
idx += 1
|
|
|
|
age_file = "#{@filename}.#{postfix}.#{idx}"
|
|
|
|
break unless FileTest.exist?(age_file)
|
|
|
|
end
|
2005-08-20 09:43:46 -04:00
|
|
|
end
|
2009-10-20 11:08:38 -04:00
|
|
|
@dev.close rescue nil
|
2005-08-20 09:43:46 -04:00
|
|
|
File.rename("#{@filename}", age_file)
|
2003-09-18 02:31:25 -04:00
|
|
|
@dev = create_logfile(@filename)
|
|
|
|
return true
|
|
|
|
end
|
2014-02-21 02:11:03 -05:00
|
|
|
end
|
2004-01-06 06:55:08 -05:00
|
|
|
end
|