fix(logging): emit the spec DEBUG logs through log/slog at debug level

.github/scripts/coverage_waivers.txt

@@ -197,93 +197,93 @@ guardcore/multipartscan.go:157
 # pipeline.go
 # Execute rebuild-error branch: rebuildIfStale has no error return path
 # (the rebuild function returns checks only), so err != nil is defensive.
-guardcore/pipeline.go:1155
 guardcore/pipeline.go:1156
+guardcore/pipeline.go:1157
 # coordinate after the identity-violation escalation shifted the Execute
 # block (same proof as above).
-guardcore/pipeline.go:1297
 guardcore/pipeline.go:1298
+guardcore/pipeline.go:1299
 # handleRebuildError body: the function is only reachable from the
 # defensive Execute branch above (the two toolchains split its blocks
 # differently).
-guardcore/pipeline.go:1233
-guardcore/pipeline.go:1236
-guardcore/pipeline.go:1242
-guardcore/pipeline.go:1246
 guardcore/pipeline.go:1234
 guardcore/pipeline.go:1237
-guardcore/pipeline.go:1239
 guardcore/pipeline.go:1243
-guardcore/pipeline.go:1245
 guardcore/pipeline.go:1247
-guardcore/pipeline.go:1249
+guardcore/pipeline.go:1235
+guardcore/pipeline.go:1238
+guardcore/pipeline.go:1240
+guardcore/pipeline.go:1244
+guardcore/pipeline.go:1246
+guardcore/pipeline.go:1248
+guardcore/pipeline.go:1250
 # handleRebuildError coordinates after the identity-violation escalation
 # and the shared counts helpers shifted the block starts (same proof).
-guardcore/pipeline.go:1376
-guardcore/pipeline.go:1379
-guardcore/pipeline.go:1381
-guardcore/pipeline.go:1385
-guardcore/pipeline.go:1387
-guardcore/pipeline.go:1389
-guardcore/pipeline.go:1391
 guardcore/pipeline.go:1377
 guardcore/pipeline.go:1380
 guardcore/pipeline.go:1382
+guardcore/pipeline.go:1386
 guardcore/pipeline.go:1388
 guardcore/pipeline.go:1390
+guardcore/pipeline.go:1392
+guardcore/pipeline.go:1378
+guardcore/pipeline.go:1381
+guardcore/pipeline.go:1383
+guardcore/pipeline.go:1389
+guardcore/pipeline.go:1391
 # handleRebuildError coordinate after the custom_response_modifier pass in
 # createErrorResponse shifted the block start (same proof).
-guardcore/pipeline.go:1392
+guardcore/pipeline.go:1393
 # handleRebuildError coordinates after the websocket detection emission
 # helper shifted the block (same proof).
-guardcore/pipeline.go:1396
-guardcore/pipeline.go:1399
-guardcore/pipeline.go:1402
-guardcore/pipeline.go:1405
-guardcore/pipeline.go:1408
-guardcore/pipeline.go:1409
-guardcore/pipeline.go:1412
-# coordinates after the country-verdict logging and the scan-budget block
-# grew the pipeline file (same proof).
-guardcore/pipeline.go:1457
-guardcore/pipeline.go:1460
-guardcore/pipeline.go:1463
-guardcore/pipeline.go:1466
-guardcore/pipeline.go:1469
-guardcore/pipeline.go:1470
-guardcore/pipeline.go:1473
-# go 1.27 splits the same statements one line lower.
 guardcore/pipeline.go:1397
 guardcore/pipeline.go:1400
-guardcore/pipeline.go:1406
+guardcore/pipeline.go:1403
+guardcore/pipeline.go:1407
 guardcore/pipeline.go:1410
+guardcore/pipeline.go:1411
+guardcore/pipeline.go:1414
+# coordinates after the country-verdict logging and the scan-budget block
+# grew the pipeline file (same proof).
+guardcore/pipeline.go:1459
+guardcore/pipeline.go:1462
+guardcore/pipeline.go:1465
+guardcore/pipeline.go:1468
+guardcore/pipeline.go:1471
+guardcore/pipeline.go:1472
+guardcore/pipeline.go:1475
+# go 1.27 splits the same statements one line lower.
+guardcore/pipeline.go:1398
+guardcore/pipeline.go:1401
+guardcore/pipeline.go:1408
+guardcore/pipeline.go:1412
 # go 1.26 splits the function one line earlier than the local toolchain
-guardcore/pipeline.go:1375
-guardcore/pipeline.go:1378
+guardcore/pipeline.go:1376
+guardcore/pipeline.go:1379
+guardcore/pipeline.go:1385
+guardcore/pipeline.go:1387
 guardcore/pipeline.go:1384
