jmettraux/rufus-scheduler

Scheduling a shutdown

itsaphel opened this issue · 9 comments

itsaphel commented

Hey.

So I have a main thread that creates a new thread with my Rufus scheduler code. In this new thread, I create a schedule, schedule a cron job, schedule a shutdown, and then join the scheduler. When I shutdown, I want all currently running tasks to first finish (but not currently running ones not to start). If I understand correctly, this is done using .schedule(:wait).

Something like this:

def run
    scheduler = Rufus::Scheduler.new

    scheduler.cron "* * * * *" do |job|
        sleep 65
        puts "Done!"
    end

    scheduler.in "2m" do
        puts "#{Time.now} Shutdown initiated"
        scheduler.shutdown(:wait)
        puts "#{Time.now} Scheduler stopped"
      end

    scheduler.join
end

So basically, with this I'd expect to see two "Done!"s, with the second job starting before the shutdown starts (and currently running at the time of shutdown), so the shutdown waiting for that job to be finished. Example output may be:

2020-11-01 20:00:05 +0000 Done!
2020-11-01 20:00:34 +0000 Shutdown initiated
2020-11-01 20:01:05 +0000 Done!
2020-11-01 20:01:05 +0000 Scheduler stopped

Instead I get either an error (saying that I cannot do :wait on the same thread), or it just doesn't do anything and shuts down as if :wait wasn't there (when I comment out the sleep 65 I get an error, when I leave it in it just stops as if :wait wasn't there). When I get the error, it is:

  2500     Rufus::Scheduler::InJob "2m" {:no_error=>true, :_t=>120}
  2500   error:
  2500     2500
  2500     ThreadError
  2500     Target thread must not be current thread

[...]

  2500       work_threads: 1
  2500         active: 1
  2500         vacant: 0
  2500         max_work_threads: 28
  2500       mutexes: {}
  2500     jobs: 0
  2500       at_jobs: 0
  2500       in_jobs: 0
  2500       every_jobs: 0
  2500       interval_jobs: 0
  2500       cron_jobs: 0
  2500     running_jobs: 1
  2500     work_queue: 1

Any idea how I can achieve what I'm trying to do here?

jmettraux commented

More details about the error:

{ 1474578217680 rufus-scheduler intercepted an error:
  1474578217680   job:
  1474578217680     Rufus::Scheduler::InJob "2m" {:no_error=>true, :_t=>120}
  1474578217680   error:
  1474578217680     1474578217680
  1474578217680     ThreadError
  1474578217680     Target thread must not be current thread
  1474578217680       /home/jmettraux/.gem/ruby/2.6.6/gems/rufus-scheduler-3.6.0/lib/rufus/scheduler.rb:525:in `join'
  1474578217680       /home/jmettraux/.gem/ruby/2.6.6/gems/rufus-scheduler-3.6.0/lib/rufus/scheduler.rb:525:in `block in join_all_work_threads'
  1474578217680       /home/jmettraux/.gem/ruby/2.6.6/gems/rufus-scheduler-3.6.0/lib/rufus/scheduler.rb:525:in `each'
  1474578217680       /home/jmettraux/.gem/ruby/2.6.6/gems/rufus-scheduler-3.6.0/lib/rufus/scheduler.rb:525:in `join_all_work_threads'
  1474578217680       /home/jmettraux/.gem/ruby/2.6.6/gems/rufus-scheduler-3.6.0/lib/rufus/scheduler.rb:127:in `shutdown'
  1474578217680       variant1.rb:16:in `block in run'
  1474578217680       /home/jmettraux/.gem/ruby/2.6.6/gems/rufus-scheduler-3.6.0/lib/rufus/scheduler/jobs.rb:223:in
`do_call'
  1474578217680       /home/jmettraux/.gem/ruby/2.6.6/gems/rufus-scheduler-3.6.0/lib/rufus/scheduler/jobs.rb:267:in
`trigger_now'
  1474578217680       /home/jmettraux/.gem/ruby/2.6.6/gems/rufus-scheduler-3.6.0/lib/rufus/scheduler/jobs.rb:312:in
`block (3 levels) in start_work_thread'
  1474578217680       /home/jmettraux/.gem/ruby/2.6.6/gems/rufus-scheduler-3.6.0/lib/rufus/scheduler/jobs.rb:315:in
`block (2 levels) in start_work_thread'
  1474578217680       /home/jmettraux/.gem/ruby/2.6.6/gems/rufus-scheduler-3.6.0/lib/rufus/scheduler/jobs.rb:301:in
`loop'
  1474578217680       /home/jmettraux/.gem/ruby/2.6.6/gems/rufus-scheduler-3.6.0/lib/rufus/scheduler/jobs.rb:301:in
`block in start_work_thread'
jmettraux commented

Hello,

I think I have it fixed. I will release a new version of the gem as soon as possible. Feel free to try the fix and tell me here if there are still problems.

One comment, I think you don't need a separate thread for just launching the scheduler, the scheduler already has its own thread. You simply have to instantiate the scheduler from your main thread and schedule. Those calls return immediately and you're free to do your main thing in your main thread.

Best regards and thanks for pointing at this issue.

itsaphel commented

@jmettraux Hey! Thanks, this fixes the error, but still doesn't achieve what I was trying to in my initial post.

The output now is:

2020-11-02 12:52:06 +0000 Done! Next run starts: 2020-11-02 12:53:00 +0000
2020-11-02 12:52:42 +0000 Shutdown initiated
2020-11-02 12:52:42 +0000 Scheduler stopped

Whereas there should be an extra "Done!" after the shutdown is initiated (reason being: two of those jobs will be initiated to start before the shutdown in 2 minutes actually starts. I would like the started job to complete before shutdown).

itsaphel commented

I tried being creative and adding the shutdown schedule into a shutdown_scheduler which shuts down the main scheduler, then joining both schedulers.

This worked a little better (it actually waits for the task to finish, it seems), but upon shutdown it also seems to run the task again, so the task runs 3 times instead of 2 (expected). Strange, because in the above example it runs only 1 time (instead of 2). Take this result with a grain of salt, though, I may be doing something weird.

jmettraux commented

Hello,

OpenBSD yawara 6.8 GENERIC.MP#0 amd64
ruby 2.6.6p146 (2020-03-31 revision 67876) [x86_64-openbsd6.7]

Gems included by the bundle:
  * concurrent-ruby (1.1.7)
  * et-orbi (1.2.4)
  * fugit (1.4.0)
  * raabro (1.4.0)
  * rufus-scheduler (3.7.0)
  * tzinfo (2.0.2)

require 'rufus-scheduler'

$stdout.sync = true

scheduler = Rufus::Scheduler.new

scheduler.cron '* * * * *' do |job|
  c = job.count
  puts "#{Time.now} #{job.id} starting... #{c}"
  sleep 65
  puts "#{Time.now} #{job.id} done. #{c}"
end

scheduler.in '2m' do |job|
  puts "#{Time.now} Shutdown initiated (#{job.id})"
  scheduler.shutdown(:wait)
  puts "#{Time.now} Scheduler stopped (#{job.id})"
end

puts "#{Time.now} joining..."
scheduler.join
puts "#{Time.now} over."

#$stdout.flush

is giving me

2020-11-02 23:47:15 +0900 joining...
2020-11-02 23:48:00 +0900 cron_1604328435.977129_232882975720 starting... 1
2020-11-02 23:49:00 +0900 cron_1604328435.977129_232882975720 starting... 2
2020-11-02 23:49:05 +0900 cron_1604328435.977129_232882975720 done. 1
2020-11-02 23:49:05 +0900 cron_1604328435.977129_232882975720 starting... 3
2020-11-02 23:49:16 +0900 Shutdown initiated (in_1604328435.9790182_0.0_231526836820)
2020-11-02 23:49:16 +0900 over.

It's quite similar to what you are reporting. I will investigate further tomorrow morning.

jmettraux commented

Hello @itsaphel,

I've just pushed changes to `Scheduler#shutdown'. I think it's right now. If you could give it a try, that'd be much appreciated.

OpenBSD yawara 6.8 GENERIC.MP#1 amd64
ruby 2.6.6p146 (2020-03-31 revision 67876) [x86_64-openbsd6.7]

require 'rufus-scheduler'

$stdout.sync = true

def now; Time.now.strftime('%F %T.%L'); end

scheduler = Rufus::Scheduler.new

scheduler.cron '* * * * *' do |job|
  c = job.count
  puts "#{now} #{job.id} starting... #{c}"# #{Thread.current}"
  sleep 65
  puts "#{now} #{job.id} done. #{c}"# #{Thread.current}"
end

scheduler.in '2m' do |job|
  puts "#{now} Shutdown initiated (#{job.id})"# #{Thread.current}"
  scheduler.shutdown(:wait)
  puts "#{now} Scheduler stopped (#{job.id})"# #{Thread.current}"
end

puts "#{now} joining..."
puts
scheduler.join
puts "#{now} over."
puts
2020-11-05 14:43:34.790 joining...

2020-11-05 14:44:00.207 cron_1604555014.7889805_1309232740140 starting... 1
2020-11-05 14:45:00.047 cron_1604555014.7889805_1309232740140 starting... 2
2020-11-05 14:45:05.215 cron_1604555014.7889805_1309232740140 done. 1
2020-11-05 14:45:05.317 cron_1604555014.7889805_1309232740140 starting... 3
2020-11-05 14:45:35.087 Shutdown initiated (in_1604555014.790724_0.0_1309924421900)
2020-11-05 14:46:05.056 cron_1604555014.7889805_1309232740140 done. 2
2020-11-05 14:46:10.334 cron_1604555014.7889805_1309232740140 done. 3
2020-11-05 14:46:10.426 Scheduler stopped (in_1604555014.790724_0.0_1309924421900)
2020-11-05 14:46:10.426 over.
itsaphel commented

Will try test again.

Question, in your output log why is a cron 3 starting? FWIW, I was getting this in my earlier tests as well when I used a separate scheduler to schedule the shutdown (hence avoiding the error); I was a bit puzzled by it:

The cron should start at 14:44:00, 14:45:00, 14:46:00, etc, right? Cron 1 and 2 start as normal, but cron 3 is started 5 seconds after 2 is started (at 14:45:05).

Other than that, your log looks okay to me, but I'd have imagined there should be only two cron jobs starting (one at 14:44:00, two at 14:45:00, then shutdown initiated at 14:45:35 so the cron 3 scheduled for 14:46:00 never starts).

jmettraux commented

The cron should start at 14:44:00, 14:45:00, 14:46:00, etc, right? Cron 1 and 2 start as normal, but cron 3 is started 5 seconds after 2 is started (at 14:45:05).

Yes, you are right. I will fix that now.

jmettraux commented 
2020-11-07 08:20:53.105 joining...
2020-11-07 08:21:00.243 cron_1604704853.103283_1569905716380 starting... 1
2020-11-07 08:22:00.114 cron_1604704853.103283_1569905716380 starting... 2
2020-11-07 08:22:05.252 cron_1604704853.103283_1569905716380 done. 1
2020-11-07 08:22:53.203 Shutdown initiated (in_1604704853.1050184_0.0_1570668441160)
2020-11-07 08:23:05.122 cron_1604704853.103283_1569905716380 done. 2
2020-11-07 08:23:05.293 Scheduler stopped (in_1604704853.1050184_0.0_1570668441160)
2020-11-07 08:23:05.293 over.

I think I nailed that second problem. Please tell me if you have anything else.

Thanks a lot!