Bug #992
openDifferent alerts reported when reading from pcap file with runmode=single and runmode=autofp
Description
When running suricata processing a pcap file, I see different alerts between runmode=autofp and runmode=single.
Some of the differences could be thresholds, but for sid:2221010, which have apps-layer-event, but no thresholds, I still see differences.
The attached script runs suricata on a specific pcap file with a specified runmode. To run the two cases, I do:
./test-one-file LL1999_Week1_Tue_inside.pcap single
./test-one-file LL1999_Week1_Tue_inside.pcap autofp
Comparing the results, there are different number of alerts for sid:2221010
grep 1:2221010:1 single-results/LL1999_Week1_Tue_inside.sorted | wc -l
4694
ken@lab-39:~/test-suricata$ grep 1:2221010:1 autofp-results/LL1999_Week1_Tue_inside.sorted | wc -l
4373
Test pcap file: http://www.ll.mit.edu/mission/communications/cyber/CSTcorpora/ideval/data/1999/training/week1/tuesday/inside.tcpdump.gz
git version: c1190545cfb1d06037847b94620591d2be6f3c07
$ LD_LIBRARY_PATH=/usr/local/lib /usr/local/bin/suricata --build-info
This is Suricata version 2.0dev (rev c119054)
Features: PCAP_SET_BUFF LIBPCAP_VERSION_MAJOR=1 AF_PACKET HAVE_PACKET_FANOUT LIBCAP_NG LIBNET1.1 HAVE_HTP_URI_NORMALIZE_HOOK
64-bits, Little-endian architecture
GCC version 4.6.3, C version 199901
__GCC_HAVE_SYNC_COMPARE_AND_SWAP_1
__GCC_HAVE_SYNC_COMPARE_AND_SWAP_2
__GCC_HAVE_SYNC_COMPARE_AND_SWAP_4
__GCC_HAVE_SYNC_COMPARE_AND_SWAP_8
__GCC_HAVE_SYNC_COMPARE_AND_SWAP_16
compiled with -fstack-protector
compiled with _FORTIFY_SOURCE=2
L1 cache line size (CLS)=64
compiled with LibHTP v0.5.7, linked against LibHTP v0.5.7
Suricata Configuration:
AF_PACKET support: yes
PF_RING support: no
NFQueue support: no
IPFW support: no
DAG enabled: no
Napatech enabled: no
Unix socket enabled: no
libnss support: no
libnspr support: no
libjansson support: no
Prelude support: no
PCRE jit: no
libluajit: no
libgeoip: no
Non-bundled htp: no
Old barnyard2 support: no
CUDA enabled: no
Suricatasc install: yes
Unit tests enabled: no
Debug output enabled: no
Debug validation enabled: no
Profiling enabled: no
Profiling locks enabled: no
Generic build parameters:
Installation prefix (--prefix): /usr/local
Configuration directory (--sysconfdir): /usr/local/etc/suricata/
Log directory (--localstatedir) : /usr/local/var/log/suricata/
Host: x86_64-unknown-linux-gnu
GCC binary: gcc
GCC Protect enabled: no
GCC march native enabled: yes
GCC Profile enabled: no
CPU (12 cores 2 threads/core):
processor : 23
vendor_id : GenuineIntel
cpu family : 6
model : 44
model name : Intel(R) Xeon(R) CPU X5660 @ 2.80GHz
stepping : 2
microcode : 0xc
cpu MHz : 2793.017
Files
KS Updated by Ken Steele almost 13 years ago
- File autofp-6732-10298.sorted autofp-6732-10298.sorted added
- File compare-results compare-results added
- File LLS_DDOS_2.0.2-inside.pcap.xz LLS_DDOS_2.0.2-inside.pcap.xz added
- File LLS-208.209.46.47.pcap LLS-208.209.46.47.pcap added
- File LLS-6732.pcap LLS-6732.pcap added
- File LLS-6732-10298.pcap LLS-6732-10298.pcap added
- File LLS-10298.pcap LLS-10298.pcap added
- File LLS-not-10298.pcap LLS-not-10298.pcap added
- File single-6732-10298.sorted single-6732-10298.sorted added
- File suricata.yaml suricata.yaml added
I have a smaller testcase that shows the different alerts generated when reading the same pcap file with runmode single and runmode autofp. Additional alerts are output in single runmode (see the difference between single-6732-10298.sorted and autofp-6732-10298.sorted).
To run the testcases, install suricata in /usr/local/bin (default location) and run:
./test-one-file LLS-6732-10298.pcap single
./test-one-file LLS-6732-10298.pcap autofp
This generates two directories: single-results and autofp-results, that contain LLS-6732-10298.fast and LLS-6732-10298.sorted (strip off time-stamps from .fast and sort).
The files LLS-6732-10298.pcap were created from Lincoln Labs 1999 DDOS file by selecting the two flows between IPs 208.209.46.37 and 172.16.115.87 with ports 6732 and ports 10298. The other LLS- files are similar, with different subsets of ports.
Most interesting, LLS-6732.pcap by itself generates the same alerts in single and autofp, as does LLS-10298.pcap, only putting both flows in the same pcap file causes the problem. Note, flow 10298 comes after flow 6732 in the pcap files. I have not tried reordering the pcap files.
File LLS-208.209.46.37.pcap contains all the flows between IPs 208.209.46.37 and 172.16.115.87 and LLS-not-10298.pcap is the same except removing flow with port 10298. The former gives different alerts, the latter the same alerts.
This testing requires the patch to disable Detect Keywors by adding testing.detect config in suricata.yaml (see attached file).
KS Updated by Ken Steele almost 13 years ago
Needs PR: https://github.com/inliniac/suricata/pull/594 to disable Detect keywords.
AS Updated by Anoop Saldanha almost 13 years ago
From the top of my head one of the reasons for the difference is alerts might be timing. When you process a pcap the global time used to track flows comes from the packet timestamps, i.e. for every packet we update the global time based on the packet timestamp. When you combine pcaps this can result in rubbish timestamp updates inside the engine, which in turn can result in flows getting culled sooner or at wrong intervals.
AS Updated by Anoop Saldanha almost 13 years ago
- Assignee set to Anoop Saldanha
- Target version set to 2.0beta2
KS Updated by Ken Steele almost 13 years ago
These files are generated by removing packets from the original file, not combining pcap files.
The reason for disabling the keywords was to remove the affects of threshold timing, but yes, there could be other timing factors.
Another option I have investigated is defining a pcap file replay "rate", for example 25,000 packets/second. If that also updated the global time, then it might be more consistent.
AS Updated by Anoop Saldanha almost 13 years ago
Ken Steele wrote:
These files are generated by removing packets from the original file, not combining pcap files.
Doesn't matter how you obtained the files. End of the day pcap file mode can introduce this issue, and combining flows from various timestamp ranges can worsen this behaviour.
The reason for disabling the keywords was to remove the affects of threshold timing, but yes, there could be other timing factors.
Yes, there are, like the one I just explained.
Another option I have investigated is defining a pcap file replay "rate", for example 25,000 packets/second. If that also updated the global time, then it might be more consistent.
Live mode shouldn't see any of the flow timing issue I suggested, afai can see, although this doesn't mean this issue can't exist.
To exemplify the issue, you can modify your conf file to use some high timeout values and see if that changes the alert nos - autofp and single, alike.
default:
new: 4294967295
established: 4294967295
closed: 4294967295
emergency-new: 4294967295
emergency-established: 4294967295
emergency-closed: 4294967295
tcp:
new: 4294967295
established: 4294967295
closed: 4294967295
emergency-new: 4294967295
emergency-established: 4294967295
emergency-closed: 4294967295
udp:
new: 4294967295
established: 4294967295
emergency-new: 4294967295
emergency-established: 4294967295
icmp:
new: 4294967295
established: 4294967295
emergency-new: 4294967295
emergency-established: 4294967295
1. Run single mode multiple times. Do you get the same no of alerts for every run?
2. Run autofp mode multiple times. Do you get the same no of alerts for every run?
3. Do the nos from (1) match the nos from (2). Has the difference/margin between the 2 increased/decreased?
VJ Updated by Victor Julien over 12 years ago
- Target version changed from 2.0beta2 to TBD
AH Updated by Andreas Herz almost 10 years ago
- Assignee changed from Anoop Saldanha to OISF Dev
AH Updated by Andreas Herz over 7 years ago
- Status changed from New 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
DW Updated by David Wharton 8 days ago
Disclosure : I had AI write up most all of this, with my guidance. All attached files are AI-generated (part of an AI pcap creation harness I'm working on using Flowsynth).
I got burned by this recently. Still present in 8.0.6 RELEASE. Attaching a minimal reproducer (suricata-992-repro.tar.gz).
The timestamp mechanism Anoop described in 2013 is directly observable, and the reproducer isolates it: two pcaps in one directory make the discontinuity explicit and controllable. Per the manpage, files read that way are "processed in order of modified time maintaining flow state between files", so a gap between captures becomes a gap in the engine's global clock.
Reproducer¶
Two pcaps, 14 packets total, one rule:
flow-a.pcap-- an HTTP transaction whose response body carries a marker string. Well-formed (Content-Lengthmatches the body), but the session is never closed: no FIN, no RST. This is ordinary for a truncated lab capture.flow-b.pcap-- an unrelated, non-matching HTTP transaction on a different source port, timestamped 1300s after flow A. Its only role is to advance the engine's packet-derived clock.test.rules-- one signature matching the marker viafile_data/from_server.
Expected result: exactly 1 alert on every run.
./run.sh 500 # default runmode ./run.sh 500 --runmode single # control
Results¶
Suricata 8.0.6 RELEASE, stock /usr/local/etc/suricata/suricata.yaml (no tuning; flow-timeouts.tcp.established at its default of 600):
| configuration | runs alerting |
|---|---|
| default runmode, 1300s gap | 988/1000 (200-run lots: 200, 198, 198, 196, 196) |
--runmode single, 1300s gap |
400/400 |
| default runmode, 2s gap | 400/400 |
Roughly 1 run in 80 loses the alert. Note that at that rate a single 200-run batch comes back clean about 1 time in 10, so ./run.sh 500 or more is worth running before concluding it does not reproduce.
What happens on a failing run¶
Flow A is split into two flow records -- it is aged out mid-connection:
failing run (eve.json, flow A only): flow state=established reason=timeout pkts_ts=2 pkts_tc=1 flow state=new reason=shutdown pkts_ts=2 pkts_tc=2 (no http event, no alert) passing run: http status=200 length=47 alert repro marker in response body flow state=established reason=shutdown pkts_ts=4 pkts_tc=3
Flow A's seven packets span 6ms of capture time, so nothing in flow A can age it out. Eviction requires the clock to be at least 600s past its last packet, which means flow B's packets (1300s later) have already advanced the global clock while flow A's remaining packets are still in flight.
The consequence is that the response arrives at a flow that no longer exists. A new flow is created with no request in it, libhtp never builds a transaction (hence no http event and no response body), and the signature is never given anything to match against. The alert is not generated late -- it is not generated at all.
Why this may be worth reopening¶
Offline pcap replay is the basis for rule validation and regression testing, so a few percent of runs silently returning a different answer on identical input is difficult to design around. Neither workaround -- keeping capture timestamps within flow-timeouts.tcp.established of each other, or running single-threaded -- is documented, and you can only arrive at either by diagnosing the failure first. A warning when consecutive files in a directory run are separated by more than the relevant flow timeout would at least make the condition visible.