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.