CRS strconv.Atoi: parsing tx.blocking_outbound_anomaly_score: invalid syntax

[davidmytton]

Description

With Core Rule Set ver.4.0.0-rc1 I'm seeing Coraza log an error when parsing the RESPONSE-980-CORRELATION.conf rule. I have tested this with Coraza v3.0.4 and also pinning to a specific commit 2624bf3

Steps to reproduce

Send an HTTP request that triggers an interrupt through Coraza with the default config + core ruleset 4.0.0-rc1

	cfg := coraza.NewWAFConfig().
		WithDirectivesFromFile(directivesDir + "coraza.conf").
		WithDirectivesFromFile(directivesDir + "coreruleset-4.0.0-rc1/crs-setup.conf").
		WithDirectivesFromFile(directivesDir + "coreruleset-4.0.0-rc1/rules/*.conf").
		WithDirectives(`SecDebugLogLevel ` + fmt.Sprintf("%d", logLevel)).
		WithDebugLogger(adapter)
        wafInstance, err := coraza.NewWAF(cfg)
	if err != nil {
		return nil, err
	}
        ...
        tx := wafInstance.NewTransactionWithID(req.GetId())
	defer func() {
		tx.ProcessLogging()
		tx.Close()
	}()

	tx.ProcessConnection(req.GetIp(), 0, req.GetHost(), 0)
	tx.ProcessURI(req.GetPath(), req.GetMethod(), req.GetProtocol())

	for k, v := range req.Headers {
		tx.AddRequestHeader(k, v)
	}

	if it := tx.ProcessRequestHeaders(); it != nil {
        ...

Actual result

a-analyze-1         | 2023-10-13T12:32:09.101Z	DEBUG	logger/waf_adapter.go:147	Evaluating rule	{"tx_id": "req_01hcmgbma0et7tnygqn81ntbkh", "rule_id": 980099}
a-analyze-1         | 2023-10-13T12:32:09.101Z	DEBUG	logger/waf_adapter.go:147	Forcing rule to match	{"tx_id": "req_01hcmgbma0et7tnygqn81ntbkh", "rule_id": 980099}
a-analyze-1         | 2023-10-13T12:32:09.101Z	DEBUG	logger/waf_adapter.go:147	Evaluating action	{"tx_id": "req_01hcmgbma0et7tnygqn81ntbkh", "action": "t"}
a-analyze-1         | 2023-10-13T12:32:09.101Z	DEBUG	logger/waf_adapter.go:147	Evaluating action	{"tx_id": "req_01hcmgbma0et7tnygqn81ntbkh", "action": "nolog"}
a-analyze-1         | 2023-10-13T12:32:09.101Z	DEBUG	logger/waf_adapter.go:147	Evaluating action	{"tx_id": "req_01hcmgbma0et7tnygqn81ntbkh", "action": "noauditlog"}
a-analyze-1         | 2023-10-13T12:32:09.101Z	DEBUG	logger/waf_adapter.go:147	Evaluating action	{"tx_id": "req_01hcmgbma0et7tnygqn81ntbkh", "action": "setvar"}
a-analyze-1         | 2023-10-13T12:32:09.102Z	DEBUG	logger/waf_adapter.go:147	Action evaluated	{"tx_id": "req_01hcmgbma0et7tnygqn81ntbkh", "var_key": "blocking_anomaly_score", "var_value": "tx.blocking_inbound_anomaly_score", "rule_id": 980099}
a-analyze-1         | 2023-10-13T12:32:09.102Z	DEBUG	logger/waf_adapter.go:147	Evaluating action	{"tx_id": "req_01hcmgbma0et7tnygqn81ntbkh", "action": "setvar"}
a-analyze-1         | 2023-10-13T12:32:09.102Z	DEBUG	logger/waf_adapter.go:147	Action evaluated	{"tx_id": "req_01hcmgbma0et7tnygqn81ntbkh", "var_key": "blocking_anomaly_score", "var_value": "+tx.blocking_outbound_anomaly_score", "rule_id": 980099}
a-analyze-1         | 2023-10-13T12:32:09.102Z	ERROR	logger/waf_adapter.go:147	Invalid value	{"tx_id": "req_01hcmgbma0et7tnygqn81ntbkh", "var_value": "+tx.blocking_outbound_anomaly_score", "rule_id": 980099, "error": "strconv.Atoi: parsing \"tx.blocking_outbound_anomaly_score\": invalid syntax"}
a-analyze-1         | a/a-decide/internal/logger.(*ZapEvent).Msg
a-analyze-1         | 	/app/internal/logger/waf_adapter.go:147
a-analyze-1         | github.com/corazawaf/coraza/v3/internal/actions.(*setvarFn).evaluateTxCollection
a-analyze-1         | 	/go/pkg/mod/github.com/corazawaf/coraza/[email protected]/internal/actions/setvar.go:158
a-analyze-1         | github.com/corazawaf/coraza/v3/internal/actions.(*setvarFn).Evaluate
a-analyze-1         | 	/go/pkg/mod/github.com/corazawaf/coraza/[email protected]/internal/actions/setvar.go:115
a-analyze-1         | github.com/corazawaf/coraza/v3/internal/corazawaf.(*Rule).matchVariable
a-analyze-1         | 	/go/pkg/mod/github.com/corazawaf/coraza/[email protected]/internal/corazawaf/rule.go:436
a-analyze-1         | github.com/corazawaf/coraza/v3/internal/corazawaf.(*Rule).doEvaluate
a-analyze-1         | 	/go/pkg/mod/github.com/corazawaf/coraza/[email protected]/internal/corazawaf/rule.go:220
a-analyze-1         | github.com/corazawaf/coraza/v3/internal/corazawaf.(*Rule).Evaluate
a-analyze-1         | 	/go/pkg/mod/github.com/corazawaf/coraza/[email protected]/internal/corazawaf/rule.go:172
a-analyze-1         | github.com/corazawaf/coraza/v3/internal/corazawaf.(*RuleGroup).Eval
a-analyze-1         | 	/go/pkg/mod/github.com/corazawaf/coraza/[email protected]/internal/corazawaf/rulegroup.go:219
a-analyze-1         | github.com/corazawaf/coraza/v3/internal/corazawaf.(*Transaction).ProcessLogging
a-analyze-1         | 	/go/pkg/mod/github.com/corazawaf/coraza/[email protected]/internal/corazawaf/transaction.go:1257
a-analyze-1         | a/a-decide/internal/analyze.(*analyzer).Analyze.func1
a-analyze-1         | 	/app/internal/analyze/waf_analyzer.go:88
a-analyze-1         | a/a-decide/internal/analyze.(*analyzer).Analyze
a-analyze-1         | 	/app/internal/analyze/waf_analyzer.go:109
a-analyze-1         | a/a-decide/internal/processing.(*analyzeService).Analyze
a-analyze-1         | 	/app/internal/processing/analyse_service.go:47
a-analyze-1         | main.main
a-analyze-1         | 	/app/cmd/analyze/main.go:186
a-analyze-1         | runtime.main
a-analyze-1         | 	/usr/local/go/src/runtime/proc.go:267

[M4tteoP]

Hi @davidmytton, thanks for reporting it. It seems like you are facing some problems related to variable expansion. The value is indeed the string name "+tx.blocking_outbound_anomaly_score" rather than its real numeric value.

I'm trying to reproduce it, but I'm not succeeding. This is the branch where I'm trying to follow your steps: https://github.com/M4tteoP/coraza/tree/atoi_repro.
Would you be able to provide a branch starting from that branch that reproduces the issue?
I did the following steps:

• Added the whole coreruleset-4.0.0-rc1 under examples/http-server
• Did little tweaks to the main.go adding the whole coreruleset and a debug logger.
• Run curl 'http://localhost:8090?script></script>'

Specifically looking at the logs of rule 980099 I get:

[DEBUG] Evaluating rule tx_id="MySCvCotYSSiVsrOJFR" rule_id=980099
[DEBUG] Forcing rule to match tx_id="MySCvCotYSSiVsrOJFR" rule_id=980099
[DEBUG] Evaluating action tx_id="MySCvCotYSSiVsrOJFR" action="t"
[DEBUG] Evaluating action tx_id="MySCvCotYSSiVsrOJFR" action="nolog"
[DEBUG] Evaluating action tx_id="MySCvCotYSSiVsrOJFR" action="noauditlog"
[DEBUG] Evaluating action tx_id="MySCvCotYSSiVsrOJFR" action="setvar"
[DEBUG] Action evaluated tx_id="MySCvCotYSSiVsrOJFR" var_key="blocking_anomaly_score" var_value="5" rule_id=980099
[DEBUG] Evaluating action tx_id="MySCvCotYSSiVsrOJFR" action="setvar"
[DEBUG] Action evaluated tx_id="MySCvCotYSSiVsrOJFR" var_key="blocking_anomaly_score" var_value="+0" rule_id=980099
[DEBUG] Evaluating action tx_id="MySCvCotYSSiVsrOJFR" action="setvar"
[DEBUG] Action evaluated tx_id="MySCvCotYSSiVsrOJFR" var_key="detection_anomaly_score" var_value="5" rule_id=980099
[DEBUG] Evaluating action tx_id="MySCvCotYSSiVsrOJFR" action="setvar"
[DEBUG] Action evaluated tx_id="MySCvCotYSSiVsrOJFR" var_key="detection_anomaly_score" var_value="+0" rule_id=980099
[DEBUG] Evaluating action tx_id="MySCvCotYSSiVsrOJFR" action="setvar"
[DEBUG] Action evaluated tx_id="MySCvCotYSSiVsrOJFR" var_key="anomaly_score" var_value="5" rule_id=980099
[DEBUG] Evaluating action tx_id="MySCvCotYSSiVsrOJFR" action="setvar"
[DEBUG] Action evaluated tx_id="MySCvCotYSSiVsrOJFR" var_key="anomaly_score" var_value="+0" rule_id=980099
[DEBUG] Rule matched tx_id="MySCvCotYSSiVsrOJFR" rule_id=980099
[DEBUG] Finish evaluating rule tx_id="MySCvCotYSSiVsrOJFR" rule_id=980099

I tried with Coraza v3.0.4 and both Go 1.20.7 and 1.21.3.

Thanks for your help

[davidmytton]

Thanks for looking into this @M4tteoP

I pushed 76aee6e which reproduces the issue from your branch with a test rule a-suspicious.conf that triggers on a specific header: curl -H 'x-a-suspicious: true' http://localhost:8090 but only in certain circumstances.

• I have written a zap adapter for logging. Without the zap adapter it does not error.
• If you disable the CRS rules and just use your default.conf and my a-suspicious.conf then the header triggers the WAF and does not error (including with my zap adapter enabled).
• So it seems to be a combination of CRS + a-suspicious.conf + the custom zap logging adapter.

Interested to hear your thoughts on whether this is an issue in the zap adapter or whether there's something else going on. Seems like CRS has something to do with it given my zap adapter works fine without CRS.

[M4tteoP]

Thanks for your repro example! As far as I can see, the root cause of the issue is a misconfiguration originated by the rules order, specifically by the a-suspicious.conf file added before the CRS rules.

Rules are executed following the inclusion order according to phases, so, within each phase, the order of rules matters.

The inclusion order of your rules files is the following:

1. coraza.conf
2. a-suspicious.conf
3. coreruleset-4.0.0-rc1/crs-setup.conf
4. coreruleset-4.0.0-rc1/rules/*.conf

Expanding it a little:

1. coraza.conf
2. a-suspicious.conf
   • rule id:10000000 ← phase:1 custom rule with deny action
3. coreruleset-4.0.0-rc1/crs-setup.conf
4. coreruleset-4.0.0-rc1/rules/*.conf
   • REQUEST-901-INITIALIZATION.conf
     • rule id: 901200 ← phase:1
   • ...
   • RESPONSE-980-CORRELATION.conf
     • rule id:980099 ← phase:5 (log phase)
     • ...

The a-suspicious.conf file, with rule id:10000000 is set before the CRS rules, and specifically, before the initialization rules of the CRS. These rules are the ones in charge of initializing the interval variables. E.g. rule 901200 has the following actions:

    setvar:'tx.blocking_inbound_anomaly_score=0',\
    setvar:'tx.detection_inbound_anomaly_score=0',\
    setvar:'tx.inbound_anomaly_score_pl1=0',\
    setvar:'tx.inbound_anomaly_score_pl2=0',\
    setvar:'tx.inbound_anomaly_score_pl3=0',\
    setvar:'tx.inbound_anomaly_score_pl4=0',\

So, the following happens:

1. Request headers are received, phase:1 rules are triggered
2. Following the inclusion order of phase 1 rules, the custom rule id:10000000 is executed very early. It is triggered, alongside its disruptive deny action.
3. Being a deny action triggered, the subsequent rules are skipped. Notably, also initialization rules, like the 901200 will not be executed.
4. phase:5 is the logging phase. It is a special phase in which the rules are executed at the end of each transaction, no matter what happened in the previous phases. Here we have the correlation rules, made for post-processing and logging purposes. rule id:980099 is one of these, which is trying to rely on variables that have not been initialized with actions like setvar:'tx.blocking_anomaly_score=+%{tx.blocking_outbound_anomaly_score}'.
5. When a variable is not found, the returned value is the variable name itself, therefore the expanded +%{tx.blocking_outbound_anomaly_score} becomes just +tx.blocking_outbound_anomaly_score (as we can see from your initial logs). At this point, the code tries to perform an arithmetical operation, trying to convert whatever is after the plus sign into an integer.
6. The strconv.Atoi conversion error will follow.

To recap: custom rules should be added after the CRS rules, or integrated into the CRS order logic. To grasp a bit more about rules positioning, a nice reference is https://github.com/coreruleset/template-plugin#order-of-rules-with-plugins-and-existing-crs-rules. It is about extending the CRS with custom plugins (aka extra rules), and current limitations of the CRS plugin architecture.

Digging into this I opened #892. I think that we should at least be a bit more verbose when this error happens, clearly stating that a variable has not been found. Among other small fixes and improvements, the PR proposes to add a warning log in that case.

I have written a zap adapter for logging. Without the zap adapter it does not error.

Just for the sake of completeness, I added 980737f in which I'm able to reproduce the Atoi error even without the zap adapter. The only difference I saw is that with a smaller logger, the error is limited to a single error line, not including the full trace printed with the Zap adapter.

[davidmytton]

Thanks for the detailed explanation, that makes sense. Moving the custom rule after CRS resolves this! The extra debug info in #892 will also be helpful.