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

danwallacenz · 2020-08-02T01:15:03Z

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

The text was updated successfully, but these errors were encountered:

jdmcd · 2020-08-02T01:18:19Z

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 · 2020-08-02T08:44:26Z

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 · 2020-08-02T20:03:29Z

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 · 2020-08-02T20:07:47Z

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

danwallacenz · 2020-08-02T20:27:33Z

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 · 2020-08-02T20:33:59Z

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 · 2020-08-02T20:47:33Z

@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 · 2020-08-02T21:51:55Z

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 · 2020-08-02T21:57:07Z

Thanks Dan. I am very new to this.
…

@felswa Me too.

felswa · 2020-08-03T13:21:23Z

Dan, I see you are working on a finance project. Me too. If you want to compare notes sometimes my email is [email protected] <mailto:[email protected]>. 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 · 2020-08-06T21:04:21Z

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?

tanner0101 · 2020-08-06T21:05:41Z

Side note, a potential workaround here could be storing the last date the job was scheduled to run at and backoff rescheduling until we get a next date that is greater.

danwallacenz · 2020-08-06T23:10:04Z

@tanner0101 Thanks for looking at this. I do have workarounds in place.

grundoon · 2020-08-07T01:04:47Z

Can you see anything here that looks out of the ordinary?

@jdmcd (et al) Apologies for dropping an aside in here, but if not actually scheduling a repeating task there

