Add error log support (#93)

* add some rule parsing tests

* feat: Add support for log callback  errors

* fix: crs workflow

* feat: add error line to parser

* add error log tests

.github/FUNDING.yml

@@ -1,2 +0,0 @@
-custom: ["https://www.paypal.com/donate?hosted_button_id=8LZP3JAR3U9BW"]
-#patreon: jptosso

.github/workflows/coreruleset.yml

@@ -0,0 +1,47 @@
+name: Core Ruleset Tests
+
+on:
+  push:
+    branches: 
+      - '*'
+  pull_request:
+    branches: [ master ]
+
+jobs:
+  test:
+    strategy:
+      matrix:
+        go-version: [1.16.x]
+        os: [ubuntu-latest]
+    runs-on: ${{ matrix.os }}
+    steps:
+    - name: Install Go
+      uses: actions/setup-go@v2
+      with:
+        go-version: ${{ matrix.go-version }}
+    - name: Checkout code
+      uses: actions/checkout@v2
+      with:
+        lfs: true
+        fetch-depth: 0 #for better blame info
+    - name: Setup libinjection
+      run: |
+        sudo make deps
+        sudo ldconfig
+    - name: Checkout code
+      uses: actions/checkout@v2
+      with:
+        lfs: true
+        fetch-depth: 0 #for better blame info
+        repository: jptosso/coraza-testsuite
+        path: ftw
+    - name: Update ftw deps
+      run: cd ftw && go get -u github.com/jptosso/coraza-waf@$GITHUB_SHA
+    - name: Download CRS
+      run: cd / && go install github.com/jptosso/crsmon/cmd/crsmon@latest
+    - name: Build CRS
+      run: crsmon -path ./crs -v paranoia_level=4 -v crs_validate_utf8_encoding=1 -v arg_name_length=100 -v arg_length=400
+    - name: clone crs tests
+      run: git clone https://github.com/coreruleset/coreruleset
+    - name: Run tests
+      run: cd ftw && go run *.go run -d ../coreruleset/tests/regression -r ../crs/crs.conf || true

loggers/formats.go

@@ -74,7 +74,7 @@ func ftwFormatter(al *AuditLog) (string, error) {
 	err := fmt.Sprintf("Access denied with code %d (phase %d)", status, phase)
 	for _, r := range al.Messages {
 		rules += fmt.Sprintf("[id \"%d\"] ", r.Data.Id)
-		msgs += fmt.Sprintf("[msg \"%s\"]", r.Data.Msg)
+		msgs += fmt.Sprintf("[msg \"%s\"] ", r.Data.Msg)
 	}
 	data := fmt.Sprintf("[%s] [error] [client %s] Coraza: %s. %s %s %s [severity \"%s\"] [uri \"%s\"] [unique_id \"%s\"]",
 		timestamp, address, err, logdata, rules, msgs, severity, uri, id)
@@ -152,4 +152,6 @@ func getFormatter(f string) (formatter, error) {
 var (
 	_ formatter = cefFormatter
 	_ formatter = ftwFormatter
+	_ formatter = modsecFormatter
+	_ formatter = jsonFormatter
 )

seclang/parser.go

@@ -81,6 +81,7 @@ func (p *Parser) FromString(data string) error {
 	var linebuffer = ""
 	pattern := regexp.MustCompile(`\\(\s+)?$`)
 	for scanner.Scan() {
+		p.currentLine++
 		line := scanner.Text()
 		linebuffer += strings.TrimSpace(line)
 		//Check if line ends with \

seclang/rule_parser_test.go

@@ -15,6 +15,7 @@
 package seclang
 
 import (
+	"strings"
 	"testing"
 
 	"github.com/jptosso/coraza-waf"
@@ -108,3 +109,15 @@ func TestVariableCases(t *testing.T) {
 		t.Errorf("failed to parse some variables, %d variables", len(rule.Variables))
 	}
 }
+
+func TestErrorLine(t *testing.T) {
+	waf := coraza.NewWaf()
+	p, _ := NewParser(waf)
+	err := p.FromString("SecAction \"id:1\"\n#test\nSomefaulty")
+	if err == nil {
+		t.Error("that shouldn't happen o.o")
+	}
+	if !strings.Contains(err.Error(), "Line 3") {
+		t.Error("failed to find error line, got " + err.Error())
+	}
+}

seclang/rules_test.go

@@ -1,9 +1,12 @@
 package seclang
 
 import (
+	"os"
+	"strings"
 	"testing"
 
 	"github.com/jptosso/coraza-waf"
+	"github.com/jptosso/coraza-waf/utils"
 )
 
 func TestRuleMatch(t *testing.T) {
@@ -129,3 +132,43 @@ func TestSecMarkers(t *testing.T) {
 		t.Errorf("not matching any rule after secmark")
 	}
 }
+
+func TestSecAuditLogs(t *testing.T) {
+	waf := coraza.NewWaf()
+	parser, _ := NewParser(waf)
+	f1 := utils.RandomString(15)
+	err := parser.FromString(`
+		SecAuditEngine On
+		SecAction "id:4482,log,auditlog, msg:'test'"
+		SecAuditLogParts ABCDEFGHIJK
+		SecRuleEngine On
+	`)
+	if err != nil {
+		t.Error(err)
+	}
+	err = parser.FromString("SecAuditLog serial file=/tmp/" + f1 + ".log format=ftw")
+	if err != nil {
+		t.Error(err)
+	}
+	tx := waf.NewTransaction()
+	tx.ProcessUri("/test.php?id=1", "get", "http/1.1")
+	tx.ProcessRequestHeaders()
+	tx.ProcessRequestBody()
+	tx.ProcessLogging()
+
+	if len(tx.MatchedRules) == 0 {
+		t.Error("failed to match rules")
+	}
+
+	if tx.AuditLog().Messages[0].Data.Id != 4482 {
+		t.Error("failed to match rule id")
+	}
+
+	data, err := os.ReadFile("/tmp/" + f1 + ".log")
+	if err != nil {
+		t.Error(err)
+	}
+	if !strings.Contains(string(data), "id \"4482\"") {
+		t.Errorf("missing rule id from audit log, got:\n%s", data)
+	}
+}

testdata/engine/variables.yaml

@@ -21,9 +21,11 @@
             - 1
             - 1234
             - 2
+            - 15
           non_triggered_rules:            
   rules: |
     SecRequestBodyAccess On
     SecRule ARGS:/^t1$/ "aaa" "id:1,phase:1,block,log"
     SecRule &ARGS_GET:/t.*/ "@gt 2" "id: 1234, phase:1, block, log, ctl:requestBodyProcessor=XML"
     SecRule XML:/*|XML://@* "test123" "id:2, phase:2,log"
+    SecRule REQUEST_METHOD "POST" "id:15, log"

transaction.go

@@ -376,6 +376,50 @@ func (tx *Transaction) MatchVars(match []MatchData) {
 
 // MatchRule Matches a rule to be logged
 func (tx *Transaction) MatchRule(rule Rule, msgs []string, match []MatchData) {
+	if rule.Log && tx.Waf.ErrorLogger != nil {
+		str := strings.Builder{}
+		str.WriteString("Warning. ")
+		variable := match[0].Collection
+		if match[0].Key != "" {
+			variable += fmt.Sprintf(":%s", match[0].Key)
+		}
+		if rule.Operator != nil {
+			str.WriteString(fmt.Sprintf("Match of \"- %s\" against %q required. ", rule.Operator.Data, variable))
+		} else {
+			//TODO check msg
+			str.WriteString("Unconditional match. ")
+		}
+		str.WriteString(fmt.Sprintf("[file %q] ", rule.File))
+		str.WriteString(fmt.Sprintf("[line \"%d\"] ", rule.Line))
+		str.WriteString(fmt.Sprintf("[id \"%d\"] ", rule.Id))
+		str.WriteString(fmt.Sprintf("[msg %q] ", msgs[0]))
+		str.WriteString(fmt.Sprintf("[data %q]", tx.MacroExpansion(rule.LogData)))
+		if rule.Severity != -1 {
+			severity := "someseverity"
+			str.WriteString(fmt.Sprintf(" [severity %q]", severity))
+		}
+		switch EventSeverity(rule.Severity) {
+		case EventEmergency:
+			tx.Waf.ErrorLogger.Emergency(str.String())
+		case EventAlert:
+			tx.Waf.ErrorLogger.Alert(str.String())
+		case EventCritical:
+			tx.Waf.ErrorLogger.Critical(str.String())
+		case EventError:
+			tx.Waf.ErrorLogger.Error(str.String())
+		case EventWarning:
+			tx.Waf.ErrorLogger.Warning(str.String())
+		case EventNotice:
+			tx.Waf.ErrorLogger.Notice(str.String())
+		case EventInfo:
+			tx.Waf.ErrorLogger.Info(str.String())
+		case EventDebug:
+			tx.Waf.ErrorLogger.Debug(str.String())
+		default:
+			//TODO
+		}
+	}
+	tx.Waf.Logger.Debug("rule matched", zap.String("txid", tx.Id), zap.Int("rule", rule.Id), zap.Int("count", len(match)))
 	mr := MatchedRule{
 		Messages:    msgs,
 		MatchedData: match,

transaction_test.go

@@ -232,6 +232,53 @@ func TestAuditLogFields(t *testing.T) {
 	}
 }
 
+type testel struct {
+	Output string
+}
+
+func (te *testel) Emergency(msg string) {
+	te.Output = msg
+}
+func (te *testel) Alert(msg string) {
+	te.Output = msg
+}
+func (te *testel) Critical(msg string) {
+	te.Output = msg
+}
+func (te *testel) Error(msg string) {
+	te.Output = msg
+}
+func (te *testel) Warning(msg string) {
+	te.Output = msg
+}
+func (te *testel) Notice(msg string) {
+	te.Output = msg
+}
+func (te *testel) Info(msg string) {
+	te.Output = msg
+}
+func (te *testel) Debug(msg string) {
+	te.Output = msg
+}
+
+var _ EventLogger = &testel{}
+
+func TestErrorLog(t *testing.T) {
+	tx := makeTransaction()
+	el := &testel{}
+	tx.Waf.ErrorLogger = el
+	rule := NewRule()
+	rule.Id = 15
+	rule.Msg = "test"
+	rule.Log = true
+	tx.MatchRule(*rule, []string{"messages"}, []MatchData{{
+		Collection: "test",
+	}})
+	if !strings.Contains(el.Output, `[id "15"]`) {
+		t.Error("failed to create error log with severity")
+	}
+}
+
 func BenchmarkTransactionCreation(b *testing.B) {
 	waf := NewWaf()
 	for i := 0; i < b.N; i++ {

waf.go

@@ -33,6 +33,7 @@ import (
 )
 
 type Phase int
+type EventSeverity int
 
 const (
 	PHASE_REQUEST_HEADERS  Phase = 1
@@ -42,6 +43,17 @@ const (
 	PHASE_LOGGING          Phase = 5
 )
 
+const (
+	EventEmergency EventSeverity = 0
+	EventAlert     EventSeverity = 1
+	EventCritical  EventSeverity = 2
+	EventError     EventSeverity = 3
+	EventWarning   EventSeverity = 4
+	EventNotice    EventSeverity = 5
+	EventInfo      EventSeverity = 6
+	EventDebug     EventSeverity = 7
+)
+
 const (
 	CONN_ENGINE_OFF        = 0
 	CONN_ENGINE_ON         = 1
@@ -65,6 +77,17 @@ const (
 	RULE_ENGINE_OFF        = 2
 )
 
+type EventLogger interface {
+	Emergency(msg string)
+	Alert(msg string)
+	Critical(msg string)
+	Error(msg string)
+	Warning(msg string)
+	Notice(msg string)
+	Info(msg string)
+	Debug(msg string)
+}
+
 // Waf instances are used to store configurations and rules
 // Every web application should have a different Waf instance
 // but you can share an instance if you are okwith sharing
@@ -175,6 +198,9 @@ type Waf struct {
 	// ctl cannot switch use it as it will update de lvl
 	// for the whole Waf instance
 	LoggerAtomicLevel zap.AtomicLevel
+
+	// Used to write logs to implementation's error log
+	ErrorLogger EventLogger
 }
 
 // NewTransaction Creates a new initialized transaction for this WAF instance