Merge pull request #91277 from borgerli/master

log tls handshake error at trace level to avoid error flooding

Kubernetes-commit: c2d15418316e9a02bf5692de80064556fb4f89f0

Godeps/Godeps.json

@@ -668,7 +668,7 @@
 		},
 		{
 			"ImportPath": "k8s.io/api",
-			"Rev": "67a68481e276"
+			"Rev": "702e5dfa819c"
 		},
 		{
 			"ImportPath": "k8s.io/apimachinery",
@@ -680,7 +680,7 @@
 		},
 		{
 			"ImportPath": "k8s.io/component-base",
-			"Rev": "12d9255b32a9"
+			"Rev": "d0ef39c660d1"
 		},
 		{
 			"ImportPath": "k8s.io/gengo",

go.mod

@@ -41,10 +41,10 @@ require (
 	gopkg.in/natefinch/lumberjack.v2 v2.0.0
 	gopkg.in/square/go-jose.v2 v2.2.2
 	gopkg.in/yaml.v2 v2.2.8
-	k8s.io/api v0.0.0-20200711010759-67a68481e276
+	k8s.io/api v0.0.0-20200711010801-702e5dfa819c
 	k8s.io/apimachinery v0.0.0-20200711010416-9894919f2c6e
 	k8s.io/client-go v0.0.0-20200711011223-16621f64440c
-	k8s.io/component-base v0.0.0-20200711012104-12d9255b32a9
+	k8s.io/component-base v0.0.0-20200711130808-d0ef39c660d1
 	k8s.io/klog/v2 v2.2.0
 	k8s.io/kube-openapi v0.0.0-20200427153329-656914f816f9
 	k8s.io/utils v0.0.0-20200619165400-6e3d28b6ed19
@@ -54,8 +54,8 @@ require (
 )
 
 replace (
-	k8s.io/api => k8s.io/api v0.0.0-20200711010759-67a68481e276
+	k8s.io/api => k8s.io/api v0.0.0-20200711010801-702e5dfa819c
 	k8s.io/apimachinery => k8s.io/apimachinery v0.0.0-20200711010416-8e134319f815
 	k8s.io/client-go => k8s.io/client-go v0.0.0-20200711011223-16621f64440c
-	k8s.io/component-base => k8s.io/component-base v0.0.0-20200711012104-12d9255b32a9
+	k8s.io/component-base => k8s.io/component-base v0.0.0-20200711130808-d0ef39c660d1
 )

go.sum

@@ -508,10 +508,10 @@ honnef.co/go/tools v0.0.0-20190106161140-3f1c8253044a/go.mod h1:rf3lG4BRIbNafJWh
 honnef.co/go/tools v0.0.0-20190418001031-e561f6794a2a/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=
 honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=
 honnef.co/go/tools v0.0.1-2019.2.3/go.mod h1:a3bituU0lyd329TUQxRnasdCoJDkEUEAqEt0JzvZhAg=
-k8s.io/api v0.0.0-20200711010759-67a68481e276/go.mod h1:x0ZnvSZqabCH9lfDzYQVDUpIhJCLTnfTXruGmRCMI+A=
+k8s.io/api v0.0.0-20200711010801-702e5dfa819c/go.mod h1:gBMjhq55fktw2TF/h/Ek23P1qoXZyw+GOdvDxMokpqQ=
 k8s.io/apimachinery v0.0.0-20200711010416-8e134319f815/go.mod h1:o7dnTWWI581t2mphuLR3towX6xooze3sUXgNRWLd3Cw=
 k8s.io/client-go v0.0.0-20200711011223-16621f64440c/go.mod h1:LDsbtsZg5daD4TayUEm3PqPDGiB/lbkKH6rw136WNM4=
-k8s.io/component-base v0.0.0-20200711012104-12d9255b32a9/go.mod h1:DO9ObuxbN1G14m1g+JofnlNRSyL7V0wAzmgU54Lmfx8=
+k8s.io/component-base v0.0.0-20200711130808-d0ef39c660d1/go.mod h1:xnSvlx0E6AEMnNZozKZ+g3A6EGTWM2y+UAY5Dng9LkI=
 k8s.io/gengo v0.0.0-20200413195148-3a45101e95ac/go.mod h1:ezvh/TsK7cY6rbqRK0oQQ8IAqLxYwwyPxAX1Pzy0ii0=
 k8s.io/klog/v2 v2.0.0/go.mod h1:PBfzABfn139FHAV07az/IF9Wp1bkk3vpT2XSJ76fSDE=
 k8s.io/klog/v2 v2.2.0 h1:XRvcwJozkgZ1UQJmfMGpvRthQHOvihEhYtDfAaxMz/A=

pkg/endpoints/metrics/metrics.go

@@ -123,6 +123,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{
@@ -177,6 +185,7 @@ var (
 		requestLatencies,
 		responseSizes,
 		DroppedRequests,
+		TLSHandshakeErrors,
 		RegisteredWatchers,
 		WatchEvents,
 		WatchEventsSizes,

pkg/server/secure_serving.go

@@ -20,8 +20,12 @@ import (
 	"context"
 	"crypto/tls"
 	"fmt"
+	"io"
+	"log"
 	"net"
 	"net/http"
+	"os"
+	"strings"
 	"time"
 
 	"golang.org/x/net/http2"
@@ -29,6 +33,7 @@ import (
 	"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)
 }
@@ -258,3 +268,22 @@ func (ln tcpKeepAliveListener) Accept() (net.Conn, error) {
 	}
 	return c, 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)
+}