emlogger.rb

require 'eventmachine'
require 'digest/md5'
require 'fiber'
require 'thread'


unless defined?(ActiveSupport)
  class String;   def blank?; self !~ /[^[:space:]]/; end; end
  class NilClass; def blank?; true;                   end; end
  class Object;   def blank?; false;                  end; end
end


class EMLogger
  ProgName = $0


  attr_accessor :progname
  attr_accessor :level
  alias sev_threshold level
  alias sev_threshold= level=


  module Severity   # Logging severity.
    TRACE   = -1    # truly ludicrous and unnecessary verbosity
    DEBUG   = 0     # low-level information, mostly for developers
    INFO    = 1     # generic, useful information about system operation
    WARN    = 2     # a warning
    ERROR   = 3     # a handleable error condition
    FATAL   = 4     # an unhandleable error that results in a program crash
    UNKNOWN = 5     # an unknown message that should always be logged
  end
  include Severity

  SeverityMap = Severity.constants.inject({}) do |memo, name|
    number = Severity.const_get(name)
    memo[number] = name.to_s
    memo
  end

  for severity in Severity.constants
    class_eval <<-EOT, __FILE__, __LINE__ + 1
      def #{severity.downcase}?
        @level <= #{severity}
      end

      def #{severity.downcase}(message=nil, progname=nil, &block)
        add(#{severity}, message, progname, &block)
      end
    EOT
  end


  class Formatter
    attr_accessor :datetime_format

    def initialize
      @datetime_format = '[%F %T.%6N]'
    end

    def call(severity, time, progname, msg)
      prefix = "#{format_time(time)} [#{severity}]#{tags_text} |"
      msga = msg.respond_to?(:each) ?
        msg.join("\n").split("\n") :
        msg.split("\n")
      msga.map! {|line| "#{prefix} #{line}"}
      msga.join("\n") + "\n"
    end

    def tagged(*tags)
      new_tags = push_tags(*tags)
      yield self
    ensure
      pop_tags(new_tags.size)
    end

    def push_tags(*tags)
      new_tags = tags.flatten.reject(&:blank?)
      current_tags.concat new_tags
      new_tags
    end

    def pop_tags(size=1)
      current_tags.pop size
    end

    def clear_tags!
      current_tags.clear
    end

    def current_tags
      Thread.current[:emlogger_formatter_tags] ||= []
    end

    private

    def tags_text
      tags = current_tags
      if tags.any?
        ' ' + tags.collect do |tag|
          case tag
          when ::String
            tag
          when :fiber_id
            "fid=#{shortid(Fiber.current.object_id) rescue -1}"
          when :thread_id
            "tid=#{shortid(Thread.current.object_id) rescue -1}"
          when :process_id
            "pid=#{Process.pid rescue -1}"
          else
            tag.inspect
          end
        end.join(' ')
      end
    end

    def shortid(data, len=4)
      digest = Digest::MD5.hexdigest(data.to_s)
      len = len > digest.length ? digest.length : len
      digest[0, len]
    end

    def format_time(time)
      time.strftime(@datetime_format)
    end
  end

  attr_writer :formatter

  def formatter
    @formatter || @default_formatter
  end

  def format_message(severity, datetime, progname, msg)
    formatter.call(severity, datetime, progname, msg)
  end

  def format_severity(severity)
    SeverityMap[severity] || 'ANY'
  end

  def datetime_format=(datetime_format)
    if formatter.respond_to?(:datetime_format=)
      formatter.datetime_format = datetime_format
    end
  end

  def datetime_format
    formatter.datetime_format if formatter.respond_to?(:datetime_format)
  end

  def tagged(*tags)
    if formatter.respond_to?(:tagged)
      formatter.tagged(*tags) { yield self }
    else
      yield self
    end
  end


  # set to false to disable the silencer defined below
  def self.silencer;        @@silencer;       end
  def silencer;             @@silencer;       end
  def self.silencer=(obj);  @@silencer = obj; end
  def silencer=(obj);       @@silencer = obj; end
  @@silencer = true

  # "silences" the logger by increasing its threshold for the duration of the
  # block passed in to it. note that by default, only debug/info/warn level
  # messages are silenced. this method may also be used to /increase/ logger
  # sensitivity, and has been aliased as :with_level so that code using it for
  # this purpose will make sense.
  def silence(silence_level = ERROR)
    if silencer
      begin
        natural_level, self.level = self.level, silence_level
        yield self
      ensure
        self.level = natural_level
      end
    else
      # silencer is disabled, act as normal
      yield self
    end
  end
  alias :with_level :silence

  def silent?
    @level >= ERROR
  end

  def silent=(bool)
    if silencer and bool
      @level = ERROR
    elsif silencer and not bool
      @level = INFO
    end
  end


  class LogDevice
    def initialize(log=nil, options={}, args=[])
      @buffer = []
      if log.respond_to?(:write) and log.respond_to?(:close)
        @dev = log
      else
        @dev = open_logfile(log)
      end
      flush_interval = options[:flush_interval] || 0.5
      timer = EventMachine::PeriodicTimer.new(flush_interval) do
        begin
          flush
        rescue => e
          STDERR.puts("Error while flushing log")
          STDERR.puts(e)
          timer.cancel
        end
      end
    end

    def write(message)
      EM.schedule do
        @buffer.push(message)
      end
    end

    def close
      flush do
        @dev.flush
        @dev.close
      end
    end

    def flush(&blk)
      return if @buffer.empty?
      current, @buffer = @buffer, []
      after_flush = block_given? ? blk : proc { @dev.flush }
      EM.schedule do
        EM::Iterator.new(current, 1).each(
          proc {|message, iterator| @dev.write(message); iterator.next },
          proc { @dev.flush }
        )
      end
    end

    private

    def open_logfile(filename)
      logdev = open(filename, (File::WRONLY | File::APPEND | File::CREAT))
      logdev.sync = false
      logdev
    end
  end


  def initialize(logdev=nil, *args)
    @default_formatter = ::EMLogger::Formatter.new
    @progname = ProgName.dup
    @level = DEBUG
    options = args.last.is_a?(Hash) ? args.pop : {}
    logdev ||= $stdout
    @logdev = LogDevice.new(logdev, options, args)
  end


  def add(severity=UNKNOWN, message = nil, progname = nil, &block)
    return true if @logdev.nil? or @level > severity
    progname ||= @progname
    message = (message || (block && block.call) || progname).to_s
    @logdev.write(
      format_message(format_severity(severity), Time.now, progname, message))
  end

  def <<(message)
    @logdev.write(message + "\n")
  end

  def log(message=nil, progname=nil, &block)
    add(INFO, message, progname, &block)
  end

  def log_error(e=$!)
    add(ERROR, "#{e}\n\t" + e.backtrace.join("\n\t") + "\n")
  end

  def close
    @logdev.close
  end

end


if __FILE__ == $0

  EM.run {
    logger = EMLogger.new(STDOUT)

    logger.log("moo")

    begin
      raise StandardError, "cows"
    rescue => e
      logger.log_error
    end

    logger.tagged :fiber_id, :thread_id do
      logger.log "this should be tagged"
      logger.log "so should this"
      logger.tagged "wee" do
        logger.log "this should have all previous tags plus 'wee'"
      end
    end

    Fiber.new do |block|
      block.call
    end.resume(proc {
      logger.tagged :fiber_id, :thread_id do
        logger.log "I can haz Fiber"
      end
    })

    EM.defer {
      logger.tagged :fiber_id, :thread_id do
        logger.log "this should have a new thread_id"
      end
      sleep 3
      logger.log "this should enter the buffer three seconds after start"
    }

    logger.trace("trace")
    logger.debug("debug")
    logger.info("info")
    logger.warn("warn")
    logger.error("error")
    logger.fatal("fatal")
    logger.unknown("unknown")

    EM.defer {
      sleep 5
      logger.close
      EM.stop
    }
  }

end