Problem with Audit Log

[kfkawalec]

I have nginx 1.16.1 with new version of modsecurity and all newest rules.
But on every request, event simple I have data in audit logs.

Of course I have SecAuditEngine RelevantOnly
All configuration from:
https://github.com/SpiderLabs/ModSecurity/blob/v3/master/modsecurity.conf-recommended
https://github.com/SpiderLabs/owasp-modsecurity-crs/blob/v3.3/dev/crs-setup.conf.example

How to change configuration to fave only real Relevant logs?

---Q3Z1GBlC---B--
GET / HTTP/1.1
Cache-Control: max-age=0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
accept-language: en-US,en;q=0.8
accept-encoding: gzip, compress

---Q3Z1GBlC---D--

---Q3Z1GBlC---E--

---Q3Z1GBlC---F--
HTTP/1.1 200
Date: Mon, 04 Nov 2019 22:09:05 GMT
Connection: keep-alive
Content-Length: 8923
Accept-Ranges: bytes
Content-Type: text/html; charset=UTF-8
Cache-Control: max-age=600, public
Last-Modified: Mon, 04 Nov 2019 21:53:52 GMT
Last-Modified: Mon, 04 Nov 2019 21:53:52 +0000
Vary: Accept-Encoding
Content-Encoding: gzip

