[BUG] - System Time Change Effects Scheduled Jobs #438

dthomas-sensonix · 2023-03-27T21:15:14Z

Describe the bug

Scheduled jobs are effected by a system time change. If the next job is scheduled for time X, but the system clock is changed to time X + 1 hour before time X, then the job does not run.

To Reproduce

Steps to reproduce the behavior:

Schedule a job to happen every X amount of time
Change the system clock
Observe that the job stops happening.

Here is a simple program that will run on Mac OS X that can demonstrate the problem:

package main

import (
	"fmt"
	"github.com/go-co-op/gocron"
	"os/exec"
	"time"
)

func SetSystemDate(newTime time.Time) error {
	// https://stackoverflow.com/questions/48906483/how-to-set-systems-date-and-time-via-go-syscall
	_, lookErr := exec.LookPath("date")
	if lookErr != nil {
		fmt.Printf("Date binary not found, cannot set system date: %s\n", lookErr.Error())
		return lookErr
	} else {
		// Use special formatting for Mac OS X
		dateString := fmt.Sprintf("%02d%02d%02d%02d%02d", newTime.Month(), newTime.Day(), newTime.Hour(), newTime.Minute(), newTime.Year()-2000)
		fmt.Printf("Setting system date to: %s\n", dateString)
		args := []string{"-u", dateString}
		return exec.Command("date", args...).Run()
	}
}

func main() {
	s := gocron.NewScheduler(time.UTC)
	s.Every(2).Seconds().Do(func() {
		fmt.Println("Hello world")
	})
	s.StartAsync()
	time.Sleep(5 * time.Second)
	timePlusOne := time.Now().UTC().Add(time.Hour * 1)
	fmt.Println(timePlusOne)
	err := SetSystemDate(timePlusOne)
	if err != nil {
		fmt.Printf("Error: %s", err.Error())
	}
	time.Sleep(10 * time.Second)
	fmt.Println("Exit")
}

Version

v1.19.0

Expected behavior

The expected behavior would be that a job printing "Hello World" would start. After some amount of time the system clock would change (corresponding to when the current time is printed below), but the job would continue running:

Hello world
Hello world
Hello world
2023-03-27 22:21:40.060268 +0000 UTC
Hello world
Hello world
Hello world
Hello world
Hello world
Exit

The actual behavior is that the job(s) stop shortly after the system clock is changed:

Hello world
Hello world
Hello world
2023-03-27 22:22:39.757308 +0000 UTC
Setting system date to: 0327222223
Hello world
Exit

Additional context

The problem was first observed on a device with an inaccurate date & time setting. Jobs were scheduled and started. Later the device obtained the correct date & time from NTP. When that happened the jobs stopped. Looking at the NextRun() information on the jobs, one could see they were scheduled to run "in the past." In some cases the NextRun() was actually before the LastRun().

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

dthomas-sensonix · 2023-03-28T13:08:41Z

As a comparison, I performed a similar test with the APScheduler library in Python. When the time is changed, I observe that library misses an instance of the job but then resumes work on subsequent ticks:

Tick! The time is: 2023-03-27 17:06:45.853149
Tick! The time is: 2023-03-27 17:06:47.856345
2023-03-27 23:06:48.853292
0327230623
Mon Mar 27 23:06:00 UTC 2023
0
Run time of job "tick (trigger: interval[0:00:02], next run at: 2023-03-27 18:06:01 CDT)" was missed by 0:00:01.155651
Tick! The time is: 2023-03-27 18:06:01.865346
Tick! The time is: 2023-03-27 18:06:03.851190

This would be reasonable behavior for gocron.

JohnRoesler · 2023-04-25T02:54:41Z

There is an accepted proposal golang/go#36141 for Go to add a concept of External time, which is akin to "real time" that will solve this issue in gocron. Until that point, if the system time changes, programs using gocron will need to be restarted to pickup the new time and schedule jobs correctly.

agilob · 2023-05-26T13:21:27Z

Is this the same jasonlvhit/gocron#44 ?

JohnRoesler · 2023-06-01T16:57:07Z

@agilob that issue looks to be around handling daylight time changes. #435 fixed that within gocron.

