rufus scheduler running twice each time

Question

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 .

Answer 1

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.

Answer 2

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