Scheduling a ScheduledJob hourly runs a few seconds early and reschedules thus running twice

[danwallacenz]

Scheduling a synchronous job to run hourly runs a few seconds early then reschedules to run at the correct time a few seconds later - thus running twice. Occasionally it will run early more than once (see 08:01:57).

I have worked around this by not running the job if it is running or if it has run within the last minute.

Steps to reproduce

    // queue job to fetch currency rates at two minutes past each hour
    try app.queues.use(.redis(url: "redis://127.0.0.1:6379"))
    app.queues.schedule(fetcher)
        .hourly()
        .at(2)
    try app.queues.startScheduledJobs()

Expected behavior

ScheduledJob should run exactly once on the specified schedule.

Actual behavior

ScheduledJob runs early. For example, if the job is scheduled to run at two minutes past each hour (11:02:00), then it will run at (say) 11.01.57 then reschedule to run at the correct time of 11:02:00 thus running twice.

[ INFO ] 2020-07-31 01:57:58 +0000 Initializing rates (App/CurrencyRatesFetcher.swift:22)
[ INFO ] 2020-07-31 01:57:58 +0000 Try to load rates from file (App/CurrencyRatesFetcher.swift:26)
[ INFO ] 2020-07-31 01:57:58 +0000 Attempting to load cached rates from file file:///app/data/rates... (App/CurrencyRatesStorage.swift:48)
[ INFO ] 2020-07-31 01:57:58 +0000 Loading cached rates from file file:///app/data/rates... (App/CurrencyRatesStorage.swift:55)
[ INFO ] 2020-07-31 01:57:58 +0000 Cached rates: [{
"rates" : {
"BTC" : 8.9993039e-05,
"EGP" : 15.9703,
"MDL" : 16.576971,
"BRL" : 5.1554,
"QAR" : 3.641,
"MWK" : 740.341469,
...
"SGD" : 1.371368,
"YER" : 250.349961,
"FKP" : 0.762474
},
"base" : "USD",
"fetchedAt" : 1596153718.0983748,
"timestamp" : 1596153600
}] (App/CurrencyRatesStorage.swift:57)
[ DEBUG ] Factory created. [RedisConnectionFactory: 8387CBC7-9040-4427-8890-6D06D8C46934] (RedisKit/RedisConnectionSource.swift:20)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 02:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ NOTICE ] Server starting on http://0.0.0.0:8080 (Vapor/HTTP/Server/HTTPServer.swift:183)
[ INFO ] 2020-07-31 02:01:59 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 02:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ ERROR ] CurrencyRatesFetcher failed: inProgress (Queues/QueuesCommand.swift:139)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 03:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 02:02:02 +0000 Fetched 171 currencies at July 31, 2020 at 2:02:02 AM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 02:02:02 +0000 Currency rates up to date at July 31, 2020 at 2:00:00 AM UTC) (App/CurrencyRatesFetcher.swift:50)
[ INFO ] 2020-07-31 02:02:02 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:57)
[ INFO ] 2020-07-31 03:01:59 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 03:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ ERROR ] CurrencyRatesFetcher failed: inProgress (Queues/QueuesCommand.swift:139)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 04:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 03:02:00 +0000 Fetched 171 currencies at July 31, 2020 at 3:02:00 AM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 03:02:00 +0000 Currency rates up to date at July 31, 2020 at 3:00:00 AM UTC) (App/CurrencyRatesFetcher.swift:50)
[ INFO ] 2020-07-31 03:02:00 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:57)
[ INFO ] 2020-07-31 04:01:57 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 04:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 04:01:58 +0000 Fetched 171 currencies at July 31, 2020 at 4:01:58 AM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 04:01:58 +0000 Currency rates up to date at July 31, 2020 at 4:00:00 AM UTC) (App/CurrencyRatesFetcher.swift:50)
[ INFO ] 2020-07-31 04:01:58 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:57)
[ DEBUG ] 2020-07-31 04:02:00 +0000 Skipping fetch. Last fetched at 2020-07-31 04:01:58 +0000 (App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 05:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 05:01:57 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 05:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 05:01:57 +0000 Fetched 171 currencies at July 31, 2020 at 5:01:57 AM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 05:01:57 +0000 Currency rates up to date at July 31, 2020 at 5:00:00 AM UTC) (App/CurrencyRatesFetcher.swift:50)
[ INFO ] 2020-07-31 05:01:57 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:57)
[ DEBUG ] 2020-07-31 05:02:00 +0000 Skipping fetch. Last fetched at 2020-07-31 05:01:57 +0000(App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 06:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 06:01:57 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 06:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 06:01:58 +0000 Fetched 171 currencies at July 31, 2020 at 6:01:58 AM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 06:01:58 +0000 Currency rates up to date at July 31, 2020 at 6:00:00 AM UTC) (App/CurrencyRatesFetcher.swift:50)
[ INFO ] 2020-07-31 06:01:58 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:57)
[ DEBUG ] 2020-07-31 06:02:00 +0000 Skipping fetch. Last fetched at 2020-07-31 06:01:58 +0000 (App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 07:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 07:01:57 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 07:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 07:01:58 +0000 Fetched 171 currencies at July 31, 2020 at 7:01:58 AM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 07:01:58 +0000 Currency rates up to date at July 31, 2020 at 7:00:00 AM UTC) (App/CurrencyRatesFetcher.swift:50)
[ INFO ] 2020-07-31 07:01:58 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:57)
[ DEBUG ] 2020-07-31 07:02:00 +0000 Skipping fetch. Last fetched at 2020-07-31 07:01:58 +0000 (App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 08:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 08:01:57 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 08:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 08:01:58 +0000 Fetched 171 currencies at July 31, 2020 at 8:01:58 AM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 08:01:58 +0000 Currency rates up to date at July 31, 2020 at 8:00:00 AM UTC) (App/CurrencyRatesFetcher.swift:50)
[ DEBUG ] 2020-07-31 08:01:59 +0000 Skipping fetch. Last fetched at 2020-07-31 08:01:58 +0000 (App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 08:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ DEBUG ] 2020-07-31 08:02:00 +0000 Skipping fetch. Last fetched at 2020-07-31 08:01:58 +0000 (App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 09:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 09:01:57 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 09:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 09:01:58 +0000 Fetched 171 currencies at July 31, 2020 at 9:01:58 AM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 09:01:58 +0000 Currency rates up to date at July 31, 2020 at 9:00:00 AM UTC) (App/CurrencyRatesFetcher.swift:50)
[ DEBUG ] 2020-07-31 09:01:59 +0000 Skipping fetch. Last fetched at 2020-07-31 09:01:58 +0000 (App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 09:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ DEBUG ] 2020-07-31 09:02:00 +0000 Skipping fetch. Last fetched at 2020-07-31 09:01:58 +0000 (App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 10:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 10:01:57 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 10:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 10:01:58 +0000 Fetched 171 currencies at July 31, 2020 at 10:01:58 AM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 10:01:58 +0000 Currency rates up to date at July 31, 2020 at 10:00:00 AM UTC) (App/CurrencyRatesFetcher.swift:50)
[ DEBUG ] 2020-07-31 10:02:00 +0000 Skipping fetch. Last fetched at 2020-07-31 10:01:58 +0000 (App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 11:02:00 +0000 (Queues/ScheduledJob.swift:36)[ INFO ] 2020-07-31 11:01:57 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 11:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 11:01:59 +0000 Fetched 171 currencies at July 31, 2020 at 11:01:59 AM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 11:01:59 +0000 Currency rates up to date at July 31, 2020 at 11:00:00 AM UTC) (App/CurrencyRatesFetcher.swift:50)
[ DEBUG ] 2020-07-31 11:02:00 +0000 Skipping fetch. Last fetched at 2020-07-31 11:01:59 +0000 (App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 12:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 12:01:57 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 12:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 12:01:58 +0000 Fetched 171 currencies at July 31, 2020 at 12:01:58 PM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 12:01:58 +0000 Currency rates up to date at July 31, 2020 at 12:00:00 PM UTC) (App/CurrencyRatesFetcher.swift:50)
[ DEBUG ] 2020-07-31 12:02:00 +0000 Skipping fetch. Last fetched at 2020-07-31 12:01:58 +0000 (App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 13:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 13:01:57 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 13:02:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-07-31 13:01:59 +0000 Fetched 171 currencies at July 31, 2020 at 1:01:59 PM UTC (App/CurrencyRatesFetcher.swift:48)
[ INFO ] 2020-07-31 13:01:59 +0000 Currency rates up to date at July 31, 2020 at 1:00:00 PM UTC) (App/CurrencyRatesFetcher.swift:50)
[ DEBUG ] 2020-07-31 13:02:00 +0000 Skipping fetch. Last fetched at 2020-07-31 13:01:59 +0000 (App/CurrencyRatesFetcher.swift:114)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 14:02:00 +0000 (Queues/ScheduledJob.swift:36)

