Rules profiling pcap #9755

regit · 2023-11-08T20:24:51Z

Fixes for usage of rules profiling in pcap reader mode.

I have read the contributing guide lines at
https://docs.suricata.io/en/latest/devguide/codebase/contributing/contribution-process.html
I have signed the Open Information Security Foundation contribution agreement at
https://suricata.io/about/contribution-agreement/ (note: this is only required once)
I have updated the user guide (in doc/userguide/) to reflect the changes made (if applicable)

Link to redmine ticket: https://redmine.openinfosecfoundation.org/issues/6550

Describe changes:

fix a transition problem during activation/deactivation of collect
add a new option to activate profiling at start

codecov · 2023-11-08T20:54:55Z

Codecov Report

Merging #9755 (48a95c4) into master (c8a7204) will decrease coverage by 0.16%.
The diff coverage is n/a.

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #9755      +/-   ##
==========================================
- Coverage   82.56%   82.40%   -0.16%     
==========================================
  Files         968      968              
  Lines      273827   273827              
==========================================
- Hits       226074   225638     -436     
- Misses      47753    48189     +436

Flag	Coverage Δ
fuzzcorpus	`64.39% <ø> (-0.47%)`	⬇️
suricata-verify	`60.94% <ø> (-0.02%)`	⬇️
unittests	`62.93% <ø> (ø)`

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

suricata-qa · 2023-11-08T22:50:03Z

Information: QA ran without warnings.

Pipeline 16421

When replaying a pcap file, it is not possible to get rules profiling because it has to be activated from the unix socket. This patch adds a new option to be able to activate profiling collection at start so a pcap run can get rules profiling information.

This fixes the state handling and simplify the logic.

suricata-qa · 2023-11-18T13:45:03Z

Information: QA ran without warnings.

Pipeline 16618

simeonmiteff · 2024-01-16T00:03:28Z

Hi @regit

I might be doing something wrong but I tried this and profiling still doesn't work (see https://redmine.openinfosecfoundation.org/issues/6619#note-8 for more context):

I started from Victor's victor/detect-cleanups/v14 branch and then cherry-picked the two commits in this PR, then did a make install and also added active: true under profiling.rules.

Result is the same: I get a rules profiling file with no entries (because all counters are zero).

catenacyber · 2024-01-17T20:47:31Z

Is this about https://redmine.openinfosecfoundation.org/issues/6550 ?

regit · 2024-01-17T21:44:33Z

Hi @regit

I might be doing something wrong but I tried this and profiling still doesn't work (see https://redmine.openinfosecfoundation.org/issues/6619#note-8 for more context):

I started from Victor's victor/detect-cleanups/v14 branch and then cherry-picked the two commits in this PR, then did a make install and also added active: true under profiling.rules.

Result is the same: I get a rules profiling file with no entries (because all counters are zero).

Rebasing this MR on top of master is working with

suricata -r file.pcap -S scirius.rules -l /tmp/ --set profiling.rules.enabled=yes

Same result by rebasing this MR on top of victor/detect-cleanups/v14

simeonmiteff · 2024-01-19T03:45:09Z

Hi @regit, I fully admit that I may be holding it wrong and this is not the right way to debug. Here is a self-contained reproducer (place in Dockerfile and build with docker build -t suri-repro .):

FROM ubuntu:22.04

RUN apt-get update

RUN apt-get -y install libpcre2-dev build-essential autoconf \
automake libtool libpcap-dev libnet1-dev libyaml-0-2 libyaml-dev \
pkg-config zlib1g zlib1g-dev libcap-ng-dev libcap-ng0 make \
libmagic-dev libjansson-dev rustc cargo jq git-core

ENV PATH="$PATH:/root/.cargo/bin"

RUN cargo install --force cbindgen

RUN git config --global user.email "fake.user@domain.com" && \
    git config --global user.name "Fake User"

RUN git clone https://github.com/regit/suricata.git && \
    cd suricata && \
    git checkout rules-profiling-pcap && \
    git remote add victor https://github.com/victorjulien/suricata.git && \
    git pull --all && \
    git rebase victor/detect-cleanups/v14 && \
    git log --oneline > /git.txt

RUN cd suricata && \
    ./scripts/bundle.sh && \
    ./autogen.sh && \
    ./configure --enable-profiling --enable-profiling-locks --enable-profiling-rules --enable-debug && \
    make && \
    make install-full &&\
    ldconfig

