log: Add module and subsystem identifiers to log

[jlucovsky]

Continuation of #7339

This changeset provides subsystem and module identifiers in the log when the log format string contains "%S". By convention, the log format surrounds "%S" with brackets.

The subsystem name is generally the same as the thread name. The module name is derived from the source code module name and usually consists of the first one or 2 segments of the name using the dash character as the segment delimiter.

Issue 2497: redmine

@jasonish suggested formatting changes -- those have been incorporated into this PR. See below for example output for non-debug and debug modes.

Updates:

• Fixes for mac build break

Describe changes: This PR adds a subsystem and module identifier to SCLog messages when the log format includes %S. Subsystem and module identifiers are intrinsic properties of threads and source code modules (respectively).

New threads are assigned a subsystem identifier when the thread is created; the identifier is a Thread-Local-Storage variable declared in util-debug.c; values are assigned to it as threads are created using SCSetSubsystem (a macro defined in util-debug.h).

Module identifiers are derived from the source code module emitting the log message. A new CPP define __SCFILENAME__ is assigned to _sc_module (util-debug.h) at compile time. Rust source module names are determined dynamically during the calls to the log function.

Subsystem and module identifiers are added to log messages when the format contains %S. The generated log message will substitute a tag built from

• The subsystem identifier. This corresponds to the calling thread which may be the Suricata main thread, or a subordinate thread for a task-specific function, e.g., RX#01.
• (Optional) The module identifier will be included if set (not all source modules will set one but most source modules have been modified to set one.) The constructed tag is of the form subsystem-id[:module-identifier] (the brackets surrounding the module-identifier indicate the module-identifier is optional and are not included in the output; output formatting is strictly controlled by the log format in effect).

Also, two travis related changes are included in this PR

1. Update Travis to use Xenial (16.04) rather than Trusty (14.04)
2. Update to display config.log when Travis build errors occur.

Example output Non-debug mode

