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!

Testudinal

Answer 1

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.

Rounding

Thanks Chuck! This is exactly what I ended up doing after a little testing on my end! – Testudinal

Answer 2

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 :)

Melissiamelita

Add this to your Logging module and you can now configure it. @out = STDOUT (as module variable) and this as a class method: def configure(config) logout = config['logout'] if logout != 'STDOUT' then @out = logout # should be a log path, like /tmp/log.txt end end – Transgress

This is wonderful except that it cannot be used in class methods (self.some_method). If you use extend instead it fixes the issue but then to use the logger for instance methods you will need to prepend logger calls with the class name.. i.e. Widget.logger or use self.class.logger. Personally I think extend is more useful in this situation. – Certainty

I tested the last version that changes the progname, but Logger.new(STDOUT) always provides me with the smae instance.. so this doesn't work; did I miss something? – Confess

This seems to be a very common pattern. We use the same for a large app product. – Logician

In Rails, I use an initializer to set the global logger. Create e.g. config/initializers/logging.rb, and write Logging.logger = Rails.logger. To allow that, you'll need to add the following to the Logging module as @Melissiamelita defines: def self.logger=(value) @logger = value end. – Palaeozoic

How do I combine this result above that logs classnames (and method names?) to work for class methods? – Grubby

It fails and crashes in class methods. – Yasminyasmine

@Angela Please see my answer for a solution that combines both features. This part in particular I solved by editing the function creating the class level logger in @pedz's answer to contain: @logger ||= EasyLogging.logger_for(self). – Merriman

How to use this with unit tests? Ideally, I would not want the class under test to log anything when I am unit testing it. – Endo

Answer 3

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.

Anesthesiology

Hi, I thought the addition would output the actual class method name as an amendment to what Jacob does? It doesn't look like from the examples I can tell which method is used. – Grubby

I'm not clear on your question or which version. In the second version with a different logger for each class, logging from a class method goes directly to the logger for the classs while logging from an instance method goes to the logger of the instance which then calls the logger for the class. – Anesthesiology

This seemed like an easy solution, but when I tried it every time logger.info "xxxx" is called, the logger statement it returns a large value that looks like "#<Concurrent::Future:0x0000564baa5da498 @__Lock__=#<Thread::Mutex:0x0000564baa5da3a8>....." – Manslayer

Answer 4

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.

Merriman

the gem looked nice except as far as I could tell, it assumes log_destination is a file, whereas I needed to specify a logging service such as Logdna::Ruby.new(ENV["LOGDNA_KEY"], log_options) – Manslayer

Answer 5

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.

Infantryman

Answer 6

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!

Testudinal

Answer 7

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

Uam

Unless you are going to subclass Logger first, please read The Chainsaw Infanticide Logger Manuever [sic] before making Logger a singleton for everyone that might re-use your code. – Lita

Answer 8

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.

Duffy

Answer 9

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.

Geotaxis

This simple solution has several flaws already pointed by others in this thread referring to Jacob's answer. I've addressed those in the easy_logging gem. As far as this approach go I think this is your safest bet. See my answer for more details. – Merriman

Fair point, as my use case did not take these edge cases (e.g. Class specific loggers) into account. Thank you. – Geotaxis