fix: Logs print different messages for each the disruptive actions (#827

)

* logs print correct messages for all the disruptive actions

* Update internal/corazarules/rule_match.go

Co-authored-by: José Carlos Chávez <jcchavezs@gmail.com>

* nit: lowecase error message

* address review, removes extra new line

* adds test for custom disruptive action

* fix double new line delegating it to callers of ErrorLog()

* DisruptiveAction enum

---------

Co-authored-by: José Carlos Chávez <jcchavezs@gmail.com>

examples/http-server/main.go

@@ -58,5 +58,5 @@ func createWAF() coraza.WAF {
 
 func logError(error types.MatchedRule) {
 	msg := error.ErrorLog()
-	fmt.Printf("[logError][%s] %s", error.Rule().Severity(), msg)
+	fmt.Printf("[logError][%s] %s\n", error.Rule().Severity(), msg)
 }

internal/corazarules/rule_match.go

@@ -54,6 +54,26 @@ func (m *MatchData) ChainLevel() int {
 	return m.ChainLevel_
 }
 
+// ActionName is used to identify an action.
+type DisruptiveAction int
+
+const (
+	DisruptiveActionUnknown DisruptiveAction = iota
+	DisruptiveActionAllow
+	DisruptiveActionDeny
+	DisruptiveActionDrop
+	DisruptiveActionPass
+	DisruptiveActionRedirect
+)
+
+var DisruptiveActionMap = map[string]DisruptiveAction{
+	"allow":    DisruptiveActionAllow,
+	"deny":     DisruptiveActionDeny,
+	"drop":     DisruptiveActionDrop,
+	"pass":     DisruptiveActionPass,
+	"redirect": DisruptiveActionRedirect,
+}
+
 // MatchedRule contains a list of macro expanded messages,
 // matched variables and a pointer to the rule
 type MatchedRule struct {
@@ -67,6 +87,9 @@ type MatchedRule struct {
 	TransactionID_ string
 	// Is disruptive
 	Disruptive_ bool
+	// Name of the disruptive action
+	// Note: not exposed in coraza v3.0.*
+	DisruptiveAction_ DisruptiveAction
 	// Is meant to be logged
 	Log_ bool
 	// Server IP address
@@ -181,13 +204,12 @@ func (mr MatchedRule) AuditLog() string {
 	for _, matchData := range mr.MatchedDatas_ {
 		fmt.Fprintf(log, "[client %q] ", mr.ClientIPAddress_)
 		if mr.Disruptive_ {
-			fmt.Fprintf(log, "Coraza: Access denied (phase %d). ", mr.Rule_.Phase())
+			writeDisruptiveActionSpecificLog(log, mr)
 		} else {
 			log.WriteString("Coraza: Warning. ")
 		}
 		mr.matchData(log, matchData)
 		mr.writeDetails(log, matchData)
-		log.WriteString("\n")
 	}
 	return log.String()
 }
@@ -211,7 +233,7 @@ func (mr MatchedRule) ErrorLog() string {
 
 	fmt.Fprintf(log, "[client %q] ", mr.ClientIPAddress_)
 	if mr.Disruptive_ {
-		fmt.Fprintf(log, "Coraza: Access denied (phase %d). ", mr.Rule_.Phase())
+		writeDisruptiveActionSpecificLog(log, mr)
 	} else {
 		log.WriteString("Coraza: Warning. ")
 	}
@@ -229,6 +251,22 @@ func (mr MatchedRule) ErrorLog() string {
 		}
 	}
 
-	log.WriteString("\n")
 	return log.String()
 }
+
+func writeDisruptiveActionSpecificLog(log *strings.Builder, mr MatchedRule) {
+	switch mr.DisruptiveAction_ {
+	case DisruptiveActionAllow:
+		fmt.Fprintf(log, "Coraza: Access allowed (phase %d). ", mr.Rule_.Phase())
+	case DisruptiveActionDeny:
+		fmt.Fprintf(log, "Coraza: Access denied (phase %d). ", mr.Rule_.Phase())
+	case DisruptiveActionDrop:
+		fmt.Fprintf(log, "Coraza: Access dropped (phase %d). ", mr.Rule_.Phase())
+	case DisruptiveActionPass:
+		log.WriteString("Coraza: Warning. ")
+	case DisruptiveActionRedirect:
+		fmt.Fprintf(log, "Coraza: Access redirected (phase %d). ", mr.Rule_.Phase())
+	default:
+		fmt.Fprintf(log, "Coraza: Custom disruptive action triggered (phase %d). ", mr.Rule_.Phase())
+	}
+}

internal/corazarules/rule_match_test.go

@@ -30,27 +30,84 @@ func TestErrorLogMessagesSizesNoExtraRuleDetails(t *testing.T) {
 	matchedRule.MatchedDatas_[0].(*MatchData).Message_ = strings.Repeat("a", 300)
 	logWithMsg := matchedRule.ErrorLog()
 	logSizeWithMsg := len(logWithMsg)
-	// The parent message is repeated twice when loggin error log
+	// The parent message is repeated twice when logging error log
 	if lenDiff := logSizeWithMsg - LogSizeWithoutMsg; lenDiff != maxSizeLogMessage*2 {
 		t.Errorf("Expected message repeated twice with total len equal to %d, got %d", maxSizeLogMessage*2, lenDiff)
 	}
 	matchedRule.MatchedDatas_[0].(*MatchData).Data_ = strings.Repeat("b", 300)
 	logWithMsgData := matchedRule.ErrorLog()
 	logSizeWithMsgData := len(logWithMsgData)
-	// The parent message is repeated twice when loggin error log
 	if lenDiff := logSizeWithMsgData - logSizeWithMsg; lenDiff != maxSizeLogMessage {
 		t.Errorf("Expected data message with len equal to %d, got %d", maxSizeLogMessage, lenDiff)
 	}
-
-	noDisruptiveLine := "Coraza: Warning."
-	if !strings.Contains(logWithMsg, noDisruptiveLine) {
-		t.Errorf("Expected string \"%s\" if not disruptive rule, got %s", noDisruptiveLine, logWithMsg)
+}
+func TestErrorLogMessages(t *testing.T) {
+	matchedRule := &MatchedRule{
+		Rule_: &RuleMetadata{
+			ID_: 1234,
+		},
+		MatchedDatas_: []types.MatchData{
+			&MatchData{
+				Variable_: variables.RequestURI,
+				Key_:      "REQUEST_URI",
+				Value_:    "/",
+				Message_:  "",
+				Data_:     "",
+			},
+		},
+	}
+	testCases := map[string]struct {
+		disruptive       bool
+		disruptiveAction DisruptiveAction
+		expectedLogLine  string
+	}{
+		"no disruptive action": {
+			disruptive:      false,
+			expectedLogLine: "Coraza: Warning.",
+		},
+		"Deny disruptive action": {
+			disruptive:       true,
+			disruptiveAction: DisruptiveActionDeny,
+			expectedLogLine:  "Coraza: Access denied",
+		},
+		"Allow disruptive action": {
+			disruptive:       true,
+			disruptiveAction: DisruptiveActionAllow,
+			expectedLogLine:  "Coraza: Access allowed",
+		},
+		"Drop disruptive action": {
+			disruptive:       true,
+			disruptiveAction: DisruptiveActionDrop,
+			expectedLogLine:  "Coraza: Access dropped",
+		},
+		"Pass disruptive action": {
+			disruptive:       true,
+			disruptiveAction: DisruptiveActionPass,
+			expectedLogLine:  "Coraza: Warning.",
+		},
+		"Redirect disruptive action": {
+			disruptive:       true,
+			disruptiveAction: DisruptiveActionRedirect,
+			expectedLogLine:  "Coraza: Access redirected",
+		},
+		"Custom disruptive action": {
+			disruptive:       true,
+			disruptiveAction: DisruptiveActionUnknown,
+			expectedLogLine:  "Coraza: Custom disruptive action",
+		},
 	}
-	matchedRule.Disruptive_ = true
-	logWithDisruptive := matchedRule.ErrorLog()
-	disruptiveLine := "Coraza: Access denied"
-	if !strings.Contains(logWithDisruptive, disruptiveLine) {
-		t.Errorf("Expected string \"%s\" if disruptive rule, got %s", disruptiveLine, logWithMsg)
+
+	for name, tCase := range testCases {
+		t.Run(name, func(t *testing.T) {
+			matchedRule.Disruptive_ = tCase.disruptive
+			if tCase.disruptive {
+				matchedRule.DisruptiveAction_ = tCase.disruptiveAction
+			}
+			logLine := matchedRule.ErrorLog()
+			if !strings.Contains(logLine, tCase.expectedLogLine) {
+				t.Errorf("Expected string \"%s\", got %s", tCase.expectedLogLine, logLine)
+			}
+		})
 	}
 }
 

internal/corazawaf/body_buffer.go

@@ -72,7 +72,7 @@ func (br *BodyBuffer) Write(data []byte) (n int, err error) {
 	if targetLen > br.options.MemoryLimit {
 		if !environment.HasAccessToFS {
 			// TinyGo MemoryLimit should be equal to Limit. Therefore, Write function has been called without Limit check.
-			return 0, errors.New("MemoryLimit reached while writing")
+			return 0, errors.New("memoryLimit reached while writing")
 		} else {
 			if br.writer == nil {
 				br.writer, err = os.CreateTemp(br.options.TmpPath, "body*")

internal/corazawaf/transaction.go

@@ -487,10 +487,16 @@ func (tx *Transaction) MatchRule(r *Rule, mds []types.MatchData) {
 		Log_:             r.Log,
 		MatchedDatas_:    mds,
 	}
-	// Populate MatchedRule Disruptive_ field only if the Engine is capable of performing disruptive actions
+	// 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
 			}

internal/corazawaf/transaction_test.go

@@ -750,7 +750,7 @@ func TestLogCallback(t *testing.T) {
 			rule.ID_ = 1
 			rule.Phase_ = 1
 			rule.Log = true
-			_ = rule.AddAction("action", testCase.action)
+			_ = rule.AddAction("deny", testCase.action)
 			tx.MatchRule(rule, []types.MatchData{
 				&corazarules.MatchData{
 					Variable_: variables.UniqueID,

testing/coreruleset/coreruleset_test.go

@@ -206,7 +206,7 @@ SecRule REQUEST_HEADERS:X-CRS-Test "@rx ^.*$" \
 	}
 	errorWriter := bufio.NewWriter(errorFile)
 	conf = conf.WithErrorCallback(func(rule types.MatchedRule) {
-		msg := rule.ErrorLog()
+		msg := rule.ErrorLog() + "\n"
 		if _, err := io.WriteString(errorWriter, msg); err != nil {
 			t.Fatal(err)
 		}

types/rule_match.go

@@ -33,7 +33,7 @@ type MatchedRule interface {
 	URI() string
 	// TransactionID is the transaction ID
 	TransactionID() string
-	// Disruptive is whether this rule will block the request
+	// Disruptive is whether this rule will perform disruptive actions (note also pass, allow, redirect are considered disruptive actions)
 	Disruptive() bool
 	// ServerIPAddress is the address of the server
 	ServerIPAddress() string