Problem with Ruby scoping rules?


#1

I’ve been using Log4r with a Rails app for some time, and it was working
fine under Webrick. Adding Log4r was easy - simply add in the following
code to environment.rb:

See Rails::Configuration for more options

begin
cfg = Log4r::Configurator
cfg[‘RAILS_ROOT’] = RAILS_ROOT
cfg[‘RAILS_ENV’] = RAILS_ENV
cfg.load_xml_file(File.dirname(FILE) +
“/…/public/config/BlackTestLog.xml”)
RAILS_DEFAULT_LOGGER = Log4r::Logger[‘default’]
RAILS_DEFAULT_LOGGER.info(“Initialised Log4r default logger”)
rescue => err
RAILS_DEFAULT_LOGGER = Logger.new(File.dirname(FILE) +
“/…/log/configuration_error.log”)
RAILS_DEFAULT_LOGGER.level = Logger::WARN
RAILS_DEFAULT_LOGGER.warn(“Error occurred whilst initialising
Log4r:”)
RAILS_DEFAULT_LOGGER.warn(err.to_s)
RAILS_DEFAULT_LOGGER.warn(err.backtrace)
end

However, I started running the Rails app under Apache. Everything
worked fine except that load_xml_file always failed and I ended up using
the default Rails logger.

To understand where I went next, you have to have a look at
configurator.rb in Log4r. In there is the following method:

def self.decode_logger_common(l, e)

  ...stuff...

  # and now for outputters
  outs = e.value_of 'outputters'

  ## The add method........................v
  Log4rTools.comma_split(outs).each {|n| l.add n.strip} unless 

outs.nil?

  e.elements.each('outputter') {|e|
    name = (e.value_of 'name' or e.text)
    l.add Outputter[name]
  }
end

What I observed happening got me very worried. The l parameter is
supposed to be an object of class Log4r::Logger, yet the call to add
(marked above) ended up running the add method on the Rails default
logger.

I made a change in decode_logger to make sure that the object created
was definitely a Log4r::Logger.

def self.decode_logger(e)
  l = Log4r::Logger.new e.value_of('name')
  decode_logger_common(l, e)
end

I then dumped l.inspect and here’s what it showed:

#<Log4r::Logger:0x3618ae8 @progname=nil, @level=0, @formatter=nil,
@logdev=#<Log4r::Logger::LogDevice:0x3618620 @shift_size=1048576,
@shift_age=0, @dev=#<File:default>, @filename=“default”,
@mutex=#<Log4r::Logger::LogDevice::LogDeviceMutex:0x36185f0
@mon_waiting_queue=[], @mon_entering_queue=[], @mon_count=0,
@mon_owner=nil>>,
@default_formatter=#<Log4r::Logger::Formatter:0x36188d8
@datetime_format=nil>>

Now this is very worrying. Firstly the created object purports to be a
Log4r::Logger, but unfortunately it has the attributes of the default
Rails Logger. For example, Log4r::Logger doesn’t have @logdev.

From any perspective, this behaviour is plain wrong. I have asked Ruby
to create a Logger object and scoped it within the Log4r namespace.
However, it has created some other Logger object and pretended that it
is the Log4r implementation. If Ruby cannot find the Log4r::Logger
object for any reason, it should throw an error, not go and create the
next best thing behind the scenes.

I’m therefore of the opinion that there is a problem with the Ruby
interpreter in the way it handles scoping. Just the results of
l.inspect above indicate there is a problem as the object has the name
of the Log4r::Logger, but has been initialised as the Rails default
Logger.

Any help with understanding what’s going on here would be welcome.

BTW I’ve now got a workaround for this problem but I don’t yet know why
it works.