Ruby - share logger instance among module/classes

Question

Working on a little Ruby script that goes out to the web and crawls various services. I've got a module with several classes inside:

module Crawler
  class Runner
  class Options
  class Engine
end

I want to share one logger among all those of those classes. Normally I'd just put this in a constant in the module and reference it like so:

Crawler::LOGGER.info("Hello, world")

The problem is that I can't create my logger instance until I know where the output is going. You start the crawler via command line and at that point you can tell it you want to run in development (log output goes to STDOUT) or production (log output goes to a file, crawler.log):

crawler --environment=production

I have a class Options that parses the options passed in through the command line. Only at that point do I know how to instantiate the logger with the correct output location.

So, my question is: how/where to I put my logger object so that all my classes have access to it?

I could pass my logger instance to each new() call for every class instance I create, but I know there has to be a better, Rubyish way to do it. I'm imagining some weird class variable on the module that shared with class << self or some other magic. :)

A little more detail: Runner starts everything by passing the command line options to the Options class and gets back an object with a couple of instance variables:

module Crawler
  class Runner
    def initialize(argv)
      @options = Options.new(argv)
      # feels like logger initialization should go here
      # @options.log_output => STDOUT or string (log file name)
      # @options.log_level => Logger::DEBUG or Logger::INFO
      @engine = Engine.new()
    end
    def run
      @engine.go
    end
  end
end

runner = Runner.new(ARGV)
runner.run

I need the code in Engine to be able to access the logger object (along with a couple more classes that are initialized inside Engine). Help!

All of this could be avoided if you could just dynamically change the output location of an already-instantiated Logger (similar to how you change the log level). I'd instantiate it to STDOUT and then change over to a file if I'm in production. I did see a suggestion somewhere about changing Ruby's $stdout global variable, which would redirect output somewhere other than STDOUT, but this seems pretty hacky.

Thanks!

Answer 1

Although an old question, I thought it worthwhile to document a different approach.

Building on Jacob's answer, I would suggest a module that you can add in as and when needed.

My version is this:

# saved into lib/my_log.rb

require 'logger'

module MyLog

  def self.logger
    if @logger.nil?
      @logger = Logger.new( STDERR)
      @logger.datetime_format = "%H:%M:%S "
    end
    @logger
  end

  def self.logger=( logger)
    @logger = logger
  end

  levels = %w(debug info warn error fatal)
  levels.each do |level|
    define_method( "#{level.to_sym}") do |msg|
      self.logger.send( level, msg)
    end
  end
end

include MyLog

I have this saved into a library of handy modules, and I would use it like this:

#! /usr/bin/env ruby
#

require_relative '../lib/my_log.rb'

MyLog.debug "hi"
# => D, [19:19:32 #31112] DEBUG -- : hi

MyLog.warn "ho"
# => W, [19:20:14 #31112]  WARN -- : ho

MyLog.logger.level = Logger::INFO

MyLog.logger = Logger.new( 'logfile.log')

MyLog.debug 'huh'
# => no output, sent to logfile.log instead

I find this a lot easier and more versatile than other options I've looked at so far, so I hope it helps you with yours.

Answer 2

Inspired by this thread I created the easy_logging gem.

It combines all the features discussed such as:

• Adds logging functionality anywhere with one, short, self-descriptive command
• Logger works in both class and instance methods
• Logger is specific to class and contains class name

Installation:

gem install 'easy_logging

Usage:

require 'easy_logging'

class YourClass
  include EasyLogging

  def do_something
    # ...
    logger.info 'something happened'
  end
end

class YourOtherClass
  include EasyLogging

  def self.do_something
    # ...
    logger.info 'something happened'
  end
end

YourClass.new.do_something
YourOtherClass.do_something

Output