[2182243] 5/4/2021 -- 08:32:51 [Suricata-main:suricata] - <Notice> -- This is Suricata version 7.0.0-dev running in USER mode
[2182243] 5/4/2021 -- 08:32:51 [Suricata-main:cpu] - <Info> -- CPUs/cores online: 16
[2182243] 5/4/2021 -- 08:32:52 [Suricata-main:coredump-config] - <Info> -- Could not set core dump size to unlimited; it's set to the hard limit.
[2182243] 5/4/2021 -- 08:32:52 [Suricata-main:logopenfile] - <Info> -- fast output device (regular) initialized: fast.log
[2182243] 5/4/2021 -- 08:32:52 [Suricata-main:logopenfile] - <Info> -- eve-log output device (regular) initialized: eve.json
[2182243] 5/4/2021 -- 08:32:52 [Suricata-main:logopenfile] - <Info> -- stats output device (regular) initialized: stats.log
[2182243] 5/4/2021 -- 08:32:52 [Suricata-main:classification-config] - <Info> -- Added "43" classification types from the classification file
[2182243] 5/4/2021 -- 08:32:52 [Suricata-main:reference-config] - <Info> -- Added "19" reference types from the reference.config file
[2182243] 5/4/2021 -- 08:32:56 [Suricata-main:detect-parse] - <Error> -- [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - unexpected option to http_header_names keyword: 'http_header_names'
[2182243] 5/4/2021 -- 08:32:56 [Suricata-main:detect-engine] - <Error> -- [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - error parsing signature "alert http $HOME_NET any -> $EXTERNAL_NET any (msg:"ET MALWARE Win32/Adware.Adposhel.A Checkin M6"; flow:established,to_server; content:"GET"; http_method; urilen:>200; content:"/q/?q="; http_uri; depth:6; fast_pattern; pcre:"/^[a-zA-Z0-9_-]+/UR"; content:"User-Agent|3a 20|"; http_user_agent; depth:12; http_header_names: content:!"Referer"; content:!"Accept"; metadata: former_category ADWARE_PUP; classtype:trojan-activity; sid:2029055; rev:2; metadata:affected_product Windows_XP_Vista_7_8_10_Server_32_64_Bit, attack_target Client_Endpoint, deployment Perimeter, signature_severity Major, created_at 2019_11_26, performance_impact Low, updated_at 2019_11_26;)" from file /home/jlucovsky/et.rules at line 19714
[2182243] 5/4/2021 -- 08:33:13 [Suricata-main:detect-engine] - <Info> -- 1 rule files processed. 19187 rules successfully loaded, 1 rules failed
[2182243] 5/4/2021 -- 08:33:13 [Suricata-main:threshold-config] - <Warning> -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/usr/local/etc/suricata//threshold.config": Permission denied
[2182243] 5/4/2021 -- 08:33:13 [Suricata-main:detect-engine] - <Info> -- 19190 signatures processed. 1094 are IP-only rules, 3860 are inspecting packet payload, 14179 inspect application layer, 0 are decoder event only
[2182716] 5/4/2021 -- 08:33:53 [RX#01:pcap-file] - <Info> -- Argument /home/jlucovsky/pcap/ was a directory
[2182243] 5/4/2021 -- 08:33:53 [Suricata-main:threads] - <Notice> -- Threads created -> RX: 1 W: 16 FM: 1 FR: 1   Engine started.
[2182716] 5/4/2021 -- 08:33:53 [RX#01:pcap-file] - <Info> -- Starting directory run for /home/jlucovsky/pcap/

Debug mode

[2102717] 5/4/2021 -- 08:18:43 [Suricata-main:suricata] - (suricata.c:1062) <Notice> (LogVersion) -- This is Suricata version 7.0.0-dev running in USER mode
[2102717] 5/4/2021 -- 08:18:43 [Suricata-main:cpu] - (util-cpu.c:178) <Info> (UtilCpuPrintSummary) -- CPUs/cores online: 16
[2102717] 5/4/2021 -- 08:18:43 [Suricata-main:coredump-config] - (util-coredump-config.c:166) <Info> (CoredumpLoadConfig) -- Could not set core dump size to unlimited; it's set to the hard limit.
[2102717] 5/4/2021 -- 08:18:43 [Suricata-main:logopenfile] - (util-logopenfile.c:596) <Info> (SCConfLogOpenGeneric) -- fast output device (regular) initialized: fast.log
[2102717] 5/4/2021 -- 08:18:43 [Suricata-main:logopenfile] - (util-logopenfile.c:596) <Info> (SCConfLogOpenGeneric) -- eve-log output device (regular) initialized: eve.json
[2102717] 5/4/2021 -- 08:18:43 [Suricata-main:logopenfile] - (util-logopenfile.c:596) <Info> (SCConfLogOpenGeneric) -- stats output device (regular) initialized: stats.log
[2102717] 5/4/2021 -- 08:18:43 [Suricata-main:classification-config] - (util-classification-config.c:363) <Info> (SCClassConfParseFile) -- Added "43" classification types from the classification file
[2102717] 5/4/2021 -- 08:18:43 [Suricata-main:reference-config] - (util-reference-config.c:339) <Info> (SCRConfParseFile) -- Added "19" reference types from the reference.config file
[2102717] 5/4/2021 -- 08:18:47 [Suricata-main:detect-parse] - (detect-parse.c:714) <Error> (SigParseOptions) -- [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - unexpected option to http_header_names keyword: 'http_header_names'
[2102717] 5/4/2021 -- 08:18:47 [Suricata-main:detect-engine] - (detect-engine-loader.c:184) <Error> (DetectLoadSigFile) -- [ERRCODE: SC_ERR_INVALID_SIGNATURE(39)] - error parsing signature "alert http $HOME_NET any -> $EXTERNAL_NET any (msg:"ET MALWARE Win32/Adware.Adposhel.A Checkin M6"; flow:established,to_server; content:"GET"; http_method; urilen:>200; content:"/q/?q="; http_uri; depth:6; fast_pattern; pcre:"/^[a-zA-Z0-9_-]+/UR"; content:"User-Agent|3a 20|"; http_user_agent; depth:12; http_header_names: content:!"Referer"; content:!"Accept"; metadata: former_category ADWARE_PUP; classtype:trojan-activity; sid:2029055; rev:2; metadata:affected_product Windows_XP_Vista_7_8_10_Server_32_64_Bit, attack_target Client_Endpoint, deployment Perimeter, signature_severity Major, created_at 2019_11_26, performance_impact Low, updated_at 2019_11_26;)" from file /home/jlucovsky/et.rules at line 19714
[2102717] 5/4/2021 -- 08:19:05 [Suricata-main:detect-engine] - (detect-engine-loader.c:354) <Info> (SigLoadSignatures) -- 1 rule files processed. 19187 rules successfully loaded, 1 rules failed
[2102717] 5/4/2021 -- 08:19:05 [Suricata-main:threshold-config] - (util-threshold-config.c:250) <Warning> (SCThresholdConfInitContext) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/usr/local/etc/suricata//threshold.config": Permission denied
[2102717] 5/4/2021 -- 08:19:06 [Suricata-main:detect-engine] - (detect-engine-build.c:1416) <Info> (SigAddressPrepareStage1) -- 19190 signatures processed. 1094 are IP-only rules, 3860 are inspecting packet payload, 14179 inspect application layer, 0 are decoder event only
[2103193] 5/4/2021 -- 08:19:45 [RX#01:pcap-file] - (source-pcap-file.c:276) <Info> (ReceivePcapFileThreadInit) -- Argument /home/jlucovsky/pcap/ was a directory
[2102717] 5/4/2021 -- 08:19:46 [Suricata-main:threads] - (tm-threads.c:2020) <Notice> (TmThreadWaitOnThreadInit) -- Threads created -> RX: 1 W: 16 FM: 1 FR: 1   Engine started.
[2103193] 5/4/2021 -- 08:19:46 [RX#01:pcap-file] - (source-pcap-file.c:177) <Info> (ReceivePcapFileLoop) -- Starting directory run for /home/jlucovsky/pcap/

#suricata-verify-pr: #suricata-verify-repo: #suricata-verify-branch: #suricata-update-pr: #suricata-update-repo: #suricata-update-branch: #libhtp-pr: #libhtp-repo: #libhtp-branch:

[codecov[bot]]

Codecov Report

Merging #7346 (de7bf67) into master (07d0ae0) will decrease coverage by 0.08%. The diff coverage is 84.11%.

@@            Coverage Diff             @@
##           master    #7346      +/-   ##
==========================================
- Coverage   75.87%   75.79%   -0.09%     
==========================================
  Files         656      656              
  Lines      190056   190104      +48     
==========================================
- Hits       144211   144089     -122     
- Misses      45845    46015     +170     

Flag	Coverage Δ
fuzzcorpus	60.33% <63.80%> (-0.21%)	:arrow_down:
suricata-verify	51.59% <86.02%> (-0.02%)	:arrow_down:
unittests	60.99% <60.63%> (-0.02%)	:arrow_down:

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

[suricata-qa]

ERROR:

ERROR: QA failed on tlpw1_files_sha256.

field	test	baseline	%
	tlpr1_stats_chk
.flow.memuse	548469248	498197568	110.09%

Pipeline 7233

[suricata-qa]

ERROR:

ERROR: QA failed on tlpw1_files_sha256.

field	test	baseline	%
	tlpr1_stats_chk
.flow.memuse	548469248	498197568	110.09%

Pipeline 7233

[jasonish]

I think my comment from Aug 2021 still stands (https://github.com/OISF/suricata/pull/6284#pullrequestreview-740004082)

I think this is good now. The extra output is nice. I'd like to hear from @victorjulien if it does fullfill his reason for creating the issue in the first place.

I does add some extra complexity in the loggin path, but logging frameworks are complex these days to get nicer output.

So ping back to @victorjulien

[suricata-qa]

ERROR:

ERROR: QA failed on tlpw1_files_sha256.

field	baseline	test	%
	tlpr1_stats_chk
.flow.memuse	548469248	498197568	110.09%

Pipeline 7233

[victorjulien]

Merged in #8308, thanks!