Suricata timestamps are +2 hours relative to their corresponding Zeek events

[philrz]

I've thus far only been able to repro this problem on my personal Thinkpad running Windows 10. I'd love to assume that my laptop is some unique corner case we'll never see in the wild, however I'd like to understand the root cause so we don't have the risk of other users running into the same problem.

Here's a repro with the Brim-Setup-rc-v0.20.0-suricata18.exe artifact and a walk through of why it creates trouble. I start by importing the https://archive.wrccdc.org/pcaps/2018/wrccdc.2018-03-23.010014000000000.pcap.gz test pcap (after uncompressing it, of course). My understanding is that in the pcap import case, we've traditionally set the default time pickers based on the begin/end timestamps we find in the overall pcap when we're indexing it, since the timestamps for all the Zeek events are expected to fall into this range as well. Here's the state of the app after that import finishes:

However, because of the +2 hour timestamp problem, a search for Suricata alerts out of the gate shows nothing.

However, if I select "Whole Space" from the time picker, the end time gets advanced by +2 and we see the Suricata alerts showing up in that time range.

Since we don't yet have Community ID on Windows (#43) it's a little tricky to pair up the alert with the corresponding Zeek event, but for this pairing it's possible since the alert is complaining about DNS contact to .biz and indeed we can find the corresponding Zeek event that summarized the same query:

My plan is to first do a bit of work with a "regular" Suricata-for-Windows and compare its output with what happens here to see if the timestamp problem is ever present on my laptop or if it follows the Suricata build.

[alfred-landrum]

FYI, I reproduced this on my Windows 10 laptop as well.

[philrz]

I've managed to reproduce this on something other than someone's personal Windows 10 laptop. 😉

It looks like the secret ingredient may be timezone settings. I spun up a Windows 2016 Server VM in Google Cloud. I installed the Brim-rc-v0.20.0-suricata20.exe artifact and imported the wrccdc pcap. All the Suricata alerts were within the pcap's time range as reflected in the picker.

However, that's when I noticed the timezone on the VM was at its default of UTC.

I then set the timezone to Pacific and redid the import, and now the alerts were outside the default range, and I had to once again change the picker settings to Whole Space to get them.

I was then able to change the timezone back to UTC and repro the problem yet again. Interestingly, from what I can tell, the delta doesn't seem to change based on which timezone I've selected, as I saw the same +2 hour difference if I changed to Eastern timezone.

[philrz]

I've now been able to narrow this down to a general Suricata problem.

On a scratch Windows 2016 VM in Google Cloud, I installed https://nmap.org/npcap/dist/npcap-1.00.exe and then https://www.openinfosecfoundation.org/download/windows/Suricata-6.0.0-beta1-1-64bit.msi. Using that same wrccdc.pcap, I test via:

"\Program Files\Suricata\suricata.exe" -r wrccdc.pcap

When my system timezone is set to default UTC, the timestamp of the top event in eve.json is 2018-03-23T19:58:22.647908+0000. If I paste that into the ISO8601 box at https://www.timestamp-converter.com/, it translates to:

Date (UTC)  Mar 23, 2018, 8:58:22 PM

Then when my system timezone is set to Pacific, the timestamp of the top event in eve.json is 2018-03-23T12:58:22.647908-0900. Pasted into that tool, it translates to:

Date (UTC)  Mar 23, 2018, 10:58:22 PM

While baselining in Suricata v5.0.3 I ran into the bug discussed at https://forum.suricata.io/t/eve-json-windows-timestamp-field-has-eastern-daylight-time-appended-to-timestamp/197 which leads to the change at https://github.com/OISF/suricata/pull/4976/commits/bbdc11842d324005567bac5eafdea5fd0fc62688#diff-d8eecda9235371babc2890abb8415eeb9310a124444ea5189aa39e36025bbff9, which seems suspicious since it involves mucking with timestamps specifically on Windows, and this problem involves timestamps and we're only seeing it on Windows. @henridf is looking closer at that code.

[philrz]

I've opened an issue with Suricata https://redmine.openinfosecfoundation.org/issues/4183 in the event they figure it out before we do.

[henridf]

fixed with brimsec/suricata#2

[philrz]

Verified with draft Brim artifact rc-v0.20.0-suricatav5.0.3-brimpre1 that includes the fixed Suricata build. Now when I import the wrccdc pcap, the Suricata alerts are immediately visible as part of the time range that's been set based on the pcap.

If I isolate and group the events without changing the time range, I see the diverse set.

If I select "Whole Space" in the picker, the numbers remain the same, as we would expect.

Thanks @henridf!