suricata icon indicating copy to clipboard operation
suricata copied to clipboard

dpdk: count number of packets with invalid checksum v1

Open lukashino opened this issue 2 years ago • 1 comments

Make sure these boxes are signed before submitting your Pull Request -- thank you.

  • [X] I have read the contributing guide lines at https://redmine.openinfosecfoundation.org/projects/suricata/wiki/Contributing
  • [X] I have signed the Open Information Security Foundation contribution agreement at https://suricata.io/about/contribution-agreement/
  • [X] I have updated the user guide (in doc/userguide/) to reflect the changes made (if applicable)

Link to redmine ticket:

Describe changes:

  • fix a lost mbuf case when Suricata packet allocation failed, Suricata continued but the mbuf was never freed
  • support counting packets with an invalid checksum
  • add XSTATS output for a more detailed debug of NIC stats

lukashino avatar Sep 21 '22 14:09 lukashino

Codecov Report

Merging #7893 (94c4ffd) into master (a9a17c8) will increase coverage by 0.21%. The diff coverage is n/a.

Additional details and impacted files
@@            Coverage Diff             @@
##           master    #7893      +/-   ##
==========================================
+ Coverage   75.85%   76.07%   +0.21%     
==========================================
  Files         666      666              
  Lines      186269   185998     -271     
==========================================
+ Hits       141301   141504     +203     
+ Misses      44968    44494     -474     
Flag Coverage Δ
fuzzcorpus 60.81% <ø> (+0.32%) :arrow_up:
suricata-verify 52.72% <ø> (+0.12%) :arrow_up:
unittests 60.69% <ø> (+0.09%) :arrow_up:

Flags with carried forward coverage won't be shown. Click here to find out more.

codecov[bot] avatar Sep 21 '22 15:09 codecov[bot]

Can you add example output? Of the PrintDPDKPortXstats function?

It prints out non-zero counters so there might be more or less output depending on how busy counters were. Here is an example:

[3390] 22/9/2022 -- 08:44:34 - (tm-threads.c:1927) <Notice> (TmThreadWaitOnThreadInit) -- Threads created -> W: 1 FM: 1 FR: 1   Engine started.                                                                                                       
[3390] 22/9/2022 -- 08:45:13 - (suricata.c:2776) <Notice> (SuricataMainLoop) -- Signal Received.  Stopping engine.
[3390] 22/9/2022 -- 08:45:14 - (suricata.c:1168) <Info> (SCPrintElapsedTime) -- time elapsed 42.095s
[3401] 22/9/2022 -- 08:45:15 - (flow-manager.c:1124) <Perf> (FlowRecycler) -- 41758 flows processed
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_good_packets:              999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_good_bytes:                760030582
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_q0_packets:                999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_q0_bytes:          760030582
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_unicast_packets:           963516
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_unicast_bytes:             724508317
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_multicast_packets:         36483
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_multicast_bytes:           39522261
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_phy_packets:               999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_phy_bytes:         764030578
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:587) <Perf> (ReceiveDPDKThreadExitStats) -- Total RX stats of 0000:3b:00.1: packets 999999 bytes: 760030582 missed: 0 errors: 0 nombufs: 0
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:598) <Perf> (ReceiveDPDKThreadExitStats) -- (W#01-0000..00.1) received packets 999999
[3390] 22/9/2022 -- 08:45:16 - (counters.c:871) <Info> (StatsLogSummary) -- Alerts: 0
[3390] 22/9/2022 -- 08:45:16 - (ippair.c:296) <Perf> (IPPairPrintStats) -- ippair memory usage: 414144 bytes, maximum: 16777216
[3390] 22/9/2022 -- 08:45:17 - (host.c:299) <Perf> (HostPrintStats) -- host memory usage: 398144 bytes, maximum: 335544320
[3390] 22/9/2022 -- 08:45:17 - (detect-engine-build.c:1784) <Info> (SigAddressCleanupStage1) -- cleaning up signature grouping structure... complete
[3390] 22/9/2022 -- 08:45:17 - (util-device.c:355) <Notice> (LiveDeviceListClean) -- Stats for '0000:3b:00.1':  pkts: 999999, drop: 0 (0.00%), invalid chksum: 0
[3390] 22/9/2022 -- 08:45:17 - (util-dpdk.c:52) <Info> (DPDKCloseDevice) -- Closing device 0000:3b:00.1

lukashino avatar Sep 22 '22 06:09 lukashino

Continues in #7900

lukashino avatar Sep 22 '22 06:09 lukashino

Can you add example output? Of the PrintDPDKPortXstats function?

It prints out non-zero counters so there might be more or less output depending on how busy counters were. Here is an example:

[3390] 22/9/2022 -- 08:44:34 - (tm-threads.c:1927) <Notice> (TmThreadWaitOnThreadInit) -- Threads created -> W: 1 FM: 1 FR: 1   Engine started.                                                                                                       
[3390] 22/9/2022 -- 08:45:13 - (suricata.c:2776) <Notice> (SuricataMainLoop) -- Signal Received.  Stopping engine.
[3390] 22/9/2022 -- 08:45:14 - (suricata.c:1168) <Info> (SCPrintElapsedTime) -- time elapsed 42.095s
[3401] 22/9/2022 -- 08:45:15 - (flow-manager.c:1124) <Perf> (FlowRecycler) -- 41758 flows processed
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_good_packets:              999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_good_bytes:                760030582
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_q0_packets:                999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_q0_bytes:          760030582
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_unicast_packets:           963516
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_unicast_bytes:             724508317
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_multicast_packets:         36483
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_multicast_bytes:           39522261
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_phy_packets:               999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_phy_bytes:         764030578
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:587) <Perf> (ReceiveDPDKThreadExitStats) -- Total RX stats of 0000:3b:00.1: packets 999999 bytes: 760030582 missed: 0 errors: 0 nombufs: 0
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:598) <Perf> (ReceiveDPDKThreadExitStats) -- (W#01-0000..00.1) received packets 999999
[3390] 22/9/2022 -- 08:45:16 - (counters.c:871) <Info> (StatsLogSummary) -- Alerts: 0
[3390] 22/9/2022 -- 08:45:16 - (ippair.c:296) <Perf> (IPPairPrintStats) -- ippair memory usage: 414144 bytes, maximum: 16777216
[3390] 22/9/2022 -- 08:45:17 - (host.c:299) <Perf> (HostPrintStats) -- host memory usage: 398144 bytes, maximum: 335544320
[3390] 22/9/2022 -- 08:45:17 - (detect-engine-build.c:1784) <Info> (SigAddressCleanupStage1) -- cleaning up signature grouping structure... complete
[3390] 22/9/2022 -- 08:45:17 - (util-device.c:355) <Notice> (LiveDeviceListClean) -- Stats for '0000:3b:00.1':  pkts: 999999, drop: 0 (0.00%), invalid chksum: 0
[3390] 22/9/2022 -- 08:45:17 - (util-dpdk.c:52) <Info> (DPDKCloseDevice) -- Closing device 0000:3b:00.1

That looks a bit... custom. Why the ___s? Why the spaces/tabs between name and values?

victorjulien avatar Sep 22 '22 10:09 victorjulien

Can you add example output? Of the PrintDPDKPortXstats function?

It prints out non-zero counters so there might be more or less output depending on how busy counters were. Here is an example:

[3390] 22/9/2022 -- 08:44:34 - (tm-threads.c:1927) <Notice> (TmThreadWaitOnThreadInit) -- Threads created -> W: 1 FM: 1 FR: 1   Engine started.                                                                                                       
[3390] 22/9/2022 -- 08:45:13 - (suricata.c:2776) <Notice> (SuricataMainLoop) -- Signal Received.  Stopping engine.
[3390] 22/9/2022 -- 08:45:14 - (suricata.c:1168) <Info> (SCPrintElapsedTime) -- time elapsed 42.095s
[3401] 22/9/2022 -- 08:45:15 - (flow-manager.c:1124) <Perf> (FlowRecycler) -- 41758 flows processed
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_good_packets:              999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_good_bytes:                760030582
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_q0_packets:                999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_q0_bytes:          760030582
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_unicast_packets:           963516
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_unicast_bytes:             724508317
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_multicast_packets:         36483
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_multicast_bytes:           39522261
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_phy_packets:               999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_phy_bytes:         764030578
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:587) <Perf> (ReceiveDPDKThreadExitStats) -- Total RX stats of 0000:3b:00.1: packets 999999 bytes: 760030582 missed: 0 errors: 0 nombufs: 0
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:598) <Perf> (ReceiveDPDKThreadExitStats) -- (W#01-0000..00.1) received packets 999999
[3390] 22/9/2022 -- 08:45:16 - (counters.c:871) <Info> (StatsLogSummary) -- Alerts: 0
[3390] 22/9/2022 -- 08:45:16 - (ippair.c:296) <Perf> (IPPairPrintStats) -- ippair memory usage: 414144 bytes, maximum: 16777216
[3390] 22/9/2022 -- 08:45:17 - (host.c:299) <Perf> (HostPrintStats) -- host memory usage: 398144 bytes, maximum: 335544320
[3390] 22/9/2022 -- 08:45:17 - (detect-engine-build.c:1784) <Info> (SigAddressCleanupStage1) -- cleaning up signature grouping structure... complete
[3390] 22/9/2022 -- 08:45:17 - (util-device.c:355) <Notice> (LiveDeviceListClean) -- Stats for '0000:3b:00.1':  pkts: 999999, drop: 0 (0.00%), invalid chksum: 0
[3390] 22/9/2022 -- 08:45:17 - (util-dpdk.c:52) <Info> (DPDKCloseDevice) -- Closing device 0000:3b:00.1

That looks a bit... custom. Why the ___s? Why the spaces/tabs between name and values?

It's a DPDK code snippet and I thought it looks fine. I have no strong feelings about that and can remove it.

lukashino avatar Sep 22 '22 11:09 lukashino

Can you add example output? Of the PrintDPDKPortXstats function?

It prints out non-zero counters so there might be more or less output depending on how busy counters were. Here is an example:

[3390] 22/9/2022 -- 08:44:34 - (tm-threads.c:1927) <Notice> (TmThreadWaitOnThreadInit) -- Threads created -> W: 1 FM: 1 FR: 1   Engine started.                                                                                                       
[3390] 22/9/2022 -- 08:45:13 - (suricata.c:2776) <Notice> (SuricataMainLoop) -- Signal Received.  Stopping engine.
[3390] 22/9/2022 -- 08:45:14 - (suricata.c:1168) <Info> (SCPrintElapsedTime) -- time elapsed 42.095s
[3401] 22/9/2022 -- 08:45:15 - (flow-manager.c:1124) <Perf> (FlowRecycler) -- 41758 flows processed
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_good_packets:              999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_good_bytes:                760030582
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_q0_packets:                999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_q0_bytes:          760030582
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_unicast_packets:           963516
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_unicast_bytes:             724508317
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_multicast_packets:         36483
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_multicast_bytes:           39522261
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_phy_packets:               999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1): _______ rx_phy_bytes:         764030578
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:587) <Perf> (ReceiveDPDKThreadExitStats) -- Total RX stats of 0000:3b:00.1: packets 999999 bytes: 760030582 missed: 0 errors: 0 nombufs: 0
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:598) <Perf> (ReceiveDPDKThreadExitStats) -- (W#01-0000..00.1) received packets 999999
[3390] 22/9/2022 -- 08:45:16 - (counters.c:871) <Info> (StatsLogSummary) -- Alerts: 0
[3390] 22/9/2022 -- 08:45:16 - (ippair.c:296) <Perf> (IPPairPrintStats) -- ippair memory usage: 414144 bytes, maximum: 16777216
[3390] 22/9/2022 -- 08:45:17 - (host.c:299) <Perf> (HostPrintStats) -- host memory usage: 398144 bytes, maximum: 335544320
[3390] 22/9/2022 -- 08:45:17 - (detect-engine-build.c:1784) <Info> (SigAddressCleanupStage1) -- cleaning up signature grouping structure... complete
[3390] 22/9/2022 -- 08:45:17 - (util-device.c:355) <Notice> (LiveDeviceListClean) -- Stats for '0000:3b:00.1':  pkts: 999999, drop: 0 (0.00%), invalid chksum: 0
[3390] 22/9/2022 -- 08:45:17 - (util-dpdk.c:52) <Info> (DPDKCloseDevice) -- Closing device 0000:3b:00.1

That looks a bit... custom. Why the ___s? Why the spaces/tabs between name and values?

It's a DPDK code snippet and I thought it looks fine. I have no strong feelings about that and can remove it.

Changed output in the version 3 branch to:

[3401] 22/9/2022 -- 08:45:15 - (flow-manager.c:1124) <Perf> (FlowRecycler) -- 41758 flows processed
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1) - rx_good_packets: 999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1) - rx_good_bytes: 760030582
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1) - rx_q0_packets: 999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1) - rx_q0_bytes: 760030582
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1) - rx_unicast_packets: 963516
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1) - rx_unicast_bytes: 724508317
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1) - rx_multicast_packets: 36483
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1) - rx_multicast_bytes: 39522261
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1) - rx_phy_packets: 999999
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:548) <Perf> (PrintDPDKPortXstats) -- Port 0 (0000:3b:00.1) - rx_phy_bytes: 764030578
[3399] 22/9/2022 -- 08:45:15 - (source-dpdk.c:587) <Perf> (ReceiveDPDKThreadExitStats) -- Total RX stats of 0000:3b:00.1: packets 999999 bytes: 760030582 missed: 0 errors: 0 nombufs: 0

lukashino avatar Sep 27 '22 09:09 lukashino