FramnkRulez · 2023-12-30T16:46:13Z

I kind of wonder if more is going on here... I've started experiencing this with duration and cron jobs after upgrading from 1.x -> 2.x and it's happening on Windows, which according to Go's comments should already be using "real time"?

FramnkRulez · 2023-12-30T20:12:39Z

This is why I'm not 100% sure this is completely related to Golang time issues. I frequently see this in 2.x after a Windows system goes to sleep. In my case I have several 1 minute cron schedules running independently. I added log messages to the top when the schedule gets triggered and at the end of the schedule task to log the next run time.

You can see after the system wakes up, one of the cron schedules has it's 'Next Run' time set to a value in the past despite the log timestamps and the timestamp in the log messages themselves reflecting the accurate system time.

Last log entry before system sleep (for a different schedule keyed as 'net'):

[28924] 2023-12-30T13:47:00-05:00 info: next run for schedule 'net': 2023-12-30T13:48:00-05:00

After system wakeup, the schedule keyed as 'disk' will never run again as its next schedule is in the past:

[28924] 2023-12-30T14:13:08-05:00 info: schedule 'disk' triggered at 2023-12-30T14:13:08-05:00
[28924] 2023-12-30T14:13:09-05:00 info: next run for schedule 'disk': 2023-12-30T13:49:00-05:00

Note that in the log messages above, the accurate timestamps shown were simply using time.Now().Format(), the inaccurate one was when I logged the value of job.NextRun()

JohnRoesler · 2023-12-31T03:15:17Z

@FramnkRulez Agreed that there is a portion of this issue that can be tackled in gocron v2. I put up a release candidate - if you're able to test and confirm that it resolves this issue with the machine going to sleep and attempting to run a next time in the past, that would be super helpful. v2.1.2-rc-1

FramnkRulez · 2023-12-31T18:33:32Z

@JohnRoesler Initial testing seems to show that this RC addresses the problem I was seeing! I'll keep an eye out for anything unusual.

JohnRoesler · 2024-01-02T16:53:52Z

@FramnkRulez v2.1.2 has this fix in it for the next run time ending up in the past 👍

The other direction (time was ahead of where it should be) of this issue - say time being synced from 11am back to 9am, is an interesting problem. From the scheduler perspective, this would be much more complex to handle 🤔 In my experience working with devices that sync with NTP, I've only ever had to sync time forward (when a device been offline for some time). If you are facing this issue, I'm curious to understand under what circumstances.

dthomas-sensonix added the bug Something isn't working label Mar 27, 2023

JohnRoesler added the v1 label Oct 28, 2023

JohnRoesler mentioned this issue Dec 21, 2023

[BUG] When date changes to before, conJob not work #626

Closed

JohnRoesler added the v2 label Jan 2, 2024

JohnRoesler closed this as completed Mar 7, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[BUG] - System Time Change Effects Scheduled Jobs #438

[BUG] - System Time Change Effects Scheduled Jobs #438

dthomas-sensonix commented Mar 27, 2023

dthomas-sensonix commented Mar 28, 2023

JohnRoesler commented Apr 25, 2023

agilob commented May 26, 2023

JohnRoesler commented Jun 1, 2023

FramnkRulez commented Dec 30, 2023

FramnkRulez commented Dec 30, 2023 •

edited

Loading

JohnRoesler commented Dec 31, 2023

FramnkRulez commented Dec 31, 2023

JohnRoesler commented Jan 2, 2024

[BUG] - System Time Change Effects Scheduled Jobs #438

[BUG] - System Time Change Effects Scheduled Jobs #438

Comments

dthomas-sensonix commented Mar 27, 2023

Describe the bug

To Reproduce

Version

Expected behavior

Additional context

dthomas-sensonix commented Mar 28, 2023

JohnRoesler commented Apr 25, 2023

agilob commented May 26, 2023

JohnRoesler commented Jun 1, 2023

FramnkRulez commented Dec 30, 2023

FramnkRulez commented Dec 30, 2023 • edited Loading

JohnRoesler commented Dec 31, 2023

FramnkRulez commented Dec 31, 2023

JohnRoesler commented Jan 2, 2024

FramnkRulez commented Dec 30, 2023 •

edited

Loading