Suricata

I dont seem to be able to reproduce it with 4.4.0 (Debian) and Suricata 3.0 -

root@SELKS:~# uname -a
Linux SELKS 4.4.0-stamus-amd64 #1 SMP Sat Feb 6 15:18:09 CET 2016 x86_64 GNU/Linux
root@SELKS:~# 
root@SELKS:~# tail -F /var/log/suricata/
certs/              core/               eve-alert.json      eve.json            fast.log            files/              StatsByDate/        stats.log           suricata.log        suricata-start.log
root@SELKS:~# tail -F /var/log/suricata/fast.log 
02/19/2016-11:49:18.133581  [**] [1:2200029:1] SURICATA ICMPv6 unknown type [**] [Classification: (null)] [Priority: 3] {IPv6-ICMP} fe80:0000:0000:0000:0482:41aa:c1c1:2740:143 -> ff02:0000:0000:0000:0000:0000:0000:0016:0
02/19/2016-11:49:20.283966  [**] [1:2200029:1] SURICATA ICMPv6 unknown type [**] [Classification: (null)] [Priority: 3] {IPv6-ICMP} fe80:0000:0000:0000:0482:41aa:c1c1:2740:143 -> ff02:0000:0000:0000:0000:0000:0000:0016:0
02/19/2016-11:56:28.218438  [**] [1:2200029:1] SURICATA ICMPv6 unknown type [**] [Classification: (null)] [Priority: 3] {IPv6-ICMP} fe80:0000:0000:0000:00de:ea21:f77e:3dd6:143 -> ff02:0000:0000:0000:0000:0000:0000:0016:0
02/19/2016-11:56:31.290526  [**] [1:2200029:1] SURICATA ICMPv6 unknown type [**] [Classification: (null)] [Priority: 3] {IPv6-ICMP} fe80:0000:0000:0000:00de:ea21:f77e:3dd6:143 -> ff02:0000:0000:0000:0000:0000:0000:0016:0
02/19/2016-11:58:22.498059  [**] [1:2200029:1] SURICATA ICMPv6 unknown type [**] [Classification: (null)] [Priority: 3] {IPv6-ICMP} fe80:0000:0000:0000:00ae:a94d:06d2:932d:143 -> ff02:0000:0000:0000:0000:0000:0000:0016:0
02/19/2016-11:58:24.648798  [**] [1:2200029:1] SURICATA ICMPv6 unknown type [**] [Classification: (null)] [Priority: 3] {IPv6-ICMP} fe80:0000:0000:0000:00ae:a94d:06d2:932d:143 -> ff02:0000:0000:0000:0000:0000:0000:0016:0
02/19/2016-11:59:03.048416  [**] [1:2200029:1] SURICATA ICMPv6 unknown type [**] [Classification: (null)] [Priority: 3] {IPv6-ICMP} fe80:0000:0000:0000:0482:41aa:c1c1:2740:143 -> ff02:0000:0000:0000:0000:0000:0000:0016:0
02/19/2016-11:59:06.118908  [**] [1:2200029:1] SURICATA ICMPv6 unknown type [**] [Classification: (null)] [Priority: 3] {IPv6-ICMP} fe80:0000:0000:0000:0482:41aa:c1c1:2740:143 -> ff02:0000:0000:0000:0000:0000:0000:0016:0
02/19/2016-12:15:56.200392  [**] [1:2200029:1] SURICATA ICMPv6 unknown type [**] [Classification: (null)] [Priority: 3] {IPv6-ICMP} fe80:0000:0000:0000:00de:ea21:f77e:3dd6:143 -> ff02:0000:0000:0000:0000:0000:0000:0016:0
02/19/2016-12:15:59.270582  [**] [1:2200029:1] SURICATA ICMPv6 unknown type [**] [Classification: (null)] [Priority: 3] {IPv6-ICMP} fe80:0000:0000:0000:00de:ea21:f77e:3dd6:143 -> ff02:0000:0000:0000:0000:0000:0000:0016:0
^C
root@SELKS:~# uname -a
Linux SELKS 4.4.0-stamus-amd64 #1 SMP Sat Feb 6 15:18:09 CET 2016 x86_64 GNU/Linux
root@SELKS:~# date
Fri Feb 19 12:17:38 EST 2016
root@SELKS:~# suricata -V
This is Suricata version 3.0 RELEASE
root@SELKS:~#

Anything specific to your environment ?

Andreas Herz wrote:

Can you please provide us with used distribution and build-info from suricata?
Couldn't reproduce it either with ArchLinux, Debian, Gentoo and CentOS and 4.4.1 (4.4.2).

I also run ArchLinux x64, latest stable kernel, and could not produce.

It is production a debian 7.9, with vanilla Kernel 4.3.3 which was ok, and i tested upgrading to kernel 4.4.0 and 4.4.2 which both showed this behaviour. Kernel configuration is the same, and Suricata is currently
This is Suricata version 3.0 RELEASE
and i have observed this also with suricata 2.0.10 and kernel 4.4. glibc is 2.13-1. The hardware is Fijitsu-Siemens R100 with dual Xeon X3430.

