Description
Describe the bug
Our friend @defanator have recently reported a strange behaviour where SecAuditLogParts "H" is not being written to the audit_log in some cases. Namely:
SecRule ARGS:testparam "@contains test" "id:1234,deny,log,status:403"
- this rule does not produce anything in H section
SecRule ARGS:testparam "@contains test" "id:1234,block,log,status:403"
- while this one does
The difference being block action vs deny action.
Logs and dumps
---C788bS9S---A--
[11/Jan/2019:15:08:25 +0000] 154721930524.840108 127.0.0.1 48688 127.0.0.1 80
---C788bS9S---B--
GET /?testparam=deny123 HTTP/1.1
Host: localhost
User-Agent: curl/7.47.0
Accept: */*
---C788bS9S---D--
---C788bS9S---E--
<html>\x0d\x0a<head><title>403 Forbidden</title></head>\x0d\x0a<body>\x0d\x0a<center><h1>403 Forbidden</h1></center>\x0d\x0a<hr><center>nginx/1.15.7</center>\x0d\x0a</body>\x0d\x0a</html>\x0d\x0a
---C788bS9S---F--
HTTP/1.1 403
Server: nginx/1.15.7
Date: Fri, 11 Jan 2019 15:08:25 GMT
Content-Length: 153
Content-Type: text/html
Connection: keep-alive
---C788bS9S---H--
---C788bS9S---I--
---C788bS9S---J--
---C788bS9S---Z--
---PuQ3VB7M---A--
[11/Jan/2019:15:08:29 +0000] 154721930978.657786 127.0.0.1 33304 127.0.0.1 8080
---PuQ3VB7M---B--
GET /?testparam=block123 HTTP/1.0
Host: 127.0.0.1:8080
Connection: close
User-Agent: curl/7.47.0
Accept: */*
---PuQ3VB7M---D--
---PuQ3VB7M---F--
HTTP/1.0 200
Server: nginx/1.15.7
Date: Fri, 11 Jan 2019 15:08:29 GMT
Content-Length: 3
Content-Type: application/octet-stream
Connection: close
---PuQ3VB7M---H--
ModSecurity: Warning. Matched "Operator `Contains' with parameter `block' against variable `ARGS:testparam' (Value: `block123' ) [file "/etc/nginx/modsec/main.conf"] [line "4"] [id "2"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/"] [unique_id "154721930978.657786"] [ref "o0,5v16,8"]
---PuQ3VB7M---I--
---PuQ3VB7M---J--
---PuQ3VB7M---Z--
---OGil38n5---A--
[11/Jan/2019:15:08:29 +0000] 154721930919.957004 127.0.0.1 48692 127.0.0.1 80
---OGil38n5---B--
GET /?testparam=block123 HTTP/1.1
Host: localhost
User-Agent: curl/7.47.0
Accept: */*
---OGil38n5---D--
---OGil38n5---F--
HTTP/1.1 200
Server: nginx/1.15.7
Date: Fri, 11 Jan 2019 15:08:29 GMT
Content-Length: 3
Content-Type: application/octet-stream
Connection: keep-alive
---OGil38n5---H--
ModSecurity: Warning. Matched "Operator `Contains' with parameter `block' against variable `ARGS:testparam' (Value: `block123' ) [file "/etc/nginx/modsec/main.conf"] [line "4"] [id "2"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "/"] [unique_id "154721930919.957004"] [ref "o0,5v16,8"]
---OGil38n5---I--
---OGil38n5---J--
---OGil38n5---Z--
To Reproduce
Steps to reproduce the behavior:
the above audit log is for 2 requests with such configuration:
SecRule ARGS:testparam "@contains deny" "id:1,deny,log,status:403"
SecRule ARGS:testparam "@contains block" "id:2,block,log,status:403"
Expected behavior
Part "H" should be written to the audit_logs regardless.
Server (please complete the following information):
- ModSecurity version (and connector): 3.0.3?
- WebServer: Nginx?
- OS (and distro): ?
Rule Set (please complete the following information):
- Running any public or commercial rule set? [e.g. SpiderLabs commercial rules]
- What is the version number? [e.g. 2018-08-11]
Additional context
Pending to test the behaviour on v2;
Interesting fact is that the same message (which should be in section H) is going to nginx error log just fine, in both cases;
modifying SecDefaultAction doesn't help;
Also worth checking changing “block” to “pass” It could help us nailing down where the issue lies
For the reference: https://github.com/SpiderLabs/ModSecurity/blob/v3/master/src/transaction.cc#L1486-L1493
Another relevant piece of code: https://github.com/SpiderLabs/ModSecurity/blob/1ecd9713061c3534626bf6a5f59d1c928c0c52bb/src/rule.cc#L805-L822
H is generated over an iteration on rule msg. If not pushed to this array it won't make to the audits
SecDefaultAction "phase:1,log,auditlog,deny,status:403"
SecDefaultAction "phase:2,log,auditlog,deny,status:403"
Getting the same parts in audit log, while "block" now leads to 403