Environment

• Vapor Framework version: 4.27.1
• Vapor Toolbox version: 18.0.0
• OS version: MacOS 10.15.5; Docker: build image: FROM swift:5.2-focal, run image: FROM swift:5.2-focal-slim

[jdmcd]

Moving this to the queues repo for better tracking. I will look into this and see if I can figure out what's up.

[danwallacenz]

Scheduling correctly running natively on Mac OS 10.15.5 via Xcode.

I set the schedule to 21 minutes after the hour for this test run.

[ DEBUG ] Could not load .env.development file: open(file:oFlag:mode:): No such file or directory (errno: 2) (Vapor/Application.swift:132)
[ DEBUG ] Could not load .env file: open(file:oFlag:mode:): No such file or directory (errno: 2) (Vapor/Application.swift:132)
[ DEBUG ] 2020-08-02 06:19:25 +0000 Initializing rates (App/CurrencyRatesFetcher.swift:23)
[ DEBUG ] 2020-08-02 06:19:25 +0000 Try to load rates from file (App/CurrencyRatesFetcher.swift:27)
[ INFO ] 2020-08-02 06:19:25 +0000 Attempting to load cached rates from file file:///Users/danw/dev/YesFX/server/YesFX-server/data/rates... (App/CurrencyRatesStorage.swift:48)
[ INFO ] 2020-08-02 06:19:25 +0000 Loading cached rates from file file:///Users/danw/dev/YesFX/server/YesFX-server/data/rates... (App/CurrencyRatesStorage.swift:55)
[ INFO ] 2020-08-02 06:19:25 +0000 Cached rates: [{
"base" : "USD",
"fetchedAt" : 1596243718.0247989,
"rates" : {
"NZD" : 1.508102,
"QAR" : 3.641,
"MGA" : 3802,
"SOS" : 584.5,
"ZAR" : 17.06885,
...
"TWD" : 29.325,
"SDG" : 55.3,
"BTN" : 74.734688,
"UAH" : 27.715963
},
"timestamp" : 1596243614
}] (App/CurrencyRatesStorage.swift:57)
[ DEBUG ] Factory created. [RedisConnectionFactory: F39DD6DF-2BBC-4070-9553-4B6EFA308E2B] (RedisKit/RedisConnectionSource.swift:20)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-08-02 06:21:00 +0000 (Queues/ScheduledJob.swift:36)
[ NOTICE ] Server starting on http://127.0.0.1:8080 (Vapor/HTTP/Server/HTTPServer.swift:183)
[ DEBUG ] 2020-08-02 06:21:00 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:118)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-08-02 07:21:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-08-02 06:21:01 +0000 Fetched 171 currencies at 2 August 2020 at 6:21:01 PM NZST (App/CurrencyRatesFetcher.swift:49)
[ INFO ] 2020-08-02 06:21:01 +0000 Currency rates up to date at 2 August 2020 at 6:00:15 PM NZST) (App/CurrencyRatesFetcher.swift:51)
[ DEBUG ] 2020-08-02 06:21:01 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:58)
[ DEBUG ] 2020-08-02 07:21:00 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:118)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-08-02 08:21:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-08-02 07:21:01 +0000 Fetched 171 currencies at 2 August 2020 at 7:21:01 PM NZST (App/CurrencyRatesFetcher.swift:49)
[ INFO ] 2020-08-02 07:21:01 +0000 Currency rates up to date at 2 August 2020 at 7:00:11 PM NZST) (App/CurrencyRatesFetcher.swift:51)
[ DEBUG ] 2020-08-02 07:21:01 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:58)
[ DEBUG ] 2020-08-02 08:21:00 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:118)
[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-08-02 09:21:00 +0000 (Queues/ScheduledJob.swift:36)
[ INFO ] 2020-08-02 08:21:02 +0000 Fetched 171 currencies at 2 August 2020 at 8:21:02 PM NZST (App/CurrencyRatesFetcher.swift:49)
[ INFO ] 2020-08-02 08:21:02 +0000 Currency rates up to date at 2 August 2020 at 8:00:07 PM NZST) (App/CurrencyRatesFetcher.swift:51)
[ DEBUG ] 2020-08-02 08:21:02 +0000 Saved rates to file rates (App/CurrencyRatesFetcher.swift:58)

[felswa]

I have noticed something that may be relevant here. I run the vapor server as a localhost on my computer. However, the server is GMT and the computer is GMT + 1. Depending on how you call schedule(), you need to input different times in order to get them to run at the same time.

// 1st case runs at the time on my computer.
app.queues.schedule(CleanupJob())
.daily()
.at(6, 08, .pm)

// runs at the time of the server. someDateTime is 5:08pm GMT
app.queues.schedule(CleanupJob()).at(Date(timeInterval: 0, since: someDateTime!))

[felswa]

It is possible that the clocks between your server and computer are off by a few seconds.

[danwallacenz]

Moving this to the queues repo for better tracking. I will look into this and see if I can figure out what's up.

Thanks Jimmy.

[danwallacenz]

It is possible that the clocks between your server and computer are off by a few seconds.

@felswa Thanks for the suggestion. Any suggestion on how I could test this?

[danwallacenz]

@felswa I ran:

#!/bin/sh
docker exec 989eac6f8cfc date
date

and got:

Sun Aug  2 20:43:30 UTC 2020
Mon  3 Aug 2020 08:43:30 NZST

So I guess the clocks are in sync.

[felswa]

Thanks Dan. I am very new to this.

…

On Aug 2, 2020, at 9:47 PM, Dan Wallace ***@***.***> wrote:  @felswa I ran: #!/bin/sh docker exec 989eac6f8cfc date date and got: Sun Aug 2 20:43:30 UTC 2020 Mon 3 Aug 2020 08:43:30 NZST So I guess the clocks are in sync. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

