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.
( 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:
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"]