Bug #2429
closedTCP-session and wrong alert timestamp
Added by Andrey Kiryukhin about 6 years ago. Updated 5 months ago.
Description
Suricata 4.0.3 (also reproduced on suricata 3.0.2 and 4.0)
I have simple net dump, which contain one tcp-session (see attach for pcap):
15:04:50.767186 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [S], seq 3153782711, win 29200, options [mss 1460,sackOK,TS val 645097 ecr0,nop,wscale 7], length 0
15:04:50.767561 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [S.], seq 895349628, ack 3153782712, win 28960, options [mss 1460,sackOK,TS val 507409790 ecr 645097,nop,wscale 7], length 0
15:04:50.767598 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [.], ack 1, win 229, options [nop,nop,TS val 645097 ecr 507409790], length 0
15:04:52.881885 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 1:8, ack 1, win 229, options [nop,nop,TS val 645625 ecr 507409790], length 7
15:04:52.882199 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 8, win 227, options [nop,nop,TS val 507411905 ecr 645625], length 0
15:04:53.112006 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 8:11, ack 1, win 229, options [nop,nop,TS val 645683 ecr 507411905], length 3
15:04:53.112240 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 11, win 227, options [nop,nop,TS val 507412134 ecr 645683], length 0
15:04:53.291222 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 11:13, ack 1, win 229, options [nop,nop,TS val 645728 ecr 507412134], length 2
15:04:53.291500 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 13, win 227, options [nop,nop,TS val 507412314 ecr 645728], length 0
15:04:54.060623 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 13:17, ack 1, win 229, options [nop,nop,TS val 645920 ecr 507412314], length 4
15:04:54.060883 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 17, win 227, options [nop,nop,TS val 507413083 ecr 645920], length 0
15:04:56.042481 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 17:22, ack 1, win 229, options [nop,nop,TS val 646415 ecr 507413083], length 5
15:04:56.042766 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 22, win 227, options [nop,nop,TS val 507415065 ecr 646415], length 0
15:04:56.431254 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 22:26, ack 1, win 229, options [nop,nop,TS val 646513 ecr 507415065], length 4
15:04:56.431904 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 26, win 227, options [nop,nop,TS val 507415454 ecr 646513], length 0
15:04:56.647552 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 26:29, ack 1, win 229, options [nop,nop,TS val 646567 ecr 507415454], length 3
15:04:56.647800 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 29, win 227, options [nop,nop,TS val 507415670 ecr 646567], length 0
15:04:56.826973 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 29:31, ack 1, win 229, options [nop,nop,TS val 646612 ecr 507415670], length 2
15:04:56.827221 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 31, win 227, options [nop,nop,TS val 507415849 ecr 646612], length 0
15:04:57.007120 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 31:35, ack 1, win 229, options [nop,nop,TS val 646657 ecr 507415849], length 4
15:04:57.007403 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 35, win 227, options [nop,nop,TS val 507416030 ecr 646657], length 0
15:04:58.502805 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 35:39, ack 1, win 229, options [nop,nop,TS val 647031 ecr 507416030], length 4
15:04:58.503039 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 39, win 227, options [nop,nop,TS val 507417525 ecr 647031], length 0
15:05:02.349810 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 39:40, ack 1, win 229, options [nop,nop,TS val 647992 ecr 507417525], length 1
15:05:02.350067 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 40, win 227, options [nop,nop,TS val 507421372 ecr 647992], length 0
15:05:02.582109 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 40:41, ack 1, win 229, options [nop,nop,TS val 648050 ecr 507421372], length 1
15:05:02.582413 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 41, win 227, options [nop,nop,TS val 507421604 ecr 648050], length 0
15:05:05.082504 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 41:54, ack 1, win 229, options [nop,nop,TS val 648675 ecr 507421604], length 13
15:05:05.082746 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 54, win 227, options [nop,nop,TS val 507424105 ecr 648675], length 0
15:05:05.373542 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 54:58, ack 1, win 229, options [nop,nop,TS val 648748 ecr 507424105], length 4
15:05:05.373790 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 58, win 227, options [nop,nop,TS val 507424396 ecr 648748], length 0
15:05:05.628330 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 58:62, ack 1, win 229, options [nop,nop,TS val 648812 ecr 507424396], length 4
15:05:05.628595 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 62, win 227, options [nop,nop,TS val 507424650 ecr 648812], length 0
15:05:06.014253 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 62:63, ack 1, win 229, options [nop,nop,TS val 648908 ecr 507424650], length 1
15:05:06.014547 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 63, win 227, options [nop,nop,TS val 507425036 ecr 648908], length 0
15:05:06.225345 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 63:67, ack 1, win 229, options [nop,nop,TS val 648961 ecr 507425036], length 4
15:05:06.225607 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 67, win 227, options [nop,nop,TS val 507425248 ecr 648961], length 0
15:05:06.404309 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 67:70, ack 1, win 229, options [nop,nop,TS val 649006 ecr 507425248], length 3
15:05:06.404563 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 70, win 227, options [nop,nop,TS val 507425427 ecr 649006], length 0
15:05:06.579484 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 70:73, ack 1, win 229, options [nop,nop,TS val 649050 ecr 507425427], length 3
15:05:06.579939 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 73, win 227, options [nop,nop,TS val 507425602 ecr 649050], length 0
15:05:08.947010 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [P.], seq 73:105, ack 1, win 229, options [nop,nop,TS val 649642 ecr 507425602], length 32
15:05:08.947301 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [.], ack 105, win 227, options [nop,nop,TS val 507427969 ecr 649642], length 0
15:05:09.915135 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [F.], seq 105, ack 1, win 229, options [nop,nop,TS val 649884 ecr 507427969], length 0
15:05:09.915836 IP 192.168.56.102.9999 > 192.168.56.101.35825: Flags [F.], seq 1, ack 106, win 227, options [nop,nop,TS val 507428938 ecr 649884], length 0
15:05:09.915853 IP 192.168.56.101.35825 > 192.168.56.102.9999: Flags [.], ack 2, win 229, options [nop,nop,TS val 649884 ecr 507428938], length 0
In one packet (time stamp 15:04:56.042481 ) exist sample test pattern "TEST".
in my test_sig.rules:
alert tcp any any -> any any (msg: "Test sig"; content: "TEST"; sid: 9000000; classtype: unknown;)
next start suricata:
sudo suricata -c /usr/local/etc/suricata/suricata.yaml -S test_sig.rules -k none -r init_dump.pcap
result:
01/27/2018-15:05:09.915135 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
Expected, that alert time must be 15:04:56.042481 (time of packet, containing test string), but it's time 15:05:09.915135 (corresponding to FYN packet).
I reproduce this case on different ways, such, as live replaying it on net, change ip search pattern and ip addresses, but i always got the same result - alert fix time of FIN packet, but not time of packet with pattern.
Files
| init_dump.pcap (3.82 KB) init_dump.pcap | Andrey Kiryukhin, 01/27/2018 06:47 AM |
Updated by Andreas Herz about 6 years ago
- Assignee set to OISF Dev
- Target version set to TBD
Updated by Andreas Herz almost 5 years ago
I can confirm that with 5.0 beta, but might be even intentional to be like that?
Updated by Victor Julien over 4 years ago
This is probably because TCP data is inspected when its ACKd. What if you enable IPS simulation (--simulate-ips). This will put the stream inspection in a more real time mode.
Updated by Andreas Herz over 4 years ago
This is w ith simulate-ips :)
01/27/2018-13:04:56.042481 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:04:56.431254 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:04:56.647552 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:04:56.826973 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:04:57.007120 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:04:58.502805 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:05:02.349810 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:05:02.582109 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:05:05.082504 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:05:05.373542 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:05:05.628330 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:05:06.014253 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:05:06.225345 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:05:06.404309 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:05:06.579484 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
01/27/2018-13:05:08.947010 [**] [1:9000000:0] Test sig [**] [Classification: Unknown Traffic] [Priority: 3] {TCP} 192.168.56.101:35825 -> 192.168.56.102:9999
Updated by Jason Ish about 2 years ago
- Related to Bug #3480: EVE JSON - Incorrect Packet Logged added
Updated by Philippe Antoine 5 months ago
- Status changed from New to Rejected
Working as expected.
There are other tickets about this such as #3480 if this behavior needs to be more highlighted