From 269431c9c894d70a4412bb79d96822d842725cb0 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Marcel=20Zi=C4=99ba?= <marcelzieba@google.com>
Date: Mon, 18 Oct 2021 14:48:47 +0000
Subject: [PATCH] Fix race condition in logging when request times out

---
 .../apiserver/pkg/server/httplog/httplog.go   | 32 +++++++++++++++----
 1 file changed, 25 insertions(+), 7 deletions(-)

diff --git a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go
index ccb137c87b3..8ac036f9b2d 100644
--- a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go
+++ b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go
@@ -24,6 +24,7 @@ import (
 	"net/http"
 	"runtime"
 	"strings"
+	"sync"
 	"time"
 
 	"k8s.io/apiserver/pkg/endpoints/metrics"
@@ -54,18 +55,22 @@ const respLoggerContextKey respLoggerContextKeyType = iota
 // the http.ResponseWriter. We can recover panics from go-restful, and
 // the logging value is questionable.
 type respLogger struct {
-	hijacked           bool
-	statusRecorded     bool
-	status             int
-	statusStack        string
+	hijacked       bool
+	statusRecorded bool
+	status         int
+	statusStack    string
+	// mutex is used when accessing addedInfo and addedKeyValuePairs.
+	// They can be modified by other goroutine when logging happens (in case of request timeout)
+	mutex              sync.Mutex
 	addedInfo          strings.Builder
 	addedKeyValuePairs []interface{}
 	startTime          time.Time
 
 	captureErrorOutput bool
 
-	req *http.Request
-	w   http.ResponseWriter
+	req       *http.Request
+	userAgent string
+	w         http.ResponseWriter
 
 	logStacktracePred StacktracePred
 }
@@ -141,6 +146,7 @@ func newLoggedWithStartTime(req *http.Request, w http.ResponseWriter, startTime
 	logger := &respLogger{
 		startTime:         startTime,
 		req:               req,
+		userAgent:         req.UserAgent(),
 		w:                 w,
 		logStacktracePred: DefaultStacktracePred,
 	}
@@ -192,6 +198,8 @@ func StatusIsNot(statuses ...int) StacktracePred {
 
 // Addf adds additional data to be logged with this request.
 func (rl *respLogger) Addf(format string, data ...interface{}) {
+	rl.mutex.Lock()
+	defer rl.mutex.Unlock()
 	rl.addedInfo.WriteString("\n")
 	rl.addedInfo.WriteString(fmt.Sprintf(format, data...))
 }
@@ -203,6 +211,8 @@ func AddInfof(ctx context.Context, format string, data ...interface{}) {
 }
 
 func (rl *respLogger) AddKeyValue(key string, value interface{}) {
+	rl.mutex.Lock()
+	defer rl.mutex.Unlock()
 	rl.addedKeyValuePairs = append(rl.addedKeyValuePairs, key, value)
 }
 
@@ -235,10 +245,18 @@ func (rl *respLogger) Log() {
 		"verb", verb,
 		"URI", rl.req.RequestURI,
 		"latency", latency,
-		"userAgent", rl.req.UserAgent(),
+		// We can't get UserAgent from rl.req.UserAgent() here as it accesses headers map,
+		// which can be modified in another goroutine when apiserver request times out.
+		// For example authentication filter modifies request's headers,
+		// This can cause apiserver to crash with unrecoverable fatal error.
+		// More info about concurrent read and write for maps: https://golang.org/doc/go1.6#runtime
+		"userAgent", rl.userAgent,
 		"audit-ID", auditID,
 		"srcIP", rl.req.RemoteAddr,
 	}
+	// Lock for accessing addedKeyValuePairs and addedInfo
+	rl.mutex.Lock()
+	defer rl.mutex.Unlock()
 	keysAndValues = append(keysAndValues, rl.addedKeyValuePairs...)
 
 	if rl.hijacked {