Login/Register
rufus scheduler running twice each time
Asked Answered
Solved ruby-on-railsherokurufus-scheduler
P

2

0

Maybe it's my task, maybe it's my scheduler, but for some reason my scheduled task is running twice or saving two versions to the DB. Here's my code:

report.rb:

  def record_page_stats!
    oauth = Koala::Facebook::OAuth.new
    @api = Koala::Facebook::API.new oauth.get_app_access_token
    @fb_page = @api.get_object(self.fb_page_id)
    self.page_stats.new(like_count: @fb_page["likes"], talking_about_count: @fb_page["talking_about_count"])
    self.save
  end

AND the scheduler.rb:

require 'rufus-scheduler'

scheduler = Rufus::Scheduler.new

scheduler.every '10m' do
  Report.where(tracking_page: true).each do |report|
    report.record_page_stats!
  end
end

am i missing something really obvious? here's the output from the database of the saved page stats:

2013-12-20 18:43:06 UTC = 8304 likes and 229 talking about count 
2013-12-20 18:43:08 UTC = 8304 likes and 229 talking about count 
2013-12-20 18:53:06 UTC = 8304 likes and 229 talking about count 
2013-12-20 18:53:08 UTC = 8304 likes and 229 talking about count 
2013-12-20 19:03:06 UTC = 8304 likes and 229 talking about count 
2013-12-20 19:03:08 UTC = 8304 likes and 229 talking about count 
2013-12-20 19:13:06 UTC = 8304 likes and 229 talking about count 
2013-12-20 19:13:08 UTC = 8304 likes and 229 talking about count 
2013-12-20 19:23:07 UTC = 8304 likes and 229 talking about count 
2013-12-20 19:23:33 UTC = 8304 likes and 229 talking about count 
2013-12-20 19:33:06 UTC = 8304 likes and 229 talking about count 
2013-12-20 19:33:32 UTC = 8304 likes and 229 talking about count

as you can see by the timestamp, it runs twice every 10 minutes

EDIT:

I just looked at the data again...and the scheduler has changed timing a few times:

  1. first, it ran the job twice in a row, each 10 minutes
  2. then, it switched to once per 10 minutes
  3. then, it switched to once per 5 minutes
  4. then, it switched to twice per 5 minutes

EDIT 2: new output after locking:

2013-12-20 22:14:22 UTC = 176155 likes and 5757 talking about count 
2013-12-20 22:14:24 UTC = 176155 likes and 6994 talking about count

My file now looks like this:

require 'rufus-scheduler'

scheduler = Rufus::Scheduler.new(:lockfile => ".rufus-scheduler.lock")

scheduler.every '10m' do
  Report.where(tracking_page: true).each do |report|
    report.record_page_stats!
  end
  log "started Scheduler #{scheduler.object_id}"
end

however in the heroku logs there's an error:

2013-12-20T22:44:42.625951+00:00 app[worker.1]:   70149016354440   job:
2013-12-20T22:44:42.625951+00:00 app[worker.1]:   70149016354440     Rufus::Scheduler::EveryJob "10m" {}
2013-12-20T22:44:42.625951+00:00 app[worker.1]: { 70149016354440 rufus-scheduler intercepted an error:
2013-12-20T22:44:42.625951+00:00 app[worker.1]:   70149016354440   error:
2013-12-20T22:44:42.625951+00:00 app[worker.1]:   70149016354440     70149016354440
2013-12-20T22:44:42.625951+00:00 app[worker.1]:   70149016354440     ArgumentError
2013-12-20T22:44:42.625951+00:00 app[worker.1]:   70149016354440     wrong number of arguments (1 for 0)
2013-12-20T22:44:42.625951+00:00 app[worker.1]:   70149016354440       /app/vendor/bundle/ruby/2.0.0/gems/yard-0.8.7.3/lib/yard/globals.rb:16:in `log'
2013-12-20T22:44:42.625951+00:00 app[worker.1]:   70149016354440       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:224:in `call'
2013-12-20T22:44:42.626163+00:00 app[worker.1]:   70149016354440       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:224:in `do_trigger'
2013-12-20T22:44:42.626163+00:00 app[worker.1]:   70149016354440       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:269:in `block (3 levels) in start_work_thread'
2013-12-20T22:44:42.626163+00:00 app[worker.1]:   70149016354440       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:272:in `call'
2013-12-20T22:44:42.626163+00:00 app[worker.1]:   70149016354440       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:272:in `block (2 levels) in start_work_thread'
2013-12-20T22:44:42.626163+00:00 app[worker.1]:   70149016354440       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:258:in `loop'
2013-12-20T22:44:42.626163+00:00 app[worker.1]:   70149016354440       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:258:in `block in start_work_thread'
2013-12-20T22:44:42.626163+00:00 app[worker.1]: } 70149016354440 .
2013-12-20T22:44:42.625951+00:00 app[worker.1]:   70149016354440       /app/config/initializers/scheduler.rb:9:in `block in <top (required)>'
2013-12-20T22:44:44.472460+00:00 app[web.1]: { 69970029016200 rufus-scheduler intercepted an error:
2013-12-20T22:44:44.472460+00:00 app[web.1]:   69970029016200   job:
2013-12-20T22:44:44.472460+00:00 app[web.1]:   69970029016200     Rufus::Scheduler::EveryJob "10m" {}
2013-12-20T22:44:44.472615+00:00 app[web.1]:   69970029016200     ArgumentError
2013-12-20T22:44:44.472615+00:00 app[web.1]:   69970029016200     wrong number of arguments (1 for 0)
2013-12-20T22:44:44.472615+00:00 app[web.1]:   69970029016200       /app/vendor/bundle/ruby/2.0.0/gems/yard-0.8.7.3/lib/yard/globals.rb:16:in `log'
2013-12-20T22:44:44.472615+00:00 app[web.1]:   69970029016200       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:224:in `call'
2013-12-20T22:44:44.472615+00:00 app[web.1]:   69970029016200       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:224:in `do_trigger'
2013-12-20T22:44:44.472615+00:00 app[web.1]:   69970029016200       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:269:in `block (3 levels) in start_work_thread'
2013-12-20T22:44:44.472615+00:00 app[web.1]:   69970029016200       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:272:in `call'
2013-12-20T22:44:44.472615+00:00 app[web.1]:   69970029016200       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:272:in `block (2 levels) in start_work_thread'
2013-12-20T22:44:44.472615+00:00 app[web.1]:   69970029016200       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:258:in `loop'
2013-12-20T22:44:44.473000+00:00 app[web.1]:   69970029016200       /app/vendor/bundle/ruby/2.0.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:258:in `block in start_work_thread'
2013-12-20T22:44:44.472460+00:00 app[web.1]:   69970029016200   error:
2013-12-20T22:44:44.472460+00:00 app[web.1]:   69970029016200     69970029016200
2013-12-20T22:44:44.472615+00:00 app[web.1]:   69970029016200       /app/config/initializers/scheduler.rb:9:in `block in <top (required)>'
2013-12-20T22:44:44.473000+00:00 app[web.1]: } 69970029016200 .
Partlet answered 20/12, 2013 at 19:39 Comment(3)
If you read my answer, I say "something like 'log "xyz"'". I do not say "type exactly this". If you had taken the time to read the error instead of directly pasting it here (like you pasted my suggestion directly into your code without thinking) you'd had perhaps learnt something. Do you want me to google for the right way to log from a Rails application running on Heroku and then explain it to you? I assumed you knew how to log since your initial issue report featured some log output... -1 – Lacylad
And you're putting the "started scheduler" message inside of the scheduled job instead of right after the scheduler initialization, do you realize you'll have to wait 10 minutes to determine how many schedulers are operating? And you waited 10 minutes to see those errors and didn't even realize that copy-pasting is not always a good idea? grrrr.... – Lacylad
One positive thing: the log you pasted shows that two processes are running "worker.1" and "web.1". Your two schedulers. Nothing wrong with rufus-scheduler. – Lacylad
L
0

So, according to the tags you placed on your question, you're using Ruby on Rails.

I have the impression you have two schedulers running (one was initialized 2 seconds after the first one, as hinted by the log output).

You can easily place something like

log "started Scheduler #{scheduler.object_id}"

after the scheduler initialization to see what's going on.

You don't mention what you run Rails on top of (Webrick, Passenger, Thin, Unicorn, ...?). Some of those run multiple copies of the Rails process.

You could use the locking system in rufus-scheduler to prevent a second (or a third...) scheduler from starting.

For a simple locking mecha: https://github.com/jmettraux/rufus-scheduler/#lockfile--mylockfiletxt

If you need more (running multiple Rails on different hosts maybe): https://github.com/jmettraux/rufus-scheduler/#advanced-lock-schemes

The variations you see in your EDIT are probably tied to the server forking new Rails copies to cope with demand.

Lacylad answered 20/12, 2013 at 21:53 Comment(5)
I tried the locking and it doesn't seem to work. It still records two records and now the records have different values! See new edit. The second values should be the same since they are being recorded seconds apart. – Partlet
And we still don't know what you're running that on top of. – Lacylad
I'm not sure what you mean by running that on top of...i'm running it on heroku..sorry if this is a simple question. Also, how do I tell how many schedulers are running? Lastly, I just looked in the heroku directory and the file that is suppose to get created from the lock command isn't there. – Partlet
You should have mentioned you're running on Heroku. How could we have guessed? I wrote in my answer something about logging the scheduler object id, do it now and if you see multiple scheduler ids coming up, then you have multiple schedulers running. I've taken the time to write an answer, please read it. – Lacylad
Sorry about that. I added it and am waiting for results. – Partlet
L
0

So you're on Heroku.

This might help: https://devcenter.heroku.com/articles/clock-processes-ruby

If you google a bit more or search the heroku documentation you'll find other places where they explain how to run special processes, apart from the Rails process, for things like scheduler and background workers.

This might help too: https://devcenter.heroku.com/articles/procfile

Lacylad answered 20/12, 2013 at 22:35 Comment(0)

© 2022 - 2024 — McMap. All rights reserved.