Logger POC with binding context

logger2.cr

abstract class Logger2
  enum Severity
    DEBUG
    INFO
  end

  abstract def log(severity : Severity, message, context : String)

  macro bind(*, context = nil, forward = nil)
    struct LoggerBinding
      getter logger : Logger2?

      def initialize(@logger : Logger2?)
      end

      protected def log(severity, message)
        @logger.try &.log(severity, message, \{{ {{context}} || @type.name.stringify.gsub(/::LoggerBinding$/, "").gsub(/::/, ".").downcase }})
      end

      {% for name in Logger2::Severity.constants %}
        def {{name.id.downcase}}(message)
          log(Logger2::Severity::{{name.id}}, message)
        end
      {% end %}
    end

    @log : LoggerBinding = LoggerBinding.new(nil)

    def logger=(value : Logger2?)
      @log = LoggerBinding.new(value)
      {% if forward %}
        {% for component in forward %}
          {{component.id}}.try &.logger=(value)
        {% end %}
      {% end %}
    end

    # :nodoc:
    protected def logger : Logger2?
      @log.logger
    end

    # :nodoc:
    protected def log
      @log
    end
  end
end

class BasicLogger < Logger2
  property level = Logger2::Severity::INFO

  def initialize(@io : IO = STDOUT)
  end

  def log(severity, message, context)
    return if severity < level
    label = severity.to_s
    @io << label[0] << ", [" << Time.now << " #" << Process.pid << "] "
    @io << label.rjust(5) << " -- " << context << ": " << message.to_s
    @io.puts
    @io.flush
  end
end

class Foo
  Logger2.bind context: "app.foo", forward: [@bar]

  @bar = Bar.new

  def do
    log.info "doing do"
    @bar.do_to
  end
end

class Bar
  Logger2.bind context: "app.bar"

  def do_to
    log.debug "doing do to"
  end
end

module Lorem::Ipsum
  class Dispatcher
    Logger2.bind

    def repeat(n)
      log.info "ready to launch"
      n.times { Dispatchee.new(logger).do }
    end
  end

  class Dispatchee
    Logger2.bind

    def initialize(logger)
      # should be done after rest of initializers
      self.logger = logger
      log.debug "initializing"
    end

    def do
      log.info "Hi"
    end
  end
end

foo = Foo.new

# loggers are optional
puts "** A"
foo.do

# loggers are forwarded to components already initialized
puts "** B"
logger = BasicLogger.new
foo.logger = logger
foo.do

# since loggers reference are shared
puts "** C"
logger.level = Logger2::Severity::DEBUG
foo.do

puts "** D"
d = Lorem::Ipsum::Dispatcher.new
d.logger = logger
d.repeat 3

output.txt

** A
** B
I, [2018-04-11 20:06:58 -03:00 #9600]  INFO -- app.foo: doing do
** C
I, [2018-04-11 20:06:58 -03:00 #9600]  INFO -- app.foo: doing do
D, [2018-04-11 20:06:58 -03:00 #9600] DEBUG -- app.bar: doing do to
** D
I, [2018-04-11 20:06:58 -03:00 #9600]  INFO -- lorem.ipsum.dispatcher: ready to launch
D, [2018-04-11 20:06:58 -03:00 #9600] DEBUG -- lorem.ipsum.dispatchee: initializing
I, [2018-04-11 20:06:58 -03:00 #9600]  INFO -- lorem.ipsum.dispatchee: Hi
D, [2018-04-11 20:06:58 -03:00 #9600] DEBUG -- lorem.ipsum.dispatchee: initializing
I, [2018-04-11 20:06:58 -03:00 #9600]  INFO -- lorem.ipsum.dispatchee: Hi
D, [2018-04-11 20:06:58 -03:00 #9600] DEBUG -- lorem.ipsum.dispatchee: initializing
I, [2018-04-11 20:06:58 -03:00 #9600]  INFO -- lorem.ipsum.dispatchee: Hi