Resque: log writing failed. can't be called from trap context

[sonots]

On stopping resque:work with Ctrl-C, I get an error as the title.

I added codes to print backtraces to ruby's standard logger and below is the resulted backtrace:

/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/monitor.rb:185:in `lock'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/monitor.rb:185:in `mon_enter'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/monitor.rb:209:in `mon_synchronize'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/logger.rb:595:in `write'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/logger.rb:378:in `add'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/logger.rb:434:in `info'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/resque-1.26.0/lib/resque/logging.rb:8:in `log'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/resque-1.26.0/lib/resque/worker.rb:872:in `log_with_severity'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/resque-1.26.0/lib/resque/worker.rb:428:in `shutdown'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/resque-1.26.0/lib/resque/worker.rb:435:in `shutdown!'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/resque-1.26.0/lib/resque/worker.rb:390:in `block in register_signal_handlers'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/resque-1.26.0/lib/resque/worker.rb:246:in `call'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/resque-1.26.0/lib/resque/worker.rb:246:in `sleep'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/resque-1.26.0/lib/resque/worker.rb:246:in `block in work'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/resque-1.26.0/lib/resque/worker.rb:206:in `loop'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/resque-1.26.0/lib/resque/worker.rb:206:in `work'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/resque-1.26.0/lib/resque/tasks.rb:19:in `block (2 levels) in <top (required)>'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/task.rb:240:in `call'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/task.rb:240:in `block in execute'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/task.rb:235:in `each'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/task.rb:235:in `execute'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/task.rb:179:in `block in invoke_with_call_chain'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/monitor.rb:211:in `mon_synchronize'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/task.rb:172:in `invoke_with_call_chain'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/task.rb:165:in `invoke'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/application.rb:150:in `invoke_task'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/application.rb:106:in `block (2 levels) in top_level'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/application.rb:106:in `each'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/application.rb:106:in `block in top_level'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/application.rb:115:in `run_with_threads'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/application.rb:100:in `top_level'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/application.rb:78:in `block in run'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/application.rb:176:in `standard_exception_handling'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/2.2.0/rake/application.rb:75:in `run'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/rake-10.4.2/bin/rake:33:in `<top (required)>'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/bin/rake:23:in `load'
/Users/seo.naotoshi/.rbenv/versions/2.2.2/bin/rake:23:in `<main>'

[sonots]

We can not use logger in signal handler https://bugs.ruby-lang.org/issues/7917, but resque does it https://github.com/resque/resque/blob/c295da9de0034b20ce79600e9f54fb279695f522/lib/resque/worker.rb#L377.

How to resolve is, for example, use IO.pipe and puts into pipe in the signal handler, and treats the signal somewhere else as sidekiq does https://github.com/mperham/sidekiq/blob/b6de0bae6b86d5abae25852141768d8ecc8ddedf/lib/sidekiq/cli.rb#L53

[dchersey]

This looks like its dead... has anyone found a good solution to logging from workers?

[j1wilmot]

https://bugs.ruby-lang.org/issues/14222 has a suggestion for how to do this:

require 'logger'

LOG = Queue.new
Thread.start {
  log = Logger.new(STDOUT)
  log.info "Now logging!"
  nil while log.info(LOG.pop)                                                
}                                         

trap :INT do                             
  LOG << "Hello"             
end         

gets

[rogerhu]

https://github.com/resque/resque/pull/1729