-
Notifications
You must be signed in to change notification settings - Fork 41.1k
client-go auth: contextual logging #129336
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: master
Are you sure you want to change the base?
Conversation
//nolint:logcheck // This looks like debug output which shouldn't occur in practice. | ||
klog.V(2).InfoS("unexpected exec plugin return error type", "type", reflect.TypeOf(err).String(), "err", err) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Shouldn't we update this instead of ignoring?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
We can update to structured logging, but doing contextual logging didn't seem worth the chain of API changes.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Wait, it is already using structured logging. The suppression is for the "contextual logging" aspect.
I can rewrite as klog.Background().V(2).Info
instead of suppressing the linter, but proper conversion (= avoiding the global logger) probably isn't worth it.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I had another look at how this code here could get connected to a context of its caller. I got as far as this, which is incomplete:
diff --git a/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/exec.go b/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/exec.go
index 652e59a2db4..f1441d82f49 100644
--- a/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/exec.go
+++ b/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/exec.go
@@ -18,6 +18,7 @@ package exec
import (
"bytes"
+ "context"
"crypto/tls"
"crypto/x509"
"errors"
@@ -206,7 +207,10 @@ func newAuthenticator(c *cache, isTerminalFunc func(int) bool, config *api.ExecC
// these functions are made comparable and stored in the cache so that repeated clientset
// construction with the same rest.Config results in a single TLS cache and Authenticator
- a.getCert = &transport.GetCertHolder{GetCert: a.cert}
+ a.getCert = &transport.GetCertHolder{GetCert: func() (*tls.Certificate, error) {
+ // TODO (?): change or extend the c.TLS.GetCertHolder API
+ return a.cert(context.TODO())
+ }}
a.dial = &transport.DialHolder{Dial: defaultDialer.DialContext}
return c.put(key, a), nil
@@ -343,7 +347,7 @@ func (r *roundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
}
ctx := req.Context()
- creds, err := r.a.getCreds()
+ creds, err := r.a.getCreds(ctx)
if err != nil {
return nil, fmt.Errorf("getting credentials: %v", err)
}
@@ -356,7 +360,7 @@ func (r *roundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
return nil, err
}
if res.StatusCode == http.StatusUnauthorized {
- if err := r.a.maybeRefreshCreds(creds); err != nil {
+ if err := r.a.maybeRefreshCreds(ctx, creds); err != nil {
klog.FromContext(ctx).Error(err, "Refreshing credentials failed")
}
}
@@ -370,15 +374,15 @@ func (a *Authenticator) credsExpired() bool {
return a.now().After(a.exp)
}
-func (a *Authenticator) cert() (*tls.Certificate, error) {
- creds, err := a.getCreds()
+func (a *Authenticator) cert(ctx context.Context) (*tls.Certificate, error) {
+ creds, err := a.getCreds(ctx)
if err != nil {
return nil, err
}
return creds.cert, nil
}
-func (a *Authenticator) getCreds() (*credentials, error) {
+func (a *Authenticator) getCreds(ctx context.Context) (*credentials, error) {
a.mu.Lock()
defer a.mu.Unlock()
@@ -386,7 +390,7 @@ func (a *Authenticator) getCreds() (*credentials, error) {
return a.cachedCreds, nil
}
- if err := a.refreshCredsLocked(); err != nil {
+ if err := a.refreshCredsLocked(ctx); err != nil {
return nil, err
}
@@ -395,7 +399,7 @@ func (a *Authenticator) getCreds() (*credentials, error) {
// maybeRefreshCreds executes the plugin to force a rotation of the
// credentials, unless they were rotated already.
-func (a *Authenticator) maybeRefreshCreds(creds *credentials) error {
+func (a *Authenticator) maybeRefreshCreds(ctx context.Context, creds *credentials) error {
a.mu.Lock()
defer a.mu.Unlock()
@@ -406,12 +410,12 @@ func (a *Authenticator) maybeRefreshCreds(creds *credentials) error {
return nil
}
- return a.refreshCredsLocked()
+ return a.refreshCredsLocked(ctx)
}
// refreshCredsLocked executes the plugin and reads the credentials from
// stdout. It must be called while holding the Authenticator's mutex.
-func (a *Authenticator) refreshCredsLocked() error {
+func (a *Authenticator) refreshCredsLocked(ctx context.Context) error {
interactive, err := a.interactiveFunc()
if err != nil {
return fmt.Errorf("exec plugin cannot support interactive mode: %w", err)
@@ -443,7 +447,7 @@ func (a *Authenticator) refreshCredsLocked() error {
}
err = cmd.Run()
- incrementCallsMetric(err)
+ incrementCallsMetric(ctx, err)
if err != nil {
return a.wrapCmdRunErrorLocked(err)
}
diff --git a/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/exec_test.go b/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/exec_test.go
index 291590eca86..606037b9496 100644
--- a/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/exec_test.go
+++ b/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/exec_test.go
@@ -42,6 +42,7 @@ import (
"k8s.io/client-go/pkg/apis/clientauthentication"
"k8s.io/client-go/tools/clientcmd/api"
"k8s.io/client-go/transport"
+ "k8s.io/klog/v2/ktesting"
testingclock "k8s.io/utils/clock/testing"
)
@@ -790,6 +791,7 @@ func TestRefreshCreds(t *testing.T) {
for _, test := range tests {
t.Run(test.name, func(t *testing.T) {
+ _, ctx := ktesting.NewTestContext(t)
c := test.config
if c.Command == "" {
@@ -813,7 +815,7 @@ func TestRefreshCreds(t *testing.T) {
a.stderr = stderr
a.environ = func() []string { return nil }
- if err := a.refreshCredsLocked(); err != nil {
+ if err := a.refreshCredsLocked(ctx); err != nil {
if !test.wantErr {
t.Errorf("get token %v", err)
} else if !strings.Contains(err.Error(), test.wantErrSubstr) {
@@ -1190,6 +1192,7 @@ func TestInstallHintRateLimit(t *testing.T) {
for _, test := range tests {
t.Run(test.name, func(t *testing.T) {
+ _, ctx := ktesting.NewTestContext(t)
c := api.ExecConfig{
Command: "does not exist",
APIVersion: "client.authentication.k8s.io/v1beta1",
@@ -1209,7 +1212,7 @@ func TestInstallHintRateLimit(t *testing.T) {
count := 0
for i := 0; i < test.calls; i++ {
- err := a.refreshCredsLocked()
+ err := a.refreshCredsLocked(ctx)
if strings.Contains(err.Error(), c.InstallHint) {
count++
}
diff --git a/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/metrics.go b/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/metrics.go
index d25122f360a..cad7750b098 100644
--- a/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/metrics.go
+++ b/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/metrics.go
@@ -17,6 +17,7 @@ limitations under the License.
package exec
import (
+ "context"
"errors"
"io/fs"
"os/exec"
@@ -90,7 +91,7 @@ func (c *certificateExpirationTracker) set(a *Authenticator, t time.Time) {
// incrementCallsMetric increments a global metrics counter for the number of calls to an exec
// plugin, partitioned by exit code. The provided err should be the return value from
// exec.Cmd.Run().
-func incrementCallsMetric(err error) {
+func incrementCallsMetric(ctx context.Context, err error) {
execExitError := &exec.ExitError{}
execError := &exec.Error{}
pathError := &fs.PathError{}
@@ -105,8 +106,7 @@ func incrementCallsMetric(err error) {
metrics.ExecPluginCalls.Increment(failureExitCode, pluginNotFoundError)
default: // We don't know about this error type.
- //nolint:logcheck // This looks like debug output which shouldn't occur in practice.
- klog.V(2).InfoS("unexpected exec plugin return error type", "type", reflect.TypeOf(err).String(), "err", err)
+ klog.FromContext(ctx).V(2).Info("unexpected exec plugin return error type", "type", reflect.TypeOf(err).String(), "err", err)
metrics.ExecPluginCalls.Increment(failureExitCode, clientInternalError)
}
}
diff --git a/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/metrics_test.go b/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/metrics_test.go
index 61360abdb7c..43219795839 100644
--- a/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/metrics_test.go
+++ b/staging/src/k8s.io/client-go/plugin/pkg/client/auth/exec/metrics_test.go
@@ -25,6 +25,7 @@ import (
"github.com/google/go-cmp/cmp"
"k8s.io/client-go/tools/clientcmd/api"
"k8s.io/client-go/tools/metrics"
+ "k8s.io/klog/v2/ktesting"
)
type mockExpiryGauge struct {
@@ -115,6 +116,7 @@ func (f *mockCallsMetricCounter) Increment(exitCode int, errorType string) {
}
func TestCallsMetric(t *testing.T) {
+ _, ctx := ktesting.NewTestContext(t)
const (
goodOutput = `{
"kind": "ExecCredential",
@@ -152,7 +154,7 @@ func TestCallsMetric(t *testing.T) {
// Run refresh creds twice so that our test validates that the metrics are set correctly twice
// in a row with the same authenticator.
refreshCreds := func() {
- if err := a.refreshCredsLocked(); (err == nil) != (exitCode == 0) {
+ if err := a.refreshCredsLocked(ctx); (err == nil) != (exitCode == 0) {
if err != nil {
t.Fatalf("wanted no error, but got %q", err.Error())
} else {
@@ -182,7 +184,7 @@ func TestCallsMetric(t *testing.T) {
t.Fatal(err)
}
a.stderr = io.Discard
- if err := a.refreshCredsLocked(); err == nil {
+ if err := a.refreshCredsLocked(ctx); err == nil {
t.Fatal("expected the authenticator to fail because the plugin does not exist")
}
wantCallsMetrics = append(wantCallsMetrics, mockCallsMetric{exitCode: 1, errorType: "plugin_not_found_error"})
The problem is that
kubernetes/staging/src/k8s.io/client-go/transport/config.go
Lines 152 to 154 in 8a5cf7b
// Callback that returns a TLS client certificate. CertData, CertFile, KeyData and KeyFile supercede this field. | |
// This struct indirection is used to make transport configs cacheable. | |
GetCertHolder *GetCertHolder |
Extending it in a backward-compatible manner is difficult because wrapper functions or structs break the caching aspect of GetCertHolder
- I tried...
Instead of //nolint:logcheck
, a klog.TODO
is more appropriate, with a comment explaining that addressing the TODO is difficult and perhaps not worth it. I'll push an update with that.
//nolint:logcheck // Should not happen. | ||
klog.V(2).Infof("%s auth provider field depricated, refresh request don't send scopes", |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This can totally happen so we should update it.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
But only if used incorrectly, right?
Do you prefer structured logging here?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Structured logging is possible, but contextual logging implies changing the factory API:
kubernetes/staging/src/k8s.io/client-go/rest/plugin.go
Lines 38 to 43 in 8a5cf7b
// Factory generates an AuthProvider plugin. | |
// | |
// clusterAddress is the address of the current cluster. | |
// config is the initial configuration for this plugin. | |
// persister allows the plugin to save updated configuration. | |
type Factory func(clusterAddress string, config map[string]string, persister AuthProviderConfigPersister) (AuthProvider, error) |
I'm leaving it as klog.TODO
with a comment explaining this.
/test pull-kubernetes-e2e-gce "failed to create fsnotify watcher: too many open files" |
/cc @deads2k |
a392191
to
2738b12
Compare
[APPROVALNOTIFIER] This PR is NOT APPROVED This pull-request has been approved by: pohly The full list of commands accepted by this bot can be found here.
Needs approval from an approver in each of these files:
Approvers can indicate their approval by writing |
No API changes are needed. In one case, a context is passed in via the http.Request. In others there is simply no need to change the calls.
2738b12
to
e4a9be7
Compare
@enj: did my changes address your comments? Please take another look. |
@pohly: The following tests failed, say
Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR. Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository. I understand the commands that are listed here. |
The Kubernetes project currently lacks enough contributors to adequately respond to all PRs. This bot triages PRs according to the following rules:
You can:
Please send feedback to sig-contributor-experience at kubernetes/community. /lifecycle stale |
/remove-lifecycle stale ping @enj |
The Kubernetes project currently lacks enough contributors to adequately respond to all PRs. This bot triages PRs according to the following rules:
You can:
Please send feedback to sig-contributor-experience at kubernetes/community. /lifecycle stale |
/remove-lifecycle stale |
What type of PR is this?
/kind cleanup
What this PR does / why we need it:
Part of #129125
Special notes for your reviewer:
No API changes are needed. In one case, a context is passed in via the http.Request. In others there is simply no need to change the calls.
Does this PR introduce a user-facing change?
/wg structured-logging