ERR MULTI calls can not be nested in release 4.9.0

[mikevoets]

I am experiencing the following error after upgrading to 4.9.0:

Redis::CommandError: ERR MULTI calls can not be nested

Caused by:

gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:253 block in enqueue_items_in_batch_for_timestamp

[PatrickTulskie]

Haven't seen that before. Can you provide any more context?

[mikevoets]

This is the stacktrace:

gems/redis-4.8.1/lib/redis/client.rb:246:in `call_pipelined': ERR MULTI calls can not be nested (Redis::CommandError)
    from gems/redis-4.8.1/lib/redis/client.rb:200:in `block in call_pipeline'
    from gems/redis-4.8.1/lib/redis/client.rb:344:in `with_reconnect'
    from gems/redis-4.8.1/lib/redis/client.rb:198:in `call_pipeline'
    from gems/redis-4.8.1/lib/redis.rb:228:in `block in multi'
    from gems/redis-4.8.1/lib/redis.rb:265:in `block in synchronize'
    from gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'
    from gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'
    from gems/redis-4.8.1/lib/redis.rb:222:in `multi'
    from gems/redis-namespace-1.11.0/lib/redis/namespace.rb:564:in `wrapped_send'
    from gems/redis-namespace-1.11.0/lib/redis/namespace.rb:588:in `namespaced_block'
    from gems/redis-namespace-1.11.0/lib/redis/namespace.rb:311:in `multi'
    from gems/resque-2.5.0/lib/resque/data_store.rb:65:in `method_missing'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:253:in `block in enqueue_items_in_batch_for_timestamp'
    from gems/redis-4.8.1/lib/redis/commands/transactions.rb:89:in `block in watch'
    from gems/redis-4.8.1/lib/redis.rb:265:in `block in synchronize'
    from gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'
    from gems/redis-4.8.1/lib/redis.rb:265:in `synchronize'
    from gems/redis-4.8.1/lib/redis/commands/transactions.rb:84:in `watch'
    from gems/redis-namespace-1.11.0/lib/redis/namespace.rb:564:in `wrapped_send'
    from gems/redis-namespace-1.11.0/lib/redis/namespace.rb:521:in `call_with_namespace'
    from gems/redis-namespace-1.11.0/lib/redis/namespace.rb:395:in `block (2 levels) in <class:Namespace>'
    from gems/resque-2.5.0/lib/resque/data_store.rb:65:in `method_missing'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:252:in `enqueue_items_in_batch_for_timestamp'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:219:in `block (2 levels) in enqueue_delayed_items_for_timestamp'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:293:in `handle_shutdown'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:216:in `block in enqueue_delayed_items_for_timestamp'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:215:in `loop'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:215:in `enqueue_delayed_items_for_timestamp'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:190:in `handle_delayed_items'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:69:in `block in run'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:57:in `loop'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb:57:in `run'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler/cli.rb:117:in `run_forever'
    from gems/resque-scheduler-4.9.0/lib/resque/scheduler/tasks.rb:18:in `block (2 levels) in <top (required)>'
    from gems/rake-13.0.6/lib/rake/task.rb:281:in `block in execute'
    from gems/rake-13.0.6/lib/rake/task.rb:281:in `each'
    from gems/rake-13.0.6/lib/rake/task.rb:281:in `execute'
    from gems/bugsnag-6.25.2/lib/bugsnag/integrations/rake.rb:20:in `execute'
    from gems/rake-13.0.6/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
    from gems/rake-13.0.6/lib/rake/task.rb:199:in `synchronize'
    from gems/rake-13.0.6/lib/rake/task.rb:199:in `invoke_with_call_chain'
    from gems/rake-13.0.6/lib/rake/task.rb:188:in `invoke'
    from gems/rake-13.0.6/lib/rake/application.rb:160:in `invoke_task'
    from gems/rake-13.0.6/lib/rake/application.rb:116:in `block (2 levels) in top_level'
    from gems/rake-13.0.6/lib/rake/application.rb:116:in `each'
    from gems/rake-13.0.6/lib/rake/application.rb:116:in `block in top_level'
    from gems/rake-13.0.6/lib/rake/application.rb:125:in `run_with_threads'
    from gems/rake-13.0.6/lib/rake/application.rb:110:in `top_level'
    from gems/rake-13.0.6/lib/rake/application.rb:83:in `block in run'
    from gems/rake-13.0.6/lib/rake/application.rb:186:in `standard_exception_handling'
    from gems/rake-13.0.6/lib/rake/application.rb:80:in `run'
    from gems/rake-13.0.6/exe/rake:27:in `<top (required)>'
    from bin/rake:25:in `load'
    from bin/rake:25:in `<top (required)>'
    from /opt/rubies/ruby-3.0.6/lib/ruby/site_ruby/3.0.0/bundler/cli/exec.rb:58:in `load'
    from /opt/rubies/ruby-3.0.6/lib/ruby/site_ruby/3.0.0/bundler/cli/exec.rb:58:in `kernel_load'
    from /opt/rubies/ruby-3.0.6/lib/ruby/site_ruby/3.0.0/bundler/cli/exec.rb:23:in `run'
    from /opt/rubies/ruby-3.0.6/lib/ruby/site_ruby/3.0.0/bundler/cli.rb:492:in `exec'
    from /opt/rubies/ruby-3.0.6/lib/ruby/site_ruby/3.0.0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
    from /opt/rubies/ruby-3.0.6/lib/ruby/site_ruby/3.0.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
    from /opt/rubies/ruby-3.0.6/lib/ruby/site_ruby/3.0.0/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
    from /opt/rubies/ruby-3.0.6/lib/ruby/site_ruby/3.0.0/bundler/cli.rb:34:in `dispatch'
    from /opt/rubies/ruby-3.0.6/lib/ruby/site_ruby/3.0.0/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
    from /opt/rubies/ruby-3.0.6/lib/ruby/site_ruby/3.0.0/bundler/cli.rb:28:in `start'
    from /opt/rubies/ruby-3.0.6/lib/ruby/gems/3.0.0/gems/bundler-2.4.14/exe/bundle:37:in `block in <top (required)>'
    from /opt/rubies/ruby-3.0.6/lib/ruby/site_ruby/3.0.0/bundler/friendly_errors.rb:117:in `with_friendly_errors'
    from /opt/rubies/ruby-3.0.6/lib/ruby/gems/3.0.0/gems/bundler-2.4.14/exe/bundle:29:in `<top (required)>'
    from /opt/rubies/ruby-3.0.6/bin/bundle:25:in `load'
    from /opt/rubies/ruby-3.0.6/bin/bundle:25:in `<main>'