[danwallacenz]

Thanks Dan. I am very new to this.
…

@felswa Me too.

[felswa]

Dan, I see you are working on a finance project. Me too. If you want to compare notes sometimes my email is wayne.felson2@gmail.com <mailto:wayne.felson2@gmail.com>. Thanks. Rgds, Wayne

…

On Aug 2, 2020, at 10:57 PM, Dan Wallace ***@***.***> wrote: Thanks Dan. I am very new to this. … <x-msg://1/#> @felswa <https://github.com/felswa> Me too. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#85 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AMU6Z6AZ2PL44EOEHNR3XHTR6XOL7ANCNFSM4PSGUBMA>.

[tanner0101]

Hi @danwallacenz, thanks for reporting. Based on the logs it looks like the target date is being calculated correctly:

[ DEBUG ] Scheduling CurrencyRatesFetcher to run at 2020-07-31 02:02:00 +0000 (Queues/ScheduledJob.swift:36)

However, the job is actually running slightly early:

[ INFO ] 2020-07-31 02:01:59 +0000 Fetching currencies on queue scheduled... (App/CurrencyRatesFetcher.swift:117)

That makes me think the issue resides here where we schedule the job on the event loop: https://github.com/vapor/queues/blob/master/Sources/Queues/ScheduledJob.swift#L39

Perhaps Date.timeIntervalSinceNow or EventLoop.scheduleRepeatedTask are less accurate on Linux? If this is working on macOS, that could be a sign that the bug is not in our code.

cc @weissi @Lukasa. Can you see anything here that looks out of the ordinary?