Improve pod logs related to Supervisor TLS certificate problems

internal/controller/supervisorconfig/tls_cert_observer.go

@@ -1,4 +1,4 @@
-// Copyright 2020-2021 the Pinniped contributors. All Rights Reserved.
+// Copyright 2020-2023 the Pinniped contributors. All Rights Reserved.
 // SPDX-License-Identifier: Apache-2.0
 
 package supervisorconfig
@@ -10,6 +10,7 @@ import (
 	"strings"
 
 	v1 "k8s.io/api/core/v1"
+	k8serrors "k8s.io/apimachinery/pkg/api/errors"
 	"k8s.io/apimachinery/pkg/labels"
 	corev1informers "k8s.io/client-go/informers/core/v1"
 
@@ -73,19 +74,33 @@ func (c *tlsCertObserverController) Sync(ctx controllerlib.Context) error {
 	issuerHostToTLSCertMap := map[string]*tls.Certificate{}
 
 	for _, provider := range allProviders {
-		secretName := ""
-		if provider.Spec.TLS != nil {
-			secretName = provider.Spec.TLS.SecretName
-		}
 		issuerURL, err := url.Parse(provider.Spec.Issuer)
 		if err != nil {
 			plog.Debug("tlsCertObserverController Sync found an invalid issuer URL", "namespace", ns, "issuer", provider.Spec.Issuer)
 			continue
 		}
-		certFromSecret, err := c.certFromSecret(ns, secretName)
+
-		if err != nil {
+		secretName := ""
+		if provider.Spec.TLS != nil {
+			secretName = provider.Spec.TLS.SecretName
+		}
+		if secretName == "" {
+			// No secret name provided, so no need to try to load any Secret.
 			continue
 		}
+
+		certFromSecret, err := c.certFromSecret(ns, secretName)
+		if err != nil {
+			// The user configured a TLS secret on the FederationDomain but it could not be loaded,
+			// so log a message which is visible at the default log level. Any error here indicates a problem,
+			// including "not found" errors.
+			plog.Error("error loading TLS certificate from Secret for FederationDomain.spec.tls.secretName", err,
+				"FederationDomain.metadata.name", provider.Name,
+				"FederationDomain.spec.tls.secretName", provider.Spec.TLS.SecretName,
+			)
+			continue
+		}
+
 		// Lowercase the host part of the URL because hostnames should be treated as case-insensitive.
 		issuerHostToTLSCertMap[lowercaseHostWithoutPort(issuerURL)] = certFromSecret
 	}
@@ -96,6 +111,13 @@ func (c *tlsCertObserverController) Sync(ctx controllerlib.Context) error {
 	defaultCert, err := c.certFromSecret(ns, c.defaultTLSCertificateSecretName)
 	if err != nil {
 		c.issuerTLSCertSetter.SetDefaultTLSCert(nil)
+		// It's okay if the default TLS cert Secret is not found (it is not required).
+		if !k8serrors.IsNotFound(err) {
+			// For any other error, log a message which is visible at the default log level.
+			plog.Error("error loading TLS certificate from Secret for Supervisor default TLS cert", err,
+				"defaultCertSecretName", c.defaultTLSCertificateSecretName,
+			)
+		}
 	} else {
 		c.issuerTLSCertSetter.SetDefaultTLSCert(defaultCert)
 	}

internal/httputil/requestutil/requestutil.go

@@ -0,0 +1,14 @@
+// Copyright 2023 the Pinniped contributors. All Rights Reserved.
+// SPDX-License-Identifier: Apache-2.0
+
+package requestutil
+
+import "net/http"
+
+func SNIServerName(req *http.Request) string {
+	name := ""
+	if req.TLS != nil {
+		name = req.TLS.ServerName
+	}
+	return name
+}

internal/oidc/provider/manager/manager.go

@@ -1,4 +1,4 @@
-// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved.
+// Copyright 2020-2023 the Pinniped contributors. All Rights Reserved.
 // SPDX-License-Identifier: Apache-2.0
 
 package manager
@@ -11,6 +11,7 @@ import (
 	corev1client "k8s.io/client-go/kubernetes/typed/core/v1"
 
 	"go.pinniped.dev/generated/latest/client/supervisor/clientset/versioned/typed/config/v1alpha1"
+	"go.pinniped.dev/internal/httputil/requestutil"
 	"go.pinniped.dev/internal/oidc"
 	"go.pinniped.dev/internal/oidc/auth"
 	"go.pinniped.dev/internal/oidc/callback"
@@ -167,12 +168,15 @@ func (m *Manager) SetProviders(federationDomains ...*provider.FederationDomainIs
 func (m *Manager) ServeHTTP(resp http.ResponseWriter, req *http.Request) {
 	requestHandler := m.findHandler(req)
 
-	plog.Debug(
+	// Using Info level so the user can safely configure a production Supervisor to show this message if they choose.
-		"oidc provider manager examining request",
+	plog.Info("received incoming request",
+		"proto", req.Proto,
 		"method", req.Method,
 		"host", req.Host,
+		"requestSNIServerName", requestutil.SNIServerName(req),
 		"path", req.URL.Path,
-		"foundMatchingIssuer", requestHandler != nil,
+		"remoteAddr", req.RemoteAddr,
+		"foundFederationDomainRequestHandler", requestHandler != nil,
 	)
 
 	if requestHandler == nil {

internal/supervisor/server/bootstrap.go

@@ -15,6 +15,8 @@ import (
 	"k8s.io/apimachinery/pkg/util/sets"
 
 	"go.pinniped.dev/internal/certauthority"
+	"go.pinniped.dev/internal/httputil/requestutil"
+	"go.pinniped.dev/internal/plog"
 )
 
 // contextKey type is unexported to prevent collisions.
@@ -41,6 +43,17 @@ func withBootstrapPaths(handler http.Handler, paths ...string) http.Handler {
 		isBootstrap, _ := req.Context().Value(bootstrapKey).(*atomic.Bool)
 
 		if isBootstrap != nil && isBootstrap.Load() && !bootstrapPaths.Has(req.URL.Path) {
+			// When a user-provided cert was not found for a request path which requires it,
+			// then emit a log statement visible at the default log level.
+			plog.Warning("error finding user-provided TLS cert to use for for incoming request",
+				"proto", req.Proto,
+				"method", req.Method,
+				"host", req.Host,
+				"requestSNIServerName", requestutil.SNIServerName(req),
+				"path", req.URL.Path,
+				"remoteAddr", req.RemoteAddr,
+			)
+
 			http.Error(w, "pinniped supervisor has invalid TLS serving certificate configuration", http.StatusInternalServerError)
 			return
 		}

internal/supervisor/server/server.go

@@ -521,30 +521,35 @@ func runSupervisor(ctx context.Context, podInfo *downward.PodInfo, cfg *supervis
 		c := ptls.Default(nil)
 		c.GetCertificate = func(info *tls.ClientHelloInfo) (*tls.Certificate, error) {
 			cert := dynamicTLSCertProvider.GetTLSCert(strings.ToLower(info.ServerName))
+			foundServerNameCert := cert != nil
 
 			defaultCert := dynamicTLSCertProvider.GetDefaultTLSCert()
 
-			if plog.Enabled(plog.LevelTrace) { // minor CPU optimization as this is generally just noise
+			if !foundServerNameCert {
-				host, port, _ := net.SplitHostPort(info.Conn.LocalAddr().String()) // error is safe to ignore here
-
-				plog.Trace("GetCertificate called",
-					"info.ServerName", info.ServerName,
-					"foundSNICert", cert != nil,
-					"foundDefaultCert", defaultCert != nil,
-					"host", host,
-					"port", port,
-				)
-			}
-
-			if cert == nil {
 				cert = defaultCert
 			}
 
+			// If we still don't have a cert for the request at this point, then using the bootstrapping cert,
+			// but in that case also set the request to fail unless it is a health check request.
+			usingBootstrapCert := false
 			if cert == nil {
+				usingBootstrapCert = true
 				setIsBootstrapConn(info.Context()) // make this connection only work for bootstrap requests
 				cert = bootstrapCert
 			}
 
+			// Emit logs visible at a higher level of logging than the default. Using Info level so the user
+			// can safely configure a production Supervisor to show this message if they choose.
+			plog.Info("choosing TLS cert for incoming request",
+				"requestSNIServerName", info.ServerName,
+				"foundCertForSNIServerNameFromFederationDomain", foundServerNameCert,
+				"foundDefaultCertFromSecret", defaultCert != nil,
+				"defaultCertSecretName", cfg.NamesConfig.DefaultTLSCertificateSecret,
+				"servingBootstrapHealthzCert", usingBootstrapCert,
+				"requestLocalAddr", info.Conn.LocalAddr().String(),
+				"requestRemoteAddr", info.Conn.RemoteAddr().String(),
+			)
+
 			return cert, nil
 		}