Instance name on process log lines and every metric (closes #91)

Process log lines carry instance, as request lines do; the instance name
is read before the other settings, so the line saying a setting is
invalid carries it too. Every metric, Go's and the process's included,
carries the label instance, set once on the registry. README.md says so,
and that Prometheus keeps it as exported_instance unless the scrape sets
honor_labels. An instance name that is not valid UTF-8 stops the start,
as the metrics library panics on such a label.

Tests that read metrics expect the label; one helper replaces the alert
tests' loops that wait for them.

Judgement call: the label is named instance, as in the log lines and
alerts, although Prometheus gives each target a label of that name.

Model: opus-5-5

internal/smallwebwaf/smallwebwaf.go

@@ -68,7 +68,8 @@ func Main(version string) int {
 // requests until ctx is done. It returns the process's exit status, 1
 // when smallwebwaf cannot start.
 func Run(ctx context.Context, params Params) int {
-	processLog := requestlog.NewProcessLogger(params.Stdout)
+	processLog := requestlog.NewProcessLogger(params.Stdout,
+		config.InstanceName(params.LookupEnv))
 
 	cfg, err := config.FromEnvironment(params.LookupEnv)
 	if err != nil {
@@ -86,7 +87,7 @@ func Run(ctx context.Context, params Params) int {
 	if cfg.LogRemoteURL != nil {
 		remote = newRemoteLogSender(cfg)
 		stdout = io.MultiWriter(params.Stdout, remote)
-		processLog = requestlog.NewProcessLogger(stdout)
+		processLog = requestlog.NewProcessLogger(stdout, cfg.InstanceName)
 
 		stopSending := startSending(ctx, remote, processLog)
 		defer stopSending()

internal/smallwebwaf/smallwebwaf_test.go

@@ -38,10 +38,14 @@ const (
 	stateCounterInterval = "SWWAF_STATE_COUNTER_INTERVAL"
 	rateLimitPerDay      = "SWWAF_RATE_LIMIT_PER_DAY"
 	rulesDir             = "SWWAF_RULES_DIR"
+	instanceName         = "SWWAF_INSTANCE_NAME"
 	adminToken           = "SWWAF_ADMIN_TOKEN"   //nolint:gosec // the setting's name
 	metricsToken         = "SWWAF_METRICS_TOKEN" //nolint:gosec // the setting's name
 	// adminSecret is the SWWAF_ADMIN_TOKEN the tests set.
 	adminSecret = "fedcba9876543210fedcba9876543210"
+	// instance is the SWWAF_INSTANCE_NAME the tests set where they look at
+	// it.
+	instance = "fsn1app1/gitea"
 	// greeting is what the tests' app answers.
 	greeting = "hello from the app"
 )
@@ -118,7 +122,10 @@ func TestInvalidSettingStopsTheStart(t *testing.T) {
 
 	out := &output{}
 
-	status := run(t.Context(), map[string]string{"SWWAF_REQUEST_MAX_BYTES": "lots"}, out)
+	status := run(t.Context(), map[string]string{
+		"SWWAF_REQUEST_MAX_BYTES": "lots",
+		instanceName:              instance,
+	}, out)
 	if status != 1 {
 		t.Errorf("exit status %d, want 1", status)
 	}
@@ -126,7 +133,8 @@ func TestInvalidSettingStopsTheStart(t *testing.T) {
 	line := out.line(t, "msg", "invalid setting")
 	message, _ := line["error"].(string)
 
-	if line["type"] != "process" || line["level"] != "ERROR" ||
+	if line["type"] != "process" || line["instance"] != instance ||
+		line["level"] != "ERROR" ||
 		!strings.HasPrefix(message, "SWWAF_REQUEST_MAX_BYTES: ") {
 		t.Errorf("start refused with %v", line)
 	}
@@ -231,6 +239,46 @@ func TestServesUntilToldToStop(t *testing.T) {
 	out.line(t, "msg", "stopped")
 }
 
+func TestEveryLogLineAndMetricCarriesTheInstanceName(t *testing.T) {
+	t.Parallel()
+
+	const token = "0123456789abcdef0123456789abcdef"
+
+	env := map[string]string{
+		listenAddr:   localhost + ":0",
+		upstreamURL:  startApp(t),
+		stateDir:     t.TempDir(),
+		rulesDir:     t.TempDir(),
+		metricsToken: token,
+		instanceName: instance,
+	}
+
+	var metrics string
+
+	out := runUntilStopped(t, env, func(url string) {
+		metrics = metricsText(t, url+"_smallwebwaf/metrics", token)
+	})
+
+	// The process's lines from its start to its stop, and the request's.
+	for line := range strings.Lines(out.text()) {
+		var fields map[string]any
+
+		err := json.Unmarshal([]byte(line), &fields)
+		if err != nil || fields["instance"] != instance {
+			t.Errorf("line %q (%v), want instance %s", line, err, instance)
+		}
+	}
+
+	// Each series, Go's and the process's included; the other lines are
+	// the comments.
+	for line := range strings.Lines(metrics) {
+		if !strings.HasPrefix(line, "#") &&
+			!strings.Contains(line, `instance="fsn1app1/gitea"`) {
+			t.Errorf("series %q, without instance=\"fsn1app1/gitea\"", line)
+		}
+	}
+}
+
 func TestStateKeptAcrossRestarts(t *testing.T) {
 	t.Parallel()
 
@@ -519,6 +567,7 @@ func TestStalledRemoteLogEndpointHoldsUpNoRequest(t *testing.T) {
 		"SWWAF_LOG_REMOTE_URL":    "syslog+tls://" + endpoint.Addr().String(),
 		"SWWAF_LOG_REMOTE_BUFFER": "1",
 		metricsToken:              token,
+		instanceName:              instance,
 	}
 
 	out := runUntilStopped(t, env, func(url string) {
@@ -528,16 +577,17 @@ func TestStalledRemoteLogEndpointHoldsUpNoRequest(t *testing.T) {
 		// last.
 		metrics := metricsText(t, url+"_smallwebwaf/metrics", token)
 		for _, series := range []string{
-			"smallwebwaf_remote_log_lines_sent_total 0",
-			"smallwebwaf_remote_log_buffer_depth 1",
+			`smallwebwaf_remote_log_lines_sent_total{instance="fsn1app1/gitea"} 0`,
+			`smallwebwaf_remote_log_buffer_depth{instance="fsn1app1/gitea"} 1`,
 		} {
 			if !strings.Contains(metrics, "\n"+series+"\n") {
 				t.Errorf("no %q in the metrics:\n%s", series, metrics)
 			}
 		}
 
-		if strings.Contains(metrics, "\nsmallwebwaf_remote_log_lines_dropped_total 0\n") ||
-			!strings.Contains(metrics, "\nsmallwebwaf_remote_log_lines_dropped_total ") {
+		const dropped = "\nsmallwebwaf_remote_log_lines_dropped_total" +
+			`{instance="fsn1app1/gitea"} `
+		if strings.Contains(metrics, dropped+"0\n") || !strings.Contains(metrics, dropped) {
 			t.Errorf("no line dropped in the metrics:\n%s", metrics)
 		}
 
@@ -547,6 +597,13 @@ func TestStalledRemoteLogEndpointHoldsUpNoRequest(t *testing.T) {
 	})
 
 	out.line(t, "type", "request")
+
+	// While the lines are sent, the process's lines give the instance name
+	// too.
+	line := out.line(t, "msg", "starting")
+	if line["instance"] != instance {
+		t.Errorf("start logged with instance %v, want %s", line["instance"], instance)
+	}
 }
 
 func TestBanIsAlertedAndAnAlertNotSentIsKeptAcrossARestart(t *testing.T) {
@@ -569,6 +626,7 @@ func TestBanIsAlertedAndAnAlertNotSentIsKeptAcrossARestart(t *testing.T) {
 		rulesDir:                      rules,
 		"SWWAF_ALERT_WEBHOOK_URL":     webhook.url,
 		"SWWAF_ALERT_WEBHOOK_HEADERS": "Authorization:Bearer " + adminSecret,
+		instanceName:                  instance,
 	}
 
 	runUntilStopped(t, env, func(url string) {
@@ -622,19 +680,13 @@ func TestBanIsAlertedAndAnAlertNotSentIsKeptAcrossARestart(t *testing.T) {
 	runUntilStopped(t, env, func(url string) {
 		webhook.waitFor(t, "permanent_ban", true)
 
-		// As long as that takes, so that a slow test process cannot fail
-		// the test.
-		const sent = "\nsmallwebwaf_alerts_sent_total{destination=\"webhook\"} 1\n"
+		const ofWebhook = `{destination="webhook",instance="fsn1app1/gitea"}`
 
-		metrics := metricsText(t, url+"_smallwebwaf/metrics", token)
-		for !strings.Contains(metrics, sent) {
-			time.Sleep(pollInterval)
-
-			metrics = metricsText(t, url+"_smallwebwaf/metrics", token)
-		}
+		metrics := metricsWith(t, url+"_smallwebwaf/metrics", token,
+			"\nsmallwebwaf_alerts_sent_total"+ofWebhook+" 1\n")
 
 		for _, series := range []string{"failed", "suppressed", "dropped"} {
-			zero := "\nsmallwebwaf_alerts_" + series + "_total{destination=\"webhook\"} 0\n"
+			zero := "\nsmallwebwaf_alerts_" + series + "_total" + ofWebhook + " 0\n"
 			if !strings.Contains(metrics, zero) {
 				t.Errorf("no %q in the metrics:\n%s", zero, metrics)
 			}
@@ -662,7 +714,7 @@ func TestBanIsAlertedToSlackAndNtfy(t *testing.T) {
 		// The metrics are read from 127.0.0.1, which no limit counts.
 		"SWWAF_ALLOW_NETS":              localhost + "/32",
 		metricsToken:                    token,
-		"SWWAF_INSTANCE_NAME":           "fsn1app1/gitea",
+		instanceName:                    instance,
 		"SWWAF_ALERT_SLACK_WEBHOOK_URL": slack.url,
 		"SWWAF_ALERT_NTFY_URL":          ntfy.url,
 		"SWWAF_ALERT_NTFY_TOKEN":        ntfyToken,
@@ -698,17 +750,13 @@ func TestBanIsAlertedToSlackAndNtfy(t *testing.T) {
 		// webhook, which is not set. As long as that takes, so that a slow
 		// test process cannot fail the test.
 		sent := []string{
-			"\nsmallwebwaf_alerts_sent_total{destination=\"slack\"} 1\n",
-			"\nsmallwebwaf_alerts_sent_total{destination=\"ntfy\"} 1\n",
-		}
-
-		metrics := metricsText(t, url+"_smallwebwaf/metrics", token)
-		for !strings.Contains(metrics, sent[0]) || !strings.Contains(metrics, sent[1]) {
-			time.Sleep(pollInterval)
-
-			metrics = metricsText(t, url+"_smallwebwaf/metrics", token)
+			"\nsmallwebwaf_alerts_sent_total{destination=\"slack\"," +
+				"instance=\"fsn1app1/gitea\"} 1\n",
+			"\nsmallwebwaf_alerts_sent_total{destination=\"ntfy\"," +
+				"instance=\"fsn1app1/gitea\"} 1\n",
 		}
 
+		metrics := metricsWith(t, url+"_smallwebwaf/metrics", token, sent...)
 		if strings.Contains(metrics, `destination="webhook"`) {
 			t.Errorf("the metrics give the webhook:\n%s", metrics)
 		}
@@ -974,6 +1022,26 @@ func metricsText(t *testing.T, url, token string) string {
 	return string(body)
 }
 
+// metricsWith asks for the metrics at url with token until they hold each
+// of series, as long as that takes, so that a slow test process cannot
+// fail the test, and returns them.
+func metricsWith(t *testing.T, url, token string, series ...string) string {
+	t.Helper()
+
+	for {
+		metrics := metricsText(t, url, token)
+
+		missing := slices.ContainsFunc(series, func(one string) bool {
+			return !strings.Contains(metrics, one)
+		})
+		if !missing {
+			return metrics
+		}
+
+		time.Sleep(pollInterval)
+	}
+}
+
 // askAsAdmin sends a request with method to url, with body and
 // adminSecret, and checks that it is answered 200.
 func askAsAdmin(t *testing.T, method, url, body string) {