rule.go -- 1. made changes for recoding rule timings 2. printing tran…

…sformation rules on console 3. enablement of above (start recording, printing_transormation rules, clear of riming records) 4. retrieving timing records 5. not stroing rules which do not have tags in them (it is like not saving non-log records)

transaction.go --1. Adding ProcessRequestBytes which directly consumes the buffer shared with it in an inline fashion
Updated following transformations -- lowercase.go, remove_nulls.go
transformations.go -- updated the optimized transaformation registration
transaction.go (non-internal files)- exposed transformations.go
waf.go (non-internal files) -- exposed WafGetRulesInfo, WafUpdateRuleFlags and implementation of same

internal/corazawaf/rule.go

@@ -5,11 +5,13 @@ package corazawaf
 
 import (
 	"fmt"
+	"os"
 	"reflect"
 	"regexp"
 	"strconv"
 	"strings"
 	"sync"
+	"time"
 	"unsafe"
 
 	"github.com/corazawaf/coraza/v3/experimental/plugins/macro"
@@ -153,6 +155,82 @@ type Rule struct {
 	withPhaseUnknownVariable bool
 }
 
+//MJ Changes [ I made a mess by making this global .. ideally should have associated corazawaf and stored there for it is independent of each instance
+var print_transformation_rules bool = false
+var record_rule_timings bool = false
+var RulesTimingRecord map[int]time.Duration = make(map[int]time.Duration)
+var RulesTimingRecordMutex sync.Mutex
+
+func init() {
+	// Initialization code here.
+	if val, ok := os.LookupEnv("PRINT_TRANSFORMATION_RULES"); ok {
+		if val == "true" {
+			print_transformation_rules = true
+		} else {
+			print_transformation_rules = false
+		}
+	} else {
+		print_transformation_rules = false
+	}
+	fmt.Println("rules.go init print_transformation_rules", print_transformation_rules)
+	if val, ok := os.LookupEnv("RECORD_RULE_TIMINGS"); ok {
+		if val == "true" {
+			record_rule_timings = true
+		} else {
+			record_rule_timings = false
+		}
+	} else {
+		record_rule_timings = false
+	}
+	fmt.Println("rules.go init record_rule_timings", record_rule_timings)
+}
+
+func GetRuleTimingsRecord() map[int]time.Duration {
+	return RulesTimingRecord
+	/*fmt.Println("Rule Timings: ")
+		for key, value := range RulesTimingRecord {
+	        fmt.Println("RuleId: ", key, " elapsedTime: ", value)
+	    }
+	*/
+}
+
+func ClearRuleTimingsRecord() {
+	RulesTimingRecordMutex.Lock()
+	RulesTimingRecord = make(map[int]time.Duration)
+	RulesTimingRecordMutex.Unlock()
+	fmt.Println("rules.go ClearRuleTimingsRecord")
+}
+
+func UpdatePrintTransformationRules(val bool) bool {
+	prev := print_transformation_rules
+	print_transformation_rules = val
+	fmt.Println("rules.go UpdatePrintTransformationRules: ", prev, val)
+	return prev
+}
+
+func UpdateRecordRuleTimings(val bool) bool {
+	prev := record_rule_timings
+	record_rule_timings = val
+	fmt.Println("rules.go UpdateRecordRuleTimings: ", prev, val)
+	return prev
+}
+
+func (r *Rule) RecordRuleTimings(startTime *time.Time) {
+	if startTime != nil {
+		elapsedTime := time.Since(*startTime)
+		RulesTimingRecordMutex.Lock()
+		val, ok := RulesTimingRecord[r.ID_]
+		if ok {
+			val = val + elapsedTime
+		}
+		RulesTimingRecord[r.ID_] = val
+		RulesTimingRecordMutex.Unlock()
+	}
+
+}
+
+//MJ Changes
+
 func (r *Rule) ParentID() int {
 	return r.ParentID_
 }
@@ -175,6 +253,13 @@ func (r *Rule) Evaluate(phase types.RulePhase, tx plugintypes.TransactionState,
 const noID = 0
 
 func (r *Rule) doEvaluate(phase types.RulePhase, tx *Transaction, collectiveMatchedValues *[]types.MatchData, chainLevel int, cache map[transformationKey]*transformationValue) []types.MatchData {
+	var startTime *time.Time = nil
+
+	if record_rule_timings == true {
+		currentTime := time.Now()
+		startTime = &currentTime
+	}
+
 	tx.Capture = r.Capture
 
 	rid := r.ID_
@@ -323,6 +408,7 @@ func (r *Rule) doEvaluate(phase types.RulePhase, tx *Transaction, collectiveMatc
 	}
 
 	if len(matchedValues) == 0 {
+		r.RecordRuleTimings(startTime)
 		return matchedValues
 	}
 
@@ -335,6 +421,7 @@ func (r *Rule) doEvaluate(phase types.RulePhase, tx *Transaction, collectiveMatc
 			tx.DebugLogger().Debug().Int("rule_id", rid).Msg("Evaluating rule chain")
 			matchedChainValues := nr.doEvaluate(phase, tx, collectiveMatchedValues, chainLevel, cache)
 			if len(matchedChainValues) == 0 {
+				r.RecordRuleTimings(startTime)
 				return matchedChainValues
 			}
 			matchedValues = append(matchedValues, matchedChainValues...)
@@ -368,22 +455,39 @@ func (r *Rule) doEvaluate(phase types.RulePhase, tx *Transaction, collectiveMatc
 			tx.MatchRule(r, matchedValues)
 		}
 	}
+	r.RecordRuleTimings(startTime)
 	return matchedValues
 }
 
 func (r *Rule) transformArg(arg types.MatchData, argIdx int, cache map[transformationKey]*transformationValue) ([]string, []error) {
+	argKey1 := arg.Key()
 	if r.MultiMatch {
 		// TODOs:
 		// - We don't need to run every transformation. We could try for each until found
 		// - Cache is not used for multimatch
+		if print_transformation_rules {
+			fmt.Println("\n---- transformArg:---- MultiMatch details: ruleId: ", r.ID_, " Parent Rule: ", r.ParentID_, " key: ", argKey1, "Value: ", arg.Value(), " args: ", arg)
+		}
 		return r.executeTransformationsMultimatch(arg.Value())
 	} else {
+		if len(r.transformations) > 0 {
+			if print_transformation_rules {
+				fmt.Println("\n---- transformArg: ---- details: ruleId: ", r.ID_, " Parent Rule: ", r.ParentID_, " key: ", argKey1, "Value: ", arg.Value())
+				fmt.Println("  transformArg: args: ", arg, " key: (", (*reflect.StringHeader)(unsafe.Pointer(&argKey1)).Data, argIdx, arg.Variable(), r.transformationsID, ")")
+				fmt.Println("  transformArg: transformations: ", r.transformations)
+			}
+		}
+
+		startTime := time.Now()
 		switch {
 		case len(r.transformations) == 0:
 			return []string{arg.Value()}, nil
 		case arg.Variable().Name() == "TX":
 			// no cache for TX
 			arg, errs := r.executeTransformations(arg.Value())
+			if print_transformation_rules {
+				fmt.Println("---- transformArg---- TX: ", r.ID_, r.ParentID_, time.Since(startTime), arg)
+			}
 			return []string{arg}, errs
 		default:
 			// NOTE: See comment on transformationKey struct to understand this hacky code
@@ -396,6 +500,9 @@ func (r *Rule) transformArg(arg types.MatchData, argIdx int, cache map[transform
 				transformationsID: r.transformationsID,
 			}
 			if cached, ok := cache[key]; ok {
+				if print_transformation_rules {
+					fmt.Println("---- transformArg: ----: cached", time.Since(startTime), cached.args)
+				}
 				return cached.args, cached.errs
 			} else {
 				ars, es := r.executeTransformations(arg.Value())
@@ -405,6 +512,9 @@ func (r *Rule) transformArg(arg types.MatchData, argIdx int, cache map[transform
 					args: args,
 					errs: es,
 				}
+				if print_transformation_rules {
+					fmt.Println("---- transformArg: ----: non-cached", time.Since(startTime), args)
+				}
 				return args, errs
 			}
 		}

internal/corazawaf/transaction.go

@@ -5,13 +5,15 @@ package corazawaf
 
 import (
 	"bufio"
+	"bytes"
 	"errors"
 	"fmt"
 	"io"
 	"math"
 	"mime"
 	"net/url"
 	"path/filepath"
+	"runtime/debug"
 	"strconv"
 	"strings"
 	"time"
@@ -463,6 +465,11 @@ func (tx *Transaction) matchVariable(match *corazarules.MatchData) {
 
 // MatchRule Matches a rule to be logged
 func (tx *Transaction) MatchRule(r *Rule, mds []types.MatchData) {
+	if len(r.RuleMetadata.Tags_) == 0 { // //"regexp" MJ Change
+		//if !r.Log
+		tx.debugLogger.Debug().Int("rule_id", r.ID_).Msg("Rule matched no log")
+		return
+	}
 	tx.debugLogger.Debug().Int("rule_id", r.ID_).Msg("Rule matched")
 	// tx.MatchedRules = append(tx.MatchedRules, mr)
 
@@ -930,6 +937,7 @@ func (tx *Transaction) ReadRequestBodyFrom(r io.Reader) (*types.Interruption, in
 //
 // Remember to check for a possible intervention.
 func (tx *Transaction) ProcessRequestBody() (*types.Interruption, error) {
+	debug.PrintStack() //in our deployment we should never reach here -- can remove after testing TODO MJ
 	if tx.RuleEngine == types.RuleEngineOff {
 		return nil, nil
 	}
@@ -1006,6 +1014,63 @@ func (tx *Transaction) ProcessRequestBody() (*types.Interruption, error) {
 	return tx.interruption, nil
 }
 
+//same as ProcessRequest only it does processing on the provided buffer
+func (tx *Transaction) ProcessRequestBytes(b []byte) (*types.Interruption, error) { //MJ CHANGES
+	//debug.PrintStack()
+	if tx.RuleEngine == types.RuleEngineOff {
+		return nil, nil
+	}
+	if tx.interruption != nil {
+		tx.debugLogger.Error().Msg("Calling ProcessRequestBody but there is a preexisting interruption")
+		return tx.interruption, nil
+	}
+	if tx.lastPhase != types.PhaseRequestHeaders {
+		if tx.lastPhase >= types.PhaseRequestBody {
+			// Phase already evaluated or skipped
+			tx.debugLogger.Warn().Msg("ProcessRequestBody should have already been called")
+		} else {
+			tx.debugLogger.Debug().Msg("Skipping request body processing, anomalous call before request headers evaluation")
+		}
+		return nil, nil
+	}
+	mime := ""
+	if m := tx.variables.requestHeaders.Get("content-type"); len(m) > 0 {
+		mime = m[0]
+	}
+	reader := bytes.NewReader(b)
+	rbp := tx.variables.reqbodyProcessor.Get()
+	if tx.ForceRequestBodyVariable {
+		// We force URLENCODED if mime is x-www... or we have an empty RBP and ForceRequestBodyVariable
+		if rbp == "" {
+			rbp = "URLENCODED"
+		}
+		tx.variables.reqbodyProcessor.Set(rbp)
+	}
+	rbp = strings.ToLower(rbp)
+	if rbp == "" {
+		// so there is no bodyprocessor, we don't want to generate an error
+		tx.WAF.Rules.Eval(types.PhaseRequestBody, tx)
+		return tx.interruption, nil
+	}
+	bodyprocessor, err := bodyprocessors.GetBodyProcessor(rbp)
+	if err != nil {
+		tx.generateRequestBodyError(errors.New("invalid body processor"))
+		tx.WAF.Rules.Eval(types.PhaseRequestBody, tx)
+		return tx.interruption, nil
+	}
+	if err := bodyprocessor.ProcessRequest(reader, tx.Variables(), plugintypes.BodyProcessorOptions{
+		Mime:        mime,
+		StoragePath: tx.WAF.UploadDir,
+	}); err != nil {
+		tx.debugLogger.Error().Err(err).Msg("Failed to process request body")
+		tx.generateRequestBodyError(err)
+		tx.WAF.Rules.Eval(types.PhaseRequestBody, tx)
+		return tx.interruption, nil
+	}
+	tx.WAF.Rules.Eval(types.PhaseRequestBody, tx)
+	return tx.interruption, nil
+}
+
 // ProcessResponseHeaders Perform the analysis on the response readers.
 //
 // This method perform the analysis on the response headers, notice however

internal/transformations/lowercase.go

@@ -13,3 +13,10 @@ func lowerCase(data string) (string, bool, error) {
 	transformedData := strings.ToLower(data)
 	return transformedData, data != transformedData, nil
 }
+
+//MJ change
+func lowerCaseOptimized(data string) (string, bool, error) {
+	// TODO: Explicit implementation of ToLower would allow optimizing away the byte by byte comparison for returning the changed boolean
+	// See https://github.com/corazawaf/coraza/pull/778#discussion_r1186963422
+	return strings.ToLower(data), true, nil
+}

internal/transformations/remove_nulls.go

@@ -12,3 +12,9 @@ func removeNulls(data string) (string, bool, error) {
 	transformedData := strings.ReplaceAll(data, "\x00", "")
 	return transformedData, len(data) != len(transformedData), nil
 }
+
+//MJ Changes
+func removeNullsOptimized(data string) (string, bool, error) {
+	transformedData := strings.ReplaceAll(data, "\x00", "")
+	return transformedData, true, nil
+}

internal/transformations/transformations.go

@@ -37,7 +37,8 @@ func init() {
 	Register("htmlEntityDecode", htmlEntityDecode)
 	Register("jsDecode", jsDecode)
 	Register("length", length)
-	Register("lowercase", lowerCase)
+	//Register("lowercase", lowerCase)
+	Register("lowercase", lowerCaseOptimized)
 	Register("md5", md5T)
 	Register("none", none)
 	Register("normalisePath", normalisePath)
@@ -46,7 +47,8 @@ func init() {
 	Register("normalizePathWin", normalisePathWin)
 	Register("removeComments", removeComments)
 	Register("removeCommentsChar", removeCommentsChar)
-	Register("removeNulls", removeNulls)
+	//Register("removeNulls", removeNulls)
+	Register("removeNulls", removeNullsOptimized)
 	Register("removeWhitespace", removeWhitespace)
 	Register("replaceComments", replaceComments)
 	Register("replaceNulls", replaceNulls)
@@ -58,4 +60,5 @@ func init() {
 	Register("trim", trim)
 	Register("trimLeft", trimLeft)
 	Register("trimRight", trimRight)
+	fmt.Println("----- All Transformations-----", transformations) //MJ c
 }

types/transaction.go

@@ -195,4 +195,6 @@ type Transaction interface {
 
 	// Closer closes the transaction and releases any resources associated with it such as request/response bodies.
 	io.Closer
+
+	ProcessRequestBytes(b []byte) (*Interruption, error) //MJ CHANGES
 }

waf.go

@@ -22,6 +22,9 @@ type WAF interface {
 	// NewTransaction Creates a new initialized transaction for this WAF instance
 	NewTransaction() types.Transaction
 	NewTransactionWithID(id string) types.Transaction
+	// MJ Change
+	WafGetRulesInfo(flagName string) interface{}
+	WafUpdateRuleFlags(flagName string, flagValue interface{}) bool
 }
 
 // NewWAF creates a new WAF instance with the provided configuration.
@@ -123,3 +126,32 @@ func (w wafWrapper) NewTransaction() types.Transaction {
 func (w wafWrapper) NewTransactionWithID(id string) types.Transaction {
 	return w.waf.NewTransactionWithID(id)
 }
+
+//MJ changes [ --
+func (w wafWrapper) WafGetRulesInfo(flagName string) interface{} {
+	return corazawaf.GetRuleTimingsRecord() //only 1 supported as of now
+}
+
+func (w wafWrapper) WafUpdateRuleFlags(flagName string, flagValue interface{}) bool {
+	ret_val := false
+	switch flagName {
+	case "printtransformationrule":
+		if val, ok := flagValue.(bool); ok {
+			corazawaf.UpdatePrintTransformationRules(val)
+			ret_val = true
+		}
+	case "recordruletimings":
+		if val, ok := flagValue.(bool); ok {
+			corazawaf.UpdatePrintTransformationRules(val)
+			ret_val = true
+		}
+	case "recordruletimingsclear":
+		corazawaf.ClearRuleTimingsRecord()
+		ret_val = true
+	default:
+		fmt.Println("WafUpdateRuleFlags: Invalid parameters: ", flagName, flagValue)
+	}
+	return ret_val
+}
+
+//MJ Changes ]