fix: logs multiple vars matched by same rule (#1074)

internal/corazawaf/rule.go

@@ -274,8 +274,12 @@ func (r *Rule) doEvaluate(logger debuglog.Logger, phase types.RulePhase, tx *Tra
 						// Set the txn variables for expansions before usage
 						r.matchVariable(tx, mr)
 
-						if r.ParentID_ != noID || r.MultiMatch {
-							// In order to support Msg and LogData for inner rules, we need to expand them now
+						// Expansion for parent rule of a chain is postponed in order to rely on updated MATCHED_* variables.
+						// In all other cases, we want to expand here before continuing the rule evaluation to log the matched data
+						// just after the match an not just the last one. It is needed to log more than one variable matched by the same rule.
+						// The same logic applies to support Msg and LogData for inner rules. As soon as the inner rule matches, we want to expand and
+						// log the matched data.
+						if r.ParentID_ != noID || !r.HasChain {
 							if r.Msg != nil {
 								mr.Message_ = r.Msg.Expand(tx)
 							}
@@ -350,7 +354,7 @@ func (r *Rule) doEvaluate(logger debuglog.Logger, phase types.RulePhase, tx *Tra
 
 		// Expansion of Msg and LogData is postponed here. It allows to run it only if the whole rule/chain
 		// matches and to rely on MATCHED_* variables updated by the chain, not just by the first rule.
-		if !r.MultiMatch {
+		if r.HasChain || r.operator == nil {
 			if r.Msg != nil {
 				matchedValues[0].(*corazarules.MatchData).Message_ = r.Msg.Expand(tx)
 			}

internal/seclang/rules_test.go

@@ -245,6 +245,33 @@ func TestTagsAreNotPrintedTwice(t *testing.T) {
 	}
 }
 
+func TestPrintedExtraMsgAndDataFromRuleWithMultipleMatches(t *testing.T) {
+	waf := corazawaf.NewWAF()
+	var logs []string
+	waf.SetErrorCallback(func(mr types.MatchedRule) {
+		logs = append(logs, mr.ErrorLog())
+	})
+	parser := NewParser(waf)
+	err := parser.FromString(`
+	SecRule ARGS_GET "@rx .*" "id:1, phase:1, log, pass, logdata:'%{MATCHED_VAR} in %{MATCHED_VAR_NAME}"
+	`)
+	if err != nil {
+		t.Error(err.Error())
+	}
+	tx := waf.NewTransaction()
+	tx.AddGetRequestArgument("test", "1")
+	tx.AddGetRequestArgument("test2", "2")
+	tx.ProcessRequestHeaders()
+	if len(logs) != 1 {
+		t.Errorf("failed to log. Expected 1 entry, got %d", len(logs))
+	}
+	if count := strings.Count(logs[0], "2 in ARGS_GET:test2"); count != 1 {
+		t.Errorf("failed to log logdata, expected %q occurence, got %v", "2 in ARGS_GET:test2", logs[0])
+	}
+	if count := strings.Count(logs[0], "1 in ARGS_GET:test"); count != 1 {
+		t.Errorf("failed to log second logdata, expected %q occurence, got %v", "1 in ARGS_GET:test", logs[0])
+	}
+}
 func TestPrintedExtraMsgAndDataFromChainedRules(t *testing.T) {
 	waf := corazawaf.NewWAF()
 	var logs []string
@@ -269,7 +296,7 @@ func TestPrintedExtraMsgAndDataFromChainedRules(t *testing.T) {
 		t.Errorf("failed to set status, got %d", it.Status)
 	}
 	if len(logs) != 1 {
-		t.Errorf("failed to log with %d", len(logs))
+		t.Errorf("failed to log. Expected 1 entry, got %d", len(logs))
 	}
 	if count := strings.Count(logs[0], "1 in ARGS_GET:test"); count != 3 {
 		t.Errorf("failed to log logdata, expected 3 repetitions, got %d", count)
@@ -290,7 +317,7 @@ func TestPrintedMultipleMsgAndDataWithMultiMatch(t *testing.T) {
 	})
 	parser := NewParser(waf)
 	err := parser.FromString(`
-	SecRule ARGS_GET "@rx .*" "id:9696, phase:1, log, chain, deny, t:lowercase, status:403, msg:'msg', logdata:'%{MATCHED_VAR} in %{MATCHED_VAR_NAME}',multiMatch"
+	SecRule ARGS_GET "@rx .*" "id:9696, phase:1, log, deny, t:lowercase, status:403, msg:'msg', logdata:'%{MATCHED_VAR} in %{MATCHED_VAR_NAME}',multiMatch"
 	`)
 	if err != nil {
 		t.Error(err.Error())