Spurious unformatted 'Apache-Error' audit log lines in 2.9.1RC1

[lifeforms]

With ModSecurity 2.9.1RC1 on FreeBSD, for every ModSecurity log line in the audit log, another line Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s line is logged. (So if there are three ModSecurity events, there are three Apache-Error lines)

This looks weird and increases the site of the audit logs.

Reproduce:

• Generate any ModSecurity event
• See in audit log an Apache-Error line for every ModSecurity log entry in H section

Example:

-16c05e04-H--
Message: Warning. Pattern match "(?i:(?:[\"'`\xc2\xb4\xe2\x80\x99\xe2\x80\x98]\\s*?\\*.+(?:x?or|div|like|between|and|id)\\W*?[\"'`\xc2\xb4\xe2\x80\x99\xe2\x80\x98]\\d)|(?:\\^[\"'`\xc2\xb4\xe2\x80\x99\xe2\x80\x98])|(?:^[\\w\\s\"'`\xc2\xb4\xe2\x80\x99\xe2\x80\x98-]+(?<=and\\s)(?<=or|xor ..." at ARGS:id. [file "/usr/local/etc/apache24/security2/activated_rules/modsecurity_crs_41_sql_injection_attacks.conf"] [line "245"] [id "981243"] [msg "Detects classic SQL injection probings 2/2"] [data "Matched Data: '''''''''''''''''''''''''''''''''' found within ARGS:id: ''''''''''''''''''''''''''''''''''"] [severity "CRITICAL"] [tag "OWASP_CRS/WEB_ATTACK/SQL_INJECTION"]
Message: Access denied with code 403 (phase 2). Pattern match "(.*)" at TX:981243-Detects classic SQL injection probings 2/2-OWASP_CRS/WEB_ATTACK/SQLI-ARGS:id. [file "/usr/local/etc/apache24/security2/activated_rules/modsecurity_crs_49_inbound_blocking.conf"] [line "26"] [id "981176"] [msg "Inbound Anomaly Score Exceeded (Total Score: 5, SQLi=1, XSS=0): Last Matched Message: 981243-Detects classic SQL injection probings 2/2"] [data "Last Matched Data: ''''''''''''''''''''''''''''''''''"]
Message: Warning. Operator GE matched 5 at TX:inbound_anomaly_score. [file "/usr/local/etc/apache24/security2/activated_rules/modsecurity_crs_60_correlation.conf"] [line "37"] [id "981204"] [msg "Inbound Anomaly Score Exceeded (Total Inbound Score: 5, SQLi=1, XSS=0): 981243-Detects classic SQL injection probings 2/2"]
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s
Action: Intercepted (phase 2)
Apache-Handler: application/x-httpd-php
Stopwatch: 1455137855165863 20183 (- - -)
Stopwatch2: 1455137855165863 20183; combined=16486, p1=4190, p2=11871, p3=0, p4=0, p5=423, sr=205, sw=2, l=0, gc=0
Producer: ModSecurity for Apache/2.9.1-RC1 (http://www.modsecurity.org/); OWASP_CRS/2.2.9.
Server: Apache/2.4.18
Engine-Mode: "ENABLED"

--16c05e04-Z--

[dune73]

I think this has been around before. Here is a dump of my audit log for ModSec 2.7.5 on Apache 2.4.18:

--30a40174-H--
Message: Warning. Pattern match "(?:(?<!\\w)(?:\\.(?:ht(?:access|passwd|group)|www_?acl)|global\\.asa|httpd\\.conf|boot\\.ini)\\b|\\/etc\\/)" at ARGS:a. [file "/core-rules/modsecurity_crs_40_generic_attacks.conf"] [line "205"] [id "950005"] [rev "3"] [msg "Remote File Access Attempt"] [data "Matched Data: /etc/ found within ARGS:a: /etc/passwd"] [severity "CRITICAL"] [ver "OWASP_CRS/2.2.9"] [maturity "9"] [accuracy "9"] [tag "OWASP_CRS/WEB_ATTACK/FILE_INJECTION"] [tag "WASCTC/WASC-33"] [tag "OWASP_TOP_10/A4"] [tag "PCI/6.5.4"]
Message: Warning. Operator LT matched 500 at TX:inbound_anomaly_score. [file "/core-rules/modsecurity_crs_60_correlation.conf"] [line "33"] [id "981203"] [msg "Inbound Anomaly Score (Total Inbound Score: 5, SQLi=, XSS=): Remote File Access Attempt"]
Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "mod_authz_core.c"] [line 809] [level 7] AH01626: authorization result of %s: %s
Apache-Error: [file "core.c"] [line 4433] [level 6] AH00128: File does not exist: %s
Stopwatch: 1457442539179655 5578 (- - -)
Stopwatch2: 1457442539179655 5578; combined=3790, p1=645, p2=1952, p3=82, p4=303, p5=807, sr=147, sw=1, l=0, gc=0
Response-Body-Transformed: Dechunked
Producer: ModSecurity for Apache/2.7.5 (http://www.modsecurity.org/).
Server: Apache
Engine-Mode: "ENABLED"

So if this is a bug, then it is an old one. Or one introduced by a fairly recent apache version.

[bridavis]

I'm seeing lots of these:

Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client %s] ModSecurity: %s%s [uri "%s"]%s

In addition to this, I see many:
Message: Cannot add scalar value without an associated key

Prior to the Apache-Error above. There seems to be a 1:1 mapping, and have started since running 2.9.1 (unfortunately I was running 2.7.3 prior to that, so can't comment exactly what build introduced this behavior.

[dune73]

@bridavis, I think the messages populated with %s etc. date back at least to 2.7.5, but nobody noticed. It may also depend on the apache version.

We see that scalar value message for the first time. Could you elaborate a bit. Ideally minimal config and request to provoke the message. That would help to reproduce and isolate.

[bridavis]

@dune73 :
Server version: Apache/2.4.6 (CentOS)

I will send you a copy of the log offline.

Attaching log here in case anyone has seen this before. This doesn't seem to be an impacting issue, other than filling up the logs, but I'd like to confirm.
modsec_audit_scaler.txt

[chavez243ca]

seeing the same here: FreeBSD 9.3-RELEASE-p39 / Apache24 / modsec 2.9.1

[arminabf]

the reason is that the error log format is used instead of the formatted error log message

I have created a pull request for this problem: #1216

[zimmerle]

Hi @arminabf, Thank you for the patch.

@dune73: Any input on the patch ?

[dune73]

-> comments with the PR.

[arminabf]

@zimmerle as #1216 is closed, should this issue be closed as well?

[zimmerle]

Hi @arminabf, that is correct! thanks for remind me.