Bug in scheduler

[JohnRoesler]

package main

import (
	"fmt"
	"time"

	"github.com/go-co-op/gocron"
)

func task() {
	fmt.Println(time.Now())
}

func main() {
	s1 := gocron.NewScheduler(time.UTC)
	s1.Every(10).Seconds().Do(task)
	<-s1.Start() // starts running (blocks current thread)
}

go run main.go
2020-03-31 23:10:10.5018339 -0500 CDT m=+10.003605201
2020-03-31 23:10:20.5028812 -0500 CDT m=+20.004652501
2020-03-31 23:10:30.501854 -0500 CDT m=+30.003625301
2020-03-31 23:10:31.5013486 -0500 CDT m=+31.003119901
2020-03-31 23:10:41.5022159 -0500 CDT m=+41.003987201
2020-03-31 23:10:51.5013717 -0500 CDT m=+51.003143001
2020-03-31 23:10:52.5031395 -0500 CDT m=+52.004910801
2020-03-31 23:11:02.5020695 -0500 CDT m=+62.003840801
2020-03-31 23:11:03.5014576 -0500 CDT m=+63.003228901
2020-03-31 23:11:13.5016872 -0500 CDT m=+73.003458501
2020-03-31 23:11:23.5017684 -0500 CDT m=+83.003539701
2020-03-31 23:11:33.5013161 -0500 CDT m=+93.003087401
2020-03-31 23:11:34.508206 -0500 CDT m=+94.009977301
2020-03-31 23:11:44.5021093 -0500 CDT m=+104.003880601
2020-03-31 23:11:45.503181 -0500 CDT m=+105.004952301
2020-03-31 23:11:55.5017912 -0500 CDT m=+115.003562501
2020-03-31 23:11:56.5028593 -0500 CDT m=+116.004630601
2020-03-31 23:12:06.5013873 -0500 CDT m=+126.003158601
2020-03-31 23:12:07.5014535 -0500 CDT m=+127.003224801
2020-03-31 23:12:17.5013532 -0500 CDT m=+137.003124501
2020-03-31 23:12:18.5029237 -0500 CDT m=+138.004695001
2020-03-31 23:12:28.501378 -0500 CDT m=+148.003149301
2020-03-31 23:12:29.5012798 -0500 CDT m=+149.003051101
2020-03-31 23:12:39.5022707 -0500 CDT m=+159.004042001
2020-03-31 23:12:49.5018604 -0500 CDT m=+169.003631701
2020-03-31 23:12:50.5017803 -0500 CDT m=+170.003551601
2020-03-31 23:13:00.5019564 -0500 CDT m=+180.003727701
2020-03-31 23:13:10.5020875 -0500 CDT m=+190.003858801
2020-03-31 23:13:20.5016438 -0500 CDT m=+200.003415101
2020-03-31 23:13:21.5017742 -0500 CDT m=+201.003545501
2020-03-31 23:13:31.503144 -0500 CDT m=+211.004915301
2020-03-31 23:13:41.5014638 -0500 CDT m=+221.003235101
2020-03-31 23:13:42.5028217 -0500 CDT m=+222.004593001
2020-03-31 23:13:52.5013111 -0500 CDT m=+232.003082401
2020-03-31 23:13:53.5014415 -0500 CDT m=+233.003212801
2020-03-31 23:14:03.501239 -0500 CDT m=+243.003010301
2020-03-31 23:14:04.5013094 -0500 CDT m=+244.003080701
2020-03-31 23:14:14.5030847 -0500 CDT m=+254.004856001
2020-03-31 23:14:24.5019311 -0500 CDT m=+264.003702401
2020-03-31 23:14:25.5020085 -0500 CDT m=+265.003779801

[brett0701]

Hi John,
Is this bug related to all scheduled times or just fast times (every 1, 5, 10 or 15 min)?

[JohnRoesler]

@brett0701 unsure at this point. Just tried it with 10s and this job. I am currently running some jobs in production that are on a 5 min cadence and haven't noticed any substantial drift. However, on a window that size, it's possible that a second here and there is just not noticed.

[avasani]

@brett0701 : I am seeing the same with 5mins. Two callback are fired backtoback.

[brett0701]

Yep. I've been running hourly schedules and it happens then as well.
All related to the issue:
jasonlvhit/gocron#142

[JohnRoesler]

@brett0701 @avasani when you are able, please test out the latest release https://github.com/go-co-op/gocron/releases/tag/v0.1.1 with the fix for this bug!

[avasani]

Thanks @brett0701 and @JohnRoesler, I verified with the last hash, not seeing the issue anymore.
Thanks for the quick fix. Really loved the library!!

[Streppel]

@avasani everything alright? I got an email but I can't see your comment here

[JohnRoesler]

@Streppel sounds like it's all good. Let us know if you find any other bugs! Glad you like the library. Issues/PRs are always welcome 😄

[avasani]

@Streppel : Ignore my email, it was a false positive. For one run, I tested with old hash which has the issue. On master it is fine.
I see consistent firing of callbacks \m/

02:19:55
02:20:55
02:21:55
02:22:55
02:23:55
02:24:55
02:25:55
02:26:55
02:27:55
02:28:55
02:29:55
02:30:55
02:31:55