Feature #894
closedFeature #789: Clean-up start and stop code
clean up output
Description
I think we are too verbose by default. I think we can improve this easily by converting a few important logs to 'notice' level and then set the default level to notice. Maybe add a -v/--verbose option to go back to 'info' for convenience.
E.g. now we have:
[18568] 19/7/2013 -- 13:45:11 - (suricata.c:1283) <Info> (main) -- This is Suricata version 2.0dev (rev 9f3e2f7) [18568] 19/7/2013 -- 13:45:11 - (util-cpu.c:166) <Info> (UtilCpuPrintSummary) -- CPUs/cores online: 2 [18568] 19/7/2013 -- 13:45:11 - (suricata.c:1356) <Info> (main) -- Live rule reloads enabled [18568] 19/7/2013 -- 13:45:11 - (source-nfq.c:277) <Info> (NFQInitConfig) -- NFQ running in standard ACCEPT/DROP mode [18568] 19/7/2013 -- 13:45:11 - (defrag-hash.c:203) <Info> (DefragInitConfig) -- allocated 131072 bytes of memory for the defrag hash... 4096 buckets of size 32 [18568] 19/7/2013 -- 13:45:11 - (defrag-hash.c:228) <Info> (DefragInitConfig) -- preallocated 1000 defrag trackers of size 104 [18568] 19/7/2013 -- 13:45:11 - (defrag-hash.c:235) <Info> (DefragInitConfig) -- defrag memory usage: 235072 bytes, maximum: 16777216 [18568] 19/7/2013 -- 13:45:11 - (tmqh-flow.c:76) <Info> (TmqhFlowRegister) -- AutoFP mode using default "Active Packets" flow load balancer [18568] 19/7/2013 -- 13:45:11 - (tmqh-packetpool.c:141) <Info> (PacketPoolInit) -- preallocated 256 packets. Total memory 1170944 [18568] 19/7/2013 -- 13:45:12 - (host.c:204) <Info> (HostInitConfig) -- allocated 3200000 bytes of memory for the host hash... 100000 buckets of size 32 [18568] 19/7/2013 -- 13:45:12 - (host.c:227) <Info> (HostInitConfig) -- preallocated 10000 hosts of size 76 [18568] 19/7/2013 -- 13:45:12 - (host.c:229) <Info> (HostInitConfig) -- host memory usage: 3960000 bytes, maximum: 536870912 [18568] 19/7/2013 -- 13:45:12 - (flow.c:412) <Info> (FlowInitConfig) -- allocated 2097152 bytes of memory for the flow hash... 65536 buckets of size 32 [18568] 19/7/2013 -- 13:45:12 - (flow.c:436) <Info> (FlowInitConfig) -- preallocated 10000 flows of size 176 [18568] 19/7/2013 -- 13:45:12 - (flow.c:438) <Info> (FlowInitConfig) -- flow memory usage: 3857152 bytes, maximum: 33554432 [18568] 19/7/2013 -- 13:45:12 - (reputation.c:473) <Info> (SRepInit) -- Loading reputation file: /etc/suricata/iprep/iprepdata.txt [18568] 19/7/2013 -- 13:45:12 - (host.c:244) <Info> (HostPrintStats) -- host memory usage: 9246408 bytes, maximum: 536870912 [18568] 19/7/2013 -- 13:45:12 - (suricata.c:1863) <Info> (main) -- Delayed detect enabled [18568] 19/7/2013 -- 13:45:12 - (suricata.c:1865) <Info> (main) -- Packets will start being processed before signatures are active. [18568] 19/7/2013 -- 13:45:12 - (util-threshold-config.c:983) <Info> (SCThresholdConfParseFile) -- Threshold config parsed: 8 rule(s) found [18568] 19/7/2013 -- 13:45:12 - (util-coredump-config.c:115) <Info> (CoredumpLoadConfig) -- Core dump size is unlimited. [18568] 19/7/2013 -- 13:45:12 - (util-logopenfile.c:169) <Info> (SCConfLogOpenGeneric) -- fast output device (regular) initialized: fast.log [18568] 19/7/2013 -- 13:45:12 - (alert-unified2-alert.c:1043) <Info> (Unified2AlertInitCtx) -- Unified2-alert initialized: filename unified2.alert, limit 32 MB [18568] 19/7/2013 -- 13:45:12 - (util-logopenfile.c:169) <Info> (SCConfLogOpenGeneric) -- http-log output device (regular) initialized: http.log [18568] 19/7/2013 -- 13:45:12 - (util-logopenfile.c:169) <Info> (SCConfLogOpenGeneric) -- drop output device (regular) initialized: drop.log [18568] 19/7/2013 -- 13:45:12 - (log-pcap.c:493) <Info> (PcapLogInitCtx) -- Using log dir /nsm_data/n270/dailylogs [18568] 19/7/2013 -- 13:45:12 - (log-pcap.c:498) <Info> (PcapLogInitCtx) -- using Sguil compatible logging [18568] 19/7/2013 -- 13:45:12 - (log-filestore.c:620) <Info> (LogFilestoreLogInitCtx) -- storing files in /var/log/suricata/files [18568] 19/7/2013 -- 13:45:12 - (util-logopenfile.c:169) <Info> (SCConfLogOpenGeneric) -- file-log output device (regular) initialized: files-json.log [18568] 19/7/2013 -- 13:45:12 - (log-file.c:451) <Info> (LogFileLogInitCtx) -- forcing magic lookup for logged files [18568] 19/7/2013 -- 13:45:12 - (log-file.c:458) <Info> (LogFileLogInitCtx) -- forcing md5 calculation for logged files [18568] 19/7/2013 -- 13:45:12 - (util-logopenfile.c:169) <Info> (SCConfLogOpenGeneric) -- tls-log output device (regular) initialized: tls.log [18587] 19/7/2013 -- 13:45:12 - (source-nfq.c:580) <Info> (NFQInitThread) -- binding this thread 0 to queue '0' [18587] 19/7/2013 -- 13:45:12 - (source-nfq.c:602) <Info> (NFQInitThread) -- setting queue length to 1024 [18587] 19/7/2013 -- 13:45:12 - (source-nfq.c:615) <Info> (NFQInitThread) -- setting nfnl bufsize to 1536000 [18568] 19/7/2013 -- 13:45:12 - (stream-tcp.c:356) <Info> (StreamTcpInitConfig) -- stream "prealloc-sessions": 2048 (per thread) [18568] 19/7/2013 -- 13:45:12 - (stream-tcp.c:372) <Info> (StreamTcpInitConfig) -- stream "memcap": 33554432 [18568] 19/7/2013 -- 13:45:12 - (stream-tcp.c:378) <Info> (StreamTcpInitConfig) -- stream "midstream" session pickups: disabled [18568] 19/7/2013 -- 13:45:12 - (stream-tcp.c:384) <Info> (StreamTcpInitConfig) -- stream "async-oneside": disabled [18568] 19/7/2013 -- 13:45:12 - (stream-tcp.c:401) <Info> (StreamTcpInitConfig) -- stream "checksum-validation": enabled [18568] 19/7/2013 -- 13:45:12 - (stream-tcp.c:423) <Info> (StreamTcpInitConfig) -- stream."inline": enabled [18568] 19/7/2013 -- 13:45:12 - (stream-tcp.c:436) <Info> (StreamTcpInitConfig) -- stream "max-synack-queued": 5 [18568] 19/7/2013 -- 13:45:12 - (stream-tcp.c:454) <Info> (StreamTcpInitConfig) -- stream.reassembly "memcap": 134217728 [18568] 19/7/2013 -- 13:45:12 - (stream-tcp.c:472) <Info> (StreamTcpInitConfig) -- stream.reassembly "depth": 1048576 [18568] 19/7/2013 -- 13:45:12 - (stream-tcp.c:555) <Info> (StreamTcpInitConfig) -- stream.reassembly "toserver-chunk-size": 2475 [18568] 19/7/2013 -- 13:45:12 - (stream-tcp.c:557) <Info> (StreamTcpInitConfig) -- stream.reassembly "toclient-chunk-size": 2455 [18568] 19/7/2013 -- 13:45:12 - (tm-threads.c:2165) <Info> (TmThreadWaitOnThreadInit) -- all 4 packet processing threads, 3 management threads initialized, engine started. [18568] 19/7/2013 -- 13:45:12 - (detect.c:408) <Warning> (SigLoadSignatures) -- [ERRCODE: SC_ERR_NO_RULES(42)] - No rules loaded from /etc/suricata/rules/files.rules [18568] 19/7/2013 -- 13:45:16 - (detect.c:408) <Warning> (SigLoadSignatures) -- [ERRCODE: SC_ERR_NO_RULES(42)] - No rules loaded from /etc/suricata/rules/icmp.rules [18568] 19/7/2013 -- 13:45:31 - (detect.c:455) <Info> (SigLoadSignatures) -- 50 rule files processed. 12674 rules successfully loaded, 4 rules failed [18568] 19/7/2013 -- 13:46:21 - (detect.c:2726) <Info> (SigAddressPrepareStage1) -- 12681 signatures processed. 1032 are IP-only rules, 5038 are inspecting packet payload, 8225 inspect application layer, 0 are decoder event only [18568] 19/7/2013 -- 13:46:21 - (detect.c:2729) <Info> (SigAddressPrepareStage1) -- building signature grouping structure, stage 1: adding signatures to signature source addresses... complete [18568] 19/7/2013 -- 13:46:23 - (detect.c:3355) <Info> (SigAddressPrepareStage2) -- building signature grouping structure, stage 2: building source address list... complete [18568] 19/7/2013 -- 13:47:52 - (detect.c:3997) <Info> (SigAddressPrepareStage3) -- building signature grouping structure, stage 3: building destination address lists... complete [18568] 19/7/2013 -- 13:48:19 - (util-profiling-rules.c:551) <Info> (SCProfilingRuleInitCounters) -- Registered 12681 rule profiling counters. [18568] 19/7/2013 -- 13:48:19 - (suricata.c:2007) <Info> (main) -- Signature(s) loaded, Detect thread(s) activated.
Lets default this to something like:
[18568] 19/7/2013 -- 13:45:11 - (suricata.c:1283) <Info> (main) -- This is Suricata version 2.0dev (rev 9f3e2f7) [18568] 19/7/2013 -- 13:45:12 - (tm-threads.c:2165) <Info> (TmThreadWaitOnThreadInit) -- all 4 packet processing threads, 3 management threads initialized, engine started. [18568] 19/7/2013 -- 13:48:19 - (suricata.c:2007) <Info> (main) -- Signature(s) loaded, Detect thread(s) activated.
Updated by Victor Julien about 11 years ago
- % Done changed from 80 to 0
I was thinking, maybe we can also enable "info" log level by default for the file output. Would that make sense?
Updated by Victor Julien about 11 years ago
- % Done changed from 0 to 80
Didn't mean to update "% done".
Updated by Victor Julien about 11 years ago
Updated by Victor Julien about 11 years ago
Think we should give a bit more info on shut down than we currently do. E.g.:
$ ./src/suricata -c suricata.yaml -r ~/sync/pcap/sandnet.pcap -l tmp/ -S emerging-all.rules --runmode=single [13944] 10/10/2013 -- 15:53:32 - (suricata.c:926) <Notice> (SCPrintVersion) -- This is Suricata version 2.0dev (rev c583c9e) [13944] 10/10/2013 -- 15:53:39 - (tm-threads.c:2192) <Notice> (TmThreadWaitOnThreadInit) -- all 1 packet processing threads, 3 management threads initialized, engine started. [13944] 10/10/2013 -- 15:54:42 - (suricata.c:2153) <Notice> (main) -- Signal Received. Stopping engine.
I think we should add a few statistics: alert cnt, packet cnt at least, and maybe also things like http, dns, etc logs. Would have nice to have it compressed though, so not each on a line, or worse, one a line per thread.
Updated by Peter Manev about 11 years ago
I agree as well and second Victors suggestion.
It would be really nice if to the the output(both verbose or non) can be added percentage (%) total dropped packets - it helps a lot in tuning.
At the moment we just have numbers.
Updated by Victor Julien almost 11 years ago
- Target version changed from 2.0beta2 to 2.0rc1
Updated by Victor Julien almost 11 years ago
- Status changed from Assigned to Closed
- % Done changed from 80 to 100
Merged https://github.com/inliniac/suricata/pull/748, thanks Eric.
For more ideas on improving output, open a new ticket.