Time difference in System log

radekpribyl · October 29, 2016, 9:42am

When looking into System log it looks like some programs log the time incorrectly. The router is set in CET timezone (Prague - UTC+2h) and the the entries from dnsmasq are correct while the cron incorrect. And it’s not only cron - e.g. lcollect and other too. It’s not a big deal but when troubleshooting it’s a little challenging to get the right time as I have to check the entries (time sequence) to get the right time.

Any suggestion why is it this way and if I can sync it?

Examples from the system log:

2016-10-29T 11:26:47+02:00 info dnsmasq-dhcp[8355]: DHCPOFFER(br-lan) 192.168.88.53 42:f8:f3:xx:xx:xx
2016-10-29T 09:27:01+02:00 info cron[3683]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2016-10-29T 11:27:03+02:00 info dnsmasq-dhcp[8355]: DHCPDISCOVER(br-lan) 42:f8:f3:xx:xx:xx

2016-10-28T 21:44:13+02:00 info kernel[]: [ 6.659997] hub 4-0:1.0: USB hub found
2016-10-28T 19:44:14+02:00 info lcollect[1751]: Loading plugin library libplugin_lcollect_majordomo_25.so

Jirka · March 10, 2017, 11:39am

noone knows? I wondering the same thing

config system
    option timezone 'CET-1CEST,M3.5.0,M10.5.0/3'
    option zonename 'Europe/Prague'

commar · March 10, 2017, 12:08pm

I got this:

/etc/config/system

config system
        option hostname 'turris'
        option timezone 'CET-1CEST,M3.5.0,M10.5.0/3'
        option zonename 'Europe/Prague'
        option cronloglevel '8'
        option conloglevel '4'

Jirka · March 10, 2017, 12:19pm

Yes, I just pick time-relevant values. I assume you have also shifted time by -1 in syslog?

commar · March 10, 2017, 12:26pm

No, the time is correct:

2017-03-10T13:22:01+01:00 info /usr/sbin/cron[13733]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-03-10T13:22:01+01:00 info /usr/sbin/cron[13732]: (root) CMD (nethist_stats.lua)
2017-03-10T13:23:01+01:00 info /usr/sbin/cron[13876]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-03-10T13:24:01+01:00 info /usr/sbin/cron[14021]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-03-10T13:24:01+01:00 info /usr/sbin/cron[14020]: (root) CMD (nethist_stats.lua)

root@turris:~# uptime
13:28:04 up 14:53, load average: 0.00, 0.03, 0.00
root@turris:~#

Jirka · March 10, 2017, 12:49pm

Some other logs in logfile, not cron particulary… I also have cron logs and date (command) fine, which is quite strange

For example try look at some ssh logs:
2017-03-10T12:43:40+01:00 info sshd[25607]: Accepted publicke

Edit: I take it back, maybe, that I have cron logs shifted also. Mystery.

2017-03-10T12:50:01+01:00 info /usr/sbin/cron[32336]: (root) CMD (nethist_stats.lua)
2017-03-10T12:50:01+01:00 info /usr/sbin/cron[32337]: (root) CMD (   /usr/bin/notifier)
2017-03-10T12:52:01+01:00 info /usr/sbin/cron[32467]: (root) CMD (nethist_stats.lua)
root@Router:~# date
Fri Mar 10 13:53:26 CET 2017

commar · March 10, 2017, 12:55pm

root@turris:~# tail /var/log/messages
2017-03-10T13:50:01+01:00 info /usr/sbin/cron[10057]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-03-10T13:50:01+01:00 info /usr/sbin/cron[10060]: (root) CMD (test -f /mnt/data/temperature_sensors/temperature_sensors.rrd && rrdtool update /mnt/data/temperature_sensors/temperature_sensors.rrd $(date +%s):$(thermometer | tr -s \\n ' ' | awk '{print $2":"$4}'))
2017-03-10T13:51:01+01:00 info /usr/sbin/cron[10297]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-03-10T13:52:01+01:00 info /usr/sbin/cron[10470]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-03-10T13:52:01+01:00 info /usr/sbin/cron[10469]: (root) CMD (nethist_stats.lua)
2017-03-10T13:53:01+01:00 info /usr/sbin/cron[10612]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-03-10T13:53:43+01:00 info sshd[14704]: syslogin_perform_logout: logout() returned an error
2017-03-10T13:54:01+01:00 info /usr/sbin/cron[10849]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-03-10T13:54:01+01:00 info /usr/sbin/cron[10848]: (root) CMD (nethist_stats.lua)
2017-03-10T13:54:02+01:00 info sshd[10752]: Accepted password for root from 90.178.154.89 port 49878 ssh2

Jirka · March 10, 2017, 12:57pm

Ok, thanks for info. Dont know, where is the root cause them, we have the same /etc/config/system …

commar · March 10, 2017, 1:01pm

config timeserver ntp
        # When resolution doesn't work because of wrong time (ntp.nic.cz)
        list server     '217.31.202.100'
        list server     '195.113.144.201'
        list server     '195.113.144.238'
        list server     '2001:1488:ffff::100'
        list server	    'ntp.nic.cz'
        list server     '0.openwrt.pool.ntp.org'
        list server     '1.openwrt.pool.ntp.org'
        list server     '2.openwrt.pool.ntp.org'
        list server     '3.openwrt.pool.ntp.org'
        option enabled 1
        option enable_server '0'

Jirka · March 10, 2017, 1:48pm

