Getting error using log4r with delayed job

Question

I have a working Rails 3.2 app (Ruby 1.9.2p290 on Windows Server 2008 R2) which uses delayed job for several background jobs. I recently replaced Rails default logging with log4r and it's working fine for the Rails app. However, when I start up the rake jobs:work task I get an error complaining about a nil outputter:

Starting job worker
rake aborted!
TypeError: Expected kind of Outputter, got NilClass
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/log4r-1.1.10/lib/log4r/logger.rb:120:in `each'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/log4r-1.1.10/lib/log4r/logger.rb:120:in `add'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/delayed_job-4.0.0/lib/delayed/worker.rb:248:in `say'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/delayed_job-4.0.0/lib/delayed/worker.rb:147:in `start'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/delayed_job-4.0.0/lib/delayed/tasks.rb:9:in `block (2 levels) in '
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/task.rb:240:in `call'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/task.rb:240:in `block in execute'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/task.rb:235:in `each'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/task.rb:235:in `execute'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/task.rb:179:in `block in invoke_with_call_chain'
F:/web-shared/Ruby192/lib/ruby/1.9.1/monitor.rb:201:in `mon_synchronize'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/task.rb:172:in `invoke_with_call_chain'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/task.rb:165:in `invoke'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/application.rb:150:in `invoke_task'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/application.rb:106:in `block (2 levels) in top_level
'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/application.rb:106:in `each'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/application.rb:106:in `block in top_level'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/application.rb:115:in `run_with_threads'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/application.rb:100:in `top_level'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/application.rb:78:in `block in run'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/application.rb:176:in `standard_exception_handling'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/lib/rake/application.rb:75:in `run'
F:/web-shared/Ruby192/lib/ruby/gems/1.9.1/gems/rake-10.2.2/bin/rake:33:in `'
F:/web-shared/Ruby192/bin/rake:19:in `load'
F:/web-shared/Ruby192/bin/rake:19:in `'
Tasks: TOP => jobs:work

Anyone else successfully using log4r with delayed job? I could use some pointers; couldn't find anything via Google or DuckDuckGo searches.

Here's the config/application.rb snippet:

require File.expand_path('../boot', __FILE__)

require 'erb'
require 'rails/all'

# log4r
require 'log4r'
require 'log4r/yamlconfigurator'
require 'log4r/outputter/datefileoutputter'
require 'log4r/outputter/consoleoutputters'
include Log4r

...

class Application < Rails::Application

...

  # assign log4r's logger as rails' logger.
  log4r_config = YAML.load(ERB.new(File.read(File.join(File.dirname(__FILE__), 'log4r.yml'))).result)
  log4r_config['ENV'] = Rails.env
  log4r_config['APPNAME'] = Rails.application.class.parent_name
  YamlConfigurator.decode_yaml(log4r_config['log4r_config'])
  config.logger = Log4r::Logger[Rails.env]
  ActiveRecord::Base.logger = Log4r::Logger[Rails.env]
end

Here's the config/log4r.yml file:

log4r_config:
  # define all loggers ...
  loggers:
  - name: production
    level: WARN
    trace: 'false'
    outputters:
      - datefile_production
      - console_production
  - name: development
    level: DEBUG
    trace: 'true'
    outputters:
      - datefile_development
      - console_development
  - name: test
    level: DEBUG
    trace: 'true'
    outputters:
      - datefile_test
      - console_test

  # define all outputters (incl. formatters)
  outputters:
  - type: DateFileOutputter
    name: datefile_production
    dirname: "<%= File.join(Rails.root, 'log') %>"
    filename: "production.log"
    formatter:
      date_pattern: '%H:%M:%S.%L'
      pattern: '%p\t%d\t%X{:remote_ip}\t%X{:user}\t%X{:controller}\t%X{:action}\t%l\t%m'
      type: PatternFormatter
  - type: DateFileOutputter
    name: datefile_development
    dirname: "<%= File.join(Rails.root, 'log') %>"
    filename: "development.log"
    formatter:
      date_pattern: '%H:%M:%S.%L'
      pattern: '%p\t%d\t%X{:remote_ip}\t%X{:user}\t%X{:controller}\t%X{:action}\t%l\t%m'
      type: PatternFormatter
  - type: DateFileOutputter
    name: datefile_test
    dirname: "<%= File.join(Rails.root, 'log') %>"
    filename: "test.log"
    formatter:
      date_pattern: '%H:%M:%S.%L'
      pattern: '%p\t%d\t%X{:remote_ip}\t%X{:user}\t%X{:controller}\t%X{:action}\t%l\t%m'
      type: PatternFormatter
  - type: StdoutOutputter
    name: console_production
    formatter:
      date_pattern: '%H:%M:%S.%L'
      pattern: '%p\t%d\t%l\t%m'
      type: PatternFormatter
  - type: StdoutOutputter
    name: console_development
    formatter:
      date_pattern: '%H:%M:%S.%L'
      pattern: '%p\t%d\t%X{:remote_ip}\t%X{:user}\t%X{:controller}\t%X{:action}\t%l\t%m'
      type: PatternFormatter
  - type: StdoutOutputter
    name: console_test
    formatter:
      date_pattern: '%H:%M:%S.%L'
      pattern: '%p\t%d\t%X{:remote_ip}\t%X{:user}\t%X{:controller}\t%X{:action}\t%l\t%m'
      type: PatternFormatter

---

UPDATE

Well, after running the rake task through the debugger, I figured out what is happening.

Delayed::Worker (delayed_job/lib/delayed/worker.rb line 248) is logging a message via the logger's add method like this:

logger.add level, "#{Time.now.strftime('%FT%T%z')}: #{text}" if logger

This is valid and correct for Ruby's Logger class, see Logger.html#method-i-add. However, by using log4r it resolves to Log4r::Logger.add (log4r/lib/log4r/logger.rb line 119) which tries to add an outputter.

I'm not sure why this is happening, or what the solution would be.

Answer 1

( see blog.mmlac.com for original comment on this issue. )

The issue is that DelayedJob expects the logger to be Rails::Logger and makes calls to it that log4r does not support.

In this article the logger variable is overwritten to use Log4r::Logger, which does not support the .add call as intended. Unlike in Java there are no packages to determine which logger class to use or slf4j that unites different loggers to a standard interface.

There is no simple solution to this issue. On the one hand you can overwrite the affected parts of delayedJob. On the other hand you can prevent loading the log4r when delayedJob is running rails, i.e. by using a custom environment:

• development
• production
• delayedJob

This is also not guaranteed to work everywhere (anything that checks the rails env == “production” will have issues).

Another way is to use environment variables and check those in the application.rb:

if (ENV["log4rlogger"] == "true") config.logger = Log4r::Logger["rails"]

Answer 2

You can now update to delayed_jobs 4.0.1 gem and this will solve this issue !