RUN mkdir /pcap && echo -n '1MOyoQIABAAAAAAAAAAAAP//AAABAAAAQ+CFTyPsDgBiAAAAYgAAAAAQ2wAAAMi8yAAAAAgARQAAVBTnAABAAS/hCgAAAUp94WMIAGkJiBwAAE+F4EMADuv/CAkKCwwNDg8QERITFBUWFxgZGhscHR4fICEiIyQlJicoKSorLC0uLzAxMjM0NTY3' | base64 -d > /pcap/icmp.pcap

RUN echo 'alert icmp any any -> any any (msg:"Test"; sid:1000000;)' > /test.rules

RUN echo '#!/bin/bash\n\
echo "=== Relevant git commits ==============================="\n\
grep "detect/profiling: improve pcap reading performance" /git.txt\n\
grep "profiling: add option to active rules profiling at start" /git.txt \n\
grep "profiling: check packet flag first" /git.txt\n\
echo "=== Running with args: $@ ==="\n\
mkdir /log\n\
/usr/local/bin/suricata -l /log $@\n\
echo "=== fast.log ==========================================="\n\
cat /log/fast.log\n\
echo "=== rule_perf.log ======================================"\n\
cat /log/rule_perf.log' > /run.sh && chmod +x /run.sh


ENTRYPOINT ["/run.sh"]

CMD ["-vvv", "--pcap-file-recursive", "-r", "/pcap", "-S", "/test.rules", "--set", "profiling.rules.enabled=yes", "--set", "profiling.rules.active=yes"]

This is how it behaves:

$ docker run --rm -ti suri-repro
=== Relevant git commits ===============================
d025dbb11 detect/profiling: improve pcap reading performance
4854b03a9 profiling: add option to active rules profiling at start
f58614de2 profiling: check packet flag first
=== Running with args: -vvv --pcap-file-recursive -r /pcap -S /test.rules --set profiling.rules.enabled=yes --set profiling.rules.active=yes ===
Notice: suricata: This is Suricata version 8.0.0-dev (f58614de2 2024-01-19) running in USER 
<snip>
Info: pcap: Starting directory run for /pcap [ReceivePcapFileLoop:source-pcap-file.c:183]
Info: pcap: Processing pcaps directory /pcap, files must be newer than 0 and older than 18446744073709550616 [PcapDirectoryDispatch:source-pcap-file-directory-helper.c:496]
Info: pcap: Found "/pcap/icmp.pcap" at 1705634465739 [PcapDirectoryPopulateBuffer:source-pcap-file-directory-helper.c:368]
Info: pcap: pcap file /pcap/icmp.pcap end of file reached (pcap err code 0) [PcapFileDispatch:source-pcap-file-helper.c:163]
Info: pcap: Processed file /pcap/icmp.pcap, processed up to 1705634465739 [PcapDirectoryDispatchForTimeRange:source-pcap-file-directory-helper.c:448]
Info: pcap: Updating processed to 1705634465739 [PcapDirectoryDispatchForTimeRange:source-pcap-file-directory-helper.c:465]
Info: pcap: Directory run mode complete [PcapDirectoryDispatch:source-pcap-file-directory-helper.c:529]
Notice: threads: Threads created -> RX: 1 W: 12 FM: 1 FR: 1   Engine started. [TmThreadWaitOnThreadRunning:tm-threads.c:1891]
Notice: suricata: Signal Received.  Stopping engine. [SuricataMainLoop:suricata.c:2810]
Info: suricata: time elapsed 0.101s [SCPrintElapsedTime:suricata.c:1166]
Perf: flow-manager: 1 flows processed [FlowRecycler:flow-manager.c:1134]
Notice: pcap: read 1 file, 1 packets, 98 bytes [ReceivePcapFileThreadExitStats:source-pcap-file.c:387]
Perf: tmqh-flow: AutoFP - Total flow handler queues - 12 [TmqhOutputFlowFreeCtx:tmqh-flow.c:216]
Info: counters: Alerts: 1 [StatsLogSummary:counters.c:888]
Perf: ippair: ippair memory usage: 406144 bytes, maximum: 16777216 [IPPairPrintStats:ippair.c:294]
Perf: profiling: Done dumping profiling data. [SCProfilingDump:util-profiling.c:292]
Perf: host: host memory usage: 390144 bytes, maximum: 33554432 [HostPrintStats:host.c:297]
Perf: app-layer-htp: htp memory 0 (0) [AppLayerHtpPrintStats:app-layer-htp.c:3038]
Perf: profiling-rules: Dumping profiling data for 1 rules. [SCProfilingRuleDump:util-profiling-rules.c:433]
Perf: profiling-rules: Done dumping profiling data. [SCProfilingRuleDump:util-profiling-rules.c:523]
Perf: profiling-keywords: Done dumping keyword profiling data. [SCProfilingKeywordDump:util-profiling-keywords.c:202]
Perf: profiling-rulegroups: Done dumping rulegroup profiling data. [SCProfilingSghDump:util-profiling-rulegroups.c:247]
=== fast.log ===========================================
04/11/2012-19:49:23.977955  [**] [1:1000000:0] Test [**] [Classification: (null)] [Priority: 3] {ICMP} 10.0.0.1:8 -> 74.125.225.99:0
=== rule_perf.log ======================================
{"timestamp":"2024-01-19T03:34:27.637083+0000","sort":"ticks","rules":[]}
{"timestamp":"2024-01-19T03:34:27.637095+0000","sort":"average ticks","rules":[]}
{"timestamp":"2024-01-19T03:34:27.637098+0000","sort":"average ticks (match)","rules":[]}
{"timestamp":"2024-01-19T03:34:27.637100+0000","sort":"average ticks (no match)","rules":[]}
{"timestamp":"2024-01-19T03:34:27.637102+0000","sort":"number of checks","rules":[]}
{"timestamp":"2024-01-19T03:34:27.637103+0000","sort":"number of matches","rules":[]}
{"timestamp":"2024-01-19T03:34:27.637105+0000","sort":"max ticks","rules":[]}

