SecAuditLogParts "H" not being written in some cases #2000

victorhora · 2019-01-11T22:40:15Z

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

The text was updated successfully, but these errors were encountered:

defanator · 2019-01-29T11:12:11Z

@victorhora were you able to check deeper on this one? Let me know if I could help.

victorhora · 2019-02-02T01:47:03Z

Hey @defan,

Going to have a look at it this week and let you know! :)

kfkawalec · 2019-02-28T08:05:56Z

Any progress? I also had problem with missing "H" log part.

defanator · 2019-03-13T09:39:23Z

@victorhora @zimmerle any chance to address this one before 3.0.4? :)

victorhora · 2019-03-15T22:26:30Z

Hi @defanator, sorry the delay :(

The problem seems to be that the conditions to push ruleMessage below is not met when only deny action is used:

https://github.com/SpiderLabs/ModSecurity/blob/6d5198b1a60992416c9c8f1d77754e8e5edba996/src/rule.cc#L815-L822

Then when the for loop to append m_rulesMessages to the audit_log string stream is called, the content of this std::list seems to be empty:

https://github.com/SpiderLabs/ModSecurity/blob/6d5198b1a60992416c9c8f1d77754e8e5edba996/src/transaction.cc#L1486-L1489

I think that this commit changed the behaviour: 69cd614

victorhora · 2019-03-15T23:00:59Z

We could fix with a condition to check if the "deny" action is present (or any disruptive action), but PR #2048 is up for evaluation. Let's see if the buildbots flag any issue :)

zimmerle · 2019-10-16T13:13:02Z

Merged at: d4dc3db

victorhora added bug It is a confirmed bug 3.x Related to ModSecurity version 3.x labels Jan 11, 2019

victorhora added this to the v3.0.4 milestone Jan 11, 2019

victorhora assigned zimmerle Jan 11, 2019

victorhora added this to To do in v3.0.4 via automation Jan 11, 2019

victorhora self-assigned this Jan 11, 2019

victorhora mentioned this issue Feb 20, 2019

audit log part H(Matched Rules) dont log the entire chain rule #2028

Closed

victorhora mentioned this issue Mar 15, 2019

Make sure m_rulesMessages is filled after successfull match #2048

Closed

victorhora added the pr available label Mar 15, 2019

molu8bits mentioned this issue Mar 25, 2019

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

Closed

zimmerle added this to To do in v3.1.0 via automation Oct 15, 2019

zimmerle removed this from To do in v3.0.4 Oct 15, 2019

zimmerle closed this as completed Oct 16, 2019

v3.1.0 automation moved this from To do to Done Oct 16, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

SecAuditLogParts "H" not being written in some cases #2000

SecAuditLogParts "H" not being written in some cases #2000

victorhora commented Jan 11, 2019 •

edited

defanator commented Jan 29, 2019

victorhora commented Feb 2, 2019

kfkawalec commented Feb 28, 2019

defanator commented Mar 13, 2019

victorhora commented Mar 15, 2019

victorhora commented Mar 15, 2019 •

edited

zimmerle commented Oct 16, 2019

SecAuditLogParts "H" not being written in some cases #2000

SecAuditLogParts "H" not being written in some cases #2000

Comments

victorhora commented Jan 11, 2019 • edited

defanator commented Jan 29, 2019

victorhora commented Feb 2, 2019

kfkawalec commented Feb 28, 2019

defanator commented Mar 13, 2019

victorhora commented Mar 15, 2019

victorhora commented Mar 15, 2019 • edited

zimmerle commented Oct 16, 2019

victorhora commented Jan 11, 2019 •

edited

victorhora commented Mar 15, 2019 •

edited