I hope that's enough context. If not, please let me know what you need and I'll try and provide it to you.

[jweir]

We are seeing the same issue and using redis-4.8.1 as well.

Redis::CommandError: ERR MULTI calls can not be nested
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis/client.rb", line 246, in call_pipelined
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis/client.rb", line 200, in block in call_pipeline
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis/client.rb", line 344, in with_reconnect
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis/client.rb", line 198, in call_pipeline
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/newrelic_rpm-9.3.0/lib/new_relic/agent/instrumentation/redis/prepend.rb", line 21, in block in call_pipeline
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/newrelic_rpm-9.3.0/lib/new_relic/agent/instrumentation/redis/instrumentation.rb", line 25, in block in call_pipeline_with_tracing
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/newrelic_rpm-9.3.0/lib/new_relic/agent/instrumentation/redis/instrumentation.rb", line 55, in block in with_tracing
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/newrelic_rpm-9.3.0/lib/new_relic/agent/tracer.rb", line 356, in capture_segment_error
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/newrelic_rpm-9.3.0/lib/new_relic/agent/instrumentation/redis/instrumentation.rb", line 55, in with_tracing
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/newrelic_rpm-9.3.0/lib/new_relic/agent/instrumentation/redis/instrumentation.rb", line 25, in call_pipeline_with_tracing
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/newrelic_rpm-9.3.0/lib/new_relic/agent/instrumentation/redis/prepend.rb", line 21, in call_pipeline
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis.rb", line 228, in block in multi
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis.rb", line 265, in block in synchronize
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis.rb", line 265, in synchronize
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis.rb", line 265, in synchronize
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis.rb", line 222, in multi
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb", line 564, in wrapped_send
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb", line 588, in namespaced_block
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb", line 311, in multi
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-2.5.0/lib/resque/data_store.rb", line 65, in method_missing
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb", line 253, in block in enqueue_items_in_batch_for_timestamp
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis/commands/transactions.rb", line 89, in block in watch
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis.rb", line 265, in block in synchronize
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis.rb", line 265, in synchronize
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis.rb", line 265, in synchronize
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-4.8.1/lib/redis/commands/transactions.rb", line 84, in watch
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb", line 564, in wrapped_send
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb", line 521, in call_with_namespace
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/redis-namespace-1.11.0/lib/redis/namespace.rb", line 395, in block (2 levels) in <class:Namespace>
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-2.5.0/lib/resque/data_store.rb", line 65, in method_missing
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb", line 252, in enqueue_items_in_batch_for_timestamp
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb", line 219, in block (2 levels) in enqueue_delayed_items_for_timestamp
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb", line 293, in handle_shutdown
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb", line 216, in block in enqueue_delayed_items_for_timestamp
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb", line 215, in loop
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb", line 215, in enqueue_delayed_items_for_timestamp
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb", line 190, in handle_delayed_items
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb", line 69, in block in run
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb", line 57, in loop
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler.rb", line 57, in run
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler/cli.rb", line 117, in run_forever
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/resque-scheduler-4.9.0/lib/resque/scheduler/tasks.rb", line 18, in block (2 levels) in <main>
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb", line 281, in block in execute
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb", line 281, in each
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb", line 281, in execute
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb", line 219, in block in invoke_with_call_chain
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb", line 199, in synchronize
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb", line 199, in invoke_with_call_chain
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb", line 188, in invoke
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb", line 160, in invoke_task
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb", line 116, in block (2 levels) in top_level
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb", line 116, in each
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb", line 116, in block in top_level
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb", line 125, in run_with_threads
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb", line 110, in top_level
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb", line 83, in block in run
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb", line 186, in standard_exception_handling
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb", line 80, in run
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/rake-13.0.6/exe/rake", line 27, in <top (required)>
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/bin/rake", line 25, in load
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/bin/rake", line 25, in <top (required)>
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/lib/bundler/cli/exec.rb", line 58, in load
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/lib/bundler/cli/exec.rb", line 58, in kernel_load
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/lib/bundler/cli/exec.rb", line 23, in run
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/lib/bundler/cli.rb", line 491, in exec
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/lib/bundler/vendor/thor/lib/thor/command.rb", line 27, in run
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/lib/bundler/vendor/thor/lib/thor/invocation.rb", line 127, in invoke_command
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/lib/bundler/vendor/thor/lib/thor.rb", line 392, in dispatch
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/lib/bundler/cli.rb", line 34, in dispatch
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/lib/bundler/vendor/thor/lib/thor/base.rb", line 485, in start
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/lib/bundler/cli.rb", line 28, in start
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/exe/bundle", line 45, in block in <top (required)>
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/lib/bundler/friendly_errors.rb", line 117, in with_friendly_errors
File "/data/pharos/ams/shared/bundle/ruby/3.2.0/gems/bundler-2.4.6/exe/bundle", line 33, in <top (required)>
File "/home/deploy/.rbenv/versions/3.2.2/bin/bundle", line 25, in load
File "/home/deploy/.rbenv/versions/3.2.2/bin/bundle", line 25, in <main>

