Modsecurity: Incorrect log message from modsec v3 for CRS rule 920450

[michaelgranzow-avi]

Describe the bug

In chained rules, if actions 'msg' or 'logdata' contain variables like %{MATCHED_VAR}, and are used in a rule that isn't the last in the chain, the wrong MATCHED_VAR can end up in the logs.

Logs and dumps

The following regression test reproduces the bug:

```.json
[
{
"enabled":1,
"version_min":300000,
"title":"Test match variable",
"expected":{
"http_code": 437,
"error_log": "msg \"Illegal header \[restricted\]\""
},
"client":{
"ip":"200.249.12.31",
"port":123
},
"request":{
"headers":{
"Host":"localhost",
"Restricted":"attack",
"Other":"Value"
},
"uri":"/",
"method":"GET"
},
"server":{
"ip":"200.249.12.31",
"port":80
},
"rules":[
"SecRuleEngine On",
"SecRule REQUEST_HEADERS_NAMES \"^.*$\" \"phase:2,setvar:'tx.header_name_%{TX.0}=/%{TX.0}/',deny,t:lowercase,capture,id:500065,msg:'Illegal header [%{MATCHED_VAR}]',logdata:'Restricted header detected: %{MATCHED_VAR}',chain\"",
"SecRule TX:/^header_name_/ \"@within /name1/restricted/name3/\" \"status:437\""
]
}
]

Full logs from regression test:

```.txt
Debug log:
[1602861515] [] [4] Initializing transaction
[1602861515] [] [4] Transaction context created.
[1602861515] [] [4] Starting phase CONNECTION. (SecRules 0)
[1602861515] [] [9] This phase consists of 0 rule(s).
[1602861515] [] [4] Starting phase URI. (SecRules 0 + 1/2)
[1602861515] [/] [4] Starting phase REQUEST_HEADERS.  (SecRules 1)
[1602861515] [/] [9] This phase consists of 0 rule(s).
[1602861515] [/] [9] Appending request body: 0 bytes. Limit set to: 0.000000
[1602861515] [/] [4] Starting phase REQUEST_BODY. (SecRules 2)
[1602861515] [/] [9] This phase consists of 1 rule(s).
[1602861515] [/] [4] (Rule: 500065) Executing operator "Rx" with param "^.*$" against REQUEST_HEADERS_NAMES.
[1602861515] [/] [9]  T (0) t:lowercase: "host"
[1602861515] [/] [9] Target value: "host" (Variable: REQUEST_HEADERS_NAMES:Host)
[1602861515] [/] [7] Added regex subexpression TX.0: host
[1602861515] [/] [9] Matched vars updated.
[1602861515] [/] [4] Running [independent] (non-disruptive) action: setvar
[1602861515] [/] [8] Saving variable: TX:header_name_host with value: /host/
[1602861515] [/] [9] Saving msg: Illegal header [host]
[1602861515] [/] [9]  T (0) t:lowercase: "restricted"
[1602861515] [/] [9] Target value: "restricted" (Variable: REQUEST_HEADERS_NAMES:Restricted)
[1602861515] [/] [7] Added regex subexpression TX.0: restricted
[1602861515] [/] [9] Matched vars updated.
[1602861515] [/] [4] Running [independent] (non-disruptive) action: setvar
[1602861515] [/] [8] Saving variable: TX:header_name_restricted with value: /restricted/
[1602861515] [/] [9] Saving msg: Illegal header [restricted]
[1602861515] [/] [9]  T (0) t:lowercase: "other"
[1602861515] [/] [9] Target value: "other" (Variable: REQUEST_HEADERS_NAMES:Other)
[1602861515] [/] [7] Added regex subexpression TX.0: other
[1602861515] [/] [9] Matched vars updated.
[1602861515] [/] [4] Running [independent] (non-disruptive) action: setvar
[1602861515] [/] [8] Saving variable: TX:header_name_other with value: /other/
[1602861515] [/] [9] Saving msg: Illegal header [other]
[1602861515] [/] [4] Rule returned 1.
[1602861515] [/] [4] Executing chained rule.
[1602861515] [/] [4] (Rule: 0) Executing operator "Within" with param "/name1/restricted/name3/" against TX:regex(^header_name_).
[1602861515] [/] [9] Target value: "/host/" (Variable: TX:header_name_host)
[1602861515] [/] [9] Target value: "/restricted/" (Variable: TX:header_name_restricted)
[1602861515] [/] [9] Matched vars updated.
[1602861515] [/] [9] Target value: "/other/" (Variable: TX:header_name_other)
[1602861515] [/] [4] Rule returned 1.
[1602861515] [/] [9] Running action: status
[1602861515] [/] [4] Running (disruptive)     action: deny.
[1602861515] [/] [8] Running action deny
[1602861515] [/] [8] Skipping this phase as this request was already intercepted.
[1602861515] [/] [4] Starting phase RESPONSE_HEADERS. (SecRules 3)
[1602861515] [/] [9] This phase consists of 0 rule(s).
[1602861515] [/] [9] Appending response body: 0 bytes. Limit set to: 0.000000
[1602861515] [/] [4] Starting phase RESPONSE_BODY. (SecRules 4)
[1602861515] [/] [4] Response body is disabled, returning... 2
[1602861515] [/] [4] Starting phase LOGGING. (SecRules 5)
[1602861515] [/] [9] This phase consists of 0 rule(s).
[1602861515] [/] [8] Checking if this request is suitable to be saved as an audit log.
[1602861515] [/] [8] Checking if this request is relevant to be part of the audit logs.
[1602861515] [/] [5] Audit log engine was not set.
[1602861515] [/] [8] Request was relevant to be saved. Parts: 4430

