PoC for logging - see Readme for explanation

README.markdown

Problems

• We have a lot of logging-gems. log4r, logging, lograge, log4r-gelf, graylog2_exceptions. I thought that I'd moved things from logging -> log4r, but it turns out that some of the logging was still going through the logging gem, meaning my configuration was imperfect.
• Additionally, virtually every gem requires some compatible configuration
• The mechanism we were using to inject tracing data was forcing all logging traffic to be sent at the same 'level' (INFO)
• Passing loggers in was a haphazard business of basically passing Procs around, if we wanted to get tracing added. It wasn't very flexible.

Solution

Gems

use Logging, remove log4r, and log4r-gelf

I'd like to roll back to the logging gem, which I now realize has the same configuration options as log4r under the hood. I'd prefer it over log4r because:

1. It already comes w/ rails, so it's one less thing to try and unwire
2. It's achieved feature parity w/ log4r
3. I read 1 message that seemed to indicate that it was under more active development, though the git commit logs on the 2 gems don't seem to indicate much one way or the other.

Remove lograge entirely

No one seemed to like the lograge model, and it was its more poorly specified mechanisms for output formatting that forced us into the 'configure and trace via proc' concept in the first place. I think it should be possible to achieve the same goals w/ custom layout classes, but even if we can't, I'd still vote to remove it simply because of the monkey wrench it's thrown into the mix.

Wrap the logger in AoP style

Wrap the logger class to add tracing details to the log messages, instead of overriding a formatter. In addition to being a cleaner implementation (adding data in a method that was designed to just format data was always distasteful, and meant that it was harder to get the extra data in non-gelf end-points. Wrapping the logger, and overriding the logging methods themselves provides the appropriate point at which to add the additional logging information orthogonally.

Easier to configure and distribute logging configuration

Additionally, wrapping the logger class that remains otherwise faithful to the signature of the rails standard logger makes it easier to configure other gems (graylog_exceptions, or configuring loggers in busibee, cloudstack, etc), because you just create a logger, and hand it off.

log_test.rb

require 'rubygems'
require 'bundler/setup'
require 'json'
require 'logging'

Logging.init :info, :debug, :warn, :error, :fatal
class TracingLogger
  extend Forwardable
  def_delegators :@logger, :<<, :<=>, :_dump_configuration, :_meta_eval, :_setup, :add, :add_appenders, :additive, :additive=, :appenders, :appenders=, :clear_appenders, :inspect, :level, :level=, :name, :parent, :remove_appenders, :trace, :trace=, :write
  def_delegators :@logger, *Logging::LEVELS.map{|name, _| "#{name}?".to_sym }

  Logging::LEVELS.each do |name, _|
    define_method name.to_sym do |data|
      data = @append_trace.call(data)
      @logger.info data
    end
  end

  def initialize(logger, append_trace=nil)
    @logger = logger
    @append_trace = append_trace || -> (data) { sample_append_trace(data) }
  end

  private

  def sample_append_trace(data)
    case data
    when Hash
      data.merge(more_datas: "woo hoo")
    when String
      {message: data, more_data: "woo hoo"}
    end
  end
end

module LoggingWrappers
  module ClassMethods
    def logger(*args)
      logger = super
      TracingLogger.new(logger)
    end
  end
  def self.prepended(base)
    class << base
      prepend ClassMethods
    end
  end
end

module Logging::Layouts
  def self.trace_gelf(*args)
    return ::Logging::Layouts::TraceLayout.json if args.empty?
    ::Logging::Layouts::TraceLayout.json(*args)
  end

  class TraceLayout < ::Logging::Layout
    def initialize( opts = {} )
      @style = opts[:style]
    end

    def format(event)
      event_info = ({}).tap do |event_info|
        event_info[:_level] = event.level
        if event.data.is_a? String
          event.data = { message: event.data }
        end
        event.data.each do |key, value|
          event_info["_#{key}"] = value
        end
      end
      event_info.to_json
    end

    def self.json(opts = {})
      opts[:style] = 'json'
      new(opts)
    end
  end
end

module Logging::Appenders
  def self.gelf(*args)
    return ::Logging::Appenders::Gelf if args.empty?
    ::Logging::Appenders::Gelf.new(*args)
  end

  class Gelf < ::Logging::Appender
    def initialize(opts = {})
      super "gelf", opts
    end

    def write(event)
      message = if event.instance_of?(::Logging::LogEvent)
        @layout.format(event)
      else
        event.to_s
      end
      puts message
    end
  end

end

Logging.send(:prepend, LoggingWrappers)
l = Logging.logger("jeff")
l.add_appenders(
  Logging.appenders.gelf(layout: Logging.layouts.trace_gelf),
  Logging.appenders.stdout
)
l.info(one: 1, two: 2)
l.info "strin log"

I know it's PoC, but what's the motivation for prepending over inheritance?