Daylight Savings Issue

[kevincolyar]

I had an issue this past Sunday morning during the daylight savings spring forward. I have a cron job that runs every minute, and when the change-over occurred supercronic started logging the following message continually for about 10 minutes until it filled up my VM with a 40gb log file.

{"log":"time=\"2021-03-14T01:00:00-08:00\" level=warning msg=\"not starting: job is still running since 2021-03-14 01:00:00 -0800 PST (0s elapsed)\" iteration=104 job.command=\"/bin/bash -l -c 'cd /home/deploy/app \u0026\u0026 RAILS_ENV=production bundle exec rake process --silent \u003e\u003e /proc/1/fd/1 2\u003e\u003e /proc/1/fd/2'\" job.position=2 job.schedule=\"0 * * * *\"\n","stream":"stderr","time":"2021-03-14T09:00:00.041059641Z"}

I'm setting my localtime zone in my Dockerfile:

ENV TZ=America/Los_Angeles
RUN ln -snf /usr/share/zoneinfo/$TZ /etc/localtime && echo $TZ > /etc/timezone

Should I stick to UTC in my container and set the timezone in my cron job? I'm running supercronic version 0.1.11.

[kevincolyar]

I believe part of my issue was due to the duplicate job handling the DST change.

https://github.com/aptible/supercronic#duplicate-jobs

I see I can disable this behavior but it would still cause supercronic to log warnings (out of control in this case).

[kevincolyar]

The fix was adding -split-logs and redirecting stderr to /dev/null so that supercronic warning messages are not logged:

docker-compose.yml
command: bash -c " whenever > ./crontab && supercronic -split-logs ./crontab 2>/dev/null"

Use the following steps to replicate the issue:

Use timezone in Dockerfile:

FROM ruby:2.3.8

ENV TZ=America/Los_Angeles
RUN ln -snf /usr/share/zoneinfo/$TZ /etc/localtime && echo $TZ > /etc/timezone

Set time (CentOS) specific:

sudo systemctl stop chronyd
sudo date -s "14 MAR 2021 01:50" 

Start containers:

docker-compose up

You should see a stream of log messages like:

time="2021-03-14T01:51:39-08:00" level=warning msg="job took too long to run: it should have started 51m39.95300068s ago"

[krallin]

This is worth investigating, I don't have a lot of time to look right now, but we should keep this open so we don't lose track of it. Thanks for sharing detailed repro instructions!

[subtlepseudonym]

The issue appears to be caused by this block in cron.monitorJob.

During the forward transition, an hour's worth of error logs are generated due to time.Until(t) returning a negative duration. During the backward transition, any jobs that should be run during the repeated hour will not be run due to time.Until(t) returning an inflated duration.

[ryanreadbooks]

DST issue still exists. For example:

func TestGetNextTime(t *testing.T) {
  laLoc, _ = time.LoadLocation("America/Los_Angeles")
  now := time.Date(2024, 3, 10, 01, 59, 40, 0, laLoc)
  expr := cronexpr.MustParse("*/30 * * * * * *")
  next := expr.Next(now)
  
  fmt.Printf("now: %v, unix: %v, utc: %v\n", now, now.Unix(), now.UTC())
  fmt.Printf("next: %v, unix: %v, utc: %v\n", next, next.Unix(), next.UTC())
}

Output:

now: 2024-03-10 01:59:40 -0800 PST, unix: 1710064780, utc: 2024-03-10 09:59:40 +0000 UTC
next: 2024-03-10 01:00:00 -0800 PST, unix: 1710061200, utc: 2024-03-10 09:00:00 +0000 UTC

According to my understanding, the expected next time should be 2024-03-10 03:00:00 -0700 PDT, but the result is 2024-03-10 01:00:00 -0800 PST.

Is this a DST bug or am I understanding it incorrectly.

[subtlepseudonym]

This patch should clear up your issue, but it produces some potentially confusing behavior around DST boundaries (ex. */2 will have one hour between jobs when the DST boundary is divisible by two)

diff --git a/cronexpr/cronexpr_next.go b/cronexpr/cronexpr_next.go
index 9f607c8..fa8b31c 100644
--- a/cronexpr/cronexpr_next.go
+++ b/cronexpr/cronexpr_next.go
@@ -129,6 +129,8 @@ func (expr *Expression) nextHour(t time.Time) time.Time {
                return expr.nextDayOfMonth(t)
        }

+       name, offset := t.Zone()
+       zone := time.FixedZone(name, offset)
        return time.Date(
                t.Year(),
                t.Month(),
@@ -137,7 +139,8 @@ func (expr *Expression) nextHour(t time.Time) time.Time {
                expr.minuteList[0],
                expr.secondList[0],
                0,
-               t.Location())
+               zone,
+       ).In(t.Location())
 }

 /******************************************************************************/

[ryanreadbooks]

This patch should clear up your issue, but it produces some potentially confusing behavior around DST boundaries (ex. */2 will have one hour between jobs when the DST boundary is divisible by two)

diff --git a/cronexpr/cronexpr_next.go b/cronexpr/cronexpr_next.go
index 9f607c8..fa8b31c 100644
--- a/cronexpr/cronexpr_next.go
+++ b/cronexpr/cronexpr_next.go
@@ -129,6 +129,8 @@ func (expr *Expression) nextHour(t time.Time) time.Time {
                return expr.nextDayOfMonth(t)
        }

+       name, offset := t.Zone()
+       zone := time.FixedZone(name, offset)
        return time.Date(
                t.Year(),
                t.Month(),
@@ -137,7 +139,8 @@ func (expr *Expression) nextHour(t time.Time) time.Time {
                expr.minuteList[0],
                expr.secondList[0],
                0,
-               t.Location())
+               zone,
+       ).In(t.Location())
 }

 /******************************************************************************/

Is this patch released yet? I can't find it in any releases.

[subtlepseudonym]

I haven't submitted the change as a PR yet. There's some more work to be done prior to that, but I figured I'd copy it here in case it's helpful on the 3rd.