Bug: ISO8601 timestamp in syslog - always using UTC time

MarcusH · Tue Apr 04, 2017 4:52 pm

There seems to be a bug in RouterOS (observed on 6.37.5 running on RB1100AHx2) related to the ISO8601 timestamp in bsd syslog messages:

Syslog config:

/system logging action print
Flags: * - default
[...]
 7   name="netwatch" target=remote remote=192.168.100.11 remote-port=5000 src-address=0.0.0.0 bsd-syslog=yes
     syslog-time-format=iso8601 syslog-facility=local3 syslog-severity=auto
     
/system logging print detail
[...]
 7    topics=script,info prefix="" action=netwatch

Generating an event and capturing it with tcpdump on the receiving end:

Message generation and router clock:

[admin@foobar] > :log info ("test01"); system clock print
                  time: 09:45:25
                  date: apr/04/2017
  time-zone-autodetect: no
        time-zone-name: EST5EDT
            gmt-offset: -04:00
            dst-active: yes

Received syslog message (via tcpdump):

# tcpdump port 5000 -An
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on enp0s20f0, link-type EN10MB (Ethernet), capture size 65535 bytes
09:45:25.593920 IP 192.168.103.10.53251 > 192.168.100.11.commplex-main: UDP, length 48
E..L..@.@..:..g
..d......8..<158>2017-04-04T13:45:25.0000-0400 foobar test01

As you can see from the tcpdump, the timestamp sent is
2017-04-04T13:45:25.0000-0400

But it should be - as verified by router clock:
2017-04-04T09:45:25.0000-0400

Looks like the Syslog message always dumps UTC time but appends the correct TZ offset.

martinb · Thu Jun 01, 2017 9:11 am

Hello,
I have the same issue on CCR1036-12G-4S (firmware version 3.27, RouterOS version 6.35.4) We have currently 8:08 AM in Czech republic. Clock on the router is sync correctly with NTP and I can agree that it is correct. But when I open the log window there I can see mesages with timestamps with 2 hours offset like 6:08 AM.

Is there any fix on this? Or it is already in production just I use old routeros version?

jprietove · Tue May 01, 2018 12:53 pm

Hello. I am having this problem too. CHR version 6.42.1. I'm reporting this as a bug

jprietove · Tue May 01, 2018 7:31 pm

Hello, after digging I've found a mistake in my rsyslog configuration that led to this problem. Mikrotik remote log is reporting logs with its current time, so I think it is fine.

adamgardner2 · Wed Oct 03, 2018 4:51 am

I'd like to say, I _don't_ think this is fine. With

syslog-time-format=iso8601

, RouterOS emits syslog events that give the timestamp pre-converted to UTC but then include a local-time UTC offset anyway.

In other words, If it is 2018/06/08 at 10:00 in America/New_York (so, UTC-0400), then the timestamp should be either 2018-06-08T10:00:00.000-0400 or 2018-06-08T14:00:00Z, but right now the Mikrotik sends a timestamp of 2018-06-08T14:00:00-0400, equivalent to 2018-06-08T18:00:00Z.

Bug: ISO8601 timestamp in syslog - always using UTC time

Bug: ISO8601 timestamp in syslog - always using UTC time

Re: Bug: ISO8601 timestamp in syslog - always using UTC time

Re: Bug: ISO8601 timestamp in syslog - always using UTC time

Re: Bug: ISO8601 timestamp in syslog - always using UTC time

Re: Bug: ISO8601 timestamp in syslog - always using UTC time

Who is online