Rule profiling not working

Help
1

I try to profile rules but I couldn’t find a file named rule_perf.log is result of rule profiling. I’m using Napatech card and would like to profile the rules in realtime traffic. Could I have tried the wrong way?

  • suricata.log(after suricata on)

{“timestamp”:“2021-05-25T16:41:03.051035+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“Registered 2023 rule profiling counters.”}}

  • suricata.yaml

profiling:
rules:
enabled: yes
filename: rule_perf.log
sort: avgticks
append: yes
limit: 100
json: yes

  • build info

This is Suricata version 6.0.2 RELEASE
Features: PCAP_SET_BUFF AF_PACKET HAVE_PACKET_FANOUT LIBCAP_NG LIBNET1.1 HAVE_HTP_URI_NORMALIZE_HOOK PCRE_JIT HAVE_NSS HAVE_LIBJANSSON PROFILING PROFILE_LOCKING TLS TLS_C11 MAGIC RUST
…
Profiling enabled: yes
Profiling locks enabled: yes
…

2

Rule profiling will place it’s output in the same directory as the logging. The configuration setting default-log-dir shows this: suricata --dump-config | grep default-log-dir

3

@Jeff_Lucovsky
Yes, I found the file. The reason I couldn’t find it was that I started suricata around 5pm and the file was created around 9pm. However, nothing is written in the file. Could you please tell me why?

image
image1061×286 1.15 KB

4

@Jeff_Lucovsky
After configuring suricata for testing and using only 1 core, I started the process. After that, it found that the profiling file is created when exiting through SIGINT.

The actual environment is a multi-core environment, but when I try to terminate a process with SIGINT, a process is not terminated. So the profiling file is not created either.

image
image754×115 1.22 KB

How can I terminate suricata to get the profiling file?

5

Hi,

How are you starting Suricata – using systemd or equivalent – or via the command line?

I understand you’re using Suricata 6.0.2 with Napatech.

6

@Jeff_Lucovsky
Hi,
I started suricata via commandline.

/home/xxx/suri/sensor/bin/suricata -c /home/xxx/suri/conf.d/suricata.yaml --napatech

7

Hi,
I’m not able to replicate the issue on a Suricata 6.0.2 system with a Napatech NIC.

Both SIGTERM and SIGINT were received immediately by Suricata followed by the shutdown sequence.

You state that SIGINT causes Suricata to stop with 1 core but not with multiple cores.

How many Napatech streams are you using? Which card? Which Napatech software version?

8

@Jeff_Lucovsky
using 64streams, NT40E3-4-PTP and ntinfo (v. 3.18.0.34-faf32)

I found that the remaining child process is terminated normally after a lot of time has elapsed.

Currently, about 20,000 alert rules are being used, and I found that keyword profiling is displayed normally, but rule profiling is not displayed.

I expected that I used too many alert rules and was using in the large traffic environment of 10-20 Gb/s is a reason that the profiling was not working, So I tried the limit and sapmple-rate options. But it didn’t work.

Can I try increasing the limit or sample-rate further? Or are there other settings to consider?

9

The sample-rate limits how often profiling is performed – a value of 100,000 means that sampling will occur after 100,000 packets are received and so on. Depending on your traffic rates and other deployment considerations (eg ruleset details), this may be too coarse. Suggest using the default value here – 1000.

10

Even if the sample-rate is set to 100, 1000, 10000…, the rule profile is not displayed normally. Currently, 0.25 billion packets are generated per second, and it is not displayed even if the sample-rate is increased to 100 billion.

11

Can you try an experiment?

Using the same Suricata configuration file, use rule profiling with the default sample-rate with a pcap file.

suricata -c /path/to/configuration-file -r /path/to/pcap-file

Let’s see if there’s something more fundamental going on by using a reduced scope example.

12

I tested using a single session dump file of about 17Mb. The rule profile and the keyword profile did not occur. When the sample-rate was set to 1000, no files were created either when commented out.

When checking suricata.log, it was possible to check as follows.

