Duplicated "end" and "idle" events received for some flows

verzulli commented 2 years ago

While analyzing my incoming UDP-stream, I noticed that sometime (in the order of once every one thousand) my nDPId-rt-analyzer receive two consecutive end event or two consecutive idle event referred to the very same flow_id

This lead my analyzer to complain, as it expect that for every flow_id, it should receive only one of end|idle event.

I double checked my analyzer, and I bet that it effectively received the events twice, despite the fact that they are identical.

I have no problem getting rid of the spurious event... but probably, this could be of some interest to you.

I'm attaching a ZIP containing the JSON-dump of a selection of 4 distinct flows (id: 7337, 30684, 33023, 32921) where you can clearly see the final double events.

duplicated_evts_example.zip

utoni commented 2 years ago

Yeah, this is indeed of interest. Thanks for reporting this. Will investigate asap.

utoni commented 2 years ago

Can you check if one of those patches fixes your issue? 0.patch.txt 1.patch.txt

utoni commented 2 years ago

Strange, the issue you described does not occur on any of my machines. How did you start nDPId ?

verzulli commented 2 years ago

On my OpenWRT box, I launched it with:

/usr/sbin/nDPId-testing -i br-lan -c 192.168.0.128:9999 -d -o max-packets-per-flow-to-send=0

If you would like to test yourself, as for the receiver side, I launched my container with:

docker run -d \
   -p 9999:9999/udp -e UDP_PORT=9999 \
   -p 2323:2323 \
   -e CLI_CONSOLE_PORT=2323 -e CLI_CONSOLE_PROMPT=nDPId-rt-analyzer \
   -e STORE_PATH=/tmp \
   --name ndpid-analyzer \
   registry.gitlab.com/verzulli/ndpid-rt-analyzer

when running, just limit debug messages to errors (loglevel error) and enable JSON capture (jsoncapture on):

[verzulli@XPSGarr ~]$ telnet localhost 2323
Trying ::1...
Connected to localhost.
Escape character is '^]'.
****************************************************
***            nDPId-rt-analyzer                 ***
***         v. 0.1 - Console Server              ***
****************************************************

nDPId-rt-analyzer> loglevel error
Enabling 'error' log level...
nDPId-rt-analyzer> jsoncapture on
Adding JSONs to /tmp/raw_json.stream ...
nDPId-rt-analyzer>

At the same time, on the container side, check console messages:

[verzulli@XPSGarr tmp]$ docker logs -f ndpid-analyzer
15-10-2022 16:15:48.875 [nDPId-rt-analyzer] info: [MAIN] Lancio il receiver...
15-10-2022 16:15:48.878 [nDPId-rt-analyzer] info: [analyzer/init] Initializing receiving UDP socket...
15-10-2022 16:15:48.880 [nDPId-rt-analyzer] info: [analyzer/init] Binding the UDP-server socket on port [9999]
15-10-2022 16:15:48.880 [nDPId-rt-analyzer] info: [MAIN] Starting Console server
15-10-2022 16:15:48.880 [nDPId-rt-analyzer] info: [EngineConsole/startConsoleServer] Starting console server: [undefined/2323]
15-10-2022 16:15:48.882 [nDPId-rt-analyzer] info: [MAIN] All done!
15-10-2022 16:16:06.419 [nDPId-rt-analyzer] info: [EngineConsole/onConsoleClientConnected] New client connected: [::ffff:172.17.0.1/50752]
15-10-2022 16:16:11.341 [nDPId-rt-analyzer] info: [EngineConsole/onConsoleSocketData] Executing ==>loglevel<===
15-10-2022 16:20:07.165 [nDPId-rt-analyzer] error: [parser/parseMessage] error: [TypeError: [sprintf] expecting number but found undefined]
15-10-2022 16:20:35.762 [nDPId-rt-analyzer] error: [parser/parseFlow] end-ed flow [141] already presente in _completedFlowMap!
15-10-2022 16:21:54.447 [nDPId-rt-analyzer] error: [parser/parseFlow] end-ed flow [456] already presente in _completedFlowMap!
15-10-2022 16:22:13.051 [nDPId-rt-analyzer] error: [parser/parseFlow] end-ed flow [404] already presente in _completedFlowMap!
15-10-2022 16:25:37.850 [nDPId-rt-analyzer] error: [parser/parseFlow] end-ed flow [762] already presente in _completedFlowMap!
15-10-2022 16:27:26.113 [nDPId-rt-analyzer] error: [parser/parseFlow] end-ed flow [969] already presente in _completedFlowMap!
15-10-2022 16:28:17.299 [nDPId-rt-analyzer] error: [parser/parseFlow] end-ed flow [1064] already presente in _completedFlowMap!

