Heads up: resque-scheduler 4.9+ on redis-rb 4.x inadvertently breaks loner locks

[ajvondrak]

Due to resque/resque-scheduler#767, resque-scheduler 4.9+ now wraps all enqueues within a Redis transaction. This means that Redis commands in before_enqueue hooks (inadvertently) no longer run synchronously under redis 4.x, which breaks gems like resque-lock-timeout (since it uses before_enqueue hooks for loner lock checks).

Repro:

require 'bundler/inline'

gemfile do
  source 'https://rubygems.org'
  gem 'resque', '~> 2.6'
  gem 'resque-scheduler', '~> 4.9'
  gem 'redis', '~> 4.0'
  gem 'resque-lock-timeout'
end

Redis.silence_deprecations = true # some unrelated deprecations due to resque-scheduler issues
Resque.redis = Redis.new

class Job
  extend Resque::Plugins::LockTimeout

  @queue = 'jobs'
  @loner = true

  def self.perform
    puts 'ok'
  end
end

Resque.redis.redis.flushdb # to ensure we start with a blank slate
2.times { Resque.enqueue_in(1, Job) }
sleep(1)
Resque::Scheduler.handle_delayed_items

$ ruby repro.rb
resque-scheduler: [INFO] 2024-01-10T16:41:38-08:00: Processing Delayed Items
resque-scheduler: [ERROR] 2024-01-10T16:41:38-08:00: NoMethodError: undefined method `nil?' for <Redis::Future [:get, "resque:lock:Job:"]>:Redis::Future ["/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-lock-timeout-0.4.1/lib/resque/plugins/lock_timeout.rb:119:in `locked?'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-lock-timeout-0.4.1/lib/resque/plugins/lock_timeout.rb:150:in `before_enqueue_lock'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-2.6.0/lib/resque.rb:447:in `block in enqueue_to'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-2.6.0/lib/resque.rb:446:in `collect'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-2.6.0/lib/resque.rb:446:in `enqueue_to'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:344:in `enqueue_from_config'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:286:in `enqueue'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:258:in `block (3 levels) in enqueue_items_in_batch_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:254:in `each'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:254:in `block (2 levels) in enqueue_items_in_batch_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:587:in `block in namespaced_block'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:227:in `block in multi'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `block in synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:222:in `multi'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:564:in `wrapped_send'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:588:in `namespaced_block'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:311:in `multi'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-2.6.0/lib/resque/data_store.rb:65:in `method_missing'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:253:in `block in enqueue_items_in_batch_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis/commands/transactions.rb:89:in `block in watch'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `block in synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis/commands/transactions.rb:84:in `watch'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:564:in `wrapped_send'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:521:in `call_with_namespace'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:395:in `block (2 levels) in <class:Namespace>'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-2.6.0/lib/resque/data_store.rb:65:in `method_missing'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:252:in `enqueue_items_in_batch_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:219:in `block (2 levels) in enqueue_delayed_items_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:293:in `handle_shutdown'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:216:in `block in enqueue_delayed_items_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:215:in `loop'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:215:in `enqueue_delayed_items_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:190:in `handle_delayed_items'", "repro.rb:28:in `<main>'"]
resque-scheduler: [ERROR] 2024-01-10T16:41:38-08:00: NoMethodError: undefined method `nil?' for <Redis::Future [:get, "resque:lock:Job:"]>:Redis::Future ["/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-lock-timeout-0.4.1/lib/resque/plugins/lock_timeout.rb:119:in `locked?'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-lock-timeout-0.4.1/lib/resque/plugins/lock_timeout.rb:150:in `before_enqueue_lock'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-2.6.0/lib/resque.rb:447:in `block in enqueue_to'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-2.6.0/lib/resque.rb:446:in `collect'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-2.6.0/lib/resque.rb:446:in `enqueue_to'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:344:in `enqueue_from_config'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:286:in `enqueue'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:258:in `block (3 levels) in enqueue_items_in_batch_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:254:in `each'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:254:in `block (2 levels) in enqueue_items_in_batch_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:587:in `block in namespaced_block'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:227:in `block in multi'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `block in synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:222:in `multi'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:564:in `wrapped_send'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:588:in `namespaced_block'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:311:in `multi'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-2.6.0/lib/resque/data_store.rb:65:in `method_missing'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:253:in `block in enqueue_items_in_batch_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis/commands/transactions.rb:89:in `block in watch'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `block in synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis/commands/transactions.rb:84:in `watch'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:564:in `wrapped_send'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:521:in `call_with_namespace'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:395:in `block (2 levels) in <class:Namespace>'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-2.6.0/lib/resque/data_store.rb:65:in `method_missing'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:252:in `enqueue_items_in_batch_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:219:in `block (2 levels) in enqueue_delayed_items_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:293:in `handle_shutdown'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:216:in `block in enqueue_delayed_items_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:215:in `loop'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:215:in `enqueue_delayed_items_for_timestamp'", "/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/resque-scheduler-4.10.2/lib/resque/scheduler.rb:190:in `handle_delayed_items'", "repro.rb:28:in `<main>'"]

This seems to not be an issue on Redis 5.x, although there are other problems with resque-scheduler's transactions there, since some commands inadvertently "spill out" of the ongoing transaction (cf. resque/resque-scheduler#787).

I think this is more a bug for resque-scheduler to fix (specifically resque/resque-scheduler#779), but it affects this gem. So, heads up.

Further reading:

• Redis 5 API for multi/pipelined commands changes transaction behavior in resque-scheduler 4.9+ resque/resque-scheduler#787
• NoMethodError when accessing Redis in enqueue hooks with redis 4.x resque/resque-scheduler#779
• ERR MULTI calls can not be nested in release 4.9.0 resque/resque-scheduler#773