Jobs processed during shutdown not appearing in stats

[ouranos]

Ruby version: ruby-2.5.1
Sidekiq version: 6.0.5

Hi,
To test deployment and graceful restart of Sidekiq workers, I've created a dummy jobs that just sleeps and output to stdout:

class SleepyWorker < BaseWorker
  SLEEP = 30

  def perform steps = 10
    steps.times do |i|
      puts "Sleeping for #{SLEEP}s (#{i}/#{steps})"
      sleep SLEEP
    end
    puts "I'm done"
  end
end

My initializer is pretty standard:

redis_config = { url: ENV['REDIS_SIDEKIQ_URL'] }

# Use redis authentication if available
redis_config[:password] = ENV['REDIS_SIDEKIQ_PASSWORD'] if ENV['REDIS_SIDEKIQ_PASSWORD'].present?

Sidekiq.configure_server do |config|
  config.redis = redis_config
end

Sidekiq.configure_client do |config|
  config.redis = redis_config
end

I've increased the shutdown timeout to 8 minutes in config/sidekiq.yml:

:timeout: 480 # 8m, default is 25s

I'm stopping Sidekiq with the TERM signal after having enqueued a 5min sleeping job, I'm expecting:

• Sidekiq to stop accepting new jobs -> worker shows as quiet in the UI ✅
• Sidekiq to wait for the job to be done before shutting down ✅
• The numbers of processed jobs to be increased by 1 => Busy is at 1 while processing but Processed is not increased ❌

Am I missing something?

[mperham]

The job is not done so it is not considered processed yet. Right?

…

On Mar 18, 2020, at 17:24, Olivier Brisse ***@***.***> wrote:  Ruby version: ruby-2.5.1 Sidekiq version: 6.0.5 Hi, To test deployment and graceful restart of Sidekiq workers, I've created a dummy jobs that just sleeps and output to stdout: class SleepyWorker < BaseWorker SLEEP = 30 def perform steps = 10 steps.times do |i| puts "Sleeping for #{SLEEP}s (#{i}/#{steps})" sleep SLEEP end puts "I'm done" end end My initializer is pretty standard: redis_config = { url: ENV['REDIS_SIDEKIQ_URL'] } # Use redis authentication if available redis_config[:password] = ENV['REDIS_SIDEKIQ_PASSWORD'] if ENV['REDIS_SIDEKIQ_PASSWORD'].present? Sidekiq.configure_server do |config| config.redis = redis_config end Sidekiq.configure_client do |config| config.redis = redis_config end I've increased the shutdown timeout to 8 minutes in config/sidekiq.yml: :timeout: 480 # 8m, default is 25s I'm stopping Sidekiq with the TERM signal after having enqueued a 5min sleeping job, I'm expecting: Sidekiq to stop accepting new jobs -> worker shows as quiet in the UI ✅ Sidekiq to wait for the job to be done before shutting down ✅ The numbers of processed jobs to be increased by 1 => Busy is at 1 while processing but Processed is not increased ❌ Am I missing something? — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub, or unsubscribe.

[ouranos]

It's actually finishing processing as it takes shorter than the 8 minutes timeout (and my actual job updates a dummy record in the db at the end which is correctly updated)
So processing is fine, it's more an issue with the stats reporting I think.

[mperham]

Did you refresh the Web page? You’re right, I’d expect that to work. A terminating process still reports its stats every five seconds.

…

On Mar 18, 2020, at 17:30, Olivier Brisse ***@***.***> wrote:  It's actually finishing processing as it takes shorter than the 8 minutes timeout (and my actual job update a record in the db at the end which is correctly updated) So processing is fine, it's more an issue with the stats reporting I think. — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or unsubscribe.

[ouranos]

Yes, I've tested multiple times as I thought it was an issue with my restart process first.

The logs are:

2020-03-19 00:17:22,005 DEBG 'sidekiq_worker' stdout output:
2020-03-19T00:17:22.005Z pid=43 tid=go8g0fhej INFO: Pausing to allow workers to finish...
...
2020-03-19 00:17:50,057 INFO waiting for sidekiq_worker to stop
2020-03-19 00:17:50,551 DEBG 'sidekiq_worker' stdout output:
Sleeping for 30s (2/8)

2020-03-19 00:17:52,555 INFO waiting for sidekiq_worker to stop
...
2020-03-19 00:20:49,594 INFO waiting for sidekiq_worker to stop
2020-03-19 00:20:50,638 DEBG 'sidekiq_worker' stdout output:
I'm done

2020-03-19 00:20:50,640 DEBG 'sidekiq_worker' stdout output:
2020-03-19T00:20:50.640Z pid=43 tid=go8hq5gbz class=SleepyWorker jid=4a287d658719e9b46c83f317 elapsed=240.145 INFO: done

2020-03-19 00:20:51,092 DEBG 'sidekiq_worker' stdout output:
2020-03-19T00:20:51.092Z pid=43 tid=go8g0fhej INFO: Bye!

Could it be that the process exit as soon as the job is done without reporting its stats first?

[mperham]

That sounds right. I need to add an at_exit.

…

On Mar 18, 2020, at 17:52, Olivier Brisse ***@***.***> wrote:  Yes, I've tested multiple times as I thought it was an issue with my restart process first. The logs are: 2020-03-19 00:17:22,005 DEBG 'sidekiq_worker' stdout output: 2020-03-19T00:17:22.005Z pid=43 tid=go8g0fhej INFO: Pausing to allow workers to finish... ... 2020-03-19 00:17:50,057 INFO waiting for sidekiq_worker to stop 2020-03-19 00:17:50,551 DEBG 'sidekiq_worker' stdout output: Sleeping for 30s (2/8) 2020-03-19 00:17:52,555 INFO waiting for sidekiq_worker to stop ... 2020-03-19 00:20:49,594 INFO waiting for sidekiq_worker to stop 2020-03-19 00:20:50,638 DEBG 'sidekiq_worker' stdout output: I'm done 2020-03-19 00:20:50,640 DEBG 'sidekiq_worker' stdout output: 2020-03-19T00:20:50.640Z pid=43 tid=go8hq5gbz class=SleepyWorker jid=4a287d658719e9b46c83f317 elapsed=240.145 INFO: done 2020-03-19 00:20:51,092 DEBG 'sidekiq_worker' stdout output: 2020-03-19T00:20:51.092Z pid=43 tid=go8g0fhej INFO: Bye! Could it be that the process exit as soon as the job is done without reporting its stats first? — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or unsubscribe.