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.