owasp-modsecurity / ModSecurity

ModSecurity is an open source, cross platform web application firewall (WAF) engine for Apache, IIS and Nginx. It has a robust event-based programming language which provides protection from a range of attacks against web applications and allows for HTTP traffic monitoring, logging and real-time analysis.
https://www.modsecurity.org
Apache License 2.0
8.26k stars 1.61k forks source link

SecAuditLogParts - only A, F works, H partially and only for blocking action #2053

Closed molu8bits closed 2 years ago

molu8bits commented 5 years ago

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:

  1. 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

  1. 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 "Operator Rx' with parameter/phpmyadmin' against variable REQUEST_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--

  1. Error logs Not relevant
  2. 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:

  1. Modsecurity 3.0.0 + Apache connector
  2. Modsecurity 3.0.2 + Nginx connector
  3. Modsecurity 3.0.3 + Nginx connector
  4. Master v3.0.3-56-g6d5198b + Nginx connector + patched file according to https://github.com/SpiderLabs/ModSecurity/issues/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-- <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">

404 Not Found

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:

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.

defanator commented 5 years ago

Looks like duplicate of #2000.

defanator commented 5 years ago

@molu8bits could you please try the PR from #2048?

molu8bits commented 5 years ago

I tried it already before raising the issue. PR #2048 adds a message when block action is given. But that doesn't solve the issue.

Please take a look at simplest case Rule: SecRule REQUEST_FILENAME "/phpmyadmin" "id:20000,phase:1,pass,log,t:lowercase,t:normalisePath,msg:'Blocking access to %{MATCHED_VAR}.',tag:'Blacklist Rules'"

The same url has been tested for Modsecurity2 and Modsecurity3: curl -XGET http://localhost/phpmyadmin?ala For this request compare section H for both version of Modsecurity:

modsec_audit.log from Modsecurity 2.9.2

--d9525e14-H-- Message: Access denied with code 403 (phase 1). Pattern match "/phpmyadmin" at REQUEST_FILENAME. [file "/etc/httpd/conf.d/mod_security.conf"] [line "94"] [id "10000"] [msg "Blocking access to /phpmyadmin."] [tag "Blacklist Rules"] Apache-Error: [file "apache2_util.c"] [line 271] [level 3] [client 127.0.0.1] ModSecurity: Access denied with code 403 (phase 1). Pattern match "/phpmyadmin" at REQUEST_FILENAME. [file "/etc/httpd/conf.d/mod_security.conf"] [line "94"] [id "10000"] [msg "Blocking access to /phpmyadmin."] [tag "Blacklist Rules"] [hostname "localhost"] [uri "/phpmyadmin"] [unique_id "XJn28xwFH9hnuefyVqX3bAAAAAM"] Action: Intercepted (phase 1) Stopwatch: 1553594099438286 1792 (- - -) Stopwatch2: 1553594099438286 1792; combined=645, p1=381, p2=0, p3=0, p4=0, p5=264, sr=0, sw=0, 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 mod_klwi/2.4 Engine-Mode: "ENABLED"

And compare with the line from Modsecurity 3:

--nGeBHQmm---H-- ModSecurity: Access denied with code 403 (phase 1). Matched "Operator Rx' with parameter /phpmyadmin' against variable REQUEST_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"]

For some cases when there is no rules with block/deny action defined e.g. curl -XOPTIONS http://localhost/ Modsecurity3 produces a log entry but not inform why:

---0F9RDt9Y---A-- [26/Mar/2019:11:27:21 +0100] 155359604188.762315 127.0.0.1 49500 127.0.0.1 80 ---0F9RDt9Y---B-- OPTIONS / HTTP/1.1 User-Agent: curl/7.29.0 Host: localhost Accept: /

---0F9RDt9Y---D--

---0F9RDt9Y---F-- HTTP/1.1 405 Server: nginx/1.12.2 Date: Tue, 26 Mar 2019 10:27:21 GMT Content-Length: 173 Content-Type: text/html Connection: keep-alive

---0F9RDt9Y---H--

---0F9RDt9Y---I--

---0F9RDt9Y---J--

---0F9RDt9Y---K--

---0F9RDt9Y---Z--

btw. it can be connected with #2054

martinhsv commented 2 years ago

@molu8bits ,

Is this still a problem?

Regarding the example at the end of your last posting: note that empty 'part H' output is consistent with ModSecurity not having had any rules triggered at all. In this case perhaps output was written to the audit log because you were using 'SecAuditEngine RelevantOnly' with SecAuditLogRelevantStatus? I.e. in this case the web server itself generated the 405 response code, and ModSecurity merely logged it because you told it to?

molu8bits commented 2 years ago

I don't use modsecurity currently, Anyway some time ago I was using nginx-ingress with built in modsecurity and it worked fine. All log parts were in place. Probably problem was solved in the meantime by some other patch.

martinhsv commented 2 years ago

@molu8bits ,

Thanks for the update.