feat: adds metrics support. (envoyproxy#29)

Co-authored-by: Anuraag Agrawal <anuraaga@gmail.com>

README.md

@@ -5,7 +5,8 @@ Web Application Firewall WASM filter built on top of [Coraza](https://github.com
 ## Getting started
 
 `go run mage.go -l` lists all the available commands:
-```
+
+```bash
 ▶ go run mage.go -l
 Targets:
   build*             builds the Coraza wasm plugin.
@@ -26,9 +27,10 @@ Targets:
 
 ### Building the filter
 
-```
+```bash
 go run mage.go build
 ```
+
 You will find the WASM plugin under `./build/main.wasm`.
 
 For performance purposes, some libs are built from non-Go implementations. The compiled polyglot wasm libs are already checked in under [./lib/](./lib/). It is possible to rely on the Dockerfiles under [./buildtools/](./buildtools/) if you wish to rebuild them from scratch
@@ -100,19 +102,25 @@ configuration:
 ### Running go-ftw (CRS Regression tests)
 
 The following command runs the [go-ftw](https://github.com/fzipi/go-ftw) test suite against the filter with the CRS fully loaded.
-```
+
+```bash
 go run mage.go ftw
 ```
+
 Take a look at its config file [ftw.yml](./ftw/ftw.yml) for details about tests currently excluded.
 
 ## Example: Spinning up the coraza-wasm-filter for manual tests
+
 Once the filter is built, via the commands `mage runExample` and `mage teardownExample` you can spin up and tear down the test environment. Envoy with the coraza-wasm filter will be reachable at `localhost:8080`. The filter is configured with the CRS loaded working in Anomaly Scoring mode. For details and locally tweaking the configuration refer to [coraza-demo.conf](./rules/coraza-demo.conf) and [crs-setup-demo.conf](./rules/crs-setup-demo.conf).
 In order to monitor envoy logs while performing requests you can run:
+
 - Envoy logs: `docker-compose -f ./example/docker-compose.yml logs -f envoy-logs`.
 - Critical wasm (audit) logs: `docker-compose -f ./example/docker-compose.yml logs -f wasm-logs`
 
 ### Manual requests
+
 Run `./e2e/e2e-example.sh` in order to run the following requests against the just set up test environment, otherwise manually execute and tweak them to grasp the behaviour of the filter:
+
 ```bash
 # True positive requests:
 # Custom rule phase 1
@@ -140,3 +148,21 @@ curl -i -X POST 'http://localhost:8080/anything' --data "Hello world"
 # An usual user-agent
 curl -I --user-agent "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/105.0.0.0 Safari/537.36" localhost:8080
 ```
+
+### WAF Metrics
+
+Metrics are exposed in the prometheus format under `localhost:8082` (admin cluster in the envoy config).
+
+```bash
+curl -s localhost:8082/stats/prometheus | grep waf_filter
+```
+
+and we get the metrics with the corresponding tags:
+
+```bash
+# TYPE waf_filter_tx_interruptions counter
+waf_filter_tx_interruptions{phase="http_request_body",rule_id="949110"} 1
+waf_filter_tx_interruptions{phase="http_response_headers",rule_id="949110"} 3
+# TYPE waf_filter_tx_total counter
+waf_filter_tx_total{} 7
+```

e2e/docker-compose.yml

@@ -10,7 +10,7 @@ services:
       - /conf/envoy-config.yaml
     volumes:
       - ../build:/build
-      - ../example:/conf  # relying on envoy-config file from /example/
+      - ../example:/conf # relying on envoy-config file from /example/
   tests:
     depends_on:
       - envoy

example/docker-compose.yml

@@ -11,6 +11,7 @@ services:
       - chown -R 101:101 /home/envoy/logs
     volumes:
       - logs:/home/envoy/logs:rw
+
   envoy:
     depends_on:
       - chown
@@ -32,6 +33,8 @@ services:
       - logs:/home/envoy/logs:rw
     ports:
       - 8080:8080
+      - 8082:8082
+
   envoy-logs:
     depends_on:
       - envoy
@@ -43,6 +46,7 @@ services:
       - tail -c +0 -f /home/envoy/logs/envoy.log
     volumes:
       - logs:/home/envoy/logs:ro
+
   wasm-logs:
     depends_on:
       - envoy
@@ -53,5 +57,6 @@ services:
       - tail -c +0 -f /home/envoy/logs/envoy.log | grep --line-buffered "[critical][wasm]"
     volumes:
       - logs:/home/envoy/logs:ro
+
 volumes:
   logs:

example/envoy-config.yaml

@@ -1,3 +1,12 @@
+stats_config:
+  stats_tags:
+    # Envoy extracts the first matching group as a value.
+    # See https://www.envoyproxy.io/docs/envoy/latest/api-v3/config/metrics/v3/stats.proto#config-metrics-v3-statsconfig.
+    - tag_name: phase
+      regex: "(_phase=([a-z_]+))"
+    - tag_name: rule_id
+      regex: "(_ruleid=([0-9]+))"
+
 static_resources:
   listeners:
     - address:
@@ -64,3 +73,10 @@ static_resources:
                     socket_address:
                       address: httpbin
                       port_value: 80
+
+admin:
+  access_log_path: "/dev/null"
+  address:
+    socket_address:
+      address: 0.0.0.0
+      port_value: 8082

go.mod

@@ -20,7 +20,7 @@ require (
 	github.com/tetratelabs/wazero v1.0.0-beta.2 // indirect
 	github.com/tidwall/match v1.1.1 // indirect
 	github.com/tidwall/pretty v1.2.1 // indirect
-	golang.org/x/net v0.0.0-20221002022538-bcab6841153b // indirect
+	golang.org/x/net v0.0.0-20221004154528-8021a29435af // indirect
 	gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127 // indirect
 	gopkg.in/yaml.v3 v3.0.1 // indirect
 )

go.sum

@@ -37,8 +37,8 @@ github.com/tidwall/pretty v1.2.0/go.mod h1:ITEVvHYasfjBbM0u2Pg8T2nJnzm8xPwvNhhso
 github.com/tidwall/pretty v1.2.1 h1:qjsOFOWWQl+N3RsoF5/ssm1pHmJJwhjlSbZ51I6wMl4=
 github.com/tidwall/pretty v1.2.1/go.mod h1:ITEVvHYasfjBbM0u2Pg8T2nJnzm8xPwvNhhsoaGGjNU=
 golang.org/x/mod v0.6.0-dev.0.20220419223038-86c51ed26bb4 h1:6zppjxzCulZykYSLyVDYbneBfbaBIQPYMevg0bEwv2s=
-golang.org/x/net v0.0.0-20221002022538-bcab6841153b h1:6e93nYa3hNqAvLr0pD4PN1fFS+gKzp2zAXqrnTCstqU=
-golang.org/x/net v0.0.0-20221002022538-bcab6841153b/go.mod h1:YDH+HFinaLZZlnHAfSS6ZXJJ9M9t4Dl22yv3iI2vPwk=
+golang.org/x/net v0.0.0-20221004154528-8021a29435af h1:wv66FM3rLZGPdxpYL+ApnDe2HzHcTFta3z5nsc13wI4=
+golang.org/x/net v0.0.0-20221004154528-8021a29435af/go.mod h1:YDH+HFinaLZZlnHAfSS6ZXJJ9M9t4Dl22yv3iI2vPwk=
 golang.org/x/sys v0.0.0-20220913175220-63ea55921009 h1:PuvuRMeLWqsf/ZdT1UUZz0syhioyv1mzuFZsXs4fvhw=
 golang.org/x/tools v0.1.12 h1:VveCTK38A2rkS8ZqFY25HIDFscX5X9OoEhJd3quQmXU=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=

main.go

@@ -43,6 +43,8 @@ type corazaPlugin struct {
 	types.DefaultPluginContext
 
 	waf coraza.WAF
+
+	metrics *wafMetrics
 }
 
 // Override types.DefaultPluginContext.
@@ -94,12 +96,19 @@ func (ctx *corazaPlugin) OnPluginStart(pluginConfigurationSize int) types.OnPlug
 
 	ctx.waf = waf
 
+	ctx.metrics = NewWAFMetrics()
+
 	return types.OnPluginStartStatusOK
 }
 
 // Override types.DefaultPluginContext.
 func (ctx *corazaPlugin) NewHttpContext(contextID uint32) types.HttpContext {
-	return &httpContext{contextID: contextID, tx: ctx.waf.NewTransaction(context.Background())}
+	return &httpContext{
+		contextID: contextID,
+		tx:        ctx.waf.NewTransaction(context.Background()),
+		// TODO(jcchavezs): figure out how/when enable/disable metrics
+		metrics: ctx.metrics,
+	}
 }
 
 type httpContext struct {
@@ -111,11 +120,13 @@ type httpContext struct {
 	httpProtocol          string
 	processedRequestBody  bool
 	processedResponseBody bool
+	metrics               *wafMetrics
 }
 
 // Override types.DefaultHttpContext.
 func (ctx *httpContext) OnHttpRequestHeaders(numHeaders int, endOfStream bool) types.Action {
 	defer logTime("OnHttpRequestHeaders", currentTime())
+	ctx.metrics.CountTX()
 	tx := ctx.tx
 
 	// This currently relies on Envoy's behavior of mapping all requests to HTTP/2 semantics
@@ -163,7 +174,7 @@ func (ctx *httpContext) OnHttpRequestHeaders(numHeaders int, endOfStream bool) t
 
 	interruption := tx.ProcessRequestHeaders()
 	if interruption != nil {
-		return ctx.handleInterruption(interruption)
+		return ctx.handleInterruption("http_request_headers", interruption)
 	}
 
 	return types.ActionContinue
@@ -198,7 +209,7 @@ func (ctx *httpContext) OnHttpRequestBody(bodySize int, endOfStream bool) types.
 		return types.ActionContinue
 	}
 	if interruption != nil {
-		return ctx.handleInterruption(interruption)
+		return ctx.handleInterruption("http_request_body", interruption)
 	}
 
 	return types.ActionContinue
@@ -218,7 +229,7 @@ func (ctx *httpContext) OnHttpResponseHeaders(numHeaders int, endOfStream bool)
 			return types.ActionContinue
 		}
 		if interruption != nil {
-			return ctx.handleInterruption(interruption)
+			return ctx.handleInterruption("http_response_headers", interruption)
 		}
 	}
 
