log tls handshake error at trace level to avoid error flooding, and add

metric to count such errors

Author: borgerli

staging/src/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go

@@ -113,6 +113,14 @@ var (
 		},
 		[]string{"requestKind"},
 	)
+	// TLSHandshakeErrors is a number of requests dropped with 'TLS handshake error from' error
+	TLSHandshakeErrors = compbasemetrics.NewCounter(
+		&compbasemetrics.CounterOpts{
+			Name:           "apiserver_tls_handshake_errors_total",
+			Help:           "Number of requests dropped with 'TLS handshake error from' error",
+			StabilityLevel: compbasemetrics.ALPHA,
+		},
+	)
 	// RegisteredWatchers is a number of currently registered watchers splitted by resource.
 	RegisteredWatchers = compbasemetrics.NewGaugeVec(
 		&compbasemetrics.GaugeOpts{
@@ -166,6 +174,7 @@ var (
 		requestLatencies,
 		responseSizes,
 		DroppedRequests,
+		TLSHandshakeErrors,
 		RegisteredWatchers,
 		WatchEvents,
 		WatchEventsSizes,

staging/src/k8s.io/apiserver/pkg/server/BUILD

@@ -102,6 +102,7 @@ go_library(
         "//staging/src/k8s.io/apiserver/pkg/endpoints/discovery:go_default_library",
         "//staging/src/k8s.io/apiserver/pkg/endpoints/filters:go_default_library",
         "//staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters:go_default_library",
+        "//staging/src/k8s.io/apiserver/pkg/endpoints/metrics:go_default_library",
         "//staging/src/k8s.io/apiserver/pkg/endpoints/openapi:go_default_library",
         "//staging/src/k8s.io/apiserver/pkg/endpoints/request:go_default_library",
         "//staging/src/k8s.io/apiserver/pkg/registry/generic:go_default_library",

staging/src/k8s.io/apiserver/pkg/server/secure_serving.go

@@ -20,15 +20,20 @@ import (
 	"context"
 	"crypto/tls"
 	"fmt"
+	"io"
+	"log"
 	"net"
 	"net/http"
+	"os"
+	"strings"
 	"time"
 
 	"golang.org/x/net/http2"
 	"k8s.io/component-base/cli/flag"
 	"k8s.io/klog/v2"
 
 	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
+	"k8s.io/apiserver/pkg/endpoints/metrics"
 	"k8s.io/apiserver/pkg/server/dynamiccertificates"
 )
 
@@ -184,6 +189,11 @@ func (s *SecureServingInfo) Serve(handler http.Handler, shutdownTimeout time.Dur
 		}
 	}
 
+	// use tlsHandshakeErrorWriter to handle messages of tls handshake error
+	tlsErrorWriter := &tlsHandshakeErrorWriter{os.Stderr}
+	tlsErrorLogger := log.New(tlsErrorWriter, "", 0)
+	secureServer.ErrorLog = tlsErrorLogger
+
 	klog.Infof("Serving securely on %s", secureServer.Addr)
 	return RunServer(secureServer, s.Listener, shutdownTimeout, stopCh)
 }
@@ -256,3 +266,22 @@ func (ln tcpKeepAliveListener) Accept() (net.Conn, error) {
 	tc.SetKeepAlivePeriod(defaultKeepAlivePeriod)
 	return tc, nil
 }
+
+// tlsHandshakeErrorWriter writes TLS handshake errors to klog with
+// trace level - V(5), to avoid flooding of tls handshake errors.
+type tlsHandshakeErrorWriter struct {
+	out io.Writer
+}
+
+const tlsHandshakeErrorPrefix = "http: TLS handshake error"
+
+func (w *tlsHandshakeErrorWriter) Write(p []byte) (int, error) {
+	if strings.Contains(string(p), tlsHandshakeErrorPrefix) {
+		klog.V(5).Info(string(p))
+		metrics.TLSHandshakeErrors.Inc()
+		return len(p), nil
+	}
+
+	// for non tls handshake error, log it as usual
+	return w.out.Write(p)
+}

staging/src/k8s.io/component-base/metrics/counter.go

@@ -45,6 +45,14 @@ func NewCounter(opts *CounterOpts) *Counter {
 	return kc
 }
 
+// Reset resets the underlying prometheus Counter to start counting from 0 again
+func (c *Counter) Reset() {
+	if !c.IsCreated() {
+		return
+	}
+	c.setPrometheusCounter(prometheus.NewCounter(c.CounterOpts.toPromCounterOpts()))
+}
+
 // setPrometheusCounter sets the underlying CounterMetric object, i.e. the thing that does the measurement.
 func (c *Counter) setPrometheusCounter(counter prometheus.Counter) {
 	c.CounterMetric = counter