The bug report cites Debian and there is the same issue reported on the user list about Ubuntu - so something is up I suspect.
As mentioned before - we can not reproduce it on a number of systems (including for Debian 4.4 and 4.4.2 kernel - at least in my tests) - strange.

Anything specific/different the way the kernel/suricata is compiled/installed?

Joachim, could you recompile Suricata with the --disable-threading-tls configure flag and see if the issue happens as well?

i will do that, it will take some time.

That does not helo. I compiled with --disable-threading-tls booted into kernel 4.4.2 and the log files have broken time stamps. I saw that there were small changes in hrtimer.c in the kernel, but i cannot see why it end up in something like this. Maybe it is a issue with glibc in combination with these kernels.

I'm also seeing this. Strange thing though:
On two machines (Debian Stretch), both with the same Suricata 3.0 compiled from source with NFQUEUE enabled, and the same kernel, also compiled from source (4.5.0-rc5), one writes the timestamp correctly and the other not:

On the one machine where this symptom plays Suricata is listening via iptables mangle on the FORWARD chain
On the other machine it listens via NFQUEUE in the mangle table on the INPUT and OUTPUT chain. Here the timestamps are correct.

00.000000 [**] [1:2200075:1] SURICATA ...etc
vs
02/25/2016-14:31:10.631435 [**] [1:2522390:2498] ...etc

I'll try to check whether changing the NFQUEUE entry makes a difference.

Are there differences in time settings? Timezones, etc?

One addition: I'm seeing this since the 7th of January 2016. Before that the timestamps in fast.log where good. After that the 0 or the 1970... stuff.
Not sure what I was running then; I'm guessing kernel 4.4.0 with Suricata 3.0-rc3 or whatever the latest rc of the kernel / Suricata was at the time).

on my machine i have the following:
LANG=de_DE.UTF-8
LC_TIME=en_DK.UTF-8
SHELL=/bin/bash
iptable uses NFQUEUE as target from INPUT, OUTPUT and FORWARD, not from mangle

Since you all mentioned the use of NFQUEUE i tried that on my machines with 4.4.x kernel and couldn't reproduce it with that mode either. It's seems to be debian/ubuntu specific for now, and even a working debian system from Marcel. Can you provide us with the following infos, so we can gather and compare them:

• suricata --build-info
• exact kernel version and maybe even the config
• other relevant package versions like glibc, libnetfilter_queue especially on the two debian machines that differ somehow
• how you run suricata (commandline)
• system wide time settings

It would be also worth testing other tools that use NFQUEUE to see if they have the same issue on your machines.

Suricata log is the only log file with broken time stamps under the conditions mentioned.

Hi lads,

I can reproduce this in a CentOS 7, Kernel is 4.4.2-1.el7.elrepo.x86_64 (from ELRepo) and Suricata is 2.0.11-1.el7.x86_64 (the one compiled by Jason Ish). The timestamps get screwed up.

# date
Fri Feb 26 22:37:18 UTC 2016

# tail -n 1 /var/log/suricata/eve.json 
{"timestamp":"1900-01-00T00:00:00.000000","event_type":"dns","src_ip":"8.8.4.4","src_port":53,"dest_ip":"xxx.xxx.xxx.xxx","dest_port":51079,"proto":"UDP","dns":{"type":"answer","id":37092,"rrname":"103.in-addr.arpa","rrtype":"SOA","ttl":1325}}

This doesn't seem to to happen in the console log though.

# tail /var/log/suricata/suricata.log 
26/2/2016 -- 22:17:32 - <Notice> - This is Suricata version 2.0.11 RELEASE
26/2/2016 -- 22:17:36 - <Notice> - all 1 packet processing threads, 3 management threads initialized, engine started.

Hope it helps,
Duarte

Joachim Schwender wrote:

I am not clear waht you mean by system wide time settings?
we run chrony on all machines, and this one is the time reference in our network. setting in /etc/default/locale is LANG="de_DE.UTF-8"

Do you use ntp for example?

@Duarte can you also say how you run suricata (which mode)?

Andreas Herz wrote:

Joachim Schwender wrote:

I am not clear waht you mean by system wide time settings?
we run chrony on all machines, and this one is the time reference in our network. setting in /etc/default/locale is LANG="de_DE.UTF-8"

Do you use ntp for example?

@Duarte can you also say how you run suricata (which mode)?

I'm running Suricata in workers mode with NFQUEUE (nftables-0.4-3 and libnetfilter_queue-1.0.2-2).

Does anyone have this problem w/o running NFQUEUE? For NFQUEUE we have a fix/workaround in the git master: https://github.com/inliniac/suricata/commit/2b263d55a2d0583a2c02e352bfe490fd4f42b39a

