fix(DetectionOnly): fixed RelevantOnly audit logs, improved matchedRules

internal/actions/allow.go

@@ -56,7 +56,7 @@ func (a *allowFn) Init(_ plugintypes.RuleMetadata, data string) error {
 
 func (a *allowFn) Evaluate(r plugintypes.RuleMetadata, txS plugintypes.TransactionState) {
 	tx := txS.(*corazawaf.Transaction)
-	tx.AllowType = a.allow
+	tx.Allow(a.allow)
 }
 
 func (a *allowFn) Type() plugintypes.ActionType {

internal/corazawaf/rule.go

@@ -377,15 +377,22 @@ func (r *Rule) doEvaluate(logger debuglog.Logger, phase types.RulePhase, tx *Tra
 		}
 
 		for _, a := range r.actions {
-			if a.Function.Type() == plugintypes.ActionTypeFlow {
-				// Flow actions are evaluated also if the rule engine is set to DetectionOnly
+			// All actions are evaluated independently from the engine being On or in DetectionOnly.
+			// The action evaluation is responsible of checking the engine mode and decide if the disruptive action
+			// has to be enforced or not. This allows finer control to the actions, such us creating the detectionOnlyInterruption and
+			// allowing RelevantOnly audit logs in detection only mode.
+			switch a.Function.Type() {
+			case plugintypes.ActionTypeFlow:
 				logger.Debug().Str("action", a.Name).Int("phase", int(phase)).Msg("Evaluating flow action for rule")
-				a.Function.Evaluate(r, tx)
-			} else if a.Function.Type() == plugintypes.ActionTypeDisruptive && tx.RuleEngine == types.RuleEngineOn {
+			case plugintypes.ActionTypeDisruptive:
 				// The parser enforces that the disruptive action is just one per rule (if more than one, only the last one is kept)
-				logger.Debug().Str("action", a.Name).Msg("Executing disruptive action for rule")
-				a.Function.Evaluate(r, tx)
+				logger.Debug().Str("action", a.Name).Int("phase", int(phase)).Msg("Executing disruptive action for rule")
+			default:
+				// Only flow and disruptive actions are supposed to be evaluated here, non disruptive actions
+				// are evaluated previously, during the variable matching.
+				continue
 			}
+			a.Function.Evaluate(r, tx)
 		}
 		if r.ID_ != noID {
 			// we avoid matching chains and secmarkers

internal/corazawaf/rulegroup.go

@@ -159,7 +159,7 @@ RulesLoop:
 		r := &rg.rules[i]
 		// if there is already an interruption and the phase isn't logging
 		// we break the loop
-		if tx.interruption != nil && phase != types.PhaseLogging {
+		if tx.IsInterrupted() && phase != types.PhaseLogging {
 			break RulesLoop
 		}
 		// Rules with phase 0 will always run
@@ -263,7 +263,7 @@ RulesLoop:
 	tx.Skip = 0
 
 	tx.stopWatches[phase] = time.Now().UnixNano() - ts
-	return tx.interruption != nil
+	return tx.IsInterrupted()
 }
 
 // NewRuleGroup creates an empty RuleGroup that

internal/corazawaf/transaction.go

@@ -54,6 +54,12 @@ type Transaction struct {
 	// True if the transaction has been disrupted by any rule
 	interruption *types.Interruption
 
+	// detectionOnlyInterruption keeps track of the interruption that would have been performed if the engine was On.
+	// It provides visibility of what would have happened in On mode when the engine is set to "DetectionOnly"
+	// and is used to correctly emit relevant only audit logs in DetectionOnly mode (When the rules would have
+	// caused an interruption if the engine was On).
+	detectionOnlyInterruption *types.Interruption
+
 	// This is used to store log messages
 	// Deprecated since Coraza 3.0.5: this variable is not used, logdata values are stored in the matched rules
 	Logdata string
@@ -62,6 +68,9 @@ type Transaction struct {
 	SkipAfter string
 
 	// AllowType is used by the allow disruptive action to skip evaluating rules after being allowed
+	// Note: Rely on tx.Allow(allowType) for tweaking this field. This field is exposed for backwards
+	// compatibility, but it is not recommended to be used directly.
+	// TODO(4.x): Evaluate to make it private
 	AllowType corazatypes.AllowType
 
 	// Copies from the WAF instance that may be overwritten by the ctl action
@@ -309,9 +318,36 @@ func (tx *Transaction) Collection(idx variables.RuleVariable) collection.Collect
 	return collections.Noop
 }
 
+// Interrupt sets the interruption for the transaction.
+// It complies with DetectionOnly definition which requires that disruptive actions are not executed.
+// Depending on the RuleEngine mode:
+// If On: it immediately interrupts the transaction and generates a response.
+// If DetectionOnly: it keeps track of what the interruption would have been if the engine was "On",
+// allowing consistent logging and visibility of potential disruptions without actually interrupting the transaction.
 func (tx *Transaction) Interrupt(interruption *types.Interruption) {
-	if tx.RuleEngine == types.RuleEngineOn {
+	switch tx.RuleEngine {
+	case types.RuleEngineOn:
 		tx.interruption = interruption
+	case types.RuleEngineDetectionOnly:
+		// In DetectionOnly mode, the interruption is not actually triggered, which means that
+		// further rules will continue to be evaluated and more actions can be executed.
+		// Let's keep only the first interruption here, matching the one that would have been triggered
+		// if the engine was on.
+		if tx.detectionOnlyInterruption == nil {
+			tx.detectionOnlyInterruption = interruption
+		}
+	}
+}
+
+// Allow sets the allow type for the transaction.
+// It complies with DetectionOnly definition which requires not executing disruptive actions.
+// Depending on the RuleEngine mode:
+// If On: it will cause the transaction to skip rules according to the allow type (phase, request, all).
+// If DetectionOnly: allow is not enforced.
+// TODO(4.x): evaluate to expose it in the interface.
+func (tx *Transaction) Allow(allowType corazatypes.AllowType) {
+	if tx.RuleEngine == types.RuleEngineOn {
+		tx.AllowType = allowType
 	}
 }
 
@@ -534,19 +570,19 @@ func (tx *Transaction) MatchRule(r *Rule, mds []types.MatchData) {
 		MatchedDatas_:    mds,
 		Context_:         tx.context,
 	}
-	// Populate MatchedRule disruption related fields only if the Engine is capable of performing disruptive actions
-	if tx.RuleEngine == types.RuleEngineOn {
-		var exists bool
-		for _, a := range r.actions {
-			// There can be only at most one disruptive action per rule
-			if a.Function.Type() == plugintypes.ActionTypeDisruptive {
-				mr.DisruptiveAction_, exists = corazarules.DisruptiveActionMap[a.Name]
-				if !exists {
-					mr.DisruptiveAction_ = corazarules.DisruptiveActionUnknown
-				}
-				mr.Disruptive_ = true
-				break
-			}
+
+	// Starting from Coraza 3.4, MatchedRule are including the disruptive action (DisruptiveAction_)
+	// also in DetectionOnly mode. This improves visibility of what would have happened if the engine was on.
+	// The Disruptive_ boolean still allows to identify actual disruptions from "potential" disruptions.
+	// Disruptive_ field is also used during logging to print different messages if the disruption has been real or not
+	// so it is important to set it according to the RuleEngine mode.
+	for _, a := range r.actions {
+		// There can be only one disruptive action per rule
+		if a.Function.Type() == plugintypes.ActionTypeDisruptive {
+			// if not found it will default to DisruptiveActionUnknown.
+			mr.DisruptiveAction_ = corazarules.DisruptiveActionMap[a.Name]
+			mr.Disruptive_ = tx.RuleEngine == types.RuleEngineOn
+			break
 		}
 	}
 
@@ -839,7 +875,7 @@ func (tx *Transaction) SetServerName(serverName string) {
 //
 // note: Remember to check for a possible intervention.
 func (tx *Transaction) ProcessRequestHeaders() *types.Interruption {
-	if tx.RuleEngine == types.RuleEngineOff {
+	if tx.IsRuleEngineOff() {
 		// Rule engine is disabled
 		return nil
 	}
@@ -849,7 +885,7 @@ func (tx *Transaction) ProcessRequestHeaders() *types.Interruption {
 		return tx.interruption
 	}
 
-	if tx.interruption != nil {
+	if tx.IsInterrupted() {
 		tx.debugLogger.Error().Msg("Calling ProcessRequestHeaders but there is a preexisting interruption")
 		return tx.interruption
 	}
@@ -871,7 +907,7 @@ func setAndReturnBodyLimitInterruption(tx *Transaction, status int) (*types.Inte
 // it returns an interruption if the writing bytes go beyond the request body limit.
 // It won't copy the bytes if the body access isn't accessible.
 func (tx *Transaction) WriteRequestBody(b []byte) (*types.Interruption, int, error) {
-	if tx.RuleEngine == types.RuleEngineOff {
+	if tx.IsRuleEngineOff() {
 		return nil, 0, nil
 	}
 
@@ -936,7 +972,7 @@ type ByteLenger interface {
 // it returns an interruption if the writing bytes go beyond the request body limit.
 // It won't read the reader if the body access isn't accessible.
 func (tx *Transaction) ReadRequestBodyFrom(r io.Reader) (*types.Interruption, int, error) {
-	if tx.RuleEngine == types.RuleEngineOff {
+	if tx.IsRuleEngineOff() {
 		return nil, 0, nil
 	}
 
@@ -1015,11 +1051,10 @@ func (tx *Transaction) ReadRequestBodyFrom(r io.Reader) (*types.Interruption, in
 //
 // Remember to check for a possible intervention.
 func (tx *Transaction) ProcessRequestBody() (*types.Interruption, error) {
-	if tx.RuleEngine == types.RuleEngineOff {
+	if tx.IsRuleEngineOff() {
 		return nil, nil
 	}
-
-	if tx.interruption != nil {
+	if tx.IsInterrupted() {
 		tx.debugLogger.Error().Msg("Calling ProcessRequestBody but there is a preexisting interruption")
 		return tx.interruption, nil
 	}
@@ -1103,7 +1138,7 @@ func (tx *Transaction) ProcessRequestBody() (*types.Interruption, error) {
 //
 // Note: Remember to check for a possible intervention.
 func (tx *Transaction) ProcessResponseHeaders(code int, proto string) *types.Interruption {
-	if tx.RuleEngine == types.RuleEngineOff {
+	if tx.IsRuleEngineOff() {
 		return nil
 	}
 
@@ -1113,7 +1148,7 @@ func (tx *Transaction) ProcessResponseHeaders(code int, proto string) *types.Int
 		return tx.interruption
 	}
 
-	if tx.interruption != nil {
+	if tx.IsInterrupted() {
 		tx.debugLogger.Error().Msg("Calling ProcessResponseHeaders but there is a preexisting interruption")
 		return tx.interruption
 	}
@@ -1145,7 +1180,7 @@ func (tx *Transaction) IsResponseBodyProcessable() bool {
 // it returns an interruption if the writing bytes go beyond the response body limit.
 // It won't copy the bytes if the body access isn't accessible.
 func (tx *Transaction) WriteResponseBody(b []byte) (*types.Interruption, int, error) {
-	if tx.RuleEngine == types.RuleEngineOff {
+	if tx.IsRuleEngineOff() {
 		return nil, 0, nil
 	}
 
@@ -1196,7 +1231,7 @@ func (tx *Transaction) WriteResponseBody(b []byte) (*types.Interruption, int, er
 // it returns an interruption if the writing bytes go beyond the response body limit.
 // It won't read the reader if the body access isn't accessible.
 func (tx *Transaction) ReadResponseBodyFrom(r io.Reader) (*types.Interruption, int, error) {
-	if tx.RuleEngine == types.RuleEngineOff {
+	if tx.IsRuleEngineOff() {
 		return nil, 0, nil
 	}
 
@@ -1266,11 +1301,11 @@ func (tx *Transaction) ReadResponseBodyFrom(r io.Reader) (*types.Interruption, i
 //
 // note Remember to check for a possible intervention.
 func (tx *Transaction) ProcessResponseBody() (*types.Interruption, error) {
-	if tx.RuleEngine == types.RuleEngineOff {
+	if tx.IsRuleEngineOff() {
 		return nil, nil
 	}
 
-	if tx.interruption != nil {
+	if tx.IsInterrupted() {
 		tx.debugLogger.Error().Msg("Calling ProcessResponseBody but there is a preexisting interruption")
 		return tx.interruption, nil
 	}
@@ -1338,12 +1373,11 @@ func (tx *Transaction) ProcessLogging() {
 	// If Rule engine is disabled, Log phase rules are not going to be evaluated.
 	// This avoids trying to rely on variables not set by previous rules that
 	// have not been executed
-	if tx.RuleEngine != types.RuleEngineOff {
+	if !tx.IsRuleEngineOff() {
 		tx.WAF.Rules.Eval(types.PhaseLogging, tx)
 	}
 
 	if tx.AuditEngine == types.AuditEngineOff {
-		// Audit engine disabled
 		tx.debugLogger.Debug().
 			Msg("Transaction not marked for audit logging, AuditEngine is disabled")
 		return
@@ -1361,11 +1395,14 @@ func (tx *Transaction) ProcessLogging() {
 		status := tx.variables.responseStatus.Get()
 		if tx.IsInterrupted() {
 			status = strconv.Itoa(tx.interruption.Status)
+		} else if tx.IsDetectionOnlyInterrupted() {
+			// This allows to check for relevant status even in detection only mode.
+			// Fixes https://github.com/corazawaf/coraza/issues/1333
+			status = strconv.Itoa(tx.detectionOnlyInterruption.Status)
 		}
 		if re != nil && !re.Match([]byte(status)) {
 			// Not relevant status
-			tx.debugLogger.Debug().
-				Msg("Transaction status not marked for audit logging")
+			tx.debugLogger.Debug().Msg("Transaction status not marked for audit logging")
 			return
 		}
 	}
@@ -1401,10 +1438,19 @@ func (tx *Transaction) IsInterrupted() bool {
 	return tx.interruption != nil
 }
 
+// TODO(4.x): evaluate to expose it in the interface.
+func (tx *Transaction) IsDetectionOnlyInterrupted() bool {
+	return tx.detectionOnlyInterruption != nil
+}
+
 func (tx *Transaction) Interruption() *types.Interruption {
 	return tx.interruption
 }
 
+func (tx *Transaction) DetectionOnlyInterruption() *types.Interruption {
+	return tx.detectionOnlyInterruption
+}
+
 func (tx *Transaction) MatchedRules() []types.MatchedRule {
 	return tx.matchedRules
 }

internal/corazawaf/transaction_test.go

@@ -753,6 +753,72 @@ func TestAuditLogFields(t *testing.T) {
 	}
 }
 
+func TestMatchRuleDisruptiveActionPopulated(t *testing.T) {
+	tests := []struct {
+		name                         string
+		engine                       types.RuleEngineStatus
+		wantDisruptive               bool
+		wantAction                   corazarules.DisruptiveAction
+		wantInterrupted              bool
+		wantDetectionOnlyInterrupted bool
+	}{
+		{
+			name:                         "engine on",
+			engine:                       types.RuleEngineOn,
+			wantDisruptive:               true,
+			wantAction:                   corazarules.DisruptiveActionDeny,
+			wantInterrupted:              true,
+			wantDetectionOnlyInterrupted: false,
+		},
+		{
+			name:                         "engine detection only",
+			engine:                       types.RuleEngineDetectionOnly,
+			wantDisruptive:               false,
+			wantAction:                   corazarules.DisruptiveActionDeny,
+			wantInterrupted:              false,
+			wantDetectionOnlyInterrupted: true,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			waf := NewWAF()
+			tx := waf.NewTransaction()
+			tx.RuleEngine = tt.engine
+
+			rule := NewRule()
+			rule.ID_ = 1
+			if err := rule.AddVariable(variables.ArgsGet, "", false); err != nil {
+				t.Fatal(err)
+			}
+			rule.SetOperator(&dummyEqOperator{}, "@eq", "0")
+			_ = rule.AddAction("deny", &dummyDenyAction{})
+
+			tx.AddGetRequestArgument("test", "0")
+
+			var matchedValues []types.MatchData
+			rule.doEvaluate(debuglog.Noop(), types.PhaseRequestHeaders, tx, &matchedValues, 0, tx.transformationCache)
+
+			if len(tx.matchedRules) != 1 {
+				t.Fatalf("expected 1 matched rule, got %d", len(tx.matchedRules))
+			}
+			mr := tx.matchedRules[0].(*corazarules.MatchedRule)
+			if mr.Disruptive_ != tt.wantDisruptive {
+				t.Errorf("Disruptive_: got %t, want %t", mr.Disruptive_, tt.wantDisruptive)
+			}
+			if mr.DisruptiveAction_ != tt.wantAction {
+				t.Errorf("DisruptiveAction_: got %d, want %d", mr.DisruptiveAction_, tt.wantAction)
+			}
+			if tx.IsInterrupted() != tt.wantInterrupted {
+				t.Errorf("IsInterrupted: got %t, want %t", tx.IsInterrupted(), tt.wantInterrupted)
+			}
+			if tx.IsDetectionOnlyInterrupted() != tt.wantDetectionOnlyInterrupted {
+				t.Errorf("IsDetectionOnlyInterrupted: got %t, want %t", tx.IsDetectionOnlyInterrupted(), tt.wantDetectionOnlyInterrupted)
+			}
+		})
+	}
+}
+
 func TestResetCapture(t *testing.T) {
 	tx := makeTransaction(t)
 	tx.Capture = true