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

[utoni]

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

[utoni]

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

[utoni]

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

[verzulli]

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]

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]

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

[utoni]

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

[verzulli]

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