resque / resque-scheduler

A light-weight job scheduling system built on top of Resque
MIT License
1.74k stars 481 forks source link

NoMethodError when accessing Redis in enqueue hooks with redis 4.x #779

Open m-shimojo opened 1 year ago

m-shimojo commented 1 year ago

We have updated resque-scheduler to 4.9.0 in our project and we are getting an error on before_enqueue while running a delayed job. The same error is occurring in 4.10.0 as well. The error occurs when using redis-rb 4.x and not with 5.x. However, we have not been able to update to 5.x due to dependency issues, so is there any way to resolve this error while still using 4.x?

I guess it has something to do with #773.

Expected behavior

No errors.

Actual behavior

NoMethodError is raised.

NoMethodError: undefined method `to_i' for <Redis::Future [:llen, "resque:queue:normal"]>:Redis::Future

Full log:

resque-scheduler: [INFO] 2023-10-30T17:09:00+09:00: Processing Delayed Items
Redis#srem will always return an Integer in Redis 5.0.0. Use Redis#srem? instead.(called from: /home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:564:in `wrapped_send')
Start before_enqueue
Pipelining commands on a Redis instance is deprecated and will be removed in Redis 5.0.0.

redis.multi do
  redis.get("key")
end

should be replaced by

redis.multi do |pipeline|
  pipeline.get("key")
end

(called from /home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:564:in `wrapped_send'}
resque-scheduler: [ERROR] 2023-10-30T17:09:00+09:00: NoMethodError: undefined method `to_i' for <Redis::Future [:llen, "resque:queue:normal"]>:Redis::Future ["/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-2.6.0/lib/resque/data_store.rb:118:in `queue_size'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/2.7.0/forwardable.rb:235:in `queue_size'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-2.6.0/lib/resque.rb:363:in `size'", "/home/user/git-repos/repro-resque-scheduler-hooks-issue/jobs/sample_job.rb:8:in `before_enqueue'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-2.6.0/lib/resque.rb:447:in `block in enqueue_to'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-2.6.0/lib/resque.rb:446:in `collect'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-2.6.0/lib/resque.rb:446:in `enqueue_to'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:344:in `enqueue_from_config'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:286:in `enqueue'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:258:in `block (3 levels) in enqueue_items_in_batch_for_timestamp'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:254:in `each'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:254:in `block (2 levels) in enqueue_items_in_batch_for_timestamp'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:587:in `block in namespaced_block'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-4.8.1/lib/redis.rb:227:in `block in multi'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-4.8.1/lib/redis.rb:265:in `block in synchronize'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-4.8.1/lib/redis.rb:222:in `multi'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:564:in `wrapped_send'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:588:in `namespaced_block'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:311:in `multi'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-2.6.0/lib/resque/data_store.rb:65:in `method_missing'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:253:in `block in enqueue_items_in_batch_for_timestamp'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-4.8.1/lib/redis/commands/transactions.rb:89:in `block in watch'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-4.8.1/lib/redis.rb:265:in `block in synchronize'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-4.8.1/lib/redis/commands/transactions.rb:84:in `watch'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:564:in `wrapped_send'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:521:in `call_with_namespace'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb:395:in `block (2 levels) in <class:Namespace>'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-2.6.0/lib/resque/data_store.rb:65:in `method_missing'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:252:in `enqueue_items_in_batch_for_timestamp'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:219:in `block (2 levels) in enqueue_delayed_items_for_timestamp'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:293:in `handle_shutdown'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:216:in `block in enqueue_delayed_items_for_timestamp'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:215:in `loop'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:215:in `enqueue_delayed_items_for_timestamp'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:190:in `handle_delayed_items'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:69:in `block in run'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:57:in `loop'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler.rb:57:in `run'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler/cli.rb:117:in `run_forever'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-scheduler-4.10.0/lib/resque/scheduler/tasks.rb:18:in `block (2 levels) in <top (required)>'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `block in execute'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `each'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `execute'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/task.rb:219:in `block in invoke_with_call_chain'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `synchronize'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `invoke_with_call_chain'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/task.rb:188:in `invoke'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/application.rb:160:in `invoke_task'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block (2 levels) in top_level'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `each'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block in top_level'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/application.rb:125:in `run_with_threads'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/application.rb:110:in `top_level'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/application.rb:83:in `block in run'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/application.rb:186:in `standard_exception_handling'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/lib/rake/application.rb:80:in `run'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/rake-13.0.6/exe/rake:27:in `<top (required)>'", "/home/user/.rbenv/versions/2.7.8/bin/rake:23:in `load'", "/home/user/.rbenv/versions/2.7.8/bin/rake:23:in `<top (required)>'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/lib/bundler/cli/exec.rb:58:in `load'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/lib/bundler/cli/exec.rb:58:in `kernel_load'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/lib/bundler/cli/exec.rb:23:in `run'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/lib/bundler/cli.rb:492:in `exec'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/lib/bundler/cli.rb:34:in `dispatch'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/lib/bundler/cli.rb:28:in `start'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/exe/bundle:37:in `block in <top (required)>'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/lib/bundler/friendly_errors.rb:117:in `with_friendly_errors'", "/home/user/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/bundler-2.4.18/exe/bundle:29:in `<top (required)>'", "/home/user/.rbenv/versions/2.7.8/bin/bundle:23:in `load'", "/home/user/.rbenv/versions/2.7.8/bin/bundle:23:in `<main>'"]

Steps to reproduce the problem

Repository for reproduction: https://github.com/m-shimojo/repro-resque-scheduler-hooks-issue

ajvondrak commented 10 months ago

This looks like yet another issue caused by https://github.com/resque/resque-scheduler/pull/767, because it tries to wrap all the enqueues done by resque-scheduler in a MULTI/EXEC transaction. Circa Redis 4.x, this means the Redis commands in your before_enqueue hook are being stashed as a Redis::Future and only fired when the MULTI block gets sent. (Circa Redis 5.x, the commands happen to get sent outside of the ongoing transaction, but I believe this to be a bug with what the transaction is trying to accomplish.)

So effectively, this is what's happening:

[1] pry(main)> require 'redis'
=> true
[2] pry(main)> Redis::VERSION
=> "4.8.1"
[3] pry(main)> r = Redis.new
=> #<Redis client v4.8.1 for redis://127.0.0.1:6379/0>
[4] pry(main)> r.multi { r.llen('anything').to_i }
Pipelining commands on a Redis instance is deprecated and will be removed in Redis 5.0.0.

redis.multi do
  redis.get("key")
end

should be replaced by

redis.multi do |pipeline|
  pipeline.get("key")
end

(called from (pry):4:in `__pry__'}
NoMethodError: undefined method `to_i' for <Redis::Future [:llen, "anything"]>:Redis::Future
from (pry):4:in `block in __pry__'

See also: