[BUG] - Job is running twice

[sylviamoss]

Describe the bug

I scheduled a job to run one time a day at a certain time. When is missing 1 sec to the scheduled time, a job instance is started. At the exact scheduled time, another instance will run for the same job. The result is the job running twice with one second of difference.

To Reproduce

Schedule a job like the following:

scheduler := gocron.NewScheduler(time.UTC)
if _, err := scheduler.Every(1).Day().At("13:30").Do(job); err != nil {
return err
}
scheduler.StartAsync()

Version

v0.7.0

Additional context

Output logs of the application I'm running:

{"level":"info","time":"2021-03-03T19:41:59Z","message":"Starting job"}
{"level":"info","time":"2021-03-03T19:42:00Z","message":"Starting job"}

This is the log I print as soon as the job starts. Note the difference between the logged times.

[JohnRoesler]

@sylviamoss I've tested out quite a few jobs locally running every day at a specific time and I haven't been able to reproduce this issue. Have you seen this happen each time the job runs that it runs twice? Are you able to reproduce it?

[sylviamoss]

@JohnRoesler I figured out that only happens when the application is running in a container.

Testing case:

func main() {
	fmt.Println("start")
	scheduler := gocron.NewScheduler(time.UTC)

	t := time.Now().Add(1 * time.Minute)
	hour := strconv.Itoa(t.Hour())
	minute := strconv.Itoa(t.Minute())
	at := fmt.Sprintf("%s:%s", hour, minute)
	stop := false
	if _, err := scheduler.Every(1).Day().At(at).Do(func() { fmt.Println("Starting job"); stop = true }); err != nil {
		fmt.Println(err)

		return
	}
	scheduler.StartAsync()

	for !stop {
	}

        time.Sleep(10 * time.Second)
	fmt.Println("stop")
}

Dockerfile:

FROM golang:latest

RUN mkdir /app 
ADD . /app/
WORKDIR /app 
RUN go build -o main .

CMD ["./main"]

This outputs:

➜  test docker build -t test .
...
➜  test docker run test       
start
Starting job
Starting job
stop

Pretty weird, right? Do you have any idea why this could be happening? It doesn't seem to happen when I change it to use StartAt. Could it be some millisecond precision problem?

[JohnRoesler]

Interesting that it only happens in docker - must be something slightly different with how the time is handled. This issue looks to be that the duration until the run isn't quite right:

20:38:34.891818 20:39
20:38:34.892017 lastRunDayPlusJobAtTime: 2021-03-04 20:39:00 +0000 UTC
20:38:34.892043 until: 2021-03-04 20:39:00 +0000 UTC
20:38:34.892066 from: 2021-03-04 20:38:34.891959 +0000 UTC
20:38:34.892081 duration: 25108041000
20:38:34.892117 will run: 2021-03-04 20:39:00 +0000 UTC
20:38:34.892153 next run: 2021-03-04 20:39:00 +0000 UTC
20:38:34.892208 time now + durationToNextRun: 2021-03-04 20:39:00.0002349 +0000 UTC
20:38:59.971931 inside afterfunc

I upped the log package level to include microseconds and inserted a bunch of extra log statements. We can see, by my calculation log.Printf("time now + durationToNextRun: %s", s.time.Now(s.location).Add(durationToNextRun)) it should be run at 20:39 and some micros. But then the log line right inside the time.Afterfunc logs just before at 20:38:39...

Interestingly, on a mac it operates as I'd expect and doesn't enter the afterfunc until the calculated time.

[sylviamoss]

Seems like in a container the time round is different and 39:00.0002349 is rounded both to 38:59 and 39:00.
Can I see the same logs when using StartAt?
I supposed at the point of running jobs both At and StartAt time will be in the same format. 🤔 Still a mystery to me!

Btw, my host OS is mac as well. Have you tested it on some other Linux machine?

[Streppel]

@JohnRoesler I figured out that only happens when the application is running in a container.

That's weird... Just tested the case you provided and it ran fine here. Will investigate a bit more as well.

[JohnRoesler]

I also just tested it again, and I can't recreate the double run issue.

I made a similar setup but used the scratch docker image

FROM scratch

COPY ./main /main
CMD ["/main"]

package main

import (
	"log"
	"time"
)

func main() {
	now := time.Now()
	t := time.Now().Add(10 * time.Second).Round(time.Second)
	log.SetFlags(log.Lmicroseconds)

	log.Printf("at: %s", t)

	durationToNext := t.Sub(now)

	time.AfterFunc(durationToNext, func() {
		log.Println("hello")
	})
	time.Sleep(20 * time.Second)
}

$ docker run --rm -it test-scratch
> 04:41:15.677798 at: 2021-03-08 04:41:26 +0000 UTC
> 04:41:26.010159 hello

[JohnRoesler]

Please reopen if you continue to see this issue occurring. For now, we'll chalk it up to something odd in the water that day as I haven't be able to recreate it since.

[artemgavrilov]

Hi, faced the same bug in my environment (MacOS + docker). After some debugging, I found that time.AfterFunc on this line triggers few milliseconds before the expected time. It seems that the root of the problem in golang:

• time: time.After and time.Sleep return early on windows/amd64 golang/go#45582
• time: wall and monotonic clocks get out of sync golang/go#27090