...or with args closer to your example above:

$ docker run --rm -ti suri-repro -r /pcap/icmp.pcap --set profiling.rules.enabled=yes -S /test.rules
=== Relevant git commits ===============================
d025dbb11 detect/profiling: improve pcap reading performance
4854b03a9 profiling: add option to active rules profiling at start
f58614de2 profiling: check packet flag first
=== Running with args: -r /pcap/icmp.pcap --set profiling.rules.enabled=yes -S /test.rules ===
Notice: suricata: This is Suricata version 8.0.0-dev (f58614de2 2024-01-19) running in USER mode [LogVersion:suricata.c:1146]
Notice: threads: Threads created -> RX: 1 W: 12 FM: 1 FR: 1   Engine started. [TmThreadWaitOnThreadRunning:tm-threads.c:1891]
Notice: suricata: Signal Received.  Stopping engine. [SuricataMainLoop:suricata.c:2810]
Notice: pcap: read 1 file, 1 packets, 98 bytes [ReceivePcapFileThreadExitStats:source-pcap-file.c:387]
=== fast.log ===========================================
04/11/2012-19:49:23.977955  [**] [1:1000000:0] Test [**] [Classification: (null)] [Priority: 3] {ICMP} 10.0.0.1:8 -> 74.125.225.99:0
=== rule_perf.log ======================================
{"timestamp":"2024-01-19T03:39:08.557274+0000","sort":"ticks","rules":[]}
{"timestamp":"2024-01-19T03:39:08.557288+0000","sort":"average ticks","rules":[]}
{"timestamp":"2024-01-19T03:39:08.557291+0000","sort":"average ticks (match)","rules":[]}
{"timestamp":"2024-01-19T03:39:08.557293+0000","sort":"average ticks (no match)","rules":[]}
{"timestamp":"2024-01-19T03:39:08.557295+0000","sort":"number of checks","rules":[]}
{"timestamp":"2024-01-19T03:39:08.557296+0000","sort":"number of matches","rules":[]}
{"timestamp":"2024-01-19T03:39:08.557298+0000","sort":"max ticks","rules":[]}

My reasoning is:

The fact that we're getting rule_perf.log written suggests it is turned on.
The ICMP packet matches the rule and ends up as an alert in fast.log so we should have 1 check and 1 match at least, with some ticks consumed.
As before, the output is empty.

regit · 2024-01-19T07:10:57Z

Can you add a content match in the signature (it does not need to match)? I think this type of signature is not going to show up in profiling.

simeonmiteff · 2024-01-23T05:02:22Z

@regit thanks for the clue.I added a content match signature and profiling info appeared.

