Incorrect log message from modsec v3 for CRS rule 920450 #2423
Comments
|
Interesting observation. Thank you for the regression @michaelgranzow-avi that speed up things. |
|
@zimmerle I've improved the test, so it actually checks for the error log. |
|
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: 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: msg "Illegal header [/restricted/]" |
|
The following patch fixes the issue for me (and doesn't break any of the existing regression tests): commit 2747a5c219f7e4fa06357ac6ad5cde6902ae62dc
Author: Michael Granzow <mgranzow@vmware.com>
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. |
|
@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? |
|
@zimmerle : I've created PRs against master/v3 and 3.1-experimental - please review. |
|
All merged. Patch available on both: v3/master and 3.1-experimental. Thank you @michaelgranzow-avi |
|
@michaelgranzow-avi (and @zimmerle if available), I would appreciate comment/insight on this matter. I have been revisiting this issue because the related pull request broke some functionality (see #2573 ) From what I have seen so far, it looks to me like the premise of this issue seems questionable. It is entirely possible that I have misunderstood something, so feel free to correct me. Allow me to explain the behaviour prior to the implementation of the pull request: The first of the two rules in the chain will run against every entry in REQUEST_HEADERS_NAMES. There are three of them and there are no guarantees about which one will be examined last but it can very well be 'Other' The 'msg' action runs and correctly populates the content using 'other'. In other words the correct MATCHED_VAR is in the log. Now, it is true that in the example case the match in the second rule of the chain is the one that is more meaningful to anyone examining the logs. But just because that happens to be the case in this example does not mean that will be true in every case. It's quite possible to imagine chained rules where the match in the first rule is actually the more meaningful one, and in other cases it might be the match in the 2nd-of-3 rules that is the most meaningful. In such cases it is now no longer possible to directly use MATCHED_VAR in order to output the desired information. (It would, of course, still be possible to assign to an intermediate variable to work around this.) So, could not the sample rule have achieved the desired output simply by including the msg action on the 2nd rule? The following seems to work perfectly well pre- #2435: To summarize my concerns (other than the fact that this broke the aforementioned multimatch use case):
|
|
Oh, I suppose I can guess the reason: because v2 only supports msg on the first rule of the chain. |
That's one aspect. The other is that the order in which we check each variable is unpredictable, so if all variables match the first rule (which in the example is not a 'real' rule, it just populates a new variable list), msg will be executed on every variable, and what then ends up in the log can be any variable in the first list. I think even in the case you have in mind, where you want to see the match of the first rule, you would want the match 'corresponding' to the variable that also hit the second rule. However, the two rules have no idea about each other's variables (and in the general case, there doesn't have to be such a connection between two chained rules). I think this exposes a limit of the modsec engine that forces users to write pseudo-rules that really correspond to program flow, not execution of checks on the request. |
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:
[ { "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:
Expected behavior
msg shows "Illegal header [restricted]" . Observed: "Illegal header [other]"
Server (please complete the following information):
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.
The text was updated successfully, but these errors were encountered: