From ac72f73d3fcb3d7d58fc2ebfc52e82daf7f15491 Mon Sep 17 00:00:00 2001
From: Patrick Ohly <patrick.ohly@intel.com>
Date: Mon, 1 Dec 2025 17:14:33 +0100
Subject: [PATCH] ktesting: fix vmodule support

Stack unwinding to determine the caller must consider the number of call levels
to skip over in logr itself. This only affected the `Enabled` check and thus
usage of the vmodule parameter, the actual caller then gets printed by
testing.T.

This also leads to a small inconsistency: the enabled check is unaware of the
testing.T.Helper calls and can only check the direct caller, without skipping
helpers, while the actual log output then skips the helper. There's no good fix
for this, testing.T would need an API for delegating the stack unwinding to the
caller (would also be useful to log a PC supplied via slog...).
---
 ktesting/helper_test.go        | 17 +++++++++++++++++
 ktesting/main_test.go          | 19 +++++++++++++++++++
 ktesting/testinglogger.go      |  2 +-
 ktesting/testinglogger_test.go | 33 +++++++++++++++++++++++++++++++--
 4 files changed, 68 insertions(+), 3 deletions(-)
 create mode 100644 ktesting/helper_test.go
 create mode 100644 ktesting/main_test.go

diff --git a/ktesting/helper_test.go b/ktesting/helper_test.go
new file mode 100644
index 00000000..e011861c
--- /dev/null
+++ b/ktesting/helper_test.go
@@ -0,0 +1,17 @@
+/*
+Copyright 2025 The Kubernetes Authors.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package ktesting_test
+
+import (
+	"k8s.io/klog/v2"
+)
+
+func callDepthHelper(logger klog.Logger, msg string) {
+	helper, logger := logger.WithCallStackHelper()
+	helper()
+	logger.Info(msg)
+}
diff --git a/ktesting/main_test.go b/ktesting/main_test.go
new file mode 100644
index 00000000..0f523f47
--- /dev/null
+++ b/ktesting/main_test.go
@@ -0,0 +1,19 @@
+/*
+Copyright 2025 The Kubernetes Authors.
+
+SPDX-License-Identifier: Apache-2.0
+*/
+
+package ktesting_test
+
+import (
+	"flag"
+	"testing"
+
+	_ "k8s.io/klog/v2/ktesting/init"
+)
+
+func TestMain(m *testing.M) {
+	flag.Parse()
+	m.Run()
+}
diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go
index 31569357..e8ffd411 100644
--- a/ktesting/testinglogger.go
+++ b/ktesting/testinglogger.go
@@ -307,7 +307,7 @@ func (l tlogger) Info(level int, msg string, kvList ...interface{}) {
 }
 
 func (l tlogger) Enabled(level int) bool {
-	return l.shared.config.vstate.Enabled(verbosity.Level(level), 1)
+	return l.shared.config.vstate.Enabled(verbosity.Level(level), l.shared.callDepth+1)
 }
 
 func (l tlogger) Error(err error, msg string, kvList ...interface{}) {
diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go
index fc22e62b..d35401d1 100644
--- a/ktesting/testinglogger_test.go
+++ b/ktesting/testinglogger_test.go
@@ -12,8 +12,10 @@ import (
 	"errors"
 	"flag"
 	"fmt"
+	"os/exec"
 	"regexp"
 	"runtime"
+	"strings"
 	"sync"
 	"testing"
 	"time"
@@ -136,9 +138,36 @@ func TestInfo(t *testing.T) {
 	}
 }
 
-func TestCallDepth(t *testing.T) {
-	logger := ktesting.NewLogger(t, ktesting.NewConfig())
+// TestCallDepthOutput produces output which gets checked by TestCallDepthVerify.
+func TestCallDepthOutput(t *testing.T) {
+	logger := ktesting.NewLogger(t, ktesting.DefaultConfig)
 	logger.Info("hello world")
+	logger.V(1).Info("you shouldn't see this with -testing.v=0")
+	callDepthHelper(logger.V(1), "you should see this with -testing.v=0 -testing.vmodule=helper_test=1")
+}
+
+// TestCallDepthVerify runs TestCallDepth with appropriate flags and checks the output.
+//
+// Invoking `go test` is necessary because we want to verify that it correctly unwinds the stack,
+// which means that we have to let it print output. We cannot intercept that log output from
+// within a test.
+func TestCallDepthVerify(t *testing.T) {
+	cmd, args := "go", "test -v -run=TestCallDepthOutput k8s.io/klog/v2/ktesting -args -testing.v=0 -testing.vmodule=helper_test=1"
+	output, err := exec.Command("go", strings.Split(args, " ")...).CombinedOutput()
+	if err != nil {
+		t.Fatalf("failed to %s %s: %v", cmd, args, err)
+	}
+	t.Log("Got output:\n", string(output))
+
+	expect := `(?m)^[[:space:]]*testinglogger_test.go:.*hello world$
+^[[:space:]]*testinglogger_test.go:.*you should see this`
+	matched, err := regexp.MatchString(expect, string(output))
+	if err != nil {
+		t.Fatalf("failed to parse regexp: %v\n\n%s", err, expect)
+	}
+	if !matched {
+		t.Fatalf("expected output\n%s\n\nto match regexp\n%s", string(output), expect)
+	}
 }
 
 type logToBuf struct {