I, [2017-06-03T21:59:25.160686 #5900]  INFO -- YourClass: something happened
I, [2017-06-03T21:59:25.160686 #5900]  INFO -- YourOtherClass: something happened

More details on GitHub.

Answer 3

Based on your comment

All of this could be avoided if you could just dynamically change the output location of an already-instantiated Logger (similar to how you change the log level).

If you are not restricted to the default logger you may use another log-gem.

As an example with log4r:

require 'log4r' 

module Crawler
  LOGGER = Log4r::Logger.new('mylog')
  class Runner
    def initialize
        LOGGER.info('Created instance for %s' % self.class)
    end
  end
end

ARGV << 'test'  #testcode

#...
case ARGV.first
  when 'test'
    Crawler::LOGGER.outputters = Log4r::StdoutOutputter.new('stdout')
  when 'prod'
    Crawler::LOGGER.outputters = Log4r::FileOutputter.new('file', :filename => 'test.log') #append to existing log
end
#...
Crawler::Runner.new

In prod mode the logging data are stored in a file (attached to existing file, but there are options to create new log files or implement rolling log files).

The result:

 INFO main: Created instance for Crawler::Runner

If you use the inheritance mechanism of log4r (a), you may define a logger for each class (or in my following example for each instance) and share the outputter.

The example:

require 'log4r' 

module Crawler
  LOGGER = Log4r::Logger.new('mylog')
  class Runner
    def initialize(id)
      @log = Log4r::Logger.new('%s::%s %s' % [LOGGER.fullname,self.class,id])
      @log.info('Created instance for %s with id %s' % [self.class, id])
    end
  end
end

ARGV << 'test'  #testcode

#...
case ARGV.first
  when 'test'
    Crawler::LOGGER.outputters = Log4r::StdoutOutputter.new('stdout')
  when 'prod'
    Crawler::LOGGER.outputters = Log4r::FileOutputter.new('file', :filename => 'test.log') #append to existing log
end
#...
Crawler::Runner.new(1)
Crawler::Runner.new(2)

The result:

 INFO Runner 1: Created instance for Crawler::Runner with id 1
 INFO Runner 2: Created instance for Crawler::Runner with id 2

(a) A logger name like A::B has the name B and is a child of the logger with the name A. As far as I know this is no object inheritance.

One advantage of this approach: If you want to use a single logger for each class, you need only to change the name of the logger.

Answer 4

As Zenagray points out, logging from class methods was left out of Jacob's answer. A small addition solves that:

require 'logger'

module Logging
  class << self
    def logger
      @logger ||= Logger.new($stdout)
    end

    def logger=(logger)
      @logger = logger
    end
  end

  # Addition
  def self.included(base)
    class << base
      def logger
        Logging.logger
      end
    end
  end

  def logger
    Logging.logger
  end
end

The intended use is via "include":

class Dog
  include Logging

  def self.bark
    logger.debug "chirp"
    puts "#{logger.__id__}"
  end

  def bark
    logger.debug "grrr"
    puts "#{logger.__id__}"
  end
end

class Cat
  include Logging

  def self.bark
    logger.debug "chirp"
    puts "#{logger.__id__}"
  end

  def bark
    logger.debug "grrr"
    puts "#{logger.__id__}"
  end
end

Dog.new.bark
Dog.bark
Cat.new.bark
Cat.bark

Produces:

D, [2014-05-06T22:27:33.991454 #2735] DEBUG -- : grrr
70319381806200
D, [2014-05-06T22:27:33.991531 #2735] DEBUG -- : chirp
70319381806200
D, [2014-05-06T22:27:33.991562 #2735] DEBUG -- : grrr
70319381806200
D, [2014-05-06T22:27:33.991588 #2735] DEBUG -- : chirp
70319381806200

Note the id of the logger is the same in all four cases. If you want a different instance for each class, then don't use Logging.logger, rather use self.class.logger:

require 'logger'

module Logging
  def self.included(base)
    class << base
      def logger
        @logger ||= Logger.new($stdout)
      end

      def logger=(logger)
        @logger = logger
      end
    end
  end

  def logger
    self.class.logger
  end
end

The same program now produces:

D, [2014-05-06T22:36:07.709645 #2822] DEBUG -- : grrr
70350390296120
D, [2014-05-06T22:36:07.709723 #2822] DEBUG -- : chirp
70350390296120
D, [2014-05-06T22:36:07.709763 #2822] DEBUG -- : grrr
70350390295100
D, [2014-05-06T22:36:07.709791 #2822] DEBUG -- : chirp
70350390295100

Note that the first two id's are the same but are different from the 2nd two ids showing that we have two instances -- one for each class.

Answer 5

I like to have a logger method available in my classes, but I don't like sprinkling @logger = Logging.logger in all my initializers. Usually, I do this:

module Logging
  # This is the magical bit that gets mixed into your classes
  def logger
    Logging.logger
  end

  # Global, memoized, lazy initialized instance of a logger
  def self.logger
    @logger ||= Logger.new(STDOUT)
  end
end

Then, in your classes:

class Widget
  # Mix in the ability to log stuff ...
  include Logging

  # ... and proceed to log with impunity:
  def discombobulate(whizbang)
    logger.warn "About to combobulate the whizbang"
    # commence discombobulation
  end
end

Because the Logging#logger method can access the instance that the module is mixed into, it is trivial to extend your logging module to record the classname with log messages:

module Logging
  def logger
    @logger ||= Logging.logger_for(self.class.name)
  end

  # Use a hash class-ivar to cache a unique Logger per class:
  @loggers = {}

  class << self
    def logger_for(classname)
      @loggers[classname] ||= configure_logger_for(classname)
    end

    def configure_logger_for(classname)
      logger = Logger.new(STDOUT)
      logger.progname = classname
      logger
    end
  end
end

Your Widget now logs messages with its classname, and didn't need to change one bit :)

Answer 6

How about wrapping the logger in a singleton then you could access it using MyLogger.instance

Answer 7

A little chunk of code to demonstrate how this works. I'm simply creating a new basic Object so that I can observe that the object_id remains the same throughout the calls:

module M

  class << self
    attr_accessor :logger
  end

  @logger = nil

  class C
    def initialize
      puts "C.initialize, before setting M.logger: #{M.logger.object_id}"
      M.logger = Object.new
      puts "C.initialize, after setting M.logger: #{M.logger.object_id}"
      @base = D.new
    end
  end

  class D
    def initialize
      puts "D.initialize M.logger: #{M.logger.object_id}"
    end
  end
end

puts "M.logger (before C.new): #{M.logger.object_id}"
engine = M::C.new
puts "M.logger (after C.new): #{M.logger.object_id}"

The output of this code looks like (an object_id of 4 means nil):

M.logger (before C.new): 4
C.initialize, before setting M.logger: 4
C.initialize, after setting M.logger: 59360
D.initialize M.logger: 59360
M.logger (after C.new): 59360

Thanks for the help guys!

Answer 8

With the design you've laid out, it looks like the easiest solution is to give Crawler a module method that returns a module ivar.

module Crawler
  def self.logger
    @logger
  end
  def self.logger=(logger)
    @logger = logger
  end
end

Or you could use "class <<self magic" if you wanted:

module Crawler
  class <<self
    attr_accessor :logger
  end
end

It does the exact same thing.

Answer 9

The may be some weird Ruby magic that could let you avoid it, but there's a fairly simple solution that doesn't need weird. Just put the logger into the module and access it directly, with a mechanism to set it. If you want to be cool about it, define a "lazy logger" that keeps a flag to say if it has a logger yet, and either silently drops messages until the logger is set, throws an exception of something is logged before the logger is set, or adds the log message to a list so it can be logged once the logger is defined.