@@ -244,7 +255,7 @@ func (ctx *httpContext) OnHttpResponseHeaders(numHeaders int, endOfStream bool)
 
 	interruption := tx.ProcessResponseHeaders(code, ctx.httpProtocol)
 	if interruption != nil {
-		return ctx.handleInterruption(interruption)
+		return ctx.handleInterruption("http_response_headers", interruption)
 	}
 
 	return types.ActionContinue
@@ -312,7 +323,9 @@ func (ctx *httpContext) OnHttpStreamDone() {
 	proxywasm.LogInfof("%d finished", ctx.contextID)
 }
 
-func (ctx *httpContext) handleInterruption(interruption *ctypes.Interruption) types.Action {
+func (ctx *httpContext) handleInterruption(phase string, interruption *ctypes.Interruption) types.Action {
+	ctx.metrics.CountTXInterruption(phase, interruption.RuleID)
+
 	proxywasm.LogInfof("%d interrupted, action %q", ctx.contextID, interruption.Action)
 	statusCode := interruption.Status
 	if statusCode == 0 {

main_test.go

@@ -15,6 +15,13 @@ import (
 	"github.com/tetratelabs/proxy-wasm-go-sdk/proxywasm/types"
 )
 
+func checkTXMetric(t *testing.T, host proxytest.HostEmulator, expectedCounter int) {
+	t.Helper()
+	value, err := host.GetCounterMetric("waf_filter.tx.total")
+	require.NoError(t, err)
+	require.Equal(t, uint64(expectedCounter), value)
+}
+
 func TestLifecycle(t *testing.T) {
 	reqHdrs := [][2]string{
 		{":path", "/hello"},
@@ -302,6 +309,8 @@ SecRuleEngine On\nSecResponseBodyAccess On\nSecRule RESPONSE_BODY \"@contains he
 				requestHdrsAction := host.CallOnRequestHeaders(id, reqHdrs, false)
 				require.Equal(t, tt.requestHdrsAction, requestHdrsAction)
 
+				checkTXMetric(t, host, 1)
+
 				// Stream bodies in chunks of 5
 
 				if requestHdrsAction == types.ActionContinue {

metrics.go

@@ -0,0 +1,44 @@
+// Copyright The OWASP Coraza contributors
+// SPDX-License-Identifier: Apache-2.0
+
+package main
+
+import (
+	"fmt"
+
+	"github.com/tetratelabs/proxy-wasm-go-sdk/proxywasm"
+)
+
+type wafMetrics struct {
+	counters map[string]proxywasm.MetricCounter
+}
+
+func NewWAFMetrics() *wafMetrics {
+	return &wafMetrics{
+		counters: make(map[string]proxywasm.MetricCounter),
+	}
+}
+
+func (m *wafMetrics) incrementCounter(fqn string) {
+	// TODO(jcchavezs): figure out if we are OK with dynamic creation of metrics
+	// or we generate the metrics on before hand.
+	counter, ok := m.counters[fqn]
+	if !ok {
+		counter = proxywasm.DefineCounterMetric(fqn)
+		m.counters[fqn] = counter
+	}
+	counter.Increment(1)
+}
+
+func (m *wafMetrics) CountTX() {
+	// This metric is processed as: waf_filter_tx_total
+	m.incrementCounter("waf_filter.tx.total")
+}
+
+func (m *wafMetrics) CountTXInterruption(phase string, ruleID int) {
+	// This metric is processed as: waf_filter_tx_interruption{phase="http_request_body",rule_id="100"}.
+	// The extraction rule is defined in envoy.yaml as a bootstrap configuration.
+	// See https://www.envoyproxy.io/docs/envoy/latest/api-v3/config/metrics/v3/stats.proto#config-metrics-v3-statsconfig.
+	fqn := fmt.Sprintf("waf_filter.tx.interruptions_ruleid=%d_phase=%s", ruleID, phase)
+	m.incrementCounter(fqn)
+}

timing.go

@@ -9,10 +9,12 @@ import (
 	"time"
 )
 
+var zeroTime = time.Time{}
+
 func currentTime() time.Time {
-	return time.Time{}
+	return zeroTime
 }
 
-func logTime(msg string, start time.Time) {
+func logTime(string, time.Time) {
 	// no-op without build tag
 }