---Q3Z1GBlC---H--
ModSecurity: Warning.  [file "/etc/nginx/modsec/crs-setup.conf"] [line "794"] [id "900990"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:inbound_anomaly_score_threshold' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "73"] [id "901100"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:outbound_anomaly_score_threshold' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "81"] [id "901110"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:paranoia_level' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "89"] [id "901120"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:executing_paranoia_level' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "97"] [id "901125"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:sampling_percentage' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "105"] [id "901130"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:critical_anomaly_score' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "113"] [id "901140"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:error_anomaly_score' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "120"] [id "901141"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:warning_anomaly_score' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "127"] [id "901142"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:notice_anomaly_score' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "134"] [id "901143"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:do_reput_block' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "142"] [id "901150"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:reput_block_duration' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "150"] [id "901152"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:allowed_methods' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "158"] [id "901160"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:allowed_request_content_type' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-901-INITIALIZATION.conf"] [line "166"] [id "901162"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
(...)
ModSecurity: Warning. Matched "Operator `Lt' with parameter `2' against variable `TX:EXECUTING_PARANOIA_LEVEL' (Value: `1' ) [file "/etc/nginx/modsec/rules/RESPONSE-950-DATA-LEAKAGES.conf"] [line "90"] [id "950014"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Lt' with parameter `2' against variable `TX:EXECUTING_PARANOIA_LEVEL' (Value: `1' ) [file "/etc/nginx/modsec/rules/RESPONSE-951-DATA-LEAKAGES-SQL.conf"] [line "447"] [id "951014"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Lt' with parameter `2' against variable `TX:EXECUTING_PARANOIA_LEVEL' (Value: `1' ) [file "/etc/nginx/modsec/rules/RESPONSE-952-DATA-LEAKAGES-JAVA.conf"] [line "79"] [id "952014"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Lt' with parameter `2' against variable `TX:EXECUTING_PARANOIA_LEVEL' (Value: `1' ) [file "/etc/nginx/modsec/rules/RESPONSE-953-DATA-LEAKAGES-PHP.conf"] [line "114"] [id "953014"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Lt' with parameter `2' against variable `TX:EXECUTING_PARANOIA_LEVEL' (Value: `1' ) [file "/etc/nginx/modsec/rules/RESPONSE-954-DATA-LEAKAGES-IIS.conf"] [line "123"] [id "954014"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Ge' with parameter `1' against variable `TX:PARANOIA_LEVEL' (Value: `1' ) [file "/etc/nginx/modsec/rules/RESPONSE-959-BLOCKING-EVALUATION.conf"] [line "28"] [id "959060"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Lt' with parameter `2' against variable `TX:EXECUTING_PARANOIA_LEVEL' (Value: `1' ) [file "/etc/nginx/modsec/rules/RESPONSE-959-BLOCKING-EVALUATION.conf"] [line "88"] [id "959014"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:dos_block_timeout' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-912-DOS-PROTECTION.conf"] [line "77"] [id "912110"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:dos_block_timeout' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-912-DOS-PROTECTION.conf"] [line "77"] [id "912110"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning. Matched "Operator `Eq' with parameter `0' against variable `TX:dos_block_timeout' (Value: `0' ) [file "/etc/nginx/modsec/rules/REQUEST-912-DOS-PROTECTION.conf"] [line "77"] [id "912110"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning.  [file "/etc/nginx/modsec/rules/RESPONSE-980-CORRELATION.conf"] [line "54"] [id "980115"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]
ModSecurity: Warning.  [file "/etc/nginx/modsec/rules/RESPONSE-980-CORRELATION.conf"] [line "97"] [id "980145"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/"] [unique_id "157290534524.356226"] [ref ""]

[invent-uk]

You are not alone, I have just identified the same problem on a modsec nginx stack. It must be a fairly recent defect, it was not present on the 6th of October.

[julienbouquet]

Same bug for me with nginx 1.17.5.

[martinhsv]

Thank you for reporting the issue.

This behaviour appears to have been triggered by the commit d4dc3db (Make sure m_ruleMessages is filled after successfull match).

Until this issue is resolved, the prior commit ( 42da29f ) may be used to avoid this issue.

[defanator]

We're also experiencing this issue.

@zimmerle do you have any input on when this would be addressed given your release schedule?

[arnaud-landry]

same problem here :/

[martinhsv]

A commit yesterday ( 199a9db ) has resolved the main issue.

There is still an anomaly, however, compared with v2.9 behaviour. If a rule chain begins with a rule with the nolog action, but the subsequent rules in the chain do not have 'nolog', then extra logging (as compared with v2.9) to part H will occur.

In OWASP CRS3, for example, three rules appear to be affected: 912100, 910130, 912110. If you wish to move to HEAD rev in ModSecurity v3/master, one option for addressing this (even if only on a temporary basis) is to add 'nolog' to the subsequent rules in those chains.

[defanator]

@martinhsv I'm still seeing an entry for transaction which is not being blocked (return code is 200) with the following audit log configuration:

SecAuditEngine RelevantOnly
SecAuditLogRelevantStatus "^(?:5|4(?!04))"
SecAuditLogParts ABIJDEFHZ
SecAuditLogType Serial
SecAuditLog /var/log/modsec_audit.log

From the debug log:

[157362647686.232319] [/modsec-full/a/b/c/] [8] Checking if this request is suitable to be saved as an audit log.
[157362647686.232319] [/modsec-full/a/b/c/] [8] Checking if this request is relevant to be part of the audit logs.
[157362647686.232319] [/modsec-full/a/b/c/] [5] Saving this request as part of the audit logs.
[157362647686.232319] [/modsec-full/a/b/c/] [8] Request was relevant to be saved. Parts: 6006

(any ideas what is "6006"?)

[martinhsv]

Hi @defanator,

6006 is the integer value of a bitmask representing the Parts that you have configured.

A=2, B=4, ..., Z=4096

ABIJDEFHZ, or reordered ABDEFHIJZ = 2+4+16+32+64+256+512+1024+4096 = 6006

[martinhsv]

With the recent commit ( 6395fe0 ), the remaining portion of this issue (mentioned above at resolved.#2196 (comment) ) should now be resolved.

[martinhsv]

Hi @kfkawalec,

I was not able to reply to your email. Regarding your report, make sure you have both fixes -- i.e. that you are at least up to commit ( 6395fe0 )

[kfkawalec]

Ok, I missed the second fix, I applied only the first.
Now its works.

[065191]

Is this fix already included in v3 / master?

---c1L6Ni73---H--
ModSecurity: Warning. Matched "Operator `Lt' with parameter `2' against variable `TX:EXECUTING_PARANOIA_LEVEL' (Value: `1' ) [file "/usr/local/nginx/conf/modsec/coreruleset/rules/2.conf"] [line "272"] [id "912014"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "0.0.0.0"] [uri "/test.html"] [unique_id "1615641842"] [ref ""]

....
nginx version: nginx/1.16.1
I see this problem recurring

[martinhsv]

The fixes referenced in this ticket were in place as of v3.0.4 and later.