Error log:
[client 200.249.12.31] ModSecurity: Access denied with code 437 (phase 2). Matched "Operator `Within' with parameter `/name1/restricted/name3/' against variable `TX:header_name_restricted' (Value: `/restricted/' ) [file "r3.json"] [line "2"]\
 [id "500065"] [rev ""] [msg "Illegal header [other]"] [data "Restricted header detected: other"] [severity "0"] [ver ""] [maturity "0"] [accuracy "0"] [hostname "200.249.12.31"] [uri "/"] [unique_id "1602861515"] [ref "o0,4v12,4t:lowercaseo\
0,10v28,10t:lowercaseo0,5v47,5t:lowercaseo6,12"]

Expected behavior

msg shows "Illegal header [restricted]" . Observed: "Illegal header [other]"

Server (please complete the following information):

• current ModSecurity version v3/master (commit 377fb723ca5ae14f4fa14e025eeae1702e904e52)

Rule Set (please complete the following information):
Issue was spotted in CRS rule 920450, but the above rule is the minimal scenario to reproduce it.

Additional context

Tests have shown that modsec v2 shows the expected behavior.

[zimmerle]

Interesting observation.

Thank you for the regression @michaelgranzow-avi that speed up things.

[michaelgranzow-avi]

@zimmerle I've improved the test, so it actually checks for the error log.

[michaelgranzow-avi]

One more observation: the behaviour in v2 is not fundamentally different. That is, the order of loops over rules, variables, transformations etc is similar. What is different is that 'meta actions' like id, msg etc can only be attached to the first rule in a chain. And those actions are executed after all rules have fired in the chain. Therefore, the 'msg' action in the test above is executed when the second rule fires. At that stage, %{MATCHED_VAR} is '/restricted/', the value of the variable 'TX:header_name_restricted, and hence the log contains the following message:

```.txt
msg "Illegal header [/restricted/]"

To emphasize: also in v2, we don't see the variable that was the root cause of the rejection by modsec (this would be REQUEST_HEADERS:Restricted), but the variable that was constructed in the first and used in the second rule.

The main difference seems to be that in v3 those 'meta actions' don't get executed again at the end, when the second rule fires. If I place the 'msg' action with the second rule in the chain (which isn't allowed in v2), I get this log message, the same as v2:
```.txt
msg "Illegal header [/restricted/]"