-guardcore/pipeline.go:1386
-guardcore/pipeline.go:1383
 # buildChecks nil-build fallback: every spec in the table defines build, so
 # spec.build == nil cannot hold.
-guardcore/pipeline.go:1360
 guardcore/pipeline.go:1361
+guardcore/pipeline.go:1362
 # coordinates after the escalation helpers shifted the buildChecks table
-guardcore/pipeline.go:1502
-guardcore/pipeline.go:1503
+guardcore/pipeline.go:1504
+guardcore/pipeline.go:1505
 # coordinate after the websocket detection emission helper shifted the
 # buildChecks table (same proof).
-guardcore/pipeline.go:1523
+guardcore/pipeline.go:1525
 # coordinates after the country-verdict logging and the scan-budget block
 # grew the pipeline file (same proof).
-guardcore/pipeline.go:1584
+guardcore/pipeline.go:1586
 # go 1.27 splits the same statement one line lower.
-guardcore/pipeline.go:1524
+guardcore/pipeline.go:1526
 # Execute rebuild-error return coordinate after the websocket detection
 # emission helper shifted the Execute block (same proof as the rebuild
 # entries above).
-guardcore/pipeline.go:1318
-# go 1.27 splits the same statement one line lower.
 guardcore/pipeline.go:1319
+# go 1.27 splits the same statement one line lower.
+guardcore/pipeline.go:1320
 # redis.go
 # RecordSlidingWindowHit rand guard: crypto/rand.Read cannot fail on the
 # supported platforms, so the error branch is defensive.
@@ -401,8 +401,8 @@ guardcore/composition.go:121
 guardcore/config.go:411
 # metachar-candidate guard and start<0 depth guard: short/attack chains
 # are covered by targeted tests in other runs of the same suite.
-guardcore/ipextraction.go:98
-guardcore/ipextraction.go:120
+guardcore/ipextraction.go:99
+guardcore/ipextraction.go:121
 # logfire Stop logs (never propagates) the flush failure.
 guardcore/logfire_handler.go:151
 # otlpwire.go json.Marshal of the internally-built OTLP envelope cannot

CHANGELOG.md

@@ -3,6 +3,15 @@ Release Notes
 
 ___
 
+Unreleased
+----------
+
+### Fixed
+
+- **The spec-DEBUG logs no longer print by default.** The no-rules, no-geolocation and loopback-exempt country verdicts (spec 02), the short-circuit `Request blocked by <check>` line (spec 03, still silenced per check by `muted_check_logs`) and the untrusted-proxy spoof line for private and loopback peers were written unconditionally on every request. They are now emitted with `log/slog` at debug level, matching the reference's DEBUG semantics, so they are hidden at the default level. Call `slog.SetLogLoggerLevel(slog.LevelDebug)` to see them. The blocked-by line now carries `check`, `path` and `method` as slog attributes.
+
+___
+
 v4.4.0 (2026-10-15)
 -------------------
 

guardcore/debuglog_test.go

