logging.rb

require 'logger'
require 'fileutils'
require 'time'
require 'fiber'

module Logging



  class Logger

    attr_accessor :scope


    def initialize(scope)
      self.scope = scope
    end

    def log(level, message, tags=[], data={})
      raise NotImplementedError, 'Implement me in subclass'
    end

    def info(*a, &b)
      log('info', *a, &b)
    end

    def error(*a, &b)
      log('error', *a, &b)
    end

    def debug(*a, &b)
      log('debug', *a, &b)
    end

    def exception(e, message="#{e.class}: #{e.message}\n#{e.backtrace.map{|l| "  #{l}" }.join("\n")}", tags=['EXCEPTION'], *a, &b)
      error(message, tags, *a, &b)
    end


    def self.create(*a, &b)
      FileLogger.new(*a, &b)
    end


  end#class Logger




  class FileLogger < Logger


    def root
      File.join(File.dirname(__FILE__), '..', '..', 'log')
    end

    def dir
      File.join(root, *scope[0..-2])
    end

    def file
      scope[-1] + '.log'
    end

    def path
      File.join(dir, file)
    end


    def logger
      @logger ||= begin
        FileUtils.mkdir_p(dir)
        l = ::Logger.new(path)
        l.formatter = lambda{|s,t,p,m| "\n#{m}" }
        l
      end
    end


    def log(level, msg, tags=[], data={})
      parts = ['<<<', "#{Time.now.xmlschema}", ($$+Fiber.current.__id__).to_s(36), "#{level}".upcase]
      parts << (tags.map{|t| "#{escape_tag t}" } +  data.map{|k,v| "#{escape_tag k}=#{escape_tag v}" }).join(' ')
      parts << '>>>'
      logger.add(::Logger.const_get(level.upcase), "#{parts.map{|p| "[#{p}]" }.join('')} #{msg}")
    end


  private

    def escape_tag(str)
      "#{str}".gsub(/([\\ \[\]=])/, '\\\\\\1')
    end


  end#class FileLogger






  def self.included(mod)
    mod.extend ClassMethods
  end




  module ClassMethods

    attr_writer :logging_scope, :logger

    def logging_scope
      return @logging_scope if @logging_scope
      parts = name.split('::')
      #ExternalServices::FooService => ['external_services', 'foo_service']
      parts.map{|p| p.gsub(/^[A-Z]/){|s| s.downcase }.gsub(/[A-Z]/){|s| '_'+s.downcase } }
    end


    def logger
      @logger ||= Logger.create(logging_scope)
    end

    [:log, :info, :error, :exception].each do |level|
      define_method level do |*a, &b|
        logger.send(level, *a, &b)
      end
    end

    def log_time(label, tags=[], data={})
      t, v = measure_time do
        yield
      end
      info("#{label}: #{t}s", (tags+['time']).uniq, {:time => t}.merge(data))
      v
    end

    def measure_time
      t = Time.now
      v = yield
      [Time.now-t, v]
    end


  end#module ClassMethods



  [:log, :info, :error, :exception, :log_time, :measure_time].each do |level|
    define_method level do |*a, &b|
      self.class.send(level, *a, &b)
    end
  end



end#module Logging