[michaelgranzow-avi]

The following patch fixes the issue for me (and doesn't break any of the existing regression tests):

```.txt
commit 2747a5c219f7e4fa06357ac6ad5cde6902ae62dc
Author: Michael Granzow [e-mail]
Date: Tue Oct 20 11:18:23 2020 +0000

Issue 2423: Run actions 'msg', 'logdata' and 'severity' only at the end of a chain

diff --git a/src/rule_with_actions.cc b/src/rule_with_actions.cc
index a2d7306..5e7e113 100644
--- a/src/rule_with_actions.cc
+++ b/src/rule_with_actions.cc
@@ -215,17 +215,6 @@ void RuleWithActions::executeActionsIndependentOfChainedRuleResult(Transaction *
}
}

• if (m_severity) {
• m_severity->evaluate(this, trans, ruleMessage);
• }
  -
• if (m_logData) {
• m_logData->evaluate(this, trans, ruleMessage);
• }
  -
• if (m_msg) {
• m_msg->evaluate(this, trans, ruleMessage);
• }
  }

@@ -257,6 +246,17 @@ void RuleWithActions::executeActionsAfterFullMatch(Transaction *trans,
executeAction(trans, containsBlock, ruleMessage, a, false);
disruptiveAlreadyExecuted = true;
}

• if (m_severity) {
• m_severity->evaluate(this, trans, ruleMessage);
• }
  +
• if (m_logData) {
• m_logData->evaluate(this, trans, ruleMessage);
• }
  +
• if (m_msg) {
• m_msg->evaluate(this, trans, ruleMessage);
• }
  for (Action *a : this->m_actionsRuntimePos) {
  if (!a->isDisruptive()
  && !(disruptiveAlreadyExecuted
  diff --git a/test/test-cases/regression/msg_in_chain.json b/test/test-cases/regression/msg_in_chain.json
  new file mode 100644
  index 0000000..9ea7803
  --- /dev/null
  +++ b/test/test-cases/regression/msg_in_chain.json
  @@ -0,0 +1,33 @@
  +[
• {
• "enabled":1,
• "version_min":300000,
• "title":"Test match variable",
• "expected":{
• "http_code": 437,
• "error_log": "msg \"Illegal header \[/restricted/\]\""
• },
• "client":{
• "ip":"200.249.12.31",
• "port":123
• },
• "request":{
• "headers":{
• "Host":"localhost",
• "Restricted":"attack",
• "Other": "Value"
• },
• "uri":"/",
• "method":"GET"
• },
• "server":{
• "ip":"200.249.12.31",
• "port":80
• },
• "rules":[
• "SecRuleEngine On",
• "SecRule REQUEST_HEADERS_NAMES \"^.*$\" \"phase:2,setvar:'tx.header_name_%{TX.0}=/%{TX.0}/',deny,t:lowercase,capture,id:500065,msg:'Illegal header [%{MATCHED_VAR}]',logdata:'Restricted header detected: %{MATCHED_VAR}',chain\"",
• "SecRule TX:/^header_name_/ \"@within /name1/restricted/name3/\" \"status:437\""
• ]
• }
  +]
  ```
  I would open a PR, but it seems I don't have the permissions.

[zimmerle]

@michaelgranzow-avi You should have permission for the pull request. However I would like to highlight the fact that we are also working on 3.1-experimental. There, this particular piece of code may look a bit different. In particular, how the MATCHED_VAR is set.

As a side note, do you have the effort to help us testing v3.1-experimental?

[michaelgranzow-avi]

@zimmerle : I've created PRs against master/v3 and 3.1-experimental - please review.

[zimmerle]

All merged. Patch available on both: v3/master and 3.1-experimental. Thank you @michaelgranzow-avi