Description
Describe the bug
SecAuditLogParts configuration works only for A,F and only partially for H. Partially - means that if hits the rule with drop/deny action that one line message is visible in section H. But even then it produces only one message without complete information which rules were hit.
Logs and dumps
Output of:
- DebugLogs (level 9)
[155354544647.949672] [] [4] Initializing transaction
[155354544647.949672] [] [4] Transaction context created.
[155354544647.949672] [] [4] Starting phase CONNECTION. (SecRules 0)
[155354544647.949672] [] [9] This phase consists of 0 rule(s).
[155354544647.949672] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[155354544647.949672] [/phpmyadmin?ala] [4] Adding request argument (GET): name "ala", value ""
[155354544647.949672] [/phpmyadmin?ala] [4] Starting phase REQUEST_HEADERS. (SecRules 1)
[155354544647.949672] [/phpmyadmin?ala] [9] This phase consists of 4 rule(s).
[155354544647.949672] [/phpmyadmin?ala] [4] (Rule: 200000) Executing operator "Rx" with param "(?:application(?:/soap+|/)|text/)xml" against REQUEST_HEADERS:Content-Type.
[155354544647.949672] [/phpmyadmin?ala] [4] Rule returned 0.
[155354544647.949672] [/phpmyadmin?ala] [9] Matched vars cleaned.
[155354544647.949672] [/phpmyadmin?ala] [4] (Rule: 200001) Executing operator "Rx" with param "application/json" against REQUEST_HEADERS:Content-Type.
[155354544647.949672] [/phpmyadmin?ala] [4] Rule returned 0.
[155354544647.949672] [/phpmyadmin?ala] [9] Matched vars cleaned.
[155354544647.949672] [/phpmyadmin?ala] [4] (Rule: 1234) Executing operator "Contains" with param "test" against ARGS:testparam.
[155354544647.949672] [/phpmyadmin?ala] [4] Rule returned 0.
[155354544647.949672] [/phpmyadmin?ala] [9] Matched vars cleaned.
[155354544647.949672] [/phpmyadmin?ala] [4] (Rule: 10000) Executing operator "Rx" with param "/phpmyadmin" against REQUEST_FILENAME.
[155354544647.949672] [/phpmyadmin?ala] [9] T (0) t:lowercase: "/phpmyadmin"
[155354544647.949672] [/phpmyadmin?ala] [9] T (0) t:normalisePath: "/phpmyadmin"
[155354544647.949672] [/phpmyadmin?ala] [9] Target value: "/phpmyadmin" (Variable: REQUEST_FILENAME)
[155354544647.949672] [/phpmyadmin?ala] [9] Matched vars updated.
[155354544647.949672] [/phpmyadmin?ala] [9] Saving msg: Blocking access to /phpmyadmin.
[155354544647.949672] [/phpmyadmin?ala] [4] Rule returned 1.
[155354544647.949672] [/phpmyadmin?ala] [4] Running (non-disruptive) action: tag
[155354544647.949672] [/phpmyadmin?ala] [9] Rule tag: Blacklist Rules
[155354544647.949672] [/phpmyadmin?ala] [9] Running action: log
[155354544647.949672] [/phpmyadmin?ala] [9] Saving transaction to logs
[155354544647.949672] [/phpmyadmin?ala] [4] Running (disruptive) action: drop.
[155354544647.949672] [/phpmyadmin?ala] [8] Running action drop [executing deny instead of drop.]
[155354544647.949672] [/phpmyadmin?ala] [8] Skipping this phase as this request was already intercepted.
[155354544647.949672] [/phpmyadmin?ala] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[155354544647.949672] [/phpmyadmin?ala] [9] This phase consists of 0 rule(s).
[155354544647.949672] [/phpmyadmin?ala] [9] Appending response body: 0 bytes. Limit set to: 524288.000000
[155354544647.949672] [/phpmyadmin?ala] [9] Appending response body: 0 bytes. Limit set to: 524288.000000
[155354544647.949672] [/phpmyadmin?ala] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[155354544647.949672] [/phpmyadmin?ala] [9] This phase consists of 0 rule(s).
[155354544647.949672] [/phpmyadmin?ala] [4] Starting phase LOGGING. (SecRules 5)
[155354544647.949672] [/phpmyadmin?ala] [9] This phase consists of 0 rule(s).
[155354544647.949672] [/phpmyadmin?ala] [8] Checking if this request is suitable to be saved as an audit log.
[155354544647.949672] [/phpmyadmin?ala] [8] Checking if this request is relevant to be part of the audit logs.
[155354544647.949672] [/phpmyadmin?ala] [5] Saving this request as part of the audit logs.
[155354544647.949672] [/phpmyadmin?ala] [8] Request was relevant to be saved. Parts: 6006
- AuditLogs
modsec_audit.log example entry for default config:
---eWBzcKDB---A--
[25/Mar/2019:21:20:18 +0100] 155354521858.170738 127.0.0.1 49456 127.0.0.1 80
---eWBzcKDB---B--
GET /ala.php?testparam=deny123 HTTP/1.1
User-Agent: curl/7.29.0
Host: localhost
Accept: /---eWBzcKDB---D--
---eWBzcKDB---F--
HTTP/1.1 404
Server: nginx/1.12.2
Date: Mon, 25 Mar 2019 20:20:18 GMT
Content-Length: 169
Content-Type: text/html
Connection: keep-alive---eWBzcKDB---H--
---eWBzcKDB---I--
---eWBzcKDB---J--
---eWBzcKDB---Z--
modsec_audit.log one entry for a rule with "deny" action:
---nGeBHQmm---A--
[25/Mar/2019:21:22:19 +0100] 155354533934.807582 127.0.0.1 49460 127.0.0.1 80
---nGeBHQmm---B--
GET /phpmyadmin?ala HTTP/1.1
User-Agent: curl/7.29.0
Host: localhost
Accept: /---nGeBHQmm---D--
---nGeBHQmm---F--
HTTP/1.1 403
Server: nginx/1.12.2
Date: Mon, 25 Mar 2019 20:22:19 GMT
Content-Length: 169
Content-Type: text/html
Connection: keep-alive---nGeBHQmm---H--
ModSecurity: Access denied with code 403 (phase 1). Matched "OperatorRx' with parameter
/phpmyadmin' against variableREQUEST_FILENAME' (Value:
/phpmyadmin' ) [file "/etc/nginx/modsec/main.conf"] [line "9"] [id "10000"] [rev ""] [msg "Blocking access to /phpmyadmin."] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [tag "Blacklist Rules"] [hostname "127.0.0.1"] [uri "/phpmyadmin"] [unique_id "155354533934.807582"] [ref "o0,11v4,11t:lowercase,t:normalisePath"]---nGeBHQmm---I--
---nGeBHQmm---J--
---nGeBHQmm---Z--
- Error logs
Not relevant - If there is a crash, the core dump file.
No crash
Notice: Be carefully to not leak any confidential information.
To Reproduce
Configuration was tested with following sets of software and always behaves the same way:
- Modsecurity 3.0.0 + Apache connector
- Modsecurity 3.0.2 + Nginx connector
- Modsecurity 3.0.3 + Nginx connector
- Master v3.0.3-56-g6d5198b + Nginx connector + patched file according to SecAuditLogParts "H" not being written in some cases #2000.
Testing rules for blocking action:
SecRule REQUEST_FILENAME "/phpmyadmin" "id:10000,phase:1,drop,log,t:lowercase,t:normalisePath,msg:'Blocking access to %{MATCHED_VAR}.',tag:'Blacklist Rules'"
SecRule REQUEST_FILENAME "/phpmyadmin" "id:10000,phase:1,deny,log,t:lowercase,t:normalisePath,msg:'Blocking access to %{MATCHED_VAR}.',tag:'Blacklist Rules'"
A curl command line that mimics the original request and reproduces the problem. Or a ModSecurity v3 test case:
curl -XGET http://localhost/phpmyadmin?ala
Expected behavior
Expected behaviour is to get full modsec_audit.log entry for all cases - like for modsecurity2.x
Example modsec_audit.log entry with multiple messages in Section H for case where the request wasn't blocked by modsecurity:
--68a39c63-A--
[01/May/2018:08:10:20 +0200] WvGgdU9AURJlp7Ta7HNRzAAAAAE 10.5.6.7 37346 192.168.0.1 443
--68a39c63-B--
GET /favicon.ico HTTP/1.1
Host: 192.168.0.1
Connection: keep-alive
Accept-Encoding: gzip, deflate
Accept: /
User-Agent: python-requests/2.13.0--68a39c63-F--
HTTP/1.1 404 Not Found
Content-Length: 209
Keep-Alive: timeout=5, max=100
Connection: Keep-Alive
Content-Type: text/html; charset=iso-8859-1--68a39c63-E--
<title>404 Not Found</title>Not Found
The requested URL /favicon.ico was not found on this server.
--68a39c63-H--
Message: Warning. Matched phrase "python-requests" at REQUEST_HEADERS:User-Agent. [file "/etc/httpd/conf.d/crs/rules/REQUEST-913-SCANNER-DETECTION.conf"] [line "164"] [id "913101"] [rev "1"] [msg "Found User-Agent associated with scripting/generic HTTP client"] [data "Matched Data: python-requests found within REQUEST_HEADERS:User-Agent: python-requests/2.13.0"] [severity "CRITICAL"] [ver "OWASP_CRS/3.0.0"] [maturity "9"] [accuracy "7"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-reputation-scripting"] [tag "OWASP_CRS/AUTOMATION/SCRIPTING"] [tag "WASCTC/WASC-21"] [tag "OWASP_TOP_10/A7"] [tag "PCI/6.5.10"] [tag "paranoia-level/2"]
Message: Warning. Pattern match "^[\d.:]+$" at REQUEST_HEADERS:Host. [file "/etc/httpd/conf.d/crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "810"] [id "920350"] [rev "2"] [msg "Host header is a numeric IP address"] [data "192.168.0.1"] [severity "WARNING"] [ver "OWASP_CRS/3.0.0"] [maturity "9"] [accuracy "9"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/IP_HOST"] [tag "WASCTC/WASC-21"] [tag "OWASP_TOP_10/A7"] [tag "PCI/6.5.10"]
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client 10.5.6.7] ModSecurity: Warning. Matched phrase "python-requests" at REQUEST_HEADERS:User-Agent. [file "/etc/httpd/conf.d/crs/rules/REQUEST-913-SCANNER-DETECTION.conf"] [line "164"] [id "913101"] [rev "1"] [msg "Found User-Agent associated with scripting/generic HTTP client"] [data "Matched Data: python-requests found within REQUEST_HEADERS:User-Agent: python-requests/2.13.0"] [severity "CRITICAL"] [ver "OWASP_CRS/3.0.0"] [maturity "9"] [accuracy "7"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-reputation-scripting"] [tag "OWASP_CRS/AUTOMATION/SCRIPTING"] [tag "WASCTC/WASC-21"] [tag "OWASP_TOP_10/A7"] [tag "PCI/6.5.10"] [tag "paranoia-level/2"] [hostname "192.168.0.1"] [uri "/favicon.ico"] [unique_id "WvGgdU9AURJlp7Ta7HNRzAAAAAE"]
Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client 10.5.6.7] ModSecurity: Warning. Pattern match "^[\\\\d.:]+$" at REQUEST_HEADERS:Host. [file "/etc/httpd/conf.d/crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "810"] [id "920350"] [rev "2"] [msg "Host header is a numeric IP address"] [data "192.168.0.1"] [severity "WARNING"] [ver "OWASP_CRS/3.0.0"] [maturity "9"] [accuracy "9"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/IP_HOST"] [tag "WASCTC/WASC-21"] [tag "OWASP_TOP_10/A7"] [tag "PCI/6.5.10"] [hostname "192.168.0.1"] [uri "/favicon.ico"] [unique_id "WvGgdU9AURJlp7Ta7HNRzAAAAAE"]
Stopwatch: 1525784693307805 2777 (- - -)
Stopwatch2: 1525784693307805 2777; combined=2021, p1=694, p2=748, p3=58, p4=209, p5=224, sr=328, sw=88, l=0, gc=0
Response-Body-Transformed: Dechunked
Producer: ModSecurity for Apache/2.9.2 (http://www.modsecurity.org/); OWASP_CRS/3.0.2.
Server: Apache/2.4.6 (CentOS) OpenSSL/1.0.2k-fips
Engine-Mode: "ENABLED"--68a39c63-Z--
Server :
Different configuration were tested:
- ModSecurity version (and connector): ModSecurity v3.0.0/v3.0.1/v3.0.2/master with nginx-connector (v1.0.0) + last apache connector (v0.0.9-beta1).
- WebServer: nginx 1.12.2
- OS (and distro): Centos7 + Ubuntu16.04
Rule Set (please complete the following information):
Tested with default modsecurity.conf only and some custom rules and with public CRS. No difference.
Additional context
JSON logging also is incomplete.
Setting SecAuditLogType from Serial to Concurrent doesn't change anything. Single files in such case don't have all the log parts.