Ruby 3.3.0 and Resque

Just deployed a new Ruby 3.3.0 branch to staging and it would appear that our Resque jobs just stopped working. Usual procedure check the logs, look for an error and backtrace. Not logs. Ok there is no log/resque.log. There is nothing in the staging.log. Ok. So the process that kicks off our service is monit. Monit log.

/var/log/monit.log

[UTC Feb 21 09:12:46] error    : 'resque-scheduler' process is not running
[UTC Feb 21 09:12:46] info     : 'resque-scheduler' trying to restart
[UTC Feb 21 09:12:46] info     : 'resque-scheduler' start: '/etc/init.d/resque-scheduler start'
[UTC Feb 21 09:13:16] error    : 'resque-scheduler' failed to start (exit status 0) -- no output
[UTC Feb 21 09:15:16] error    : 'resque' process is not running
[UTC Feb 21 09:15:16] info     : 'resque' trying to restart
[UTC Feb 21 09:15:16] info     : 'resque' start: '/etc/init.d/resque start'
[UTC Feb 21 09:15:46] error    : 'resque' failed to start (exit status 0) -- '/etc/init.d/resque start': /etc/init.d/resque: 12: kill: No such process

Brilliant, it states it has exit status 0 and nothing else. OK. Script tells us that it should boot the process, nothing out of the ordinary here. Nothing to indicate that it is locked to an older Ruby version or anything.

/etc/init.d/resque

PID=/home/deploy/app/shared/pids/resque.pid
CMD="cd /home/deploy/app/current; PIDFILE=$PID BACKGROUND=yes bundle exec rake environment resque:work QUEUE=* RAILS_ENV=production"
echo $CMD

It is backgrounded though, if there was an error it wouldn’t end up in STDOUT. Ok, how about we boot without the background option.

$ bundle exec rake environment resque:work QUEUE=* RAILS_ENV=staging
rake aborted!
NoMethodError: undefined method `[]' for nil
/home/deploy/app/shared/bundle/ruby/3.3.0/gems/resque-2.0.0/lib/resque/logging.rb:8:in `log'
/home/deploy/app/shared/bundle/ruby/3.3.0/gems/resque-2.0.0/lib/resque/logging.rb:13:in `info'
/home/deploy/app/shared/bundle/ruby/3.3.0/gems/resque-2.0.0/lib/resque/worker.rb:854:in `log'
/home/deploy/app/shared/bundle/ruby/3.3.0/gems/resque-2.0.0/lib/resque/tasks.rb:19:in `block (2 levels) in <main>'
/home/deploy/app/shared/bundle/ruby/3.3.0/gems/rake-13.0.6/exe/rake:27:in `<top (required)>'
/home/deploy/app/shared/bundle/ruby/3.3.0/gems/bundler-2.5.5/lib/bundler/cli/exec.rb:58:in `load'
/home/deploy/app/shared/bundle/ruby/3.3.0/gems/bundler-2.5.5/lib/bundler/cli/exec.rb:58:in `kernel_load'

Ah, there is is. So the Resque::Logging.log proxies onto the Resque.logger if it is defined.

module Resque
  # Include this module in classes you wish to have logging facilities
  module Logging
    module_function

    # Thunk to the logger's own log method (if configured)
    def self.log(severity, message)
      Resque.logger.__send__(severity, message) if Resque.logger
    end

    # Log level aliases
    def debug(message); Logging.log :debug, message; end
    def info(message);  Logging.log :info,  message; end
    def warn(message);  Logging.log :warn,  message; end
    def error(message); Logging.log :error, message; end
    def fatal(message); Logging.log :fatal, message; end
  end
end

Let’s try it.

% rails c
Loading development environment (Rails 6.1.7)
rirb: warn: can't alias measure from irb_measure.
irb(main):001> Resque.logger.debug('blah')
/Users/rl/.asdf/installs/ruby/3.3.0/lib/ruby/3.3.0/logger.rb:384:in `level': undefined method `[]' for nil (NoMethodError)

    @level_override[Fiber.current] || @level

Ah, that’s a problem. The Resque.logger we’re using seem incompatable with Logger.

And we’re not the only ones to see this. https://talk.jekyllrb.com/t/error-when-executing-bundle-install/8822/6

It would appear that Logger has changed, there is a fix in Jekyll 4.3.3 for their issue. So what’s our issue.

https://github.com/jekyll/jekyll/commit/595cc230678952fab244a62dc1811ea39ec34041

Resque by default defines the Resque.logger as an instance of MonoLogger. Never heard of it.

lib/resque.rb

# Log to STDOUT by default
Resque.logger           = MonoLogger.new(STDOUT)
Resque.logger.formatter = Resque::QuietFormatter.new

Our Gemfile.lock reckons we’re using 1.1.1 of mono_logger

Gemfile.lock

mongoid_paranoia (0.5.0)
       mongoid (~> 7.3)
     mono_logger (1.1.1)
     msgpack (1.7.2)
     multi_json (1.15.0)
     multi_xml (0.6.0)

There is a new patch version of mono_logger available. And there it is in the commit history.

https://github.com/steveklabnik/mono_logger/commit/14bfb8302609123d702ace527c9114a8ff7c438a

They have also fixed it. Logger initializer has changed, so if you’re going to use it sub-class Logger use their initializer. Upgrading to bundle update mono_logger bumps the version to 1.1.2 and fixed our issue.