Time difference in System log

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

noone knows? I wondering the same thing

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

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'

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

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:~#

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

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
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

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

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'

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'

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 :rage:

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.

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

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…

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.

1 Like

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

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

1 Like

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)); 
};
1 Like

Please check this issue:

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