From 521c91707e396deff8c79ebd4a96c7a188f0412b Mon Sep 17 00:00:00 2001 From: Renn F Date: Fri, 16 Oct 2026 12:02:01 +0200 Subject: [PATCH] fix(logging): emit the spec DEBUG logs through log/slog at debug level --- .github/scripts/coverage_waivers.txt | 98 ++++++++++++++-------------- CHANGELOG.md | 9 +++ guardcore/debuglog_test.go | 72 ++++++++++++++++++++ guardcore/ipextraction.go | 3 +- guardcore/pipeline.go | 10 +-- 5 files changed, 138 insertions(+), 54 deletions(-) create mode 100644 guardcore/debuglog_test.go diff --git a/.github/scripts/coverage_waivers.txt b/.github/scripts/coverage_waivers.txt index 1aa7c11..cf96f2d 100644 --- a/.github/scripts/coverage_waivers.txt +++ b/.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 diff --git a/CHANGELOG.md b/CHANGELOG.md index 48e296f..3c54eaf 100644 --- a/CHANGELOG.md +++ b/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 ` 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) ------------------- diff --git a/guardcore/debuglog_test.go b/guardcore/debuglog_test.go new file mode 100644 index 0000000..06815a6 --- /dev/null +++ b/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()) + } +} diff --git a/guardcore/ipextraction.go b/guardcore/ipextraction.go index e23bb08..f6c776a 100644 --- a/guardcore/ipextraction.go +++ b/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)) } diff --git a/guardcore/pipeline.go b/guardcore/pipeline.go index 74c1f71..cc83e1c 100644 --- a/guardcore/pipeline.go +++ b/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