Duplicated log messages when chained rule matched

[airween]

ModSecurity v3 sends log lines multiple times

If there is a chained SecRule (for eg. CRS 920250), then the engine sends the rule messages many times as the rule chained (the 920250 sends as two times).

The lines are in reversed order, at the first place is the last chained rule, the last is the first rule (I think it about the tag actions of each chained rules).

Example output

ModSecurity: Warning. Matched "Operator `ValidateUtf8Encoding' with parameter `' against variable `ARGS:test' (Value: `test%\xff1' ) [file "/usr/share/modsecurity-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "451"] [id "920250"] [rev ""] [msg "UTF8 Encoding Abuse Attack Attempt"] [data "1"] [severity "4"] [ver "OWASP_CRS/3.1.1"] [maturity "0"] [accuracy "0"] [hostname "127.0.0.1"] [uri "http://localhost/"] [unique_id "156685033144.236286"] [ref "o5,7v27,7"]

ModSecurity: Warning. Matched "Operator `ValidateUtf8Encoding' with parameter `' against variable `ARGS:test' (Value: `test%\xff1' ) [file "/usr/share/modsecurity-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "451"] [id "920250"] [rev ""] [msg "UTF8 Encoding Abuse Attack Attempt"] [data "1"] [severity "4"] [ver "OWASP_CRS/3.1.1"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/EVASION"] [hostname "127.0.0.1"] [uri "http://localhost/"] [unique_id "156685033144.236286"] [ref "o5,7v27,7"]

Note, that Operator attributes of rule messages are equal - I guess that's not right, because each rule has an own and unique operator.

Also there is a bug (I think that's a new parser issue), that the line attributes are wrong: the logged values are not the correct line numbers, they are next empty lines after the previous rule.

How to Reproduce

With a simple curl command: curl -v "http://localhost/?test=test%FF1", and see the log.

Expected behavior

I think the expected behavior would be that every (chained) rule exists only once per request with the correct line number. But this is my question: is this a feature or a bug?

[zimmerle]

Hi @airween,

Thank you for the report, please provide a way to reproduce the issue.

[airween]

Here is a gist:

https://gist.github.com/airween/42d00345d7f9de0082462c2417f47a5e

but I don't know why, the debug.log is empty when I run the test/regression_test.
With a real config, you can see that there are so many log lines how the rule chained.

[zimmerle]

Whenever you run the regression tests the debug log is printed on the console by the end of a failed test case.

[airween]

Sorry, I thought error.log, not debug.log. The duplicated logs are in webserver's error.log.

[zimmerle]

Same thing. The error log is in the console output.

[airween]

Right, changed the regression test, see the new one:

https://gist.github.com/airween/3e9c40c4b6663b38168bbc08233e7660

The output:

ModSecurity: Warning. Matched "Operator `Pm' with parameter `AppleWebKit Android' against variable `REQUEST_HEADERS:User-Agent' (Value: `curl/7.38.0' ) [file "issue-2157.json"] [line "3"] [id "920300"] [rev ""] [msg "Request Missing an Accept Header"] [data ""] [severity "5"] [ver "OWASP_CRS/3.2.0"] [maturity "0"] [accuracy "0"] [hostname "200.249.12.31"] [uri "/"] [unique_id "156873216068.506055"] [ref "v0,3v54,11"]
ModSecurity: Warning. Matched "Operator `Pm' with parameter `AppleWebKit Android' against variable `REQUEST_HEADERS:User-Agent' (Value: `curl/7.38.0' ) [file "issue-2157.json"] [line "3"] [id "920300"] [rev ""] [msg "Request Missing an Accept Header"] [data ""] [severity "5"] [ver "OWASP_CRS/3.2.0"] [maturity "0"] [accuracy "0"] [hostname "200.249.12.31"] [uri "/"] [unique_id "156873216068.506055"] [ref "v0,3v54,11"]
ModSecurity: Warning. Matched "Operator `Pm' with parameter `AppleWebKit Android' against variable `REQUEST_HEADERS:User-Agent' (Value: `curl/7.38.0' ) [file "issue-2157.json"] [line "3"] [id "920300"] [rev ""] [msg "Request Missing an Accept Header"] [data ""] [severity "5"] [ver "OWASP_CRS/3.2.0"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS"] [tag "OWASP_CRS/PROTOCOL_VIOLATION/MISSING_HEADER_ACCEPT"] [tag "WASCTC/WASC-21"] [tag "OWASP_TOP_10/A7"] [tag "PCI/6.5.10"] [tag "paranoia-level/2"] [hostname "200.249.12.31"] [uri "/"] [unique_id "156873216068.506055"] [ref "v0,3v54,11"]

with one request.

Thanks.

[martinhsv]

This duplication issue was corrected in v3/master back on November with 6395fe0

Only the final rule in a chain results in a 'Matched' message. This is consistent with v2.9 behaviour and appears to have been an intentional design decision ... although that's a decision we may choose to revisit at some point.

[airween]

Now I ran into this problem again.

git log -1
commit 0eb3c123f447b8787ea726ad4d4439018a07ee31 (HEAD -> v3/master, upstream/v3/master)
Merge: a1a8c0fd b9620c26
Author: martinhsv <55407942+martinhsv@users.noreply.github.com>
Date:   Mon Jul 6 07:54:44 2020 -0400

    Merge pull request #2348 from martinhsv/v3/master
    
    rx:exit after full match; fix TX population after unused group

I'm using OWASP CRS 3.3.

curl -vvv -H "Accept:" "http://localhost:8080/"

In error.log:

2020/07/07 11:11:43 [info] 319570#319570: *1 ModSecurity: Warning. Matched "Operator `Pm' with parameter `AppleWebKit Android' against variable `REQUEST_HEADERS:User-Agent' (Value: `curl/7.68.0' ) [file "/usr/share/modsecurity-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "1256"] [id "920300"] [rev ""] [msg "Request Missing an Accept Header"] [data ""] [severity "5"] [ver "OWASP_CRS/3.3.0"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS"] [tag "capec/1000/210/272"] [tag "PCI/6.5.10"] [tag "paranoia-level/2"] [hostname "0.0.0.0"] [uri "/"] [unique_id "1594120303"] [ref "v0,3v48,11"], client: ::1, server: _, request: "GET / HTTP/1.1", host: "localhost:8080"
2020/07/07 11:11:43 [info] 319570#319570: *1 ModSecurity: Warning. Matched "Operator `Pm' with parameter `AppleWebKit Android' against variable `REQUEST_HEADERS:User-Agent' (Value: `curl/7.68.0' ) [file "/usr/share/modsecurity-crs/rules/REQUEST-920-PROTOCOL-ENFORCEMENT.conf"] [line "1256"] [id "920300"] [rev ""] [msg "Request Missing an Accept Header"] [data ""] [severity "5"] [ver "OWASP_CRS/3.3.0"] [maturity "0"] [accuracy "0"] [tag "application-multi"] [tag "language-multi"] [tag "platform-multi"] [tag "attack-protocol"] [tag "OWASP_CRS"] [tag "capec/1000/210/272"] [tag "PCI/6.5.10"] [tag "paranoia-level/2"] [hostname "0.0.0.0"] [uri "/"] [unique_id "1594120303"] [ref "v0,3v48,11"], client: ::1, server: _, request: "GET / HTTP/1.1", host: "localhost:8080"

Is that the expected?

[martinhsv]

Hi @airween ,

I can reproduce what you have reported. And, no, I'm pretty sure it's not an expected behaviour.

Note that it is not related to the most recent merge (Indeed, that would be quite a surprising side effect of that change).

This may be a temporary phenomenon given that some of the v3.1 code changes have yet to be merged. Thanks for mentioning it though.

[martinhsv]

Hi @airween ,

Just following up on the post-closure activity and I find that I cannot currently reproduce what you had reported -- not with current v3/master and not with v3/master as it existed in July 2020.

I no longer have the same setup that I used back then so it makes me wonder aloud if there might have been some other configuration detail common to us both that might have been the actual cause of this effect (e.g. error redirects resulting in two requests being analyzed, perhaps?)

If you believe this is a current problem, I'm going to suggest opening a fresh issue for it. For one thing, if there is a problem in ModSecurity code, I think it's likely to be different from the original solution to 2157 (implemented in Nov. 2019). Also, it would make for clearer tracking to have an issue with the 'Open' status.

If you believe it is still a problem, we can then work through whatever is needed to make it reproducible on my end.