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

[onyxraven]

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).

Do you happen to have a fork with a mitigation? I just started looking at this issue, as we just ran into it, and looking for any prior art before I go spelunking.

[ajvondrak]

No forks I'm afraid, but the mitigations I see:

1. Lock to earlier versions resque-scheduler or redis so that you don't get this unfavorable interaction. Not ideal, but it's where I'm at now. 😅
2. resque-scheduler could revert Adding batching to re-queuing for timestamp resque/resque-scheduler#767 (or you could do so in a fork) since it causes a bunch of issues, as linked above. But then you lose out at the attempted batching functionality, fwiw.
3. The "proper" fix would be to patch the resque + resque-scheduler gems to pass around the Redis pipeline object, but it's a hairy enough change that I haven't seen anyone attempt it. The code would have to straddle both gems, iirc.

[onyxraven]

Thanks, yep. I'm currently rolling back scheduler & redis to mitigate a live issue now, and will be looking into option 2. Option 3 I think would require 'injecting' Resque.enqueue with a given pipeline'd instance, which looks... not easy right now but maybe a longer term fix.

FWIW, I'll probably publish both that and our fork of resque-lock-timeout (which incorporates a few of the other fork fixes that have been around).

[ajvondrak]

Nice. Hugops and will be curious to see to any other tweaks you have lying around. :)

Now that I'm spooling context back up on option 3 (credit to this comment), I think even that refactor still wouldn't resolve resque/resque-scheduler#779 since enqueue hooks would still be executed in the middle of an open transaction so...option 2 seems like honestly the most feasible thing anyway.

[onyxraven]

Was just able to come back and finish up some work around this.

Ibotta/resque-scheduler#1 This PR has my proposal (currently a PR against my own fork). It allows handling the delayed enqueue batching as an opt-in option. As noted in the comments, I'm open to switching it to be opt-out (which we'd use).

I've also linked my integration test Ibotta/resque-plugin-integration-tests#1 between resque-scheduler and resque-lock-timeout.

I'm going to let this bake a bit, and do some experimentation in our internal repositories, but I'll likely propose the patch 'upstream' as well.