Ruby does not allow logging within trap handlers

[rogerhu]

If I kill -USR2, I see "log writing failed. can't be called from trap context". Delete these logging lines until a better fix can be found (Sidekiq for instance rewrites to IO.pipes - https://github.com/mperham/sidekiq/blob/b6de0bae6b86d5abae25852141768d8ecc8ddedf/lib/sidekiq/cli.rb#L53)

[rogerhu]

Ping on this one. :)

[rogerhu]

Anyone there? :)

[jrochkind]

There are other places this comes up.

For instance, these log lines would be REALLY useful to see, to figure out if the "new" "graceful shutdown" code is working/how:

https://github.com/resque/resque/blob/master/lib/resque/worker.rb#L536-L546

But they are always called in a signal trap handler in fact, so they simply never log anything.

I'd consider trying to come up with a PR to use a logging technique that would work, perhaps modeled off of other open source peers... but it looks like other PR's do not get any attention or possible merging by maintainers, so...

[iloveitaly]

@rogerhu Thanks for the contribution here! This is definitely something we should change. Given that Sidekiq already has a great solution for this case, could we take a similar approach here instead of simply removing the log entries?

Something along the lines of:

_, self_write = IO.pipe
self_write.puts "log message"

[rogerhu]

@rogerhu Thanks for the contribution here! This is definitely something we should change. Given that Sidekiq already has a great solution for this case, could we take a similar approach here instead of simply removing the log entries?

Something along the lines of:

_, self_write = IO.pipe
self_write.puts "log message"

Done.

[iloveitaly]

@rogerhu @jrochkind do you use a custom logger for Resque?

I looked into this a bit more and this exact case is why https://github.com/steveklabnik/mono_logger is used instead of the default ruby logger.

I think the change here may just updating the logging documentation in the readme noting this edge case and underscoring the importance of using MonoLogger and not the Rails or stdlib logger.

[jrochkind]

Aha, now that you bring our attention to that, I can find that in the CHANGELOG, @iloveitaly, yup.

Note that it's not just the Rails logger that won't work, but any logger based on stdlib logger.

I can't find anywhere in my app that sets a custom resque logger, but i guess it must.... I wonder if some other gem I am using does it.

It's pretty unexpected not to be able to use a stdlib logger, as is pretty standard for ruby (not just rails). Documenting it better would be one step; maybe even warning if you pass a stdlib logger in?

But ideally I would still have the feature request to change logging implementation so a stdlib logger can be used, perhaps based on how sidekiq does it. (That is not what this PR does, acknowledged). Its both unexpected and inconvenient to have to use a different logger for resque than for the rest of the app resque is part of.

[matthewhively]

EDIT: I found the issue, our newrelic gem is mucking with logger and apparently re-adds mutexes thus causing it to fail.

---

I'm confused. It looks like if you're using MonoLogger for resque that these ThreadErrors shouldn't be happening.
But I am definitely using MonoLogger, and still getting them when attempting to shutdown workers.

Resque worker is running in background and forking per job = true (default)

config

# Open the new separate log file
logfile = File.open(File.join(Rails.root, 'log', "resque_#{Rails.env}.log"), 'a')
# Flush the buffer to the file continuously
logfile.sync = true
# Replace the default STDOUT with our new logfile
Resque.logger = MonoLogger.new(logfile)
Resque.logger.level = (!Rails.env.production? ? MonoLogger::DEBUG : MonoLogger::INFO)
Resque.logger.info "Resque Logger Initialized with #{Resque.logger.class}!"

Send sigQUIT to the worker process results in these messages from resque_development.log

E, [2022-03-09T17:28:21.508227 #34067] ERROR -- : Failed to start worker : #<ThreadError: can't be called from trap context>
E, [2022-03-09T17:28:21.508744 #34067] ERROR -- : Logger is of type: MonoLogger
E, [2022-03-09T17:28:21.509982 #34067] ERROR -- : <backtrace>... def shutdown => log_with_severity :info, 'Exiting...' ...</backtrace>

The last 2 lines I added to the Resque gemfile just to confirm that the process generating the ThreadError was indeed using MonoLogger, and which line was generating the call.

So I guess what I'm asking is, am I doing something wrong with changing the logger to use a file? or is there some other bug here?

[diclophis]

Is this issue still under development?