[PatrickTulskie]

Still not seeing this in any of my installs which is weird. Can you give me some steps to reproduce? Alternatively, if you see where in the code it's happening, can you open a PR with a fix?

[jweir]

I have not been able to reproduce. This occurred a couple of times in production. If I am able to get another trace and reproduce I will post here.

-- edit --

Looking this over I don't see how the multi block could get nested. We have no hooks that would create another multi pipeline.

[mikevoets]

@PatrickTulskie I'm pretty sure this is caused by one of our scheduled jobs doing a Redis watch and multi. When this job gets enqueued by the following code:

# lib/resque/scheduler.rb:252

watch_result = Resque.redis.watch(timestamp_bucket_key) do
  Resque.redis.multi do |pipeline|
    encoded_jobs_to_requeue.each do |encoded_job|
      pipeline.srem("timestamps:#{encoded_job}", timestamp_bucket_key)
  
      decoded_job = Resque.decode(encoded_job)
      enqueue(decoded_job)
    end
  
    pipeline.ltrim(timestamp_bucket_key, batch_size, -1)
  end
end

this creates a nested multi block that causes this error.

[PatrickTulskie]

Gotcha. One thing you might want to do here is make a new connection to Redis when you're doing that... there were bugs with the pipelining in previous versions of Resque and Resque Scheduler that were resolved so that's probably why you're seeing this.

