Project

General

Profile

Actions

Bug #1715

closed

nfq: broken time stamps with recent Linux kernel 4.4

Added by Joachim Schwender over 5 years ago. Updated over 5 years ago.

Status:
Closed
Priority:
Normal
Assignee:
Target version:
Affected Versions:
Effort:
Difficulty:
Label:

Description

Suricata 3.0 and 2.0.11 have broken time stamps in log files when they run Linux kernel 4.4.0 ... 4.4.2
With older kernels (tested 4.3.3) the time stamp is ok.
This blocks the use of suricata on newer kernels.


Files

fast (4.69 KB) fast portion of fast.log showing the result Joachim Schwender, 02/19/2016 11:00 AM
sucata1715.tar.gz (197 KB) sucata1715.tar.gz build info, kernel version, list of packages... Joachim Schwender, 02/26/2016 03:07 AM
Actions #1

Updated by Peter Manev over 5 years ago

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 ?

Actions #2

Updated by Andreas Herz over 5 years ago

  • Assignee set to Anonymous
  • Target version set to 70

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

Actions #3

Updated by Jay MJ over 5 years ago

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.

Actions #4

Updated by Joachim Schwender over 5 years ago

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.

Actions #5

Updated by Peter Manev over 5 years ago

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?

Actions #6

Updated by Victor Julien over 5 years ago

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

Actions #7

Updated by Joachim Schwender over 5 years ago

i will do that, it will take some time.

Actions #8

Updated by Victor Julien over 5 years ago

  • Status changed from New to Assigned
  • Assignee changed from Anonymous to Victor Julien
Actions #9

Updated by Joachim Schwender over 5 years ago

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.

Actions #10

Updated by Marcel de Groot over 5 years ago

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.

Actions #11

Updated by Victor Julien over 5 years ago

Are there differences in time settings? Timezones, etc?

Actions #12

Updated by Marcel de Groot over 5 years ago

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

Actions #13

Updated by Joachim Schwender over 5 years ago

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

Actions #14

Updated by Andreas Herz over 5 years ago

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.

Actions #15

Updated by Joachim Schwender over 5 years ago

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"

Actions #16

Updated by Joachim Schwender over 5 years ago

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

Actions #17

Updated by Duarte Silva over 5 years ago

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

Actions #18

Updated by Andreas Herz over 5 years ago

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

Actions #19

Updated by Duarte Silva over 5 years ago

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

Actions #20

Updated by Victor Julien over 5 years ago

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

Actions #21

Updated by Duarte Silva over 5 years ago

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.

Actions #22

Updated by Joachim Schwender over 5 years ago

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.

Actions #23

Updated by Andreas Herz over 5 years ago

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

Actions #24

Updated by Joachim Schwender over 5 years ago

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.

Actions #25

Updated by Joachim Schwender over 5 years ago

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

Actions #26

Updated by Victor Julien over 5 years ago

  • Subject changed from Broken time stamps with recent Linux kernel 4.4 to nfq: broken time stamps with recent Linux kernel 4.4
  • Status changed from Assigned to Closed
  • Target version changed from 70 to 3.0.1RC1
Actions

Also available in: Atom PDF