Issue with syslog parsing and dates on inserts to database


#1

Morning All,

I’m having a weird issue with times in the postgresql database for opennms. We use the syslog server to take in events from remove system, and then parse these into events using the syslogd component of OpenNMS.

Since we updated the system last week, the syslog messages being raised into the database end up being reverted to 2018 instead of 2019. Please see the output from the database here:

eventid | eventtime | eventuei | eventlogmsg
----------±-----------------------±------------------------------------------±-------------------------------------------------------
35568801 | 2019-03-06 09:41:14+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 9:41:14.19
35568800 | 2019-03-06 09:41:12+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 9:41:11.91
35568748 | 2018-03-06 09:35:57+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 9:35:56.94
35568747 | 2018-03-06 09:35:55+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 9:35:55.63
35568746 | 2018-03-06 09:35:33+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 9:35:33.48
35568690 | 2018-03-06 09:24:48+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 9:24:47.69
35568673 | 2018-03-06 09:03:22+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 9:03:22.11
35568648 | 2018-03-06 08:33:22+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 8:33:22.11
35568597 | 2018-03-06 08:03:22+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 8:03:22.11
35568567 | 2018-03-06 07:33:22+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 7:33:22.12
35568547 | 2018-03-06 07:03:23+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 7:03:22.13
35568525 | 2018-03-06 06:33:23+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 6:33:22.13
35568496 | 2018-03-06 06:03:22+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 6:03:22.11
35568454 | 2018-03-06 05:33:24+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 5:33:23.42
35568431 | 2019-03-06 05:03:24+00 | syslog/Logstash/informational | Message: logstash is running ok 06/03/2019 5:03:23.68

Please note the event times which go from 2019 to 2018 and upon system restart to back to 2019.
Restarting is not enough, i am forced to start the system before it is correct (Please also note the system time is correct)

Does anyone have any ideas which could cause this?

This only seems to affect the syslog components all over events are the correct time.

Thanks

Joe.


#2

I’d guess this recent change may be related: NMS-10548

Do you happen to have any clock skew between OpenNMS and the devices sending the syslog events?


#3

That sounds like the same issue

I actually raised a bug too.

https://issues.opennms.org/browse/NMS-10605

We do not have clock skew, all our systems are NTP sync and i’ve double checked that that is working as that was my first thought.

We have been asked to try org.opennms.netmgt.syslogd.RadixTreeSyslogParser syslog parser but the same issue happens with that.

eventid | eventtime | eventuei | eventlogmsg | nodeid
----------±-----------------------±------------------------------------------±-------------------------------------------------------±-------
35572126 | 2018-03-08 09:17:28+00 | syslog/Logstash/informational | Message: logstash is running ok 08/03/2019 9:17:27.16 | 82
35572100 | 2018-03-08 08:47:28+00 | syslog/Logstash/informational | Message: logstash is running ok 08/03/2019 8:47:27.17 | 82
35572072 | 2018-03-08 08:17:28+00 | syslog/Logstash/informational | Message: logstash is running ok 08/03/2019 8:17:27.22 | 82
35572054 | 2018-03-08 07:47:27+00 | syslog/Logstash/informational | Message: logstash is running ok 08/03/2019 7:47:27.17 | 82
35572030 | 2018-03-08 07:17:27+00 | syslog/Logstash/informational | Message: logstash is running ok 08/03/2019 7:17:27.18 | 82
35572015 | 2018-03-08 06:47:27+00 | syslog/Logstash/informational | Message: logstash is running ok 08/03/2019 6:47:27.18 | 82
35571976 | 2018-03-08 06:17:27+00 | syslog/Logstash/informational | Message: logstash is running ok 08/03/2019 6:17:27.17 | 82
35571942 | 2018-03-08 05:47:27+00 | syslog/Logstash/informational | Message: logstash is running ok 08/03/2019 5:47:27.24 | 82
35571913 | 2019-03-08 05:17:27+00 | syslog/Logstash/informational | Message: logstash is running ok 08/03/2019 5:17:27.21 | 82
35571890 | 2019-03-08 04:47:31+00 | syslog/Logstash/informational | Message: logstash is running ok 08/03/2019 4:47:31.89 | 82
35571867 | 2018-03-08 04:17:29+00 | syslog/Logstash/informational | Message: logstash is running ok 08/03/2019 4:17:27.95 | 82

It odd that it randomly happens, heres an example of the issue occouring and it was fine with the 2 seconds messages after it.

Cheers

Joe.