Support #305
closedSuricata exits during startup when loading large rule files
Description
Suricata exits with the following error when loading the combined ET and VRT ruleset (~30k rules)
[7069] 27/7/2011 -- 14:14:09 - (detect.c:631) <Info> (SigLoadSignatures) -- 102 rule files processed. 30183 rules succesfully loaded, 164 rules failed
[7069] 27/7/2011 -- 14:14:47 - (detect.c:2161) <Info> (SigAddressPrepareStage1) -- 30701 signatures processed. 1800 are IP-only rules, 20152 are inspecting packet payload, 11088 inspect application layer, 0 are decoder event only
[7069] 27/7/2011 -- 14:14:47 - (detect.c:2164) <Info> (SigAddressPrepareStage1) -- building signature grouping structure, stage 1: adding signatures to signature source addresses... complete
[7069] 27/7/2011 -- 14:14:48 - (detect.c:2806) <Info> (SigAddressPrepareStage2) -- building signature grouping structure, stage 2: building source address list... complete
[7069] 27/7/2011 -- 14:16:40 - (detect.c:3363) <Info> (SigAddressPrepareStage3) -- MPM memory 1801173581 (dynamic 1801173581, ctxs 0, avg per ctx 0)
[7069] 27/7/2011 -- 14:16:40 - (detect.c:3365) <Info> (SigAddressPrepareStage3) -- max sig id 30701, array size 3838
[7069] 27/7/2011 -- 14:16:40 - (detect.c:3376) <Info> (SigAddressPrepareStage3) -- building signature grouping structure, stage 3: building destination address lists... complete
[7069] 27/7/2011 -- 14:16:43 - (detect-engine-siggroup.c:1583) <Error> (SigGroupHeadBuildHeadArray) -- [ERRCODE: SC_ERR_MEM_ALLOC(1)] - SCMalloc failed: Cannot allocate memory, while trying to allocate 558852 bytes
[7069] 27/7/2011 -- 14:16:43 - (detect-engine-siggroup.c:1583) <Error> (SigGroupHeadBuildHeadArray) -- [ERRCODE: SC_ERR_FATAL(169)] - Out of memory. The engine cannot be initialized. Exiting...
Watching top (refreshing at .2 sec) during the startup process I noticed a rather large and fast spike in memory utilization up to between 2 and 3 GB, followed by an immediate drop as Suricata exits with the error mentioned above. At no time have I seen the memory utilization exceed 4 GB via top.
Suricata loads and runs fine when using either the ET or the VRT ruleset with significantly less rules included. The error has only happened when using the combined ruleset with ~30k rules. Initial fix was to increase system RAM from 4GB to 8GB. No change. Increased it further to 16 GB and no change.
I've included my suricata.yaml file in case there is a configuration setting in there that I've boned up.
Additionally I've included a file with the results of 'free -m' and the memory stats from running 'collectl' during the startup process. Again the record interval is .2sec. You can see how quickly Suricata spikes then drops right before exiting.
I'm running Suricata 1.1b2 from the tarball on a CentOS 5.6 based VM with 4 cores and 16GB ram allocated. It is the 32bit Kernel, but we just installed the kernel-PAE packages today to allow it to access more than 4GB of ram.
Files
Updated by Peter Manev over 13 years ago
- File SuriWith30KRules.png SuriWith30KRules.png added
I had a the exact same problem on ubuntu 32 bit VM , but increasing the memory did it for me.(from 1.5 to 2.5G)
Please find file attached a screenshot of Suri running with 30K rules on the same machine with 2.5 Gb of mem.
[14176] 27/7/2011 -- 17:41:46 - (detect.c:2403) <Info> (SigAddressPrepareStage1) -- 29921 signatures processed. 1267 are IP-only rules, 19969 are inspecting packet payload, 8883 inspect application layer, 72 are decoder event only
[14176] 27/7/2011 -- 17:41:46 - (detect.c:2406) <Info> (SigAddressPrepareStage1) -- building signature grouping structure, stage 1: adding signatures to signature source addresses... complete
[14176] 27/7/2011 -- 17:42:20 - (detect.c:3048) <Info> (SigAddressPrepareStage2) -- building signature grouping structure, stage 2: building source address list... complete
[14176] 27/7/2011 -- 17:44:12 - (detect.c:3605) <Info> (SigAddressPrepareStage3) -- MPM memory 2067277323 (dynamic 2067277323, ctxs 0, avg per ctx 0)
[14176] 27/7/2011 -- 17:44:12 - (detect.c:3607) <Info> (SigAddressPrepareStage3) -- max sig id 29921, array size 3741
[14176] 27/7/2011 -- 17:44:12 - (detect.c:3618) <Info> (SigAddressPrepareStage3) -- building signature grouping structure, stage 3: building destination address lists... complete
[14176] 27/7/2011 -- 17:45:19 - (alert-fastlog.c:372) <Info> (AlertFastLogInitCtx) -- Fast log output initialized, filename: fast.log
[14176] 27/7/2011 -- 17:45:19 - (alert-unified2-alert.c:897) <Info> (Unified2AlertInitCtx) -- Unified2-alert initialized: filename unified2.alert, limit 32 MB
[14176] 27/7/2011 -- 17:45:19 - (runmodes.c:336) <Warning> (RunModeInitializeOutputs) -- [ERRCODE: SC_ERR_INVALID_ARGUMENT(13)] - No output module named alert-prelude, ignoring
[14176] 27/7/2011 -- 17:45:19 - (log-droplog.c:182) <Info> (LogDropLogInitCtx) -- Drop log output initialized, filename: drop.log
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:355) <Info> (StreamTcpInitConfig) -- stream "max_sessions": 262144
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:367) <Info> (StreamTcpInitConfig) -- stream "prealloc_sessions": 32768
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:377) <Info> (StreamTcpInitConfig) -- stream "memcap": 33554432
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:384) <Info> (StreamTcpInitConfig) -- stream "midstream" session pickups: disabled
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:392) <Info> (StreamTcpInitConfig) -- stream "async_oneside": disabled
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:408) <Info> (StreamTcpInitConfig) -- stream "checksum_validation": enabled
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:419) <Info> (StreamTcpInitConfig) -- stream."inline": disabled
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:428) <Info> (StreamTcpInitConfig) -- stream.reassembly "memcap": 67108864
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:438) <Info> (StreamTcpInitConfig) -- stream.reassembly "depth": 1048576
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:461) <Info> (StreamTcpInitConfig) -- stream.reassembly "toserver_chunk_size": 2560
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:463) <Info> (StreamTcpInitConfig) -- stream.reassembly "toclient_chunk_size": 2560
[14183] 27/7/2011 -- 17:45:19 - (source-pcap.c:389) <Info> (ReceivePcapThreadInit) -- using interface eth0
[14176] 27/7/2011 -- 17:45:19 - (tm-threads.c:1488) <Info> (TmThreadWaitOnThreadInit) -- all 5 packet processing threads, 3 management threads initialized, engine started.
.........
[14165] 27/7/2011 -- 17:38:09 - (suricata.c:622) <Info> (main) -- This is Suricata version 1.1beta2 (rev df3ca32)
Could that be a kernel/CentOS issue?
Updated by Anoop Saldanha over 13 years ago
Peter Manev wrote:
I had a the exact same problem on ubuntu 32 bit VM , but increasing the memory did it for me.(from 1.5 to 2.5G)
Please find file attached a screenshot of Suri running with 30K rules on the same machine with 2.5 Gb of mem.[14176] 27/7/2011 -- 17:41:46 - (detect.c:2403) <Info> (SigAddressPrepareStage1) -- 29921 signatures processed. 1267 are IP-only rules, 19969 are inspecting packet payload, 8883 inspect application layer, 72 are decoder event only
[14176] 27/7/2011 -- 17:41:46 - (detect.c:2406) <Info> (SigAddressPrepareStage1) -- building signature grouping structure, stage 1: adding signatures to signature source addresses... complete
[14176] 27/7/2011 -- 17:42:20 - (detect.c:3048) <Info> (SigAddressPrepareStage2) -- building signature grouping structure, stage 2: building source address list... complete
[14176] 27/7/2011 -- 17:44:12 - (detect.c:3605) <Info> (SigAddressPrepareStage3) -- MPM memory 2067277323 (dynamic 2067277323, ctxs 0, avg per ctx 0)
[14176] 27/7/2011 -- 17:44:12 - (detect.c:3607) <Info> (SigAddressPrepareStage3) -- max sig id 29921, array size 3741
[14176] 27/7/2011 -- 17:44:12 - (detect.c:3618) <Info> (SigAddressPrepareStage3) -- building signature grouping structure, stage 3: building destination address lists... complete
[14176] 27/7/2011 -- 17:45:19 - (alert-fastlog.c:372) <Info> (AlertFastLogInitCtx) -- Fast log output initialized, filename: fast.log
[14176] 27/7/2011 -- 17:45:19 - (alert-unified2-alert.c:897) <Info> (Unified2AlertInitCtx) -- Unified2-alert initialized: filename unified2.alert, limit 32 MB
[14176] 27/7/2011 -- 17:45:19 - (runmodes.c:336) <Warning> (RunModeInitializeOutputs) -- [ERRCODE: SC_ERR_INVALID_ARGUMENT(13)] - No output module named alert-prelude, ignoring
[14176] 27/7/2011 -- 17:45:19 - (log-droplog.c:182) <Info> (LogDropLogInitCtx) -- Drop log output initialized, filename: drop.log
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:355) <Info> (StreamTcpInitConfig) -- stream "max_sessions": 262144
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:367) <Info> (StreamTcpInitConfig) -- stream "prealloc_sessions": 32768
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:377) <Info> (StreamTcpInitConfig) -- stream "memcap": 33554432
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:384) <Info> (StreamTcpInitConfig) -- stream "midstream" session pickups: disabled
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:392) <Info> (StreamTcpInitConfig) -- stream "async_oneside": disabled
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:408) <Info> (StreamTcpInitConfig) -- stream "checksum_validation": enabled
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:419) <Info> (StreamTcpInitConfig) -- stream."inline": disabled
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:428) <Info> (StreamTcpInitConfig) -- stream.reassembly "memcap": 67108864
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:438) <Info> (StreamTcpInitConfig) -- stream.reassembly "depth": 1048576
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:461) <Info> (StreamTcpInitConfig) -- stream.reassembly "toserver_chunk_size": 2560
[14176] 27/7/2011 -- 17:45:19 - (stream-tcp.c:463) <Info> (StreamTcpInitConfig) -- stream.reassembly "toclient_chunk_size": 2560
[14183] 27/7/2011 -- 17:45:19 - (source-pcap.c:389) <Info> (ReceivePcapThreadInit) -- using interface eth0
[14176] 27/7/2011 -- 17:45:19 - (tm-threads.c:1488) <Info> (TmThreadWaitOnThreadInit) -- all 5 packet processing threads, 3 management threads initialized, engine started.
.........[14165] 27/7/2011 -- 17:38:09 - (suricata.c:622) <Info> (main) -- This is Suricata version 1.1beta2 (rev df3ca32)
Could that be a kernel/CentOS issue?
can you change the mpm to b2gc and post the logs, for the ruleset you tried?
Updated by Peter Manev over 13 years ago
It gets killed by the system, because I think it wants memory.But the same rule set with mpm algo ac is quite alright, no problem.
[16140] 28/7/2011 -- 16:45:27 - (detect.c:635) <Info> (SigLoadSignatures) -- 107 rule files processed. 28948 rules succesfully loaded, 1790 rules failed
[16140] 28/7/2011 -- 16:46:20 - (detect.c:2403) <Info> (SigAddressPrepareStage1) -- 29921 signatures processed. 1267 are IP-only rules, 19969 are inspecting packet payload, 8883 inspect application layer, 72 are decoder event only
[16140] 28/7/2011 -- 16:46:20 - (detect.c:2406) <Info> (SigAddressPrepareStage1) -- building signature grouping structure, stage 1: adding signatures to signature source addresses... complete
[16140] 28/7/2011 -- 16:46:56 - (detect.c:3048) <Info> (SigAddressPrepareStage2) -- building signature grouping structure, stage 2: building source address list... complete
[16140] 28/7/2011 -- 16:50:30 - (detect.c:3605) <Info> (SigAddressPrepareStage3) -- MPM memory 913076344 (dynamic 913076344, ctxs 0, avg per ctx 0)
[16140] 28/7/2011 -- 16:50:30 - (detect.c:3607) <Info> (SigAddressPrepareStage3) -- max sig id 29921, array size 3741
[16140] 28/7/2011 -- 16:50:30 - (detect.c:3618) <Info> (SigAddressPrepareStage3) -- building signature grouping structure, stage 3: building destination address lists... complete
Killed
......
Updated by Peter Manev over 13 years ago
- File SurCentOS5_6.png SurCentOS5_6.png added
Hi,
I just tried running Suri on CentOS5.6 with Gene's yaml - it does start and load and inspect traffic - no problem.
CentOS5.6 32bit - 4 gigs of Mem , running as root.
:
[28003] 7/8/2011 -- 11:05:56 - (detect.c:2403) <Info> (SigAddressPrepareStage1) -- 29921 signatures processed. 1267 are IP-only rules, 19969 are inspecting packet payload, 8883 inspect application layer, 72 are decoder event only
[28003] 7/8/2011 -- 11:05:56 - (detect.c:2406) <Info> (SigAddressPrepareStage1) -- building signature grouping structure, stage 1: adding signatures to signature source addresses... complete
[28003] 7/8/2011 -- 11:06:20 - (detect.c:3048) <Info> (SigAddressPrepareStage2) -- building signature grouping structure, stage 2: building source address list... complete
[28003] 7/8/2011 -- 11:08:04 - (detect.c:3605) <Info> (SigAddressPrepareStage3) -- MPM memory 2067277323 (dynamic 2067277323, ctxs 0, avg per ctx 0)
[28003] 7/8/2011 -- 11:08:04 - (detect.c:3607) <Info> (SigAddressPrepareStage3) -- max sig id 29921, array size 3741
[28003] 7/8/2011 -- 11:08:04 - (detect.c:3618) <Info> (SigAddressPrepareStage3) -- building signature grouping structure, stage 3: building destination address lists... complete
[28003] 7/8/2011 -- 11:08:22 - (util-threshold-config.c:106) <Warning> (SCThresholdConfInitContext) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "threshold.config": No such file or directory
[28003] 7/8/2011 -- 11:08:22 - (alert-fastlog.c:372) <Info> (AlertFastLogInitCtx) -- Fast log output initialized, filename: fast.log
[28003] 7/8/2011 -- 11:08:22 - (alert-unified2-alert.c:897) <Info> (Unified2AlertInitCtx) -- Unified2-alert initialized: filename unified2.alert, limit 32 MB
[28003] 7/8/2011 -- 11:08:22 - (runmodes.c:336) <Warning> (RunModeInitializeOutputs) -- [ERRCODE: SC_ERR_INVALID_ARGUMENT(13)] - No output module named alert-prelude, ignoring
[28003] 7/8/2011 -- 11:08:22 - (log-droplog.c:182) <Info> (LogDropLogInitCtx) -- Drop log output initialized, filename: drop.log
[28003] 7/8/2011 -- 11:08:22 - (stream-tcp.c:355) <Info> (StreamTcpInitConfig) -- stream "max_sessions": 262144
[28003] 7/8/2011 -- 11:08:22 - (stream-tcp.c:367) <Info> (StreamTcpInitConfig) -- stream "prealloc_sessions": 32768
[28003] 7/8/2011 -- 11:08:22 - (stream-tcp.c:377) <Info> (StreamTcpInitConfig) -- stream "memcap": 567554432
[28003] 7/8/2011 -- 11:08:22 - (stream-tcp.c:384) <Info> (StreamTcpInitConfig) -- stream "midstream" session pickups: enabled
[28003] 7/8/2011 -- 11:08:22 - (stream-tcp.c:392) <Info> (StreamTcpInitConfig) -- stream "async_oneside": enabled
[28003] 7/8/2011 -- 11:08:22 - (stream-tcp.c:408) <Info> (StreamTcpInitConfig) -- stream "checksum_validation": disabled
[28003] 7/8/2011 -- 11:08:22 - (stream-tcp.c:419) <Info> (StreamTcpInitConfig) -- stream."inline": enabled
[28003] 7/8/2011 -- 11:08:22 - (stream-tcp.c:428) <Info> (StreamTcpInitConfig) -- stream.reassembly "memcap": 67108864
[28003] 7/8/2011 -- 11:08:22 - (stream-tcp.c:438) <Info> (StreamTcpInitConfig) -- stream.reassembly "depth": 1048576
[28003] 7/8/2011 -- 11:08:22 - (stream-tcp.c:461) <Info> (StreamTcpInitConfig) -- stream.reassembly "toserver_chunk_size": 2560
[28003] 7/8/2011 -- 11:08:22 - (stream-tcp.c:463) <Info> (StreamTcpInitConfig) -- stream.reassembly "toclient_chunk_size": 2560
[28010] 7/8/2011 -- 11:08:22 - (source-pcap.c:502) <Info> (ReceivePcapThreadInit) -- using interface eth0
[28003] 7/8/2011 -- 11:08:22 - (tm-threads.c:1488) <Info> (TmThreadWaitOnThreadInit) -- all 5 packet processing threads, 3 management threads initialized, engine started.
somemore info:
[root@localhost Desktop]# free
total used free shared buffers cached
Mem: 3107236 2612252 494984 0 48900 671540
-/+ buffers/cache: 1891812 1215424
Swap: 1048568 0 1048568
Thanks
Updated by Gene Albin over 13 years ago
Based on Peter's post I tried it again, but it still failed. Used same suricata.yaml file. One difference I see between my output and Peter's output is the "MPM memory" line. Peter's has 2.0GB and my latest run had 1.8GB. Again, the symptoms were increasing memory utilization up to 2.0GB then a quick spike up to 3.7 then quit.
[26924] 9/8/2011 -- 15:18:14 - (detect.c:631) <Info> (SigLoadSignatures) -- 102 rule files processed. 30183 rules succesfully loaded, 164 rules failed
[26924] 9/8/2011 -- 15:18:54 - (detect.c:2161) <Info> (SigAddressPrepareStage1) -- 30701 signatures processed. 1800 are IP-only rules, 20152 are inspecting packet payload, 11088 inspect application layer, 0 are decoder event only
[26924] 9/8/2011 -- 15:18:54 - (detect.c:2164) <Info> (SigAddressPrepareStage1) -- building signature grouping structure, stage 1: adding signatures to signature source addresses... complete
[26924] 9/8/2011 -- 15:18:55 - (detect.c:2806) <Info> (SigAddressPrepareStage2) -- building signature grouping structure, stage 2: building source address list... complete
[26924] 9/8/2011 -- 15:20:50 - (detect.c:3363) <Info> (SigAddressPrepareStage3) -- MPM memory 1801173581 (dynamic 1801173581, ctxs 0, avg per ctx 0)
[26924] 9/8/2011 -- 15:20:50 - (detect.c:3365) <Info> (SigAddressPrepareStage3) -- max sig id 30701, array size 3838
[26924] 9/8/2011 -- 15:20:50 - (detect.c:3376) <Info> (SigAddressPrepareStage3) -- building signature grouping structure, stage 3: building destination address lists... complete
[26924] 9/8/2011 -- 15:20:53 - (detect-engine-siggroup.c:1583) <Error> (SigGroupHeadBuildHeadArray) -- [ERRCODE: SC_ERR_MEM_ALLOC(1)] - SCMalloc failed: Cannot allocate memory, while trying to allocate 559048 bytes
[26924] 9/8/2011 -- 15:20:53 - (detect-engine-siggroup.c:1583) <Error> (SigGroupHeadBuildHeadArray) -- [ERRCODE: SC_ERR_FATAL(169)] - Out of memory. The engine cannot be initialized. Exiting...
[gene@localhost suricata]$ free
total used free shared buffers cached
Mem: 16632140 673800 15958340 0 155140 431708
-/+ buffers/cache: 86952 16545188
Swap: 2096472 0 2096472
Hope this helps a bit.
Gene
Updated by Gene Albin about 13 years ago
Updated to the git master and still have the same error. Here are the details from the latest run:
Suricata version:
[13496] 25/8/2011 -- 10:39:55 - (suricata.c:622) <Info> (main) -- This is Suricata version 1.1beta2 (rev b3f7e6a)
Console output:
[13202] 25/8/2011 -- 10:33:10 - (detect.c:635) <Info> (SigLoadSignatures) -- 102 rule files processed. 30187 rules succesfully loaded, 160 rules failed
[13202] 25/8/2011 -- 10:33:47 - (detect.c:2403) <Info> (SigAddressPrepareStage1) -- 30705 signatures processed. 1800 are IP-only rules, 20158 are inspecting packet payload, 11089 inspect application layer, 0 are decoder event only
[13202] 25/8/2011 -- 10:33:47 - (detect.c:2406) <Info> (SigAddressPrepareStage1) -- building signature grouping structure, stage 1: adding signatures to signature source addresses... complete
[13202] 25/8/2011 -- 10:33:48 - (detect.c:3048) <Info> (SigAddressPrepareStage2) -- building signature grouping structure, stage 2: building source address list... complete
[13202] 25/8/2011 -- 10:35:28 - (detect.c:3605) <Info> (SigAddressPrepareStage3) -- MPM memory 1801871065 (dynamic 1801871065, ctxs 0, avg per ctx 0)
[13202] 25/8/2011 -- 10:35:28 - (detect.c:3607) <Info> (SigAddressPrepareStage3) -- max sig id 30705, array size 3839
[13202] 25/8/2011 -- 10:35:28 - (detect.c:3618) <Info> (SigAddressPrepareStage3) -- building signature grouping structure, stage 3: building destination address lists... complete
[13202] 25/8/2011 -- 10:35:30 - (detect-engine-siggroup.c:1621) <Error> (SigGroupHeadBuildHeadArray) -- [ERRCODE: SC_ERR_MEM_ALLOC(1)] - SCMalloc failed: Cannot allocate memory, while trying to allocate 558936 bytes
[13202] 25/8/2011 -- 10:35:30 - (detect-engine-siggroup.c:1621) <Error> (SigGroupHeadBuildHeadArray) -- [ERRCODE: SC_ERR_FATAL(169)] - Out of memory. The engine cannot be initialized. Exiting...
Memory stats:
$ free
total used free shared buffers cached
Mem: 16632140 12913272 3718868 0 97696 12633356
-/+ buffers/cache: 182220 16449920
Swap: 2096472 112 2096360
Attached my config file.
Everything works fine if I keep the ruleset down around 17,000 rules. Haven't looked for the max rules threshold yet.
Gene
Updated by Victor Julien about 13 years ago
- Status changed from New to Assigned
- Assignee set to Victor Julien
- Target version changed from 1.1beta2 to 1.1beta3
Updated by Victor Julien about 13 years ago
- Target version deleted (
1.1beta3)
Gene, I reached out to you privately a while ago but received no reply. Is this issue solved for you?
Updated by Victor Julien over 12 years ago
- Status changed from Assigned to Closed