Skip to content
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.

Sign up for GitHub

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

Jump to bottom

kubelet: migrate pkg/kubelet/certificate to structured logging #98993

Merged
merged 1 commit into from Mar 4, 2021
Merged

kubelet: migrate pkg/kubelet/certificate to structured logging #98993

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
20 changes: 10 additions & 10 deletions pkg/kubelet/certificate/bootstrap/bootstrap.go
View file
Open in desktop
Expand Up @@ -61,7 +61,7 @@ func LoadClientConfig(kubeconfigPath, bootstrapPath, certDir string) (certConfig
if err != nil {
return nil, nil, fmt.Errorf("unable to load kubeconfig: %v", err)
}
klog.V(2).Infof("No bootstrapping requested, will use kubeconfig")
klog.V(2).InfoS("No bootstrapping requested, will use kubeconfig")
return clientConfig, restclient.CopyConfig(clientConfig), nil
}

Expand All @@ -81,7 +81,7 @@ func LoadClientConfig(kubeconfigPath, bootstrapPath, certDir string) (certConfig
if err != nil {
return nil, nil, fmt.Errorf("unable to load kubeconfig: %v", err)
}
klog.V(2).Infof("Current kubeconfig file contents are still valid, no bootstrap necessary")
klog.V(2).InfoS("Current kubeconfig file contents are still valid, no bootstrap necessary")
return clientConfig, restclient.CopyConfig(clientConfig), nil
}

Expand All @@ -97,7 +97,7 @@ func LoadClientConfig(kubeconfigPath, bootstrapPath, certDir string) (certConfig
if err := writeKubeconfigFromBootstrapping(clientConfig, kubeconfigPath, pemPath); err != nil {
return nil, nil, err
}
klog.V(2).Infof("Use the bootstrap credentials to request a cert, and set kubeconfig to point to the certificate dir")
klog.V(2).InfoS("Use the bootstrap credentials to request a cert, and set kubeconfig to point to the certificate dir")
return bootstrapClientConfig, clientConfig, nil
}

Expand All @@ -112,11 +112,11 @@ func LoadClientCert(ctx context.Context, kubeconfigPath, bootstrapPath, certDir
return err
}
if ok {
klog.V(2).Infof("Kubeconfig %s exists and is valid, skipping bootstrap", kubeconfigPath)
klog.V(2).InfoS("Kubeconfig exists and is valid, skipping bootstrap", "path", kubeconfigPath)
return nil
}

klog.V(2).Info("Using bootstrap kubeconfig to generate TLS client cert, key and kubeconfig file")
klog.V(2).InfoS("Using bootstrap kubeconfig to generate TLS client cert, key and kubeconfig file")