@@ -0,0 +1,72 @@
+package guardcore
+
+import (
+	"bytes"
+	"log"
+	"log/slog"
+	"os"
+	"strings"
+	"testing"
+)
+
+type blockingStubCheck struct{}
+
+func (blockingStubCheck) CheckName() string              { return "stub_check" }
+func (blockingStubCheck) AppliesTo(*SecurityConfig) bool { return true }
+func (blockingStubCheck) EnforcedOnExcludedPaths() bool  { return false }
+func (blockingStubCheck) Check(Request) *Response {
+	return NewResponseFactory().CreateResponse("no", 403)
+}
+
+// emitDebugLines drives every spec-DEBUG emit site once.
+func emitDebugLines(t *testing.T, muted map[string]bool) {
+	t.Helper()
+	cfg := testConfig(t)
+	for _, resultType := range []string{"no_rules", "no_geolocation", "loopback_exempt"} {
+		logCountryCheckResult(cfg, resultType, "203.0.113.9", "")
+	}
+	cfg.MutedCheckLogs = muted
+	p := NewSecurityCheckPipeline([]SecurityCheck{blockingStubCheck{}}, cfg, nil)
+	if resp := p.Execute(newTestRequest(t, nil)); resp == nil {
+		t.Fatal("the stub check must block")
+	}
+	handleUntrustedProxy(cfg, newTestRequest(t, nil), "10.0.0.1", "10.0.0.1", "203.0.113.99")
+}
+
+// Spec 02-config (country verdicts) and 03-pipeline (blocked-by) mandate DEBUG:
+// hidden at the default slog level, shown after slog.SetLogLoggerLevel(Debug).
+func TestSpecDebugLogsFollowSlogLevel(t *testing.T) {
+	var buf bytes.Buffer
+	log.SetOutput(&buf)
+	prev := slog.SetLogLoggerLevel(slog.LevelInfo)
+	t.Cleanup(func() { log.SetOutput(os.Stderr); slog.SetLogLoggerLevel(prev) })
+
+	emitDebugLines(t, map[string]bool{})
+	if out := buf.String(); strings.Contains(out, "No countries blocked") || strings.Contains(out, "Request blocked by") ||
+		strings.Contains(out, "Potential IP spoof") || strings.Contains(out, "geolocat") || strings.Contains(out, "Loopback") {
+		t.Fatalf("debug lines must be hidden at the default level, got %q", out)
+	}
+
+	slog.SetLogLoggerLevel(slog.LevelDebug)
+	buf.Reset()
+	emitDebugLines(t, map[string]bool{})
+	out := buf.String()
+	for _, want := range []string{
+		"DEBUG No countries blocked or whitelisted 203.0.113.9",
+		"DEBUG IP not geolocated 203.0.113.9 - IP geolocation failed",
+		"DEBUG Loopback IP exempt from country allowlist check 203.0.113.9",
+		"DEBUG Request blocked by stub_check check=stub_check path=",
+		"method=",
+		"DEBUG Potential IP spoof attempt: X-Forwarded-For header 203.0.113.99",
+	} {
+		if !strings.Contains(out, want) {
+			t.Errorf("missing %q in %q", want, out)
+		}
+	}
+
+	buf.Reset()
+	emitDebugLines(t, map[string]bool{"stub_check": true})
+	if strings.Contains(buf.String(), "Request blocked by") {
+		t.Fatalf("muted_check_logs must still silence the blocked-by line, got %q", buf.String())
+	}
+}

guardcore/ipextraction.go

@@ -2,6 +2,7 @@ package guardcore
 
 import (
 	"log"
+	"log/slog"
 	"net/netip"
 	"strings"
 	"sync"
@@ -269,7 +270,7 @@ func handleUntrustedProxy(cfg *SecurityConfig, req Request, connectingIP, canoni
 		message := "Potential IP spoof attempt: X-Forwarded-For header " +
 			displayForwardedFor + " received from untrusted IP " + connectingIP
 		if isPrivateOrLoopback(connectingIP) {
-			log.Printf("[debug] %s", sanitizeForLog(message))
+			slog.Debug(sanitizeForLog(message))
 		} else {
 			log.Printf("[warning] %s", sanitizeForLog(message))
 		}

guardcore/pipeline.go

@@ -4,6 +4,7 @@ import (
 	"errors"
 	"fmt"
 	"log"
+	"log/slog"
 	"net/netip"
 	"sort"
 	"strings"
@@ -371,11 +372,11 @@ func globalCountryVerdict(cfg *SecurityConfig, ip string) (string, bool) {
 func logCountryCheckResult(cfg *SecurityConfig, resultType, ip, country string) {
 	switch resultType {
 	case "no_rules":
-		log.Printf("No countries blocked or whitelisted %s - No countries blocked or whitelisted", ip)
+		slog.Debug(fmt.Sprintf("No countries blocked or whitelisted %s - No countries blocked or whitelisted", ip))
 	case "no_geolocation":
-		log.Printf("IP not geolocated %s - IP geolocation failed", ip)
+		slog.Debug(fmt.Sprintf("IP not geolocated %s - IP geolocation failed", ip))
 	case "loopback_exempt":
-		log.Printf("Loopback IP exempt from country allowlist check %s", ip)
+		slog.Debug(fmt.Sprintf("Loopback IP exempt from country allowlist check %s", ip))
 	case "blocked":
 		if cfg == nil || cfg.LogSuspiciousLevel == "" {
 			return
@@ -1400,7 +1401,8 @@ func (p *SecurityCheckPipeline) Execute(req Request) *Response {
 			continue
 		}
 		if !muted[check.CheckName()] {
-			p.logger.Printf("Request blocked by %s (path=%s method=%s)", check.CheckName(), req.URLPath(), req.Method())
+			slog.Debug(fmt.Sprintf("Request blocked by %s", check.CheckName()),
+				"check", check.CheckName(), "path", req.URLPath(), "method", req.Method())
 		}
 		cfg := p.config
 		var reason, triggerInfo string