backend: oidc-callback: Stop logging unrelated outer-scope error on missing state#5724
Conversation
495ea88 to
2ada63a
Compare
There was a problem hiding this comment.
Pull request overview
Fixes misleading /oidc-callback logging by ensuring the “missing state” branch does not log a captured outer-scope kubeconfig-load error, and adds a regression test to prevent reintroduction.
Changes:
- Update
/oidc-callbackmissing-state logging to passnilerror (avoids outer-scopeerrcapture) and document the scoping pitfall. - Add a regression test that hooks
logger.SetLogFuncand asserts the missing-state log entry carries anilerror.
CI/check status and PR commit history (e.g., merge commits) aren’t available in this review context—please confirm CI is green and the PR history is linear.
Reviewed changes
Copilot reviewed 2 out of 2 changed files in this pull request and generated 1 comment.
| File | Description |
|---|---|
| backend/cmd/headlamp.go | Fixes the missing-state log call to avoid logging an unrelated outer-scope error; adds an explanatory comment. |
| backend/cmd/headlamp_test.go | Adds regression test capturing logger calls to ensure no stale error is logged on empty state. |
Comments suppressed due to low confidence (3)
backend/cmd/headlamp_test.go:1448
- In this test, calling createHeadlampHandler(context.Background(), cfg) with an empty PluginDir triggers the background plugin watcher paths in createHeadlampHandler (because !UseInCluster), and plugins.Watch treats an empty watchPath as the current directory, which can walk/watch a large tree and consume many fsnotify resources during tests. Consider setting PluginDir to t.TempDir() (and optionally UserPluginDir/StaticPluginDir) and using a cancellable context (context.WithCancel + t.Cleanup(cancel)) so the watcher goroutines are stopped at the end of the test.
cfg := &HeadlampConfig{
HeadlampConfig: &headlampconfig.HeadlampConfig{
HeadlampCFG: &headlampconfig.HeadlampCFG{
UseInCluster: false,
KubeConfigPath: "/tmp/" + staleErrMarker,
KubeConfigStore: kubeconfig.NewContextStore(),
},
Cache: cache.New[interface{}](),
TelemetryConfig: GetDefaultTestTelemetryConfig(),
TelemetryHandler: &telemetry.RequestHandler{},
},
}
backend/cmd/headlamp_test.go:1463
- logMu is locked and held via defer until the end of the test. Since the logger hook acquires the same mutex on every log call, any background goroutine that logs after this point will block until the test returns, which can create unnecessary contention or even hangs in the presence of cleanup that logs. Prefer copying logCalls under the mutex and unlocking immediately before searching/asserting.
logMu.Lock()
defer logMu.Unlock()
backend/cmd/headlamp_test.go:1417
- Using a hard-coded "/tmp/" + marker for KubeConfigPath can collide if that path happens to exist on the test machine (making the startup kubeconfig load succeed and weakening the regression). Consider using filepath.Join(t.TempDir(), "missing") (or similar) to guarantee a non-existent kubeconfig path.
// Bad path so the startup kubeconfig load returns a distinctive err.
staleErrMarker := "no-such-kubeconfig-for-issue-4839"
…issing state
The /oidc-callback handler logged a stray err variable when the state
query parameter was missing:
logger.Log(logger.LevelError, nil, err, "invalid request state is empty")
That err was not declared inside the handler closure. It resolved to
the err returned by the kubeconfig load that runs once when
createHeadlampHandler is constructed at server startup. Every malformed
callback request therefore surfaced whatever happened at boot, for
example
error loading kubeconfig files: error reading kubeconfig file:
open /home/headlamp/.config/Headlamp/kubeconfigs/config: no such
file or directory
attached to an unrelated 400 response, making the log misleading and
hard to interpret.
Pass nil to logger.Log on this branch and leave a short comment so the
next reader does not reintroduce the capture. Add a regression test
that drives the handler with a deliberately broken KubeConfigPath,
fires GET /oidc-callback with no state, captures logger output via
logger.SetLogFunc, and asserts the missing-state log carries no error
value.
Issue: kubernetes-sigs#4839
Signed-off-by: Govind Pandey <govindup63@gmail.com>
2ada63a to
b296550
Compare
illume
left a comment
There was a problem hiding this comment.
Thanks for working on this.
Would you mind addressing the open Copilot review comments? Please mark each comment as resolved after addressing it.
|
Thanks @illume, marked them as resolved. |
The regression test added in the previous commit tripped two lint rules
in CI:
- funlen: the test body is 67 lines, over the 60-line cap. Other tests
in the same file already use //nolint:funlen for the same reason
(see TestHelmRouteReleaseHandlerTokenExtraction). Apply the same
directive.
- wsl_v5: missing blank line around the captured := append(...) line
that copies logCalls out from under the mutex.
Signed-off-by: Govind Pandey <govindup63@gmail.com>
|
golangci-lint was failing on the new test (funlen + wsl_v5). Pushed a fix in |
createHeadlampHandler unconditionally reassigns config.StaticPluginDir from the HEADLAMP_STATIC_PLUGINS_DIR environment variable, so the test setting cfg.HeadlampCFG.StaticPluginDir = scratch was a no-op and the plugin watcher could end up walking whatever directory the env var named in CI. Set the env var via t.Setenv so the static-plugin dir is deterministic for the duration of the test, and drop the dead field assignment. Signed-off-by: Govind Pandey <govindup63@gmail.com>
|
Thanks @copilot, addressed in |
…eclaration A comment was load-bearing in the previous commit: it warned future editors that the early-branch logger.Log must not reference err, because err would resolve to createHeadlampHandler's outer-scope kubeconfig-load result. Hoist `var err error` to the top of the /oidc-callback closure so the shadow is enforced by the language, not by a comment. Any future log call inside the handler now references the closure-local err that begins life as nil. Signed-off-by: Govind Pandey <govindup63@gmail.com>
|
Thanks @copilot, applied in |
…ogger.Log The shadow declaration on the previous commit reliably leaves err nil at the missing-state branch, so logger.Log was being passed nil indirectly. Pass nil directly to make the call self-evident; the shadow declaration above still protects against future log calls elsewhere in the closure. Signed-off-by: Govind Pandey <govindup63@gmail.com>
|
Right, fixed in |
|
[APPROVALNOTIFIER] This PR is APPROVED This pull-request has been approved by: govindup63, illume The full list of commands accepted by this bot can be found here. The pull request process is described here DetailsNeeds approval from an approver in each of these files:
Approvers can indicate their approval by writing |
| originalLogFunc := logger.SetLogFunc(func(level uint, _ map[string]string, err interface{}, msg string) { | ||
| logMu.Lock() | ||
| defer logMu.Unlock() | ||
|
|
||
| logCalls = append(logCalls, logCall{level: level, msg: msg, err: err}) | ||
| }) | ||
| defer logger.SetLogFunc(originalLogFunc) |
Summary
The
/oidc-callbackhandler inbackend/cmd/headlamp.gologged a strayerrvariable when the OIDCstatequery parameter was missing. The variable was not declared in the handler closure: it resolved to the outer-scopeerrreturned by the kubeconfig load that runs once at server startup insidecreateHeadlampHandler.The practical effect is that every malformed callback request surfaced whatever happened at boot, attached to an unrelated 400 response. For example, a typical in-cluster pod without a local kubeconfig logs this on every empty-state callback:
That is the exact misleading line reported in the issue.
Related Issue
Fixes #4839
Changes
backend/cmd/headlamp.go: passniltologger.Logon the missing-state branch (instead of the captured outer-scopeerr). Added a short comment explaining the scoping trap so the capture is not reintroduced.backend/cmd/headlamp_test.go: new regression testTestOidcCallbackEmptyStateDoesNotLogStaleError. Hooks the logger vialogger.SetLogFunc, runscreateHeadlampHandlerwith a deliberately brokenKubeConfigPathso the kubeconfig load returns a known error into the captured outer-scopeerr, firesGET /oidc-callbackwith nostate, then asserts:400 Bad Request(unchanged behavior).invalid request state is emptycarries anilerror value (not the stale kubeconfig load error).Steps to Test
cd backend && go test ./cmd/ -run TestOidcCallbackEmptyStateDoesNotLogStaleError -v. Passes.headlamp.go(keeping the test) reproduces the bug: the test fails withExpected nil, but got: &errors.errorString{s:"error loading kubeconfig files: error reading kubeconfig file: open .../kubeconfigs/config: no such file or directory"}. That is exactly the misleading log the reporter described.cd backend && go test ./cmd/... -race. All existingcmd/tests still pass.cd backend && go build ./... && go vet ./cmd/.... Clean.Notes for the Reviewer
400 Bad Requeston missingstate) is unchanged. Only the log line argument changes.logger.Log(... , nil, err, ...)when the oauth2 token has no expected token field). At that point the closure's localerris alwaysnil, so the call is misleading-but-harmless rather than a real outer-scope leak. I left it untouched to keep this PR scoped to the issue. Happy to clean it up in a follow-up.logger.SetLogFunc, which the logger package already exposes for tests (seebackend/pkg/logger/logger_test.go). No new test helpers were added.