Support #3104
closedeve-nsm log of flow has timestamp much later than flow end
Description
I'm experimenting with suricata and examining flow logging in eve-nsm.json, and occasionally a flow is logged with a timestamp that is much later (hours or days later) than the flow end.
I've looked for issues in my system logs and suricata logs and found no indications of resource issues or suricata errors.
I've looked through bugs and not found any specifically tied to this kind of problem, though I have noticed some bugs related to deadlocks in the past.
Am I misunderstanding the data, or is this an indication that suricata (or one of its threads) is hanging for a long time before logging a finished flow?
Also, lmk if there is a better forum to ask this.
Here's an example json record (ip addresses removed):
{
"timestamp": "2019-08-01T14:49:27.001024+0000",
"flow_id": 110494497537784,
"event_type": "flow",
"src_ip": "x.x.x.x",
"src_port": 54150,
"dest_ip": "y.y.y.y",
"dest_port": 443,
"proto": "TCP",
"app_proto": "tls",
"flow": {
"pkts_toserver": 28,
"pkts_toclient": 11,
"bytes_toserver": 4392,
"bytes_toclient": 6954,
"start": "2019-07-31T20:59:50.818936+0000",
"end": "2019-07-31T21:01:47.119398+0000",
"age": 117,
"state": "established",
"reason": "timeout",
"alerted": false
},
"tcp": {
"tcp_flags": "1b",
"tcp_flags_ts": "1b",
"tcp_flags_tc": "1a",
"syn": true,
"fin": true,
"psh": true,
"ack": true,
"state": "close_wait"
}
}
TIA
Files
Updated by Peter Manev over 4 years ago
It says age -
"age": 117
Is this a flow record that is logged hours and days after it actually closed ?
Usually the the timeouts control this behavior - https://github.com/OISF/suricata/blob/master/suricata.yaml.in#L1250
What is your set up like where you see this - live traffic/pcap/suricata version/ suricata --build-info output etc ?
Updated by Bill Homan over 4 years ago
Thanks for the response! Yes - the flow record is logged hours after flow end. I have other examples where the log timestamp is days later than flow end. This is live traffic, not replays, in an environment where the flow might have ended because of a routing change. The suricata instance is running on a moderately powerful AWS instance and was not under stress at the time of the above event.
The timeouts are configured exactly as in the link you provided.
Here's build-info output:
suricata --build-info This is Suricata version 4.1.3 RELEASE Features: NFQ PCAP_SET_BUFF AF_PACKET HAVE_PACKET_FANOUT LIBCAP_NG LIBNET1.1 HAVE_HTP_URI_NORMALIZE_HOOK PCRE_JIT HAVE_NSS HAVE_LUA HAVE_LUAJIT HAVE_LIBJANSSON TLS MAGIC RUST SIMD support: none Atomic intrisics: 1 2 4 8 byte(s) 64-bits, Little-endian architecture GCC version 5.4.0 20160609, C version 199901 compiled with _FORTIFY_SOURCE=2 L1 cache line size (CLS)=64 thread local storage method: __thread compiled with LibHTP v0.5.30, linked against LibHTP v0.5.27 Suricata Configuration: AF_PACKET support: yes eBPF support: no XDP support: no PF_RING support: no NFQueue support: yes NFLOG support: no IPFW support: no Netmap support: no DAG enabled: no Napatech enabled: no WinDivert enabled: no Unix socket enabled: yes Detection enabled: yes Libmagic support: yes libnss support: yes libnspr support: yes libjansson support: yes liblzma support: yes hiredis support: yes hiredis async with libevent: yes Prelude support: no PCRE jit: yes LUA support: yes, through luajit libluajit: yes libgeoip: yes Non-bundled htp: yes Old barnyard2 support: no Hyperscan support: no Libnet support: yes liblz4 support: yes Rust support: yes Rust strict mode: no Rust debug mode: no Rust compiler: rustc 1.30.0 Rust cargo: cargo 1.30.0 Install suricatasc: yes Install suricata-update: yes Profiling enabled: no Profiling locks enabled: no Development settings: Coccinelle / spatch: no Unit tests enabled: no Debug output enabled: no Debug validation enabled: no Generic build parameters: Installation prefix: /usr Configuration directory: /etc/suricata/ Log directory: /var/log/suricata/ --prefix /usr --sysconfdir /etc --localstatedir /var --datarootdir /usr/share Host: x86_64-pc-linux-gnu Compiler: gcc (exec name) / gcc (real) GCC Protect enabled: yes GCC march native enabled: no GCC Profile enabled: no Position Independent Executable enabled: yes CFLAGS -g -O2 -fPIE -fstack-protector-strong -Wformat -Werror=format-security -I${srcdir}/../rust/gen/c-headers PCAP_CFLAGS -I/usr/include SECCFLAGS -fstack-protector -D_FORTIFY_SOURCE=2 -Wformat -Wformat-security
Updated by Bill Homan over 4 years ago
I'm posting a copy of our config.
Updated by Peter Manev over 4 years ago
Can you please try the latest stable - 4.1.4 (you are currently on 4.1.3)
Also what i noticed is some mismatch which could result in unexpected behaviour -
compiled with LibHTP v0.5.30, linked against LibHTP v0.5.27
both should be
v0.5.30
It means the libhtp on the system has not been updated during the install or there is something else.
Updated by Bill Homan over 4 years ago
Thanks for the suggestion. Will update when I can apply.
Updated by Andreas Herz over 4 years ago
- Status changed from New to Feedback
- Assignee set to Community Ticket
- Target version set to Support
Updated by Andreas Herz over 3 years ago
- Status changed from Feedback to Closed
Hi, we're closing this issue since there have been no further responses.
If you think this bug is still relevant, try to test it again with the
most recent version of suricata and reopen the issue. If you want to
improve the bug report please take a look at
https://redmine.openinfosecfoundation.org/projects/suricata/wiki/Reporting_Bugs