search

lantins / resque-lock-timeout

A Resque plugin; adds locking, with optional timeout/deadlock handling to resque jobs.
MIT License
53 stars 20 forks source link

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

Open ajvondrak opened 9 months ago

ajvondrak commented 9 months ago

Due to https://github.com/resque/resque-scheduler/pull/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. https://github.com/resque/resque-scheduler/issues/787).

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

Further reading:

onyxraven commented 2 months ago

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 commented 2 months ago

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 https://github.com/resque/resque-scheduler/pull/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 commented 2 months ago

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 commented 2 months ago

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 https://github.com/resque/resque-scheduler/issues/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.