Project

General

Profile

Bug #14266

Cron tasks triggering on UTC time, not local time

Added by Kevin Horton over 4 years ago. Updated almost 4 years ago.

Status:
Closed: Cannot reproduce
Priority:
Important
Assignee:
Chris Torek
Category:
Middleware
Target version:
Seen in:
Severity:
New
Reason for Closing:
Reason for Blocked:
Needs QA:
Yes
Needs Doc:
Yes
Needs Merging:
Yes
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:
ChangeLog Required:
No

Description

Cron tasks trigger on UTC time, not local time, on FreeNAS-9.10-STABLE, updated from 9.3.1-STABLE. This is a change in behaviour from 9.3.1, where they would trigger on local time.

The time zone is correctly set, and the time shows correctly in the GUI and in the CLI via the date command.

History

#1 Updated by Jordan Hubbard over 4 years ago

  • Assignee set to Chris Torek
  • Priority changed from No priority to Important

I'm starting to wonder if FreeBSD 10 is setting the default environment differently than 9? First the weird locale issue with proftpd, now this.

#2 Updated by Jordan Hubbard over 4 years ago

  • Target version set to 261

#3 Updated by Chris Torek over 4 years ago

  • Status changed from Unscreened to Screened

Hmm, I set up a set on a VM running 9.10(ish) and it's behaving as though /etc/crontab entries are using local time... a small reproducer example would help.

#4 Updated by Sean Fagan over 4 years ago

If you run date in the console, is it local or UTC?

#5 Updated by Kevin Horton over 4 years ago

Sean Fagan wrote:

If you run date in the console, is it local or UTC?

In the console, date is local.

The difference between my situation and Chris Torek's test, as described, is that I updated from FN 9.3.1-STABLE, rather than stating with a new installation of FN-9.10.

I experimented a few minutes ago with two tasks to email me pool status and SMART info, and confirmed that the tasks are triggering at UTC time.

The lines in /etc/crontab for my two latest tests are:

15      09      *       *       *       root    PATH="/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin:/root/bin" /root/bin/zpool_email.sh > /dev/null
16      09      *       *       *       root    PATH="/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin:/usr/local/sbin:/root/bin" /root/bin/smart_email.sh > /dev/null

The email from those two tasks were received at 05:15 and 05:16 EST, but they show in the GUI and crontab as being defined at 09:15 and 09:16.

#6 Updated by Kevin Horton over 4 years ago

This may or may not be related, but on my system the time stamps in /var/log/messages have a mix of local and UTC time. E.g. shortly after the reboot following the update to FreeNAS-9.10-STABLE-201603252134:

Mar 26 15:19:40 freenas kernel: epair1b: link state changed to UP
Mar 26 15:19:40 freenas kernel: epair1a: promiscuous mode enabled
Mar 26 19:19:40 freenas devd: Executing '/etc/pccard_ether epair1b start'
Mar 26 15:19:40 freenas rtsold[1205]: <rtsock_input_ifannounce> interface epair1b removed
Mar 26 19:19:41 freenas devd: Executing '/etc/rc.d/dhclient quietstart epair1a'
Mar 26 15:19:41 freenas kernel: ng_ether_ifnet_arrival_event: can't re-name node epair1b

I'm in North America, 4 hours west of UTC - the local time when that log sample was grabbed was 15:19. UTC was 19:19.

#7 Updated by Kevin Horton over 4 years ago

And now, after updating to FreeNAS-9.10-STABLE-201603252134 (and rebooting as required by the update), cron tasks are working on local time, as expected.

/var/log/messages and /var/log/debug.log have settled out to have all entries in local time for the last few hours. The last log entries in UTC time were roughly 90 minutes after the reboot.

#8 Updated by Jordan Hubbard over 4 years ago

  • Status changed from Screened to Closed: Cannot reproduce

Moving to cannot reproduce since this mysterious problem (which we could never see) evidently fixed itself!

#9 Updated by Chris Torek over 4 years ago

I bet something went wrong with one of those updates, during the time we had /etc/local and /usr/local/etc kind of messed-up. Apparently the second update fixed it. It might have been interesting to see what rcorder was spitting out while things were messed-up: I'm guessing that some daemons fired up before /etc/localtime got created, and hence were running in UTC (and hence the mismatched syslog date stamps).

#10 Updated by Kevin Horton over 4 years ago

I still get the very occasional UTC date stamp in debug.log. devd is logging in UTC:

Mar 27 05:15:35 freenas alert.py: [middleware.notifier:214] Popen()ing: zpool get -H -o value version pool
Mar 27 09:17:19 freenas devd: Pushing table
Mar 27 09:17:19 freenas devd: Processing notify event
Mar 27 09:17:19 freenas devd: Popping table
Mar 27 05:20:36 freenas alert.py: [middleware.notifier:214] Popen()ing: zpool get -H -o value version pool

Perhaps cron was affected only until the reboot, but now devd is the problem child.

#11 Avatar?id=14398&size=24x24 Updated by Kris Moore about 4 years ago

  • Target version changed from 261 to N/A

#12 Updated by Maarten Vanraes almost 4 years ago

I'm running "FreeNAS-9.10-STABLE-201606270534 (dd17351)". I have the same? (possibly different) issue?

I was setting up cron tasks to run at 00h 02m; but i found out this morning that the task is starting at 09:02 instead of 00:02. (the idea was something taking a few hours wasn't running during local daylight hours; but i confirmed it still running too. the logs show a date command which means it actually starts at 09:02).

These local times are all CEST (timezone is set correctly, and everything).

Since the server is at CEST (UTC+2), and it's a 9h difference, this would mean cron is running at UTC-7 ...

I wonder if it's dependant the timezone setting of the machine compiling cron...

perhaps when compiling the cron package, there's a setting that it uses the local time of the compiling machine instead of the local time of the machine running cron... either that, or when cron starts its UTC-7 ? and it's dependant on freenas timesettings at boot time before ntp and/or timezone settings?

#13 Updated by Maarten Vanraes almost 4 years ago

i'll note that i found (at the top of /var/log/messages)

Oct 13 09:00:00 Backup-Colo newsyslog19913: logfile turned over due to size>100K
Oct 13 00:00:00 Backup-Colo syslog-ng1622: Configuration reload request received, reloading configuration;

sounds like time is reset at this time... is this during boot time?

I restarted cron service and will check if this "fixes" the problem (probably until next reboot)

Also available in: Atom PDF