Semantic of MATCHED_VARS / MATCHED_VARS_NAMES

[mirkodziadzka-avi]

Hi,

I have a question about the exact intended semantic of MATCHED_VARS / MATCHED_VARS_NAMES

The documentation is a little bit vague with

Similar to MATCHED_VAR_NAME except that it is a collection of all matches for the current operator check.

SecRule ARGS pattern "chain,deny,id:28"
  SecRule MATCHED_VARS_NAMES "@eq ARGS:param"

And all the examples and also the CoreRuleset always have this form: The second rule in the chain is accessing the matches from the first rule. So far, so good.

But what should happen if we have multiple rules (without chain)

From the documentation and my intuition, I would assume that the request GET /?foo=1&bar=2&baz=2 against these rules

SecRule ARGS "@rx 1" "id:1, phase:1, pass"
SecRule ARGS "@rx 2" "id:2, phase:1, pass"
SecRule MATCHED_VARS_NAMES "@contains ARGS:foo" "id:3, phase:1, deny, status:403"

would not block in rule 3, because MATCHED_VARS_NAMES should only contain the matches from rule 2: ARGS:bar and ARGS:baz at this point in time.

My assumption is:

After execution of rule 1:

• MATCHED_VAR_NAME = "ARGS:foo",
• MATCHED_VARS_NAMES = { "ARGS:foo" }

After execution of rule 2:

• MATCHED_VAR_NAME = "ARGS:baz" (or "ARGS:bar" depending on the order)
• MATCHED_VARS_NAMES = { "ARGS:bar", "ARGS:baz" }

So the 3rd rule should not match.

But when I add this as a regression test

[
  {
    "enabled":1,
    "version_min":300000,
    "title":"Testing Variables :: MATCHED_VARS_NAMES (3/3)",
    "request":{
      "uri":"/?foo=1&bar=2&baz=2",
      "method":"GET"
    },
    "expected":{
     "http_code": 200
    },
    "rules":[
      "SecRuleEngine On",
      "SecRule ARGS \"@rx 1\" \"id:1,phase:1,pass\"",
      "SecRule ARGS \"@rx 2\" \"id:2,phase:1,pass\"",
      "SecRule MATCHED_VARS_NAMES \"@contains ARGS:foo\" \"id:3,phase:1,deny,status:403\""
    ]
  }
]

and run it with the latest build

commit aab47091b1b95add953a54bbd8769540d2dfc0fe (HEAD -> v3/master, origin/v3/master, origin/HEAD)
Merge: 990d99b1 797f7dc4
Date:   Sun May 11 10:54:47 2025 +0200

the test is failing with

Test failed. From: test-cases/regression/avi.json.
Test name: Testing Variables :: MATCHED_VARS_NAMES (3/3).
Reason: 
HTTP code mismatch. expecting: 200 got: 403

Debug log:
[174732390351.534433] [] [4] Initializing transaction
[174732390351.534433] [] [4] Transaction context created.
[174732390351.534433] [] [4] Starting phase CONNECTION. (SecRules 0)
[174732390351.534433] [] [9] This phase consists of 0 rule(s).
[174732390351.534433] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Adding request argument (GET): name "foo", value "1"
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Adding request argument (GET): name "bar", value "2"
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Adding request argument (GET): name "baz", value "2"
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] This phase consists of 3 rule(s).
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] (Rule: 1) Executing operator "Rx" with param "1" against ARGS.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Target value: "1" (Variable: ARGS:foo)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Matched vars updated.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Target value: "2" (Variable: ARGS:bar)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Target value: "2" (Variable: ARGS:baz)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Rule returned 1.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Running (disruptive)     action: pass.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [8] Running action pass
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] (Rule: 2) Executing operator "Rx" with param "2" against ARGS.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Target value: "1" (Variable: ARGS:foo)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Target value: "2" (Variable: ARGS:bar)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Matched vars updated.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Target value: "2" (Variable: ARGS:baz)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Matched vars updated.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Rule returned 1.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Running (disruptive)     action: pass.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [8] Running action pass
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] (Rule: 3) Executing operator "Contains" with param "ARGS:foo" against MATCHED_VARS_NAMES.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Target value: "ARGS:foo" (Variable: MATCHED_VARS_NAMES:ARGS:foo)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Matched vars updated.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Target value: "ARGS:bar" (Variable: MATCHED_VARS_NAMES:ARGS:bar)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Target value: "ARGS:baz" (Variable: MATCHED_VARS_NAMES:ARGS:baz)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Rule returned 1.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Running action: status
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Running (disruptive)     action: deny.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [8] Running action deny
[174732390351.534433] [/?foo=1&bar=2&baz=2] [8] Skipping this phase as this request was already intercepted.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Appending request body: 0 bytes. Limit set to: 0.000000
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Starting phase REQUEST_BODY. (SecRules 2)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] This phase consists of 0 rule(s).
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] This phase consists of 0 rule(s).
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] Appending response body: 0 bytes. Limit set to: 0.000000
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Response body is disabled, returning... 2
[174732390351.534433] [/?foo=1&bar=2&baz=2] [4] Starting phase LOGGING. (SecRules 5)
[174732390351.534433] [/?foo=1&bar=2&baz=2] [9] This phase consists of 0 rule(s).
[174732390351.534433] [/?foo=1&bar=2&baz=2] [8] Checking if this request is suitable to be saved as an audit log.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [8] Checking if this request is relevant to be part of the audit logs.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [5] Audit log engine was not set.
[174732390351.534433] [/?foo=1&bar=2&baz=2] [8] Request was relevant to be saved. Parts: 4430