I won't complain too loudly, as I imagine most consumers of profiling output are intimate with the the detection engine code, but I'd like to (humbly) suggest that the coverage of profiling documented so that it is clear what is included and excluded.

Meanwhile I still needed to know why the code wasn't producing any profiling output with the full (ET/Pro + other) ruleset on the system where I'm crunching terrabytes of PCAPs. I copied that host's suricata config back to my system and bisected between it and the config from the reproducer container above until I determined the following, which is also possibly a pair of bugs:

Rules profiling now requires packet profiling to be also enabled, otherwise it produces empty output.
The profiling.rules.active flag has no effect: with the default (apparently no) I still get profiling without starting it via the unix socket interface.

regit · 2024-01-23T08:04:45Z

I got it working here with command:

suricata -S tests/sample.rules -r ~/Downloads/2022/2019-07-05-Ursnif-with-Trickbot-and-IcedID.pcap -l /tmp/profiling/ --set profiling.rules.active=yes -c suricata.yaml

suricata.yaml is stock config from the source tree and I've just set the active flag for the profiling.

My configure line only includes profiling-rules

./configure --prefix=/home/eric/builds/suricata 'CFLAGS=-ggdb -O0  -g -fsanitize=address -fno-omit-frame-pointer' CC=clang ac_cv_func_malloc_0_nonnull=yes ac_cv_func_realloc_0_nonnull=yes --enable-ebpf --enable-ebpf-build --enable-nfqueue --enable-unittests --enable-luajit --enable-profiling-rules

simeonmiteff · 2024-01-29T23:41:34Z

@regit thanks for your help, removing --enable-profiling and keeping --enable-profiling-rules fixed it for me.

victorjulien · 2024-01-30T05:36:02Z

@regit thanks for your help, removing --enable-profiling and keeping --enable-profiling-rules fixed it for me.

Hmm that is odd, does this mean rule profiling still doesn't work for you with --enable-profiling? That would be another issue then, as --enable-profiling-rules is supposed to be a subset of --enable-profiling.

catenacyber

Could you rebase and add the ticket number in the commit message Eric ?

suricata-qa · 2024-03-26T14:20:06Z

Information: QA ran without warnings.

Pipeline 16618

regit requested review from victorjulien and a team as code owners November 8, 2023 20:24

victorjulien added the needs ticket Needs (link to) redmine ticket label Nov 9, 2023

regit added 2 commits November 18, 2023 12:08

profiling: check packet flag first

dc312e1

This fixes the state handling and simplify the logic.

regit force-pushed the rules-profiling-pcap branch from 48a95c4 to dc312e1 Compare November 18, 2023 11:16

catenacyber added the needs rebase Needs rebase to master label Mar 21, 2024

catenacyber requested changes Mar 21, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Rules profiling pcap #9755

Rules profiling pcap #9755

regit commented Nov 8, 2023 •

edited

codecov bot commented Nov 8, 2023

suricata-qa commented Nov 8, 2023

suricata-qa commented Nov 18, 2023

simeonmiteff commented Jan 16, 2024

catenacyber commented Jan 17, 2024

regit commented Jan 17, 2024

simeonmiteff commented Jan 19, 2024

regit commented Jan 19, 2024

simeonmiteff commented Jan 23, 2024

regit commented Jan 23, 2024 •

edited

simeonmiteff commented Jan 29, 2024

victorjulien commented Jan 30, 2024

catenacyber left a comment

suricata-qa commented Mar 26, 2024

Rules profiling pcap #9755

Are you sure you want to change the base?

Rules profiling pcap #9755

Conversation

regit commented Nov 8, 2023 • edited

codecov bot commented Nov 8, 2023

Codecov Report

suricata-qa commented Nov 8, 2023

suricata-qa commented Nov 18, 2023

simeonmiteff commented Jan 16, 2024

catenacyber commented Jan 17, 2024

regit commented Jan 17, 2024

simeonmiteff commented Jan 19, 2024

regit commented Jan 19, 2024

simeonmiteff commented Jan 23, 2024

regit commented Jan 23, 2024 • edited

simeonmiteff commented Jan 29, 2024

victorjulien commented Jan 30, 2024

catenacyber left a comment

Choose a reason for hiding this comment

suricata-qa commented Mar 26, 2024

regit commented Nov 8, 2023 •

edited

regit commented Jan 23, 2024 •

edited