Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 7 commits into from
Jul 25, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions internal/corazarules/rule_match.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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_
}
Expand Down
48 changes: 28 additions & 20 deletions internal/corazawaf/transaction.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -1403,26 +1405,32 @@ 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
// An assertion has to be done to check if the MatchedRule implements the Log() function before calling Log()
// It is performed to avoid breaking the Coraza v3.* API adding a Log() method to the MatchedRule interface
mrWithlog, ok := mr.(*corazarules.MatchedRule)
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(),
},
})
}
}
}
}
Expand Down
1 change: 1 addition & 0 deletions internal/corazawaf/transaction_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
59 changes: 51 additions & 8 deletions testing/auditlog_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -81,16 +81,16 @@ func TestAuditLogRelevantOnly(t *testing.T) {
SecAuditLogRelevantStatus 401
SecRule ARGS "@unconditionalMatch" "id:1,phase:1,log,msg:'unconditional match'"
`); err != nil {
t.Error(err)
t.Fatal(err)
}
// generate a random tmp file
file, err := os.Create(filepath.Join(t.TempDir(), "tmp.log"))
if err != nil {
t.Error(err)
t.Fatal(err)
}
defer os.Remove(file.Name())
if err := parser.FromString(fmt.Sprintf("SecAuditLog %s", file.Name())); err != nil {
t.Error(err)
t.Fatal(err)
}
tx := waf.NewTransaction()
tx.AddGetRequestArgument("test", "test")
Expand All @@ -113,11 +113,11 @@ func TestAuditLogRelevantOnlyOk(t *testing.T) {
// generate a random tmp file
file, err := os.Create(filepath.Join(t.TempDir(), "tmp.log"))
if err != nil {
t.Error(err)
t.Fatal(err)
}
defer os.Remove(file.Name())
if err := parser.FromString(fmt.Sprintf("SecAuditLog %s", file.Name())); err != nil {
t.Error(err)
t.Fatal(err)
}
if err := parser.FromString(`
SecRuleEngine DetectionOnly
Expand Down Expand Up @@ -156,16 +156,16 @@ func TestAuditLogRelevantOnlyNoAuditlog(t *testing.T) {
SecAuditLogRelevantStatus ".*"
SecRule ARGS "@unconditionalMatch" "id:1,phase:1,noauditlog,msg:'unconditional match'"
`); err != nil {
t.Error(err)
t.Fatal(err)
}
// generate a random tmp file
file, err := os.Create(filepath.Join(t.TempDir(), "tmp.log"))
if err != nil {
t.Error(err)
t.Fatal(err)
}
defer os.Remove(file.Name())
if err := parser.FromString(fmt.Sprintf("SecAuditLog %s", file.Name())); err != nil {
t.Error(err)
t.Fatal(err)
}
tx := waf.NewTransaction()
tx.AddGetRequestArgument("test", "test")
Expand All @@ -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.Fatal(err)
}
// generate a random tmp file
file, err := os.Create(filepath.Join(t.TempDir(), "tmp.log"))
if err != nil {
t.Fatal(err)
}
defer os.Remove(file.Name())
if err := parser.FromString(fmt.Sprintf("SecAuditLog %s", file.Name())); err != nil {
t.Fatal(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 {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Are there any assertions about the content of the logs?

t.Errorf("Unexpected rule logged")
}
} else {
t.Error(err)
}
}
33 changes: 17 additions & 16 deletions testing/engine/allow.go
Original file line number Diff line number Diff line change
Expand Up @@ -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'"
`,
})
4 changes: 3 additions & 1 deletion testing/engine/chains_multiphase.go
Original file line number Diff line number Diff line change
Expand Up @@ -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" \
Expand Down Expand Up @@ -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'"
Expand Down
20 changes: 10 additions & 10 deletions testing/engine/default_actions.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
`,
})
2 changes: 1 addition & 1 deletion testing/engine/directives.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down
4 changes: 2 additions & 2 deletions testing/engine/flow_actions.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down
15 changes: 8 additions & 7 deletions testing/engine/multiphase.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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"
`,
})
4 changes: 2 additions & 2 deletions testing/engine/skip.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
`,
})
Expand Down Expand Up @@ -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
`,
Expand Down
Loading