mperham/sidekiq — pull request #1406 by jonhyman (2013-12-21 14:10:50+00:00)
Title: Attempt a bulk requeue for reliable-fetch when shutting down.

I believe there is a case where an #assign will happen after a requeue and cause work to remain in the reliable-fetch queue.

We're still seeing reliable fetch pick up jobs on service restart, albeit very, very rarely. Here are some logs with some monkey patching that I put in. Concurrency == 2, the worker only processes a single queue called "data_process."

So you can see that `bulk_requeue` is being called because I added the log statement at the top of it, and that bulk requeue is not moving any jobs, since otherwise it would log `Sidekiq.logger.info {"Moving work from #{working_queue} back to #{queue}"}`.

My guess here is that the actors are shutting down, `Manager#requeue` gets called for each actor but then I think an `assign` gets called which is:

```ruby
def assign(work)
watchdog("Manager#assign died") do
if stopped?
# Race condition between Manager#stop if Fetcher
# is blocked on redis and gets a message after
# all the ready Processors have been stopped.
# Push the message back to redis.
work.requeue
else
processor = @ready.pop
@in_progress[processor.object_id] = work
@busy << processor
processor.async.process(work)
end
end
end
```

and then since we're stopped, it calls `work.requeue` but that does nothing since reliable-fetch relies on the bulk_requeue behavior. This never gets pushed back onto the queue since `bulk_requeue` is not called again, and when the process starts up, it grabs work that it never processed before. AFAICT in my system, these jobs that get picked up from the working queue are not being run twice, so that aligns with what I would expect in this scenario.

(although, on a side note, I see that `bulk_requeue` always get called N+2 times, where N is concurrency. Below you see 4 log statements for "At the top of bulk_requeue" with concurrency 2. If I make the concurrency 5, you'll see that 7 times. If I make it 25, you'll see that 27 times, etc. Can't figure out where the extra 2 calls are coming from, though.)

```
21 08:27:39 _prod_production_util_domU-12-31-39-0E-20-91 syslog: Dec 21 13:27:39 localhost monit[15901]: 'sidekiq__prod_4' stop: /engineyard/bin/sidekiq
Dec 21 08:27:39 _prod_production_util_domU-12-31-39-0E-20-91 syslog: Dec 21 13:27:39 localhost sidekiq__prod: Good, found a conf file. Proceeding...
Dec 21 08:27:39 _prod_production_util_domU-12-31-39-0E-20-91 syslog: Dec 21 13:27:39 localhost monit-sidekiq[8345]: stoping Sidekiq worker sidekiq_4
Dec 21 08:27:39 _prod_production_util_domU-12-31-39-0E-20-91 syslog: Dec 21 13:27:39 localhost monit-sidekiq[8328]: removing /tmp/sidekiq_3.monit-lock for 8328
Dec 21 08:27:39 _prod_production_util_domU-12-31-39-0E-20-91 syslog: Dec 21 13:27:39 localhost monit-sidekiq[8328]: exiting wrapper cleanly with 0
Dec 21 08:27:40 _prod_production_util_domU-12-31-39-0E-20-91 syslog: Dec 21 13:27:39 localhost monit-sidekiq[8345]: Issuing kill with -INT 23821
Dec 21 08:27:40 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:27:39.957653601] (23824) [DEBUG] Got INT signal
Dec 21 08:27:40 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:27:39.958097032] (23824) [INFO] Shutting down
Dec 21 08:27:40 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:27:39.958962896] (23824) [INFO] Shutting down 2 quiet workers
Dec 21 08:27:40 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:27:39.959812789] (23824) [DEBUG] Clearing workers in redis
Dec 21 08:27:40 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:27:39.962878386] (23824) [INFO] At the top of bulk_requeue
Dec 21 08:27:40 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:27:39.965565125] (23824) [INFO] At the top of bulk_requeue
Dec 21 08:27:40 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:27:39.969348547] (23824) [INFO] At the top of bulk_requeue
Dec 21 08:27:40 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:27:39.979500562] (23824) [INFO] At the top of bulk_requeue
Dec 21 08:27:40 _prod_production_util_domU-12-31-39-0E-20-91 syslog: Dec 21 13:27:39 localhost monit-sidekiq[8345]: exiting wrapper cleanly with 0
Dec 21 08:27:40 _prod_production_util_domU-12-31-39-0E-20-91 syslog: Dec 21 13:27:40 localhost monit[15901]: 'sidekiq__prod_4' start: /engineyard/bin/sidekiq
Dec 21 08:28:34 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:28:34.470902237] (8391) [INFO] Running in ruby 2.0.0p353 (2013-11-22 revision 43784) [x86_64-linux]
Dec 21 08:28:34 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:28:34.470990880] (8391) [INFO] Sidekiq Pro 1.4.0, commercially licensed. Thanks for your support!
Dec 21 08:28:34 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:28:34.471048260] (8391) [INFO] Starting processing, hit Ctrl-C to stop
Dec 21 08:28:34 _prod_production_util_domU-12-31-39-0E-20-91 sidekiq_5.log: /data/_prod/releases/20131221051938/config/routes.rb:1: warning: already initialized constant ID_PATTERN
Dec 21 08:28:34 _prod_production_util_domU-12-31-39-0E-20-91 sidekiq_5.log: /data/_prod/releases/20131221051938/config/routes.rb:1: warning: previous definition of ID_PATTERN was here
Dec 21 08:28:35 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:28:34.916465699] (8391) [DEBUG] {:queues=>["data_process"], :concurrency=>2, :require=>"/data/_prod/current", :environment=>"production", :timeout=>600, :profile=>false, :index=>4, :tag=>"_prod-4", :strict=>true, :config_file=>"/data/_prod/shared/config/sidekiq_4.yml", :notifications=>{}, :backup_limit=>1000, :fetch=>Sidekiq::Pro::ReliableFetch}
Dec 21 08:28:35 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:28:34.987348771] (8391) [INFO] ReliableFetch activated
Dec 21 08:28:35 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:28:35.000635770] (8391) [WARN] ReliableFetch: recovering work on 1 messages
Dec 21 08:28:35 _prod_production_util_domU-12-31-39-0E-20-91 production.log: [ 1:28:35.029231539] (8391) [WARN] Sidekiq processing internal job from queue queue:data_process (queue:data_process_domU-12-31-39-0E-20-91_4): "
```