resque: [BUG] RESQUE_PRE_SHUTDOWN_TIMEOUT not working at all on Heroku

Hi,

I’m coming back again about the RESQUE_PRE_SHUTDOWN_TIMEOUT env variable, it’s not working at all after doing some tests on a staging environment.

Here is the configuration I’ve made:

#Procfile
one_worker_and_scheduler: WORKER_COUNT=1 bin/start-stunnel bin/worker_and_scheduler

#bin/worker_and_scheduler
#!/bin/bash
(bundle exec rake resque:scheduler) & (env COUNT=$WORKER_COUNT QUEUE=* bundle exec rake resque:workers)

# Heroku environment variables: 
RESQUE_PRE_SHUTDOWN_TIMEOUT=6
RESQUE_TERM_TIMEOUT=6
TERM_CHILD=1

#jobs/test_job.rb
class TestJob
  @queue = :system_events

  def self.perform
    count = 1
    loop do
      puts "TESTJOB: #{count}"
      sleep(1)
      count += 1
    end
  end
end

# In rails console on staging: 
Resque.enqueue TestJob
#=> true 

#another terminal tab, logs on this specific dyno are showing:
# heroku logs --remote staging -t --dyno one_worker_and_scheduler
2017-04-12T14:55:40.973899+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 1
2017-04-12T14:55:41.974026+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 2
2017-04-12T14:55:42.974199+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 3
2017-04-12T14:55:43.974346+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 4
2017-04-12T14:55:44.974519+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 5
2017-04-12T14:55:45.974694+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 6
2017-04-12T14:55:46.974857+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 7
2017-04-12T14:55:47.975032+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 8
2017-04-12T14:55:48.975194+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 9

Then I do this in another terminal tab: heroku restart --remote staging

And in my worker logs, I can see this:

2017-04-12T14:55:49.975723+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 10
2017-04-12T14:55:50.724713+00:00 heroku[one_worker_and_scheduler.1]: Restarting
2017-04-12T14:55:50.725252+00:00 heroku[one_worker_and_scheduler.1]: State changed from up to starting
2017-04-12T14:55:50.975897+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 11
2017-04-12T14:55:51.282979+00:00 heroku[one_worker_and_scheduler.1]: Stopping all processes with SIGTERM
2017-04-12T14:55:51.290502+00:00 app[one_worker_and_scheduler.1]: buildpack=stunnel at=app-end
2017-04-12T14:55:51.290636+00:00 app[one_worker_and_scheduler.1]: buildpack=stunnel at=exit process=app
2017-04-12T14:55:51.290678+00:00 app[one_worker_and_scheduler.1]: rake aborted!
2017-04-12T14:55:51.290772+00:00 app[one_worker_and_scheduler.1]: SignalException: SIGTERM
2017-04-12T14:55:51.291114+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/resque-1.27.3/lib/resque/tasks.rb:37:in `join'
2017-04-12T14:55:51.291117+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/resque-1.27.3/lib/resque/tasks.rb:37:in `block (3 levels) in <top (required)>'
2017-04-12T14:55:51.291118+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/resque-1.27.3/lib/resque/tasks.rb:37:in `each'
2017-04-12T14:55:51.291118+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/resque-1.27.3/lib/resque/tasks.rb:37:in `block (2 levels) in <top (required)>'
2017-04-12T14:55:51.291119+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/lib/bundler/cli/exec.rb:74:in `load'
2017-04-12T14:55:51.291120+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/lib/bundler/cli/exec.rb:74:in `kernel_load'
2017-04-12T14:55:51.291120+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/lib/bundler/cli/exec.rb:27:in `run'
2017-04-12T14:55:51.291121+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/lib/bundler/cli.rb:332:in `exec'
2017-04-12T14:55:51.291122+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
2017-04-12T14:55:51.291122+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
2017-04-12T14:55:51.291123+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/lib/bundler/vendor/thor/lib/thor.rb:359:in `dispatch'
2017-04-12T14:55:51.291123+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/lib/bundler/cli.rb:20:in `dispatch'
2017-04-12T14:55:51.291124+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/lib/bundler/vendor/thor/lib/thor/base.rb:440:in `start'
2017-04-12T14:55:51.291125+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/lib/bundler/cli.rb:11:in `start'
2017-04-12T14:55:51.291125+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/exe/bundle:34:in `block in <top (required)>'
2017-04-12T14:55:51.291126+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/lib/bundler/friendly_errors.rb:100:in `with_friendly_errors'
2017-04-12T14:55:51.291126+00:00 app[one_worker_and_scheduler.1]: /app/vendor/bundle/ruby/2.3.0/gems/bundler-1.13.7/exe/bundle:26:in `<top (required)>'
2017-04-12T14:55:51.291127+00:00 app[one_worker_and_scheduler.1]: /app/bin/bundle:3:in `load'
2017-04-12T14:55:51.291127+00:00 app[one_worker_and_scheduler.1]: /app/bin/bundle:3:in `<main>'
2017-04-12T14:55:51.291131+00:00 app[one_worker_and_scheduler.1]: Tasks: TOP => resque:workers
2017-04-12T14:55:51.291172+00:00 app[one_worker_and_scheduler.1]: (See full trace by running task with --trace)
2017-04-12T14:55:51.291776+00:00 app[one_worker_and_scheduler.1]: buildpack=stunnel at=kill-app pid=20
2017-04-12T14:55:51.292117+00:00 app[one_worker_and_scheduler.1]: bin/start-stunnel: line 49: kill: (-20) - No such process
2017-04-12T14:55:51.292195+00:00 app[one_worker_and_scheduler.1]: buildpack=stunnel at=wait-app pid=20
2017-04-12T14:55:51.292314+00:00 app[one_worker_and_scheduler.1]: buildpack=stunnel at=kill-aux name=stunnel pid=19 signal=SIGINT
2017-04-12T14:55:51.292859+00:00 app[one_worker_and_scheduler.1]: buildpack=stunnel at=stunnel-end
2017-04-12T14:55:51.381566+00:00 heroku[one_worker_and_scheduler.1]: Process exited with status 0
2017-04-12T14:56:00.901580+00:00 heroku[one_worker_and_scheduler.1]: Starting process with command `WORKER_COUNT=1 bin/start-stunnel bin/worker_and_schedule

As you can see, there is no delay between

2017-04-12T14:55:50.725252+00:00 heroku[one_worker_and_scheduler.1]: State changed from up to starting
2017-04-12T14:55:50.975897+00:00 app[one_worker_and_scheduler.1]: TESTJOB: 11
2017-04-12T14:55:51.282979+00:00 heroku[one_worker_and_scheduler.1]: Stopping all processes with SIGTERM

and the job actually being killed completly.

When I read this: https://github.com/resque/resque#signals-on-heroku It seems that the delay should always be < 10 seconds (The time Heroku send a SIGKILL).

Am I doing something wrong or it does not work? Happy to give more information, as it’s quite critical for a bunch of people out there I believe.

Thank you!