It might be it, because sometimes I get the right timestamp, and others the wrong.

{"timestamp":"1900-01-00T00:00:00.000000","event_type":"http","src_ip":"xxx.xxx.xxx.xxx","src_port":55038,"dest_ip":"88.221.14.17","dest_port":80,"proto":"TCP","http":{"hostname":"ocsp.startssl.com","url":"\/sub\/class1\/server\/ca\/MEgwRjBEMEIwQDAJBgUrDgMCGgUABBRlaIdPQHUPAWo0dWJeH1yT5aJtWAQU60I00Jiwq5%2f0G2sI98xkLu8OLEUCBwYr%2brOfAEw%3d","http_content_type":"application\/ocsp-response"}}
{"timestamp":"1900-01-00T00:00:00.000000","event_type":"alert","src_ip":"yyy.yyy.yyy.yyy","src_port":45716,"dest_ip":"xxx.xxx.xxx.xxx","dest_port":80,"proto":"TCP","alert":{"action":"blocked","gid":1,"signature_id":2006446,"rev":11,"signature":"ET WEB_SERVER Possible SQL Injection Attempt UNION SELECT","category":"Web Application Attack","severity":1}}
{"timestamp":"1900-01-00T00:00:00.000000","event_type":"alert","src_ip":"yyy.yyy.yyy.yyy","src_port":45716,"dest_ip":"xxx.xxx.xxx.xxx","dest_port":80,"proto":"TCP","alert":{"action":"blocked","gid":1,"signature_id":2010963,"rev":5,"signature":"ET WEB_SERVER SELECT USER SQL Injection Attempt in URI","category":"Web Application Attack","severity":1}}
{"timestamp":"1900-01-00T00:00:00.000000","event_type":"http","src_ip":"yyy.yyy.yyy.yyy","src_port":45716,"dest_ip":"xxx.xxx.xxx.xxx","dest_port":80,"proto":"TCP","http":{"hostname":"www.domain.tld","url":"\/index?tag=network%27%20UNION%20ALL%20SELECT%201,2,3,user--","http_user_agent":"Mozilla\/5.0 (X11; Linux x86_64; rv:38.0) Gecko\/20100101 Firefox\/38.0"}}
{"timestamp":"2016-02-27T13:01:22.892294","event_type":"http","src_ip":"yyy.yyy.yyy.yyy","src_port":45718,"dest_ip":"xxx.xxx.xxx.xxx","dest_port":80,"proto":"TCP","http":{"hostname":"www.domain.tld","url":"\/wp-content\/themes\/twentyfifteen-child\/style.css?ver=4.4.2","http_user_agent":"Mozilla\/5.0 (X11; Linux x86_64; rv:38.0) Gecko\/20100101 Firefox\/38.0","http_content_type":"text\/css"}}
{"timestamp":"2016-02-27T13:01:22.907107","event_type":"http","src_ip":"yyy.yyy.yyy.yyy","src_port":45724,"dest_ip":"xxx.xxx.xxx.xxx","dest_port":80,"proto":"TCP","http":{"hostname":"www.domain.tld","url":"\/wp-includes\/js\/jquery\/jquery-migrate.min.js?ver=1.2.1","http_user_agent":"Mozilla\/5.0 (X11; Linux x86_64; rv:38.0) Gecko\/20100101 Firefox\/38.0","http_content_type":"application\/javascript"}}
{"timestamp":"2016-02-27T13:01:22.908906","event_type":"http","src_ip":"yyy.yyy.yyy.yyy","src_port":45726,"dest_ip":"xxx.xxx.xxx.xxx","dest_port":80,"proto":"TCP","http":{"hostname":"www.domain.tld","url":"\/wp-content\/themes\/twentyfifteen\/js\/skip-link-focus-fix.js?ver=20141010","http_user_agent":"Mozilla\/5.0 (X11; Linux x86_64; rv:38.0) Gecko\/20100101 Firefox\/38.0","http_content_type":"application\/javascript"}}

I'm going to test newer versions to see if it changes behaviour.

Andreas Herz wrote:

Joachim Schwender wrote:

I am not clear waht you mean by system wide time settings?
we run chrony on all machines, and this one is the time reference in our network. setting in /etc/default/locale is LANG="de_DE.UTF-8"

Do you use ntp for example?

@Duarte can you also say how you run suricata (which mode)?

We don't use ntp, we use chrony instead to adjust the system time.

@Joachim can you test the fix/workaround that Victor linked? On the mailinglist we have the first who said that solved the issue at his system.

Running suricata 3.0 with vanilla kernel 4.4.2 all timestamps are ok in the logs i have in use (dns, fast, stats, suricata-start, suricata) . --disable-threading-tls does not make a difference, so i removed this compile option.

I can confirm that it also works with vanilla kernel 4.4.3.

https://bugzilla.netfilter.org/show_bug.cgi?id=1066