[mikevoets]

Actually I was wrong... I wasn't able to reproduce it as we're using a different connection for Redis for that. So back to square one :(

[mikevoets]

Hello! A little update from me. We've managed to upgrade the redis gem to version 5. This issue doesn't seem to occur with version 5 anymore. So I won't be able to provide further reproduction steps.

[ajvondrak]

I can reproduce this locally using a MULTI call on the same Redis connection from an enqueue hook, as noted in the discussion:

require "bundler/inline"

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

$stderr.sync = true
$stdout.sync = true
$redis = Redis.new(logger: Logger.new($stdout, level: Logger::DEBUG))

Resque.redis = $redis

class Job
  @queue = "jobs"

  def self.before_enqueue
    $redis.multi { |m| m.ping }
    true
  end
end

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

Output

$ ruby repro.rb
D, [2023-12-28T11:38:47.069449 #90672] DEBUG -- : [Redis] command=FLUSHDB args=
D, [2023-12-28T11:38:47.070676 #90672] DEBUG -- : [Redis] call_time=0.77 ms
D, [2023-12-28T11:38:47.070833 #90672] DEBUG -- : [Redis] command=RPUSH args="resque:delayed:1703792328" "{\"class\":\"Job\",\"args\":[],\"queue\":\"jobs\"}"
D, [2023-12-28T11:38:47.070977 #90672] DEBUG -- : [Redis] call_time=0.13 ms
D, [2023-12-28T11:38:47.071075 #90672] DEBUG -- : [Redis] command=SADD args="resque:timestamps:{\"class\":\"Job\",\"args\":[],\"queue\":\"jobs\"}" ["delayed:1703792328"]
D, [2023-12-28T11:38:47.071195 #90672] DEBUG -- : [Redis] call_time=0.11 ms
D, [2023-12-28T11:38:47.071217 #90672] DEBUG -- : [Redis] command=ZADD args="resque:delayed_queue_schedule" 1703792328 1703792328
D, [2023-12-28T11:38:47.071324 #90672] DEBUG -- : [Redis] call_time=0.10 ms
D, [2023-12-28T11:38:48.073990 #90672] DEBUG -- : [Redis] command=ZRANGEBYSCORE args="resque:delayed_queue_schedule" "-inf" 1703792328 "LIMIT" 0 1
D, [2023-12-28T11:38:48.080165 #90672] DEBUG -- : [Redis] call_time=5.97 ms
resque-scheduler: [INFO] 2023-12-28T11:38:48-08:00: Processing Delayed Items
D, [2023-12-28T11:38:48.082248 #90672] DEBUG -- : [Redis] command=INFO args=
D, [2023-12-28T11:38:48.082774 #90672] DEBUG -- : [Redis] call_time=0.45 ms
D, [2023-12-28T11:38:48.088263 #90672] DEBUG -- : [Redis] command=SCRIPT args="load" "if redis.call('SETNX', KEYS[1], ARGV[1]) == 1\nthen\n  redis.call('EXPIRE', KEYS[1], 180)\n  return 1\nelse\n  return 0\nend\n"
D, [2023-12-28T11:38:48.088585 #90672] DEBUG -- : [Redis] call_time=0.24 ms
D, [2023-12-28T11:38:48.088694 #90672] DEBUG -- : [Redis] command=EVALSHA args="8f4a4e422bfa8f9a0931e350d6e30b1c3ce97c33" 1 "resque:resque:resque_scheduler_master_lock" "localhost:90672"
D, [2023-12-28T11:38:48.089028 #90672] DEBUG -- : [Redis] call_time=0.30 ms
D, [2023-12-28T11:38:48.089167 #90672] DEBUG -- : [Redis] command=LRANGE args="resque:delayed:1703792328" 0 99
D, [2023-12-28T11:38:48.089343 #90672] DEBUG -- : [Redis] call_time=0.14 ms
D, [2023-12-28T11:38:48.089754 #90672] DEBUG -- : [Redis] command=WATCH args="resque:delayed:1703792328"
D, [2023-12-28T11:38:48.090058 #90672] DEBUG -- : [Redis] call_time=0.26 ms
Redis#srem will always return an Integer in Redis 5.0.0. Use Redis#srem? instead.(called from: /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')
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 repro.rb:20:in `before_enqueue'}
D, [2023-12-28T11:38:48.093181 #90672] DEBUG -- : [Redis] command=MULTI args=
D, [2023-12-28T11:38:48.093243 #90672] DEBUG -- : [Redis] command=SREM args="resque:timestamps:{\"class\":\"Job\",\"args\":[],\"queue\":\"jobs\"}" "delayed:1703792328"
D, [2023-12-28T11:38:48.093474 #90672] DEBUG -- : [Redis] command=MULTI args=
D, [2023-12-28T11:38:48.093501 #90672] DEBUG -- : [Redis] command=PING args=
D, [2023-12-28T11:38:48.093525 #90672] DEBUG -- : [Redis] command=EXEC args=
D, [2023-12-28T11:38:48.093559 #90672] DEBUG -- : [Redis] command=SADD args="resque:queues" ["jobs"]
D, [2023-12-28T11:38:48.093591 #90672] DEBUG -- : [Redis] command=RPUSH args="resque:queue:jobs" "{\"class\":\"Job\",\"args\":[]}"
D, [2023-12-28T11:38:48.093623 #90672] DEBUG -- : [Redis] command=LTRIM args="resque:delayed:1703792328" 100 -1
D, [2023-12-28T11:38:48.093647 #90672] DEBUG -- : [Redis] command=EXEC args=
D, [2023-12-28T11:38:48.094471 #90672] DEBUG -- : [Redis] call_time=0.78 ms
D, [2023-12-28T11:38:48.094735 #90672] DEBUG -- : [Redis] command=UNWATCH args=
D, [2023-12-28T11:38:48.094985 #90672] DEBUG -- : [Redis] call_time=0.21 ms
/Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis/client.rb:246:in `call_pipelined': ERR MULTI calls can not be nested (Redis::CommandError)
	from /Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis/client.rb:200:in `block in call_pipeline'
	from /Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis/client.rb:344:in `with_reconnect'
	from /Users/alex.vondrak/.local/share/rtx/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/redis-4.8.1/lib/redis/client.rb:198:in `call_pipeline'
	from /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:228:in `block in multi'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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>'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from /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'
	from repro.rb:28:in `<main>'

This all seems to tie back to #767, which wraps the batch of enqueues in a MULTI/EXEC block. Circa Redis 4.x, before_enqueue hooks and the like will execute commands within the same transaction, which can now cause other bugs like #779 where commands are asynchronous (i.e., they're now getting buffered before being sent as a single pipelined MULTI ... EXEC to the Redis server). Circa Redis 5.x, "nested" calls to multi/pipelined will silently fire outside the resque-scheduler transaction—including pipelined calls from the resque gem itself, which I believe defeats the purpose of the transaction, as discussed in #787.