From a710dc8651f885243edbb898d07d44d6998623cf Mon Sep 17 00:00:00 2001 From: SAY-5 Date: Tue, 5 May 2026 06:24:15 -0700 Subject: [PATCH] client: report caller line for OpenStack debug logs The Logger.Printf wrapper used a hard-coded stack-frame window [10..20] and matched only /github.com/gophercloud/gophercloud, which fails to span gophercloud/utils where the RoundTripper now lives. With modern net/http the real caller is outside that window, so klog falls back to the wrapper's own line and every debug entry is shown as client.go:128. Walk the full stack and pick the frame above the deepest gophercloud frame (matching both gophercloud/gophercloud and gophercloud/utils) so klog attributes the log to the originating call site. Fixes #2300 Signed-off-by: SAY-5 --- pkg/client/client.go | 24 +++++----- pkg/client/client_test.go | 96 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 107 insertions(+), 13 deletions(-) create mode 100644 pkg/client/client_test.go diff --git a/pkg/client/client.go b/pkg/client/client.go index 153cf16e0e..9fea9c2fc7 100644 --- a/pkg/client/client.go +++ b/pkg/client/client.go @@ -106,22 +106,20 @@ func (l Logger) Printf(format string, args ...interface{}) { // extra check in case, when verbosity has been changed dynamically if debugger { + // Walk the stack and find the deepest gophercloud frame (matches both + // gophercloud/gophercloud and gophercloud/utils, where the + // RoundTripper lives). The frame above it is the actual caller that + // triggered the API request, which is what we want klog to report. + const gc = "/github.com/gophercloud/" var skip int - var found bool - var gc = "/github.com/gophercloud/gophercloud" - - // detect the depth of the actual function, which calls gophercloud code - // 10 is the common depth from the logger to "github.com/gophercloud/gophercloud/v2" - for i := 10; i <= 20; i++ { - if _, file, _, ok := runtime.Caller(i); ok && !found && strings.Contains(file, gc) { - found = true - continue - } else if ok && found && !strings.Contains(file, gc) { - skip = i - break - } else if !ok { + for i := 1; ; i++ { + _, file, _, ok := runtime.Caller(i) + if !ok { break } + if strings.Contains(file, gc) { + skip = i + 1 + } } for _, v := range strings.Split(fmt.Sprintf(format, args...), "\n") { diff --git a/pkg/client/client_test.go b/pkg/client/client_test.go new file mode 100644 index 0000000000..0ef58eadcf --- /dev/null +++ b/pkg/client/client_test.go @@ -0,0 +1,96 @@ +/* +Copyright 2026 The Kubernetes Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package client + +import ( + "bytes" + "context" + "flag" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/gophercloud/gophercloud/v2" + "github.com/gophercloud/gophercloud/v2/openstack" + "github.com/gophercloud/utils/v2/client" + "k8s.io/klog/v2" +) + +// TestLoggerReportsCallerLine verifies that debug log lines emitted through +// the Logger wrapper are attributed to the caller that initiated the +// gophercloud request, not to the wrapper file itself (issue #2300). +func TestLoggerReportsCallerLine(t *testing.T) { + state := klog.CaptureState() + defer state.Restore() + + var fs flag.FlagSet + klog.InitFlags(&fs) + if err := fs.Set("v", "6"); err != nil { + t.Fatalf("failed to set verbosity: %v", err) + } + if err := fs.Set("logtostderr", "false"); err != nil { + t.Fatalf("failed to set logtostderr: %v", err) + } + if err := fs.Set("skip_headers", "false"); err != nil { + t.Fatalf("failed to set skip_headers: %v", err) + } + + var buf bytes.Buffer + klog.SetOutput(&buf) + + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte(`{}`)) + })) + defer srv.Close() + + provider, err := openstack.NewClient(srv.URL) + if err != nil { + t.Fatalf("failed to build provider: %v", err) + } + provider.HTTPClient = http.Client{ + Transport: &client.RoundTripper{ + Rt: http.DefaultTransport, + Logger: &Logger{}, + }, + } + + if _, err := provider.Request(context.Background(), http.MethodGet, srv.URL, &gophercloud.RequestOpts{ + KeepResponseBody: true, + OkCodes: []int{http.StatusOK}, + }); err != nil { + t.Fatalf("request failed: %v", err) + } + + klog.Flush() + + output := buf.String() + if output == "" { + t.Fatalf("expected klog output, got none") + } + // The wrapper's own file must not appear as the source location, since + // that would mean every debug line is mis-attributed to client.go (the + // behavior reported in issue #2300). + if strings.Contains(output, "client.go:") && !strings.Contains(output, "client_test.go:") { + t.Fatalf("debug output is attributed to the wrapper, expected the caller; got:\n%s", output) + } + if !strings.Contains(output, "client_test.go:") { + t.Fatalf("expected debug output to reference the test caller (client_test.go); got:\n%s", output) + } +}