{“timestamp”:“2021-06-14T12:42:12.467216+0900”,“log_level”:“Error”,“event_type”:“engine”,“engine”:{“error_code”:187,“error”: “SC_ERR_RUNMODE”,“message”:“The custom type "workers" doesn’t exist for this runmode type "PCAP_FILE". Please use --list-runmodes to see available custom types for this runmode”}}

So, I tested with runmode as single, but the file was still not created. The log generated at this time is as follows.

{“timestamp”:“2021-06-14T13:15:22.869447+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“0 new flows, 0 established flows were timed out, 0 flows in closed state”}}
{“timestamp”:“2021-06-14T13:15:22.869525+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“0 new flows, 0 established flows were timed out, 0 flows in closed state”}}
{“timestamp”:“2021-06-14T13:15:23.207757+0900”,“log_level”:“Info”,“event_type”:“engine”,“engine”:{“message”:“time elapsed 17.482s” }}
{“timestamp”:“2021-06-14T13:15:23.535419+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“2 flows processed”} }
{“timestamp”:“2021-06-14T13:15:23.535490+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“28 flows processed”} }
{“timestamp”:“2021-06-14T13:15:23.535511+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“0 flows processed”} }
{“timestamp”:“2021-06-14T13:15:23.535567+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“13 flows processed”} }
{“timestamp”:“2021-06-14T13:15:23.603954+0900”,“log_level”:“Notice”,“event_type”:“engine”,“engine”:{“message”:“Pcap-file module read 1 files, 385491 packets, 519718810 bytes”}}
{“timestamp”:“2021-06-14T13:15:23.630633+0900”,“log_level”:“Info”,“event_type”:“engine”,“engine”:{“message”:“Alerts: 0”} }
{“timestamp”:“2021-06-14T13:15:24.490508+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“ippair memory usage: 414144 bytes, maximum: 16777216”}}
{“timestamp”:“2021-06-14T13:15:31.102299+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:"Done dumping profiling data. "}}
{“timestamp”:“2021-06-14T13:15:31.102364+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“host memory usage: 20307200 bytes, maximum: 1073741824”}}
{“timestamp”:“2021-06-14T13:15:31.149485+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“Dumping profiling data for 20276 rules.”}}
{“timestamp”:“2021-06-14T13:15:31.156440+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:"Done dumping profiling data. "}}
{“timestamp”:“2021-06-14T13:15:31.156872+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“Done dumping keyword profiling data .”}}
{“timestamp”:“2021-06-14T13:15:31.299257+0900”,“log_level”:“Info”,“event_type”:“engine”,“engine”:{“message”:“cleaning up signature grouping structure …complete”}}
{“timestamp”:“2021-06-14T13:15:31.306878+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:"Cleaning up Hyperscan global scratch "}}
{“timestamp”:“2021-06-14T13:15:31.306920+0900”,“log_level”:“Perf”,“event_type”:“engine”,“engine”:{“message”:“Clearing Hyperscan database cache” }}

13

This doesn’t match what I’d expect.

Can you provide the exact command line you used to process the pcap files?
Can you upload the suricata configuration file you’re using?

14

Sensitive information is partially corrected and delivered.
And by suricata1.yaml, the runmode is workers, but in the second attempt above, I changed the runmode to single and operated it.
I also tried setting the sample rate to 1000 and commented it out.

  • command line
    ./sensor/bin/suricata -c ./suricata1.yaml -r ./test.pcap

suricata1.yaml (10.2 KB)

15

I think you need to have relevant rules hitting in order to get those stats in rule_perf.log going.
For example if you run against a pcap that has some relevant traffic you should get the log populated - i just did small run on latest master

Screenshot from 2021-06-15 14-52-59
Screenshot from 2021-06-15 14-52-591040×435 19.3 KB

16

Additionally, if you add --runmode=autofp to the command line i listed the other day, you’ll get rule profiling information (if, as @pevma states, there are packets that match the rules you’re using)

17

@Jeff_Lucovsky @pevma
Does the rule_profiling function only work in autofp runmode?

18

Rule profiling is orthogonal from the runmode … they’re not directly related.

autofp is needed when reading from a pcap file.

suricata --list-runmodes displays the runmodes available for each packet source (pcap, af_packet, …). When using pcap files, runmode must be single or autofp