Adds Log() to MatchedRule, fixes audit log without log

internal/corazarules/rule_match.go

@@ -67,6 +67,8 @@ type MatchedRule struct {
 	TransactionID_ string
 	// Is disruptive
 	Disruptive_ bool
+	// Is meant to be logged
+	Log_ bool
 	// Server IP address
 	ServerIPAddress_ string
 	// Client IP address
@@ -97,6 +99,10 @@ func (mr *MatchedRule) Disruptive() bool {
 	return mr.Disruptive_
 }
 
+func (mr *MatchedRule) Log() bool {
+	return mr.Log_
+}
+
 func (mr *MatchedRule) ServerIPAddress() string {
 	return mr.ServerIPAddress_
 }

internal/corazawaf/transaction.go

@@ -484,6 +484,7 @@ func (tx *Transaction) MatchRule(r *Rule, mds []types.MatchData) {
 		ServerIPAddress_: tx.variables.serverAddr.Get(),
 		ClientIPAddress_: tx.variables.remoteAddr.Get(),
 		Rule_:            &r.RuleMetadata,
+		Log_:             r.Log,
 		MatchedDatas_:    mds,
 	}
 	// Populate MatchedRule Disruptive_ field only if the Engine is capable of performing disruptive actions
@@ -509,6 +510,7 @@ func (tx *Transaction) MatchRule(r *Rule, mds []types.MatchData) {
 	if tx.WAF.ErrorLogCb != nil && r.Log {
 		tx.WAF.ErrorLogCb(mr)
 	}
+
 }
 
 // GetStopWatch is used to debug phase durations
@@ -1403,26 +1405,33 @@ func (tx *Transaction) AuditLog() *auditlog.Log {
 			}
 		case types.AuditLogPartRulesMatched:
 			for _, mr := range tx.matchedRules {
-				r := mr.Rule()
-				for _, matchData := range mr.MatchedDatas() {
-					al.Messages_ = append(al.Messages_, auditlog.Message{
-						Actionset_: strings.Join(tx.WAF.ComponentNames, " "),
-						Message_:   matchData.Message(),
-						Data_: &auditlog.MessageData{
-							File_:     mr.Rule().File(),
-							Line_:     mr.Rule().Line(),
-							ID_:       r.ID(),
-							Rev_:      r.Revision(),
-							Msg_:      matchData.Message(),
-							Data_:     matchData.Data(),
-							Severity_: r.Severity(),
-							Ver_:      r.Version(),
-							Maturity_: r.Maturity(),
-							Accuracy_: r.Accuracy(),
-							Tags_:     r.Tags(),
-							Raw_:      r.Raw(),
-						},
-					})
+				// Log action is required to log a matched rule on both error log and audit log
+				// RuleLogger is added to avoid breaking the Coraza v3.* API adding a Log() method to the MatchedRule interface
+				// An assertion has to be done to check if the MatchedRule implements ruleLogger before calling Log()
+				type ruleLogger interface{ Log() bool }
+				mrWithlog, ok := mr.(ruleLogger)
+				if ok && mrWithlog.Log() {
+					r := mr.Rule()
+					for _, matchData := range mr.MatchedDatas() {
+						al.Messages_ = append(al.Messages_, auditlog.Message{
+							Actionset_: strings.Join(tx.WAF.ComponentNames, " "),
+							Message_:   matchData.Message(),
+							Data_: &auditlog.MessageData{
+								File_:     mr.Rule().File(),
+								Line_:     mr.Rule().Line(),
+								ID_:       r.ID(),
+								Rev_:      r.Revision(),
+								Msg_:      matchData.Message(),
+								Data_:     matchData.Data(),
+								Severity_: r.Severity(),
+								Ver_:      r.Version(),
+								Maturity_: r.Maturity(),
+								Accuracy_: r.Accuracy(),
+								Tags_:     r.Tags(),
+								Raw_:      r.Raw(),
+							},
+						})
+					}
 				}
 			}
 		}

internal/corazawaf/transaction_test.go

@@ -651,6 +651,7 @@ func TestAuditLogFields(t *testing.T) {
 	tx.AddResponseHeader("test", "test")
 	rule := NewRule()
 	rule.ID_ = 131
+	rule.Log = true
 	tx.MatchRule(rule, []types.MatchData{
 		&corazarules.MatchData{
 			Variable_: variables.UniqueID,

testing/auditlog_test.go

@@ -181,3 +181,46 @@ func TestAuditLogRelevantOnlyNoAuditlog(t *testing.T) {
 		t.Errorf("there should be no audit log, got %v", al2)
 	}
 }
+
+func TestAuditLogOnNoLog(t *testing.T) {
+	waf := corazawaf.NewWAF()
+	parser := seclang.NewParser(waf)
+	if err := parser.FromString(`
+		SecRuleEngine DetectionOnly
+		SecAuditEngine On
+		SecAuditLogFormat json
+		SecAuditLogType serial
+		SecAuditLogParts ABCHIJKZ
+		SecAuditLogRelevantStatus ".*"
+		# auditlog tells that the transaction will have to log matches meant to be logged (not the ones with nolog)
+		SecRule ARGS "@unconditionalMatch" "id:1,phase:1,nolog,auditlog,msg:'nolog message'"
+	`); err != nil {
+		t.Error(err)
+	}
+	// generate a random tmp file
+	file, err := os.Create(filepath.Join(t.TempDir(), "tmp.log"))
+	if err != nil {
+		t.Error(err)
+	}
+	defer os.Remove(file.Name())
+	if err := parser.FromString(fmt.Sprintf("SecAuditLog %s", file.Name())); err != nil {
+		t.Error(err)
+	}
+	tx := waf.NewTransaction()
+	tx.AddGetRequestArgument("test", "test")
+	tx.ProcessRequestHeaders()
+	// now we read file
+	if _, err := file.Seek(0, 0); err != nil {
+		t.Error(err)
+	}
+	tx.ProcessLogging()
+	var al2 auditlog.Log
+	// there should be no audit log because of nolog
+	if err := json.NewDecoder(file).Decode(&al2); err == nil {
+		if al2.Messages() != nil {
+			t.Errorf("Unexpected rule logged")
+		}
+	} else {
+		t.Error(err)
+	}
+}

testing/engine/allow.go

@@ -155,41 +155,42 @@ var _ = profile.RegisterProfile(profile.Profile{
 	Rules: `
 SecDebugLogLevel 5
 SecRequestBodyAccess On
+SecDefaultAction "phase:1,log,pass"
 
-SecRule REQUEST_URI "/allow_me" "id:1,phase:1,allow,msg:'ALLOWED'"
-SecRule REQUEST_URI "/allow_me" "id:2,phase:1,deny,msg:'DENIED'"
+SecRule REQUEST_URI "/allow_me" "id:1,phase:1,allow,log,msg:'ALLOWED'"
+SecRule REQUEST_URI "/allow_me" "id:2,phase:1,deny,log,msg:'DENIED'"
 
 # Rule 11 allows phase 1, so rule 12 and 13, being both phase 1, are not triggered. Rule 22 is then triggered in phase 2.
 SecRule REQUEST_URI "/partial_allow" "id:11,phase:1,allow:phase,msg:'Allowed in this phase only'"
 SecRule REQUEST_URI "/partial_allow" "id:12,phase:1,deny,msg:'NOT DENIED'"
 SecRule REQUEST_URI "/partial_allow" "id:13,phase:1,deny,msg:'NOT DENIED'"
-SecRule REQUEST_URI "/partial_allow" "id:22,phase:2,deny,status:500,msg:'DENIED'"
+SecRule REQUEST_URI "/partial_allow" "id:22,phase:2,deny,log,status:500,msg:'DENIED'"
 
 # Rule 31 allows all the request phases (1 and 2), therefore rules 32, 33 and 34 should not be triggered. Rule 42 is
 # expected to be triggered at phase 3.
-SecRule REQUEST_URI "/request_allow" "id:31,phase:1,allow:request,msg:'Allowed at the request'"
-SecRule REQUEST_URI "/request_allow" "id:32,phase:1,deny,msg:'NOT DENIED'"
-SecRule REQUEST_URI "/request_allow" "id:33,phase:2,deny,msg:'NOT DENIED'"
-SecRule REQUEST_URI "/request_allow" "id:34,phase:2,deny,msg:'NOT DENIED'"
-SecRule REQUEST_URI "/request_allow" "id:42,phase:3,deny,status:500,msg:'DENIED'"
+SecRule REQUEST_URI "/request_allow" "id:31,phase:1,allow:request,log,msg:'Allowed at the request'"
+SecRule REQUEST_URI "/request_allow" "id:32,phase:1,deny,log,msg:'NOT DENIED'"
+SecRule REQUEST_URI "/request_allow" "id:33,phase:2,deny,log,msg:'NOT DENIED'"
+SecRule REQUEST_URI "/request_allow" "id:34,phase:2,deny,log,msg:'NOT DENIED'"
+SecRule REQUEST_URI "/request_allow" "id:42,phase:3,deny,log,status:500,msg:'DENIED'"
 
 # Rule 45 allows only request phases (1 and 2), it should not impact on phase 3.
 # Therefore, rule 46 is expected to be triggered.
-SecRule REQUEST_URI "/useless_request_allow" "id:45,phase:1,allow:request,msg:'Allowed at the request'"
-SecRule REQUEST_URI "/useless_request_allow" "id:46,phase:3,deny,status:500,msg:'DENIED'"
+SecRule REQUEST_URI "/useless_request_allow" "id:45,phase:1,allow:request,log,msg:'Allowed at the request'"
+SecRule REQUEST_URI "/useless_request_allow" "id:46,phase:3,deny,log,status:500,msg:'DENIED'"
 
 # Rule 50 allows only the current phase (phase 1), it should not impact any other rule (being part of other phases).
 # Rule 61 is meant to allow only from phase 3 (so phase 3 and 4), rule 51, at phase 2 should deny the request
 # before reaching phase 3. Therefore rule 61 and 62 should not be triggered.
 # Suitable for testing that allow:phase is not propagated to other phases
-SecRule REQUEST_URI "/allow_only_response" "id:50,phase:1,allow:phase,msg:'Allowed phase 1'"
-SecRule REQUEST_BODY "allow_only_response" "id:51,phase:2,deny,status:500,msg:'Denied request'"
-SecRule REQUEST_URI "/allow_only_response" "id:61,phase:3,allow,msg:'Allowed Response not triggered'"
-SecRule REQUEST_URI "/allow_only_response" "id:62,phase:4,deny,msg:'Deny response not triggered'"
+SecRule REQUEST_URI "/allow_only_response" "id:50,phase:1,allow:phase,log, msg:'Allowed phase 1'"
+SecRule REQUEST_BODY "allow_only_response" "id:51,phase:2,deny,log,status:500,msg:'Denied request'"
+SecRule REQUEST_URI "/allow_only_response" "id:61,phase:3,allow,log,msg:'Allowed Response not triggered'"
+SecRule REQUEST_URI "/allow_only_response" "id:62,phase:4,deny,log,msg:'Deny response not triggered'"
 
 # Rule 70 should deny the request at phase:2 before rule 71.
 # Suitable for testing multiphase evaluation combined with allow actions.
-SecRule REQUEST_BODY "response_allow" "id:70,phase:2,deny,status:500,msg:'Denied request'"
-SecRule REQUEST_URI "/response_allow" "id:71,phase:3,allow,msg:'Allowed Response not triggered'"
+SecRule REQUEST_BODY "response_allow" "id:70,phase:2,deny,log,status:500,msg:'Denied request'"
+SecRule REQUEST_URI "/response_allow" "id:71,phase:3,allow,log,msg:'Allowed Response not triggered'"
 `,
 })

testing/engine/chains_multiphase.go

@@ -280,12 +280,13 @@ var _ = profile.RegisterProfile(profile.Profile{
 SecDebugLogLevel 9
 SecRequestBodyAccess On
 
-SecAction "id:1, phase:1, pass, setvar:'tx.CRS_VALIDATE_UTF8_ENCODING=1'"
+SecAction "id:1, phase:1, pass, log, setvar:'tx.CRS_VALIDATE_UTF8_ENCODING=1'"
 SecRule TX:CRS_VALIDATE_UTF8_ENCODING "@eq 1" \
     "id:920250,\
     phase:2,\
     deny,\
 	status:403,\
+	log,\
     t:none,\
     chain"
     SecRule REQUEST_FILENAME|ARGS|ARGS_NAMES "@validateUtf8Encoding" \
@@ -355,6 +356,7 @@ SecRequestBodyAccess On
 SecRule ARGS "@rx (?i)(?:(?:url|jar):)?(?:a(?:cap|f[ps]|ttachment)|b(?:eshare|itcoin|lob)|c(?:a(?:llto|p)|id|vs|ompress.(?:zlib|bzip2))|d(?:a(?:v|ta)|ict|n(?:s|tp))|e(?:d2k|xpect)|f(?:(?:ee)?d|i(?:le|nger|sh)|tps?)|g(?:it|o(?:pher)?|lob)|h(?:323|ttps?)|i(?:ax|cap|(?:ma|p)ps?|rc[6s]?)|ja(?:bbe)?r|l(?:dap[is]?|ocal_file)|m(?:a(?:ilto|ven)|ms|umble)|n(?:e(?:tdoc|ws)|fs|ntps?)|ogg|p(?:aparazzi|h(?:ar|p)|op(?:2|3s?)|r(?:es|oxy)|syc)|r(?:mi|sync|tm(?:f?p)?|ar)|s(?:3|ftp|ips?|m(?:[bs]|tps?)|n(?:ews|mp)|sh(?:2(?:.(?:s(?:hell|(?:ft|c)p)|exec|tunnel))?)?|vn(?:\+ssh)?)|t(?:e(?:amspeak|lnet)|ftp|urns?)|u(?:dp|nreal|t2004)|v(?:entrilo|iew-source|nc)|w(?:ebcal|ss?)|x(?:mpp|ri)|zip)://(?:[^@]+@)?([^/]*)" \
     "id:931130, phase:2, deny, status:403, t:none,\
     setvar:'tx.rfi_parameter_%{MATCHED_VAR_NAME}=.%{tx.1}',\
+	log,\
     chain"
     SecRule TX:/rfi_parameter_.*/ "!@endsWith .%{request_headers.host}" \
         "setvar:'tx.inbound_anomaly_score_pl2=+1'"

testing/engine/default_actions.go

@@ -43,15 +43,15 @@ var _ = profile.RegisterProfile(profile.Profile{
 		},
 	},
 	Rules: `
-SecAction "id:1, phase:1, pass"
-SecAction "id:2, phase:2, pass"
-SecAction "id:3, phase:3, pass"
-SecAction "id:4, phase:4, pass"
-SecAction "id:5, phase:5, pass"
-SecAction "id:6, phase:1, pass"
-SecAction "id:7, phase:2, pass"
-SecAction "id:8, phase:3, pass"
-SecAction "id:9, phase:4, pass"
-SecAction "id:10, phase:5, pass"
+SecAction "id:1, phase:1, log, pass"
+SecAction "id:2, phase:2, log, pass"
+SecAction "id:3, phase:3, log, pass"
+SecAction "id:4, phase:4, log, pass"
+SecAction "id:5, phase:5, log, pass"
+SecAction "id:6, phase:1, log, pass"
+SecAction "id:7, phase:2, log, pass"
+SecAction "id:8, phase:3, log, pass"
+SecAction "id:9, phase:4, log, pass"
+SecAction "id:10, phase:5, log, pass"
 `,
 })

testing/engine/directives.go

@@ -44,7 +44,7 @@ var _ = profile.RegisterProfile(profile.Profile{
 	},
 	Rules: `
 SecAction "id: 1, log"
-SecAction "id: 2, nolog, skipAfter:test-mark"
+SecAction "id: 2, log, skipAfter:test-mark"
 
 SecAction "id: 4, log"
 SecAction "id: 5,log"

testing/engine/flow_actions.go

@@ -34,11 +34,11 @@ var _ = profile.RegisterProfile(profile.Profile{
 	},
 	Rules: `
 	SecRuleEngine DetectionOnly
-	SecRule REQUEST_URI "@unconditionalMatch" "id:1,phase:1,pass,nolog,skipAfter:END-REPORTING"
+	SecRule REQUEST_URI "@unconditionalMatch" "id:1,phase:1,pass,log,skipAfter:END-REPORTING"
 	SecAction "id:2,phase:1,deny,status:403,log,msg:'Should not be triggered, being skipped by skipAfter of rule 1'"
 	SecMarker "END-REPORTING"
 
-	SecRule REQUEST_URI "@unconditionalMatch" "id:3,phase:2,pass,nolog,skipAfter:END,chain"
+	SecRule REQUEST_URI "@unconditionalMatch" "id:3,phase:2,pass,log,skipAfter:END,chain"
 	SecRule REQUEST_URI "@rx /UrlThatWillNotMatch" "id:3,phase:2,pass,log"
 	SecAction "id:4,phase:2,deny,status:403,log,msg:'Should match because rule 3 should not be triggered, not being the whole chain matched'"
 	SecMarker "END"

testing/engine/multiphase.go

@@ -130,10 +130,11 @@ var _ = profile.RegisterProfile(profile.Profile{
 SecDebugLogLevel 9
 SecRequestBodyAccess On
 
-SecAction "id:900001, phase:1, nolog, pass, t:none, setvar:tx.detection_paranoia_level=1"
+# log is added to these rules for tests purposes, to check wether they are triggered or not
+SecAction "id:900001, phase:1, log, pass, t:none, setvar:tx.detection_paranoia_level=1"
 
-SecRule TX:DETECTION_PARANOIA_LEVEL "@lt 2" "id:911011,phase:1,pass,nolog,skipAfter:END-REQUEST"
-SecRule TX:DETECTION_PARANOIA_LEVEL "@lt 2" "id:911012,phase:2,pass,nolog,skipAfter:END-REQUEST"
+SecRule TX:DETECTION_PARANOIA_LEVEL "@lt 2" "id:911011,phase:1,pass,log,skipAfter:END-REQUEST"
+SecRule TX:DETECTION_PARANOIA_LEVEL "@lt 2" "id:911012,phase:2,pass,log,skipAfter:END-REQUEST"
 
 SecRule REQUEST_LINE|ARGS|ARGS_NAMES|REQUEST_COOKIES|REQUEST_COOKIES_NAMES|REQUEST_HEADERS|XML:/*|XML://@* "@rx (?i)(?:\$|$?)(?:\{|&l(?:brace|cub);?)(?:[^\}]{0,15}(?:\$|$?)(?:\{|&l(?:brace|cub);?)|jndi|ctx)" \
     "id:944150, phase:2, deny, status:503"
@@ -179,9 +180,9 @@ var _ = profile.RegisterProfile(profile.Profile{
 SecDebugLogLevel 9
 SecRequestBodyAccess On
 
-SecRule REQUEST_URI "@rx /" "id:1, phase:1, pass, t:none, ctl:ruleRemoveTargetById=2-3;REQUEST_URI"
-SecRule REQUEST_URI "@rx test" "id:2, phase:1, deny, status:503"
-SecRule REQUEST_URI|REQUEST_BODY "@rx test" "id:3, phase:2, deny, status:504"
-SecRule REQUEST_URI "@unconditionalMatch" "id:4, phase:1, pass"
+SecRule REQUEST_URI "@rx /" "id:1, phase:1, pass, log, t:none, ctl:ruleRemoveTargetById=2-3;REQUEST_URI"
+SecRule REQUEST_URI "@rx test" "id:2, phase:1, deny, log, status:503"
+SecRule REQUEST_URI|REQUEST_BODY "@rx test" "id:3, phase:2, deny, log, status:504"
+SecRule REQUEST_URI "@unconditionalMatch" "id:4, phase:1, pass, log"
 `,
 })

testing/engine/skip.go

@@ -126,7 +126,7 @@ SecRequestBodyAccess On
 
 # Skip action works only within the current phase, rule 30 should skip rule 32, not rule 31
 SecRule REQUEST_URI "/phase_multi_skip" "id:30, phase:2, skip:1,log"
-SecRule REQUEST_URI "/phase_multi_skip" "id:31, phase:1,pass"
+SecRule REQUEST_URI "/phase_multi_skip" "id:31, phase:1,pass, log"
 SecRule REQUEST_BODY "phase_multi_skip" "id:32, phase:2, t:none, log, deny, status:500"
 `,
 })
@@ -207,7 +207,7 @@ SecDebugLogLevel 5
 
 # skipAfter action works only within the current phase, rule 50 should skip rule 52, not rule 51
 SecRule REQUEST_URI "/multi_skipafter_phase" "id:50, phase:2, skipAfter:LOCATION_TWO,log"
-SecRule REQUEST_URI "/multi_skipafter_phase" "id:51, phase:1,pass"
+SecRule REQUEST_URI "/multi_skipafter_phase" "id:51, phase:1,pass, log"
 SecRule REQUEST_BODY "multi_skipafter_phase" "id:52, phase:2, t:none, log, deny, status:500"
 SecMarker LOCATION_TWO
 `,

types/rule_match.go

@@ -35,6 +35,11 @@ type MatchedRule interface {
 	TransactionID() string
 	// Disruptive is whether this rule will block the request
 	Disruptive() bool
+	// // Log is whether this rule is marked as expected to be logged
+	// Log() is commented out to avoid breaking changes in Coraza v3.*
+	// As a workaround, an assertion (E.g. mr.(types.ruleLogger)) can be performed before calling Log()
+	// with ruleLogger defined as: type ruleLogger interface{ Log() bool }
+	// Log() bool
 	// ServerIPAddress is the address of the server
 	ServerIPAddress() string
 	// ClientIPAddress is the address of the client