bootstrapClientConfig, err := loadRESTClientConfig(bootstrapPath)
if err != nil {
Expand Down Expand Up @@ -147,7 +147,7 @@ func LoadClientCert(ctx context.Context, kubeconfigPath, bootstrapPath, certDir
// managed by the store.
privKeyPath := filepath.Join(certDir, tmpPrivateKeyFile)
if !verifyKeyData(keyData) {
klog.V(2).Infof("No valid private key and/or certificate found, reusing existing private key or creating a new one")
klog.V(2).InfoS("No valid private key and/or certificate found, reusing existing private key or creating a new one")
// Note: always call LoadOrGenerateKeyFile so that private key is
// reused on next startup if CSR request fails.
keyData, _, err = keyutil.LoadOrGenerateKeyFile(privKeyPath)
Expand All @@ -157,7 +157,7 @@ func LoadClientCert(ctx context.Context, kubeconfigPath, bootstrapPath, certDir
}

if err := waitForServer(ctx, *bootstrapClientConfig, 1*time.Minute); err != nil {
klog.Warningf("Error waiting for apiserver to come up: %v", err)
klog.InfoS("Error waiting for apiserver to come up", "err", err)
}

certData, err := requestNodeCertificate(ctx, bootstrapClient, keyData, nodeName)
Expand All @@ -168,7 +168,7 @@ func LoadClientCert(ctx context.Context, kubeconfigPath, bootstrapPath, certDir
return err
}
if err := os.Remove(privKeyPath); err != nil && !os.IsNotExist(err) {
klog.V(2).Infof("failed cleaning up private key file %q: %v", privKeyPath, err)
klog.V(2).InfoS("Failed cleaning up private key file", "path", privKeyPath, "err", err)
}

return writeKubeconfigFromBootstrapping(bootstrapClientConfig, kubeconfigPath, store.CurrentPath())
Expand Down Expand Up @@ -292,7 +292,7 @@ func waitForServer(ctx context.Context, cfg restclient.Config, deadline time.Dur
var connected bool
wait.JitterUntil(func() {
if _, err := cli.Get().AbsPath("/healthz").Do(ctx).Raw(); err != nil {
klog.Infof("Failed to connect to apiserver: %v", err)
klog.InfoS("Failed to connect to apiserver", "err", err)
return
}
cancel()
Expand Down Expand Up @@ -352,7 +352,7 @@ func requestNodeCertificate(ctx context.Context, client clientset.Interface, pri
ctx, cancel := context.WithTimeout(ctx, 3600*time.Second)
defer cancel()

klog.V(2).Infof("Waiting for client certificate to be issued")
klog.V(2).InfoS("Waiting for client certificate to be issued")
return csr.WaitForCertificate(ctx, client, reqName, reqUID)
}

Expand Down
13 changes: 8 additions & 5 deletions pkg/kubelet/certificate/transport.go
View file
Open in desktop
Expand Up @@ -21,6 +21,7 @@ import (
"fmt"
"net"
"net/http"
"os"
"time"

"k8s.io/klog/v2"
Expand Down Expand Up @@ -105,18 +106,20 @@ func addCertRotation(stopCh <-chan struct{}, period time.Duration, clientConfig
// the certificate has been deleted from disk or is otherwise corrupt
if now.After(lastCertAvailable.Add(exitAfter)) {
if clientCertificateManager.ServerHealthy() {
klog.Fatalf("It has been %s since a valid client cert was found and the server is responsive, exiting.", exitAfter)
klog.ErrorS(nil, "No valid client certificate is found and the server is responsive, exiting.", "lastCertificateAvailabilityTime", lastCertAvailable, "shutdownThreshold", exitAfter)
os.Exit(1)
} else {
klog.Errorf("It has been %s since a valid client cert was found, but the server is not responsive. A restart may be necessary to retrieve new initial credentials.", exitAfter)
klog.ErrorS(nil, "No valid client certificate is found but the server is not responsive. A restart may be necessary to retrieve new initial credentials.", "lastCertificateAvailabilityTime", lastCertAvailable, "shutdownThreshold", exitAfter)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

are the keys selected for messages like these considered a stable API log consumers can write extraction/monitoring around?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not as of beta but we're moving in that direction for GA. Right now we're trying to figure out a good (loose, non-enforced) schema that we can later enforce.

}
}
} else {
// the certificate is expired
if now.After(curr.Leaf.NotAfter) {
if clientCertificateManager.ServerHealthy() {
klog.Fatalf("The currently active client certificate has expired and the server is responsive, exiting.")
klog.ErrorS(nil, "The currently active client certificate has expired and the server is responsive, exiting.")
os.Exit(1)
} else {
klog.Errorf("The currently active client certificate has expired, but the server is not responsive. A restart may be necessary to retrieve new initial credentials.")
klog.ErrorS(nil, "The currently active client certificate has expired, but the server is not responsive. A restart may be necessary to retrieve new initial credentials.")
Copy link
Member

@liggitt liggitt Mar 3, 2021 •
edited

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

passing a nil error to ErrorS seems strange... should this do something like klog.ErrorS(errors.New("The currently active client...")) instead? (same question for several places above as well)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Docs on calling ErrorS with nil: https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#using-errors

Calling ErrorS with nil as error is semi-acceptable if there is error condition that deserves a stack trace at this origin point. For expected errors (errors that can happen during routine operations) please consider using klog.InfoS and pass error in err key instead.

I think this is an unexpected error so this is ok?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it looks like the klog implementation gracefully omits the err=nil from the output:

kubernetes/vendor/k8s.io/klog/v2/klog.go

Lines 803 to 806 in c8fe1d9

if err != nil {
b.WriteByte(' ')
b.WriteString(fmt.Sprintf("err=%q", err.Error()))
}

but the structured logger always includes an err param, even if nil:

kubernetes/staging/src/k8s.io/component-base/logs/json/json.go

Lines 171 to 173 in c8fe1d9

func handleError(err error) zap.Field {
return zap.NamedError("err", err)
}

is that expected by structured log consumers?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, that's right. We just get the log message with no named error, so it's equivalent to the current behaviour.

}
}
lastCertAvailable = now
Expand All @@ -129,7 +132,7 @@ func addCertRotation(stopCh <-chan struct{}, period time.Duration, clientConfig
}
lastCert = curr

klog.Infof("certificate rotation detected, shutting down client connections to start using new credentials")
klog.InfoS("Certificate rotation detected, shutting down client connections to start using new credentials")
// The cert has been rotated. Close all existing connections to force the client
// to reperform its TLS handshake with new cert.
//
Expand Down