and as you can see from the last six lines, there are duplications.

I'm attaching here the /tmp/raw_json.stream generated, inside which you can find the final double end (flow_id 456):

[root@XPSGarr tmp]# grep 'flow_id":456' raw_json.stream 
{"flow_event_id":1,"flow_event_name":"new","thread_id":2,"packet_id":40626,"source":"br-lan","alias":"GW-Big-Brother","flow_id":456,"flow_state":"info","flow_src_packets_processed":1,"flow_dst_packets_processed":0,"flow_first_seen":1665850781509334,"flow_src_last_pkt_time":1665850781509334,"flow_dst_last_pkt_time":1665850781509334,"flow_idle_time":3285032704,"flow_src_min_l4_payload_len":0,"flow_dst_min_l4_payload_len":0,"flow_src_max_l4_payload_len":0,"flow_dst_max_l4_payload_len":0,"flow_src_tot_l4_payload_len":0,"flow_dst_tot_l4_payload_len":0,"midstream":0,"thread_ts_usec":1665850781509334,"l3_proto":"ip4","src_ip":"192.168.0.128","dst_ip":"138.201.89.83","src_port":56114,"dst_port":443,"l4_proto":"tcp","flow_datalink":1,"flow_max_packets":0}
{"flow_event_id":7,"flow_event_name":"detected","thread_id":2,"packet_id":40661,"source":"br-lan","alias":"GW-Big-Brother","flow_id":456,"flow_state":"info","flow_src_packets_processed":3,"flow_dst_packets_processed":1,"flow_first_seen":1665850781509334,"flow_src_last_pkt_time":1665850781605959,"flow_dst_last_pkt_time":1665850781600229,"flow_idle_time":3285032704,"flow_src_min_l4_payload_len":0,"flow_dst_min_l4_payload_len":0,"flow_src_max_l4_payload_len":576,"flow_dst_max_l4_payload_len":0,"flow_src_tot_l4_payload_len":576,"flow_dst_tot_l4_payload_len":0,"midstream":0,"thread_ts_usec":1665850781605959,"l3_proto":"ip4","src_ip":"192.168.0.128","dst_ip":"138.201.89.83","src_port":56114,"dst_port":443,"l4_proto":"tcp","ndpi": {"flow_risk": {"15": {"risk":"TLS (probably) Not Carrying HTTPS","severity":"Low","risk_score": {"total":760,"client":680,"server":80}}},"confidence": {"6":"DPI"},"proto":"TLS","proto_id":"91","encrypted":1,"breed":"Safe","category_id":5,"category":"Web","hostname":"www.soabit.com","tls": {"version":"TLSv1.2","ja3":"784e2f24aea88930342d050fd31bce1c","ja3s":"","unsafe_cipher":0,"cipher":"TLS_NULL_WITH_NULL_NULL","tls_supported_versions":"TLSv1.3,TLSv1.2,TLSv1.1,TLSv1"}}}
{"flow_event_id":8,"flow_event_name":"detection-update","thread_id":2,"packet_id":40675,"source":"br-lan","alias":"GW-Big-Brother","flow_id":456,"flow_state":"info","flow_src_packets_processed":3,"flow_dst_packets_processed":3,"flow_first_seen":1665850781509334,"flow_src_last_pkt_time":1665850781605959,"flow_dst_last_pkt_time":1665850781685139,"flow_idle_time":3285032704,"flow_src_min_l4_payload_len":0,"flow_dst_min_l4_payload_len":0,"flow_src_max_l4_payload_len":576,"flow_dst_max_l4_payload_len":137,"flow_src_tot_l4_payload_len":576,"flow_dst_tot_l4_payload_len":137,"midstream":0,"thread_ts_usec":1665850781685139,"l3_proto":"ip4","src_ip":"192.168.0.128","dst_ip":"138.201.89.83","src_port":56114,"dst_port":443,"l4_proto":"tcp","ndpi": {"flow_risk": {"15": {"risk":"TLS (probably) Not Carrying HTTPS","severity":"Low","risk_score": {"total":760,"client":680,"server":80}}},"confidence": {"6":"DPI"},"proto":"TLS","proto_id":"91","encrypted":1,"breed":"Safe","category_id":5,"category":"Web","hostname":"www.soabit.com","tls": {"version":"TLSv1.2","ja3":"784e2f24aea88930342d050fd31bce1c","ja3s":"fbe78c619e7ea20046131294ad087f05","unsafe_cipher":0,"cipher":"TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256","tls_supported_versions":"TLSv1.3,TLSv1.2,TLSv1.1,TLSv1"}}}
{"flow_event_id":2,"flow_event_name":"end","thread_id":2,"packet_id":61572,"source":"br-lan","alias":"GW-Big-Brother","flow_id":456,"flow_state":"finished","flow_src_packets_processed":8,"flow_dst_packets_processed":8,"flow_first_seen":1665850781509334,"flow_src_last_pkt_time":1665850787126037,"flow_dst_last_pkt_time":1665850787185214,"flow_idle_time":3285032704,"flow_src_min_l4_payload_len":0,"flow_dst_min_l4_payload_len":0,"flow_src_max_l4_payload_len":896,"flow_dst_max_l4_payload_len":392,"flow_src_tot_l4_payload_len":1523,"flow_dst_tot_l4_payload_len":529,"midstream":0,"thread_ts_usec":1665850912917254,"l3_proto":"ip4","src_ip":"192.168.0.128","dst_ip":"138.201.89.83","src_port":56114,"dst_port":443,"l4_proto":"tcp","flow_datalink":1,"flow_max_packets":0,"ndpi": {"flow_risk": {"15": {"risk":"TLS (probably) Not Carrying HTTPS","severity":"Low","risk_score": {"total":760,"client":680,"server":80}}},"confidence": {"6":"DPI"},"proto":"TLS","proto_id":"91","encrypted":1,"breed":"Safe","category_id":5,"category":"Web"}}
{"flow_event_id":2,"flow_event_name":"end","thread_id":2,"packet_id":61572,"source":"br-lan","alias":"GW-Big-Brother","flow_id":456,"flow_state":"finished","flow_src_packets_processed":8,"flow_dst_packets_processed":8,"flow_first_seen":1665850781509334,"flow_src_last_pkt_time":1665850787126037,"flow_dst_last_pkt_time":1665850787185214,"flow_idle_time":3285032704,"flow_src_min_l4_payload_len":0,"flow_dst_min_l4_payload_len":0,"flow_src_max_l4_payload_len":896,"flow_dst_max_l4_payload_len":392,"flow_src_tot_l4_payload_len":1523,"flow_dst_tot_l4_payload_len":529,"midstream":0,"thread_ts_usec":1665850912917254,"l3_proto":"ip4","src_ip":"192.168.0.128","dst_ip":"138.201.89.83","src_port":56114,"dst_port":443,"l4_proto":"tcp","flow_datalink":1,"flow_max_packets":0,"ndpi": {"flow_risk": {"15": {"risk":"TLS (probably) Not Carrying HTTPS","severity":"Low","risk_score": {"total":760,"client":680,"server":80}}},"confidence": {"6":"DPI"},"proto":"TLS","proto_id":"91","encrypted":1,"breed":"Safe","category_id":5,"category":"Web"}}
[root@XPSGarr tmp]#

raw_json.stream.zip

verzulli commented 2 years ago

I further investigated the issue, just to be sure it really was a problem in the "incoming flows", and not related to some bug of my analyzer. I'm attaching a ZIP file, containing a PCAP file I captured this morning. As you can see:

in packets 3989 and 3990, tcpdump captured TWO "idle" events, related to flow_id=491;
in packets 8288 and 8292, tcpdump captured TWO "end" events, related to flow_id=1179;
in packets 19022 and 19023, tcpdump captured TWO "end" events, related to flow_id=2030.

There are some more others.... but I think the above should be enough to start troubleshooting.

Cheers, DV

sniff.dump.zip

utoni commented 2 years ago

I am not sure, but the issue might be related to the UDP endpoint setting. Still investigating.

utoni commented 2 years ago

While investigating your pcap file, i clearly see this unwanted behavior. But I was still not able to reproduce this on my side.

verzulli commented 2 years ago

I'll close this issue as, even from my side, the behaviour seems to have been disappeared. Should I detect it again, I'll open a new issue. Thanks

utoni / nDPId

Duplicated "end" and "idle" events received for some flows #12