Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

log: Add module and subsystem identifiers to log #6024

Closed
wants to merge 10 commits into from

Conversation

jlucovsky
Copy link
Contributor

Continuation of #6022

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:

  1. Clang-format fixups

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:

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.
Temporary update to display config.log file on failure.
Address the issue with supplying the actual thread name for the thread
formatting character `%m`. The subsystem identifier is a reliable proxy
for the thread name and can be used here; it avoids the potential
deadlock condition.
This commit converts the file logging logic to use JsonBuilder instead
of libjansson.
@codecov
Copy link

codecov bot commented Apr 5, 2021

Codecov Report

Merging #6024 (13c39aa) into master (b05bd05) will increase coverage by 0.01%.
The diff coverage is 74.04%.

@@            Coverage Diff             @@
##           master    #6024      +/-   ##
==========================================
+ Coverage   76.91%   76.93%   +0.01%     
==========================================
  Files         612      612              
  Lines      187721   187796      +75     
==========================================
+ Hits       144391   144484      +93     
+ Misses      43330    43312      -18     
Flag Coverage Δ
fuzzcorpus 52.67% <46.51%> (+0.08%) ⬆️
suricata-verify 50.28% <75.42%> (-0.01%) ⬇️
unittests 63.20% <45.37%> (-0.02%) ⬇️

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

@jlucovsky
Copy link
Contributor Author

Continued in #6037

@jlucovsky jlucovsky closed this Apr 7, 2021
@jlucovsky jlucovsky deleted the 2497/21 branch January 30, 2022 15:30
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

1 participant