The job gets scheduled two times.

[ypadlyak]

The job gets scheduled two times. The first time a few seconds before the time.

Jun 20 08:59:44 ip-10-0-3-198 sidekiq.log: 2016-06-20T05:59:44.109Z 12758 TID-ouu97i214 Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: start
Jun 20 08:59:49 ip-10-0-3-198 sidekiq.log: 2016-06-20T05:59:49.681Z 12758 TID-ouu97i214 Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: Scheduling Schedulable::Reports::DailyOrganizersWorker for 2016-06-20 06:00
Jun 20 08:59:49 ip-10-0-3-198 sidekiq.log: 2016-06-20T05:59:49.684Z 12758 TID-ouu97i214 Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: done: 5.575 sec
Jun 20 09:00:22 ip-10-0-3-198 sidekiq.log: 2016-06-20T06:00:22.767Z 12758 TID-ouu97i214 Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: start
Jun 20 09:00:28 ip-10-0-3-198 sidekiq.log: 2016-06-20T06:00:27.937Z 12758 TID-ouu97i214 Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: Scheduling Schedulable::Reports::DailyOrganizersWorker for 2016-06-21 06:00
Jun 20 09:00:28 ip-10-0-3-198 sidekiq.log: 2016-06-20T06:00:27.939Z 12758 TID-ouu97i214 Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: done: 5.172 sec
Jun 21 08:59:53 ip-10-0-3-198 sidekiq.log: 2016-06-21T05:59:52.970Z 12758 TID-ouu23dphg Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: start
Jun 21 08:59:59 ip-10-0-3-198 sidekiq.log: 2016-06-21T05:59:59.144Z 12758 TID-ouu23dphg Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: Scheduling Schedulable::Reports::DailyOrganizersWorker for 2016-06-21 06:00
Jun 21 08:59:59 ip-10-0-3-198 sidekiq.log: 2016-06-21T05:59:59.146Z 12758 TID-ouu23dphg Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: done: 6.177 sec
Jun 21 09:00:03 ip-10-0-3-198 sidekiq.log: 2016-06-21T06:00:03.452Z 12758 TID-149g1o Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: start
Jun 21 09:00:09 ip-10-0-3-198 sidekiq.log: 2016-06-21T06:00:09.703Z 12758 TID-149g1o Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: Scheduling Schedulable::Reports::DailyOrganizersWorker for 2016-06-22 06:00
Jun 21 09:00:09 ip-10-0-3-198 sidekiq.log: 2016-06-21T06:00:09.706Z 12758 TID-149g1o Schedulable::Reports::DailyOrganizersWorker JID-5579f811c533cdaa06509954 INFO: done: 6.254 sec

[felixbuenemann]

Do you run multiple Sidekiq worker processes? Dejavu currently doesn't take a distributed Redis lock when scheduling the first run, which could lead to race conditions.

Does the problem go away when you restart one of the Sidekiq workers?

It would also be helpful if you could post the schedule yaml from your Sidekiq config.

[ypadlyak]

Yes, we run Sidekiq at two servers. But at the time of the log, above there are no messages at the other server.

We do restart it quite often, when we deploy, usually about daily. Both at the same time.
I've just restarted just one and will get back with the result tomorrow.

The configs are the same at two server:
:verbose: false
:concurrency: 2
:queues:

• [default, 7]
• [carrierwave, 5]
• [mailer, 3]
• [zoho, 8]
  :schedule:
  daily_organizer_report: &default_schedule
  interval: '0 6 * * *' # every day at 6:00
  class: Schedulable::Reports::DailyOrganizersWorker
  queue: default
  retry: true # Used to be false
  backtrace: false

[felixbuenemann]

Oh, I think I see the error now. Because the scheduled job ran shortly before its scheduled time, it was rescheduled for the same time again instead of rescheduling for the next run on the next day. That definitely shouldn't happen…

This might have to do with how exact the scheduling in Sidekiq itself is. I'll have to investigate some more.

[ypadlyak]

Yes, that also caught my attention

[felixbuenemann]

I looked at the scheduling code in Sidekiq and under normal circumstances, scheduling should never happen before the given time.

@ypadlyak Could it be that your two workers are running on different servers and are not correctly synced to NTP? That way it could happen, that it's already 6 o'clock on worker 1, which pops the job off the schedule and pushes it onto the work queue. Worker 2 could grab this job and would still have it's time at slightly before 6 o'clock after finishing the job, so it would get rescheduled at the last interval, which has already passed on worker 1, but has not yet passed on worker 2.

If I look at the log, it seems the Schedulable::Reports::DailyOrganizersWorker was started around 8 seconds early, while under normal circumstances scheduling should be up to [number of workers] * 15 seconds (or Sidekiq.options[:average_scheduled_poll_interval]) late, but never too early.

@mperham Please correct me, if the above observation is wrong.

[ypadlyak]

@felixbuenemann There is NTP setup. I've checked now, and they are almost in sync (subsecond difference).

[felixbuenemann]

That's strange. What versions of the sidekiq and sidekiq-dejavu gems are you using?

[ypadlyak]

sidekiq (4.1.2)
sidekiq-dejavu (0.0.3)