Error log:
ModSecurity: Warning. Matched "Operator `Rx' with parameter `1' against variable `ARGS:foo' (Value: `1' ) [file "avi.json"] [line "2"] [id "1"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname ""] [uri "/"] [unique_id "174732390351.534433"] [ref "o0,1v10,1"]
ModSecurity: Warning. Matched "Operator `Rx' with parameter `2' against variable `ARGS:baz' (Value: `2' ) [file "avi.json"] [line "3"] [id "2"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname ""] [uri "/"] [unique_id "174732390351.534433"] [ref "o0,1v16,1o0,1v22,1"]
[client ] ModSecurity: Access denied with code 403 (phase 1). Matched "Operator `Contains' with parameter `ARGS:foo' against variable `MATCHED_VARS_NAMES:ARGS:foo' (Value: `ARGS:foo' ) [file "avi.json"] [line "4"] [id "3"] [rev ""] [msg ""] [data ""] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname ""] [uri "/"] [unique_id "174732390351.534433"] [ref "o0,8v30,8"]

I would consider this as a bug because apparently the collection MATCH_VARS_NAMES is never cleaned and collect all the data from all the previous rules.

If this is intended, I think at least a documentation update is needed and maybe the CoreRuleset rules should be adapted (other project, I know)

[airween]

Hi @mirkodziadzka-avi,

thanks for this detailed report.

Just a side note before the relevant part:

And all the examples and also the CoreRuleset always have this form: The second rule in the chain is accessing the matches from the first rule. So far, so good.

I think we have to investigate this more, because as I remember, there is a problem with this variable in case of chained rules too. I have to look up that issue.

I would consider this as a bug because apparently the collection MATCH_VARS_NAMES is never cleaned and collect all the data from all the previous rules.

Yes, I think too. Especially if we take a look at the previous variable in (both) documentation:

• v2/MATCHED_VAR_NAME
• v3/MATCHED_VAR_NAME

There is an explanation:
"Note : Be aware that this variable holds data for the last operator match. This means that if there are more than one matches, only the last one will be populated. Use MATCHED_VARS_NAMES variable if you want all matches."

I think the relevant part here is this: "this variable holds data for the last operator match".

If we agree that these variables are similar, then the variable MATCHED_VARS_NAMES should follow the MATCHED_VAR_NAME's behavior (namely: holds the data for the last operator match).

If this is intended, I think at least a documentation update is needed

I think this is not intentional, but a bug that we have to fix.

But let others to explain their opinions - I mean what others say if we change a variable's behavior after N+1 years...

[airween]

I have to look up that issue.

I can't find the exact issue, but as I remember CRS does this trick because %{MATCHED_VAR_NAME} is not expanding in log message (and go-ftw tests were failed).

[MirkoDziadzka]

Hi @airween

Another observation and why this is a little bit more relevant:

MATCHED_VARS has the same behaviour as MATCHED_VARS_NAMES and this is used in multiple Core Ruleset rules. With the result that there could be some interesting interactions. So let's look at them:

Consider this simplified version of chain rules similar to how they are used in core ruleset

[
  {
    "enabled":1,
    "version_min":300000,
    "title":"Testing Variables :: MATCHED_VARS demo",
    "request":{
      "uri":"/?foo=maybeattack-specificpattern&bar=suspiciouspattern",
      "method":"GET"
    },
    "expected":{
     "http_code": 200
    },
    "rules":[
      "SecRuleEngine On",
      "SecAction \"setvar:tx.score=0\"",

      "SecRule ARGS \"@rx maybeattack\" \"id:1,phase:1, pass, chain\"",
      "    SecRule MATCHED_VARS \"@rx specificpattern\" \"setvar:'tx.score=+1'\"",

      "SecRule ARGS \"@rx suspiciouspattern\" \"id:2,phase:1, pass, chain\"",
      "    SecRule MATCHED_VARS \"@rx attack\" \"setvar:'tx.score=+1'\"",

      "SecRule TX:score \"@gt 1\" \"id:10, phase:1, deny, status:410\""
    ]
  }
]

What should TX:score be at the end.

The first rule contributes 1. If you disable the second rule, you get 1.
The second rule should contribute nothing. And on its own (if you remove rule 1) it does nothing.

But when both rules are there, the second rule contributes 2(!) to the score. So the final score is 3.

It usually works in practice "by accident" because when you add a rule between 1 and 2 which is not matching anything, then MATCHED_VARS get cleaned. In my opinion, this is very brittle behavior.

So the current semantic seems to be: "MATCHED_VARS is cleared on every non-matching SecRule"

[airween]

Hi @mirkodziadzka-avi,

So the current semantic seems to be: "MATCHED_VARS is cleared on every non-matching SecRule"

Agree. I can make a fix next week.