I have

   config timeserver 'ntp'
        list server '217.31.202.100'
        list server '195.113.144.201'
        list server '195.113.144.238'
        list server '2001:1488:ffff::100'
        list server 'ntp.nic.cz'
        list server '0.openwrt.pool.ntp.org'
        list server '1.openwrt.pool.ntp.org'
        list server '2.openwrt.pool.ntp.org'
        list server '3.openwrt.pool.ntp.org'
        option enabled '1'

Jirka · March 12, 2017, 7:12pm

After lurking I find that I can confirm first post behauviour. Dnsmasq and syslog-ng itself logs are fine, others (cron, sshd) are 1 hour behind. Date command throws the correct timestamp.

2017-03-12 20:20:01 notice syslog-ng[27834]: syslog-ng starting up; version='3.0.9'
2017-03-12 19:28:44 info sshd[28322]: Accepted publickey

There is something wrong with timezone, for some of the services

Jirka · March 12, 2017, 7:51pm

Finally fixed by ignoring senders timezone. This system-ng config works as it should (you can propably change only ISOTIME to R_ISOTIME, if you are comfortable with default format)

    destination messages {
    file("/var/log/messages" suppress(5) template("${R_YEAR}-${R_MONTH}-${R_DAY} ${R_HOUR}:${R_MIN}:${R_SEC} ${PRIORITY} ${PROGRAM}[${PID}]: ${MSGONLY}\n") log_fifo_size(256));
};

destination cron {
    file("/var/log/cron" suppress(5) template("${R_YEAR}-${R_MONTH}-${R_DAY} ${R_HOUR}:${R_MIN}:${R_SEC} ${PRIORITY} ${PROGRAM}[${PID}]: ${MSGONLY}\n") log_fifo_size(256));
};

Result:

2017-03-12 20:48:49 notice syslog-ng[29601]: syslog-ng shutting down; version='3.0.9'
2017-03-12 20:48:49 notice syslog-ng[29650]: syslog-ng starting up; version='3.0.9'
2017-03-12 20:49:06 info sshd[29666]: Accepted publickey for root

2017-03-12 20:52:01 info /usr/sbin/cron[29854]: (root) CMD (nethist_stats.lua)
2017-03-12 20:54:01 info /usr/sbin/cron[30020]: (root) CMD (nethist_stats.lua)

date
Sun Mar 12 20:55:11 CET 2017

This doesnt solve the root cause, just syslog output, so maybe statistics/collect will be still shifted, but I cant test it myself.

peci1 · June 1, 2017, 11:44pm

The “logger” utility logs with wrong time. Couldn’t this be the “almost root” cause?

adorjanig · October 17, 2017, 3:20pm

This is still an issue in 3.7.5 (I know there are newer versions out, I just haven’t yet updated, because I previously had bad experiences). The timestamps in the system log are totally garbled, both CEST and UTC/GMT are there.

# grep timezone /etc/config/system 
 option timezone 'CET-1CEST,M3.5.0,M10.5.0/3'
#

Snippet from /var/log/messages:

2017-10-17T17:12:04+02:00 info dnsmasq-dhcp[2164]: DHCPACK …
2017-10-17T15:12:05+02:00 info hostapd[]: wlan0: …
2017-10-17T15:12:09+02:00 info hostapd[]: wlan0: …
2017-10-17T15:12:09+02:00 info hostapd[]: wlan0: …
2017-10-17T15:12:09+02:00 info hostapd[]: wlan0: …
2017-10-17T15:12:09+02:00 info hostapd[]: wlan0: …
2017-10-17T17:12:10+02:00 info dnsmasq-dhcp[2164]: DHCPREQUEST …
2017-10-17T17:12:10+02:00 info dnsmasq-dhcp[2164]: DHCPACK …
2017-10-17T15:12:28+02:00 info sshd[19295]: Accepted password for root…

Jirka · October 18, 2017, 9:27am

did you tried my solution above? i am on 3.8.2 and still working fine… Correct time, and format nice to read.

Forgot to mention: Look on file /etc/syslog-ng.conf, inside that file to the part, where you have destination messages {

If you use string which I have,
template("${R_YEAR}-${R_MONTH}-${R_DAY} ${R_HOUR}:${R_MIN}:${R_SEC} ${PRIORITY} ${PROGRAM}[${PID}]: ${MSGONLY}\n"

you should have correct timestamps, I believe. Pity that this is “bug” from default settings. But at least fix is relativelly easy to apply.

adorjanig · October 25, 2017, 11:06am

I haven’t yet tried it, but thanks for the tip, will do.

paja · October 25, 2017, 11:45am

You can also try replace busybox logger with logger from util-linux

tardyp · February 6, 2020, 8:51pm

Just configuring a new Turris Omnia 2019 here, and I still get this issue.

This was a problem for configuring fail2ban as all the messages where detected as it was 1 hour earlier, thus ignored.

workaround worked:

    destination messages {
        file("/var/log/messages" suppress(5) template("${R_YEAR}-${R_MONTH}-${R_DAY} ${R_HOUR}:${R_MIN}:${R_SEC} ${PRIORITY} ${PROGRAM}[${PID}]: ${MSGONLY}\n") log_fifo_size(256)); 
};

Pepe · February 6, 2020, 9:30pm

Please check this issue:

Pepe · February 20, 2020, 5:04pm

This topic was automatically closed after 13 days. New replies are no longer allowed.