let task = context.eventLoop.scheduleRepeatedTask(
    initialDelay: .microseconds(Int64(date.timeIntervalSinceNow * 1_000_000)),
    delay: .seconds(0)
) { task in
    // always cancel
    task.cancel()

is there a reason for not just using scheduleTask(deadline:_:) or scheduleTask(in:_:)?

Perhaps I'm missing something, but I'm not readily seeing anywhere that class RepeatedTask is being used where struct Scheduled would not suffice (and that .cancel() in the closure could be eliminated?).

tanner0101 · 2020-08-07T01:11:32Z

@grundoon good catch, that looks like an oversight. scheduleTask seems like the better API for this case.

tanner0101 · 2020-08-07T01:15:44Z

@grundoon would you wanna open an issue for that or PR it? Otherwise I can

grundoon · 2020-08-07T01:22:16Z

@tanner0101 A little backed up here, but not too badly and I think I can add it to my, uh... queue. 😄

Lukasa · 2020-08-07T06:19:04Z

@tanner0101 Maybe I’m confused, but I don’t see how this runs a second time. This always calls cancel, which should always be done before the original future completes, and so this should never reschedule.

As to the question of why it might run early: NIO doesn’t schedule jobs on wall clock time, it schedules them against a monotonic uptime clock. The intention is that for event loops you usually want to say “run this in 10 seconds” and to have that mean in ten seconds, not in three seconds because the ntp daemon decided to jump the clock forward. The monotonic uptime clock is not affected by changes to wall time, and therefore asking to run something at a given wall time is not something NIO supports.

This means that yes, some systems may see inaccuracy when attempting to schedule things against the wall clock. That is just not really what NIO’s event loops are for. If you want things to be scheduled against a wall clock then something like DispatchSources may be more useful for the immediate use-case.

Lukasa · 2020-08-07T06:50:23Z

Hmm, I realise I should add to this something explicit that is implicit above: the monotonic uptime clock is still affected by ntp changes! It just doesn't jump: it skews, instead. The end result is that if you run something "once per hour" against the monotonic clock you should see it run approximately once per wall clock hour, but sometimes it'll run a bit early and sometimes it'll run a bit late. Over time it'll correct itself to the right interval, however.

tanner0101 · 2020-08-07T15:36:03Z

@Lukasa OK that makes sense and seems very likely to be the culprit. I imagine Date.timeIntervalSinceNow is using the "wall clock" so that's where we're getting a divergence. I will look into DispatchSources, thank you!

Maybe I’m confused, but I don’t see how this runs a second time. This always calls cancel, which should always be done before the original future completes, and so this should never reschedule.

Ignore that we are using scheduleRepeatedTask here. That should really be scheduleTask as @grundoon pointed out. Once the task completes, we calculate the next date and schedule again. If the task starts too early, that next date resolves to the previously scheduled date resulting in it running again at basically the same time.

grundoon · 2020-08-07T22:47:05Z

@tanner0101 After messing with it a bit, I'm going to withdraw that suggestion. While the API switch superficially seems to make sense, the returned Scheduled would be a generic and likely carry more overhead than any minimal benefit derived. Since the observed behavior is entirely unrelated, not seeing any real point in trying to extricate RepeatedTask from the package... it's pretty embedded, and sensibly so.

tanner0101 · 2020-08-07T22:55:35Z

@grundoon either way it seems like we need to switch to Dispatch or something else given what Cory said. Thanks for looking into it though 👍

danwallacenz · 2020-08-12T02:51:34Z

I have not seen these scheduling errors after deploying my container to an AWS Elastic Beanstalk multi-container Docker environment running on 64bit Amazon Linux/2.20.4.

jdmcd transferred this issue from vapor/vapor Aug 2, 2020

tanner0101 added the bug Something isn't working label Aug 6, 2020

omochi mentioned this issue Mar 3, 2021

ScheduledJob run twice quickly because actual sleep duration is shorter than expected. #94

Open

gwynne mentioned this issue Mar 3, 2021

Extend sleep if it doesn't scheduled date #95

Open

MahdiBM mentioned this issue Apr 22, 2021

every() funcs final implementation #98

Closed

MahdiBM added a commit to MahdiBM/queues that referenced this issue Apr 22, 2021

fix for issue vapor#85 and vapor#94

1404673

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

danwallacenz commented Aug 2, 2020

jdmcd commented Aug 2, 2020

danwallacenz commented Aug 2, 2020 •

edited

Loading

felswa commented Aug 2, 2020

felswa commented Aug 2, 2020

danwallacenz commented Aug 2, 2020

danwallacenz commented Aug 2, 2020

danwallacenz commented Aug 2, 2020

felswa commented Aug 2, 2020 via email

danwallacenz commented Aug 2, 2020

felswa commented Aug 3, 2020 via email

tanner0101 commented Aug 6, 2020 •

edited

Loading

tanner0101 commented Aug 6, 2020 •

edited

Loading

danwallacenz commented Aug 6, 2020

grundoon commented Aug 7, 2020

tanner0101 commented Aug 7, 2020

tanner0101 commented Aug 7, 2020 •

edited

Loading

grundoon commented Aug 7, 2020

Lukasa commented Aug 7, 2020

Lukasa commented Aug 7, 2020

tanner0101 commented Aug 7, 2020 •

edited

Loading

grundoon commented Aug 7, 2020

tanner0101 commented Aug 7, 2020

danwallacenz commented Aug 12, 2020

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

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

Comments

danwallacenz commented Aug 2, 2020

Steps to reproduce

Expected behavior

Actual behavior

Environment

jdmcd commented Aug 2, 2020

danwallacenz commented Aug 2, 2020 • edited Loading

felswa commented Aug 2, 2020

felswa commented Aug 2, 2020

danwallacenz commented Aug 2, 2020

danwallacenz commented Aug 2, 2020

danwallacenz commented Aug 2, 2020

felswa commented Aug 2, 2020 via email

danwallacenz commented Aug 2, 2020

felswa commented Aug 3, 2020 via email

tanner0101 commented Aug 6, 2020 • edited Loading

tanner0101 commented Aug 6, 2020 • edited Loading

danwallacenz commented Aug 6, 2020

grundoon commented Aug 7, 2020

tanner0101 commented Aug 7, 2020

tanner0101 commented Aug 7, 2020 • edited Loading

grundoon commented Aug 7, 2020

Lukasa commented Aug 7, 2020

Lukasa commented Aug 7, 2020

tanner0101 commented Aug 7, 2020 • edited Loading

grundoon commented Aug 7, 2020

tanner0101 commented Aug 7, 2020

danwallacenz commented Aug 12, 2020

danwallacenz commented Aug 2, 2020 •

edited

Loading

tanner0101 commented Aug 6, 2020 •

edited

Loading

tanner0101 commented Aug 6, 2020 •

edited

Loading

tanner0101 commented Aug 7, 2020 •

edited

Loading

tanner0101 commented Aug 7, 2020 •

edited

Loading