fix(logging): limit size of request bodies in trace level logging (#380)

Author: PeterSchafer

pkg/networking/logging.go

@@ -13,6 +13,8 @@ import (
 
 const defaultNetworkLogLevel = zerolog.DebugLevel
 const extendedNetworkLogLevel = zerolog.TraceLevel
+const maxNumberOfRequestBodyCharacters = 60
+const maxNumberOfResponseBodyCharacters = -1 // log complete response body
 
 func shouldNotLog(currentLevel zerolog.Level, levelToLogAt zerolog.Level) bool {
 	// Don't log if logger level is above the threshold
@@ -71,16 +73,16 @@ func decodeBody(bodyBytes []byte, contentEncoding string) (string, error) {
 	}
 }
 
-func logBody(logger *zerolog.Logger, logLevel zerolog.Level, logPrefix string, body io.ReadCloser, header http.Header) {
+func logBody(logger *zerolog.Logger, logLevel zerolog.Level, logPrefix string, body io.ReadCloser, header http.Header, maxBodyCharacters int64) {
 	if body != nil {
-		bodyBytes, bodyErr := io.ReadAll(body)
 		defer func() {
 			closeErr := body.Close()
 			if closeErr != nil {
 				logger.WithLevel(logLevel).Err(closeErr).Msg("failed to close body")
 			}
 		}()
 
+		bodyBytes, bodyErr := io.ReadAll(body)
 		if bodyErr != nil {
 			return
 		}
@@ -89,11 +91,24 @@ func logBody(logger *zerolog.Logger, logLevel zerolog.Level, logPrefix string, b
 		if err != nil {
 			logger.WithLevel(logLevel).Err(err).Msgf("%s Failed to decode request body", logPrefix)
 		} else if len(bodyString) > 0 {
+			bodyString = shortenStringFromCenter(bodyString, maxBodyCharacters)
 			logger.WithLevel(logLevel).Msgf("%s body: %v", logPrefix, bodyString)
 		}
 	}
 }
 
+// shortenStringFromCenter shortens the given string and keeps only maxCharacters of it. It removes content from the center
+// of the string and adds a placeholder making this obvious.
+func shortenStringFromCenter(str string, maxCharacters int64) string {
+	// shorten body if maxBodyCharacters is set
+	bodyLength := int64(len(str))
+	if maxCharacters > 0 && bodyLength > maxCharacters {
+		subLength := maxCharacters / 2
+		str = fmt.Sprintf("%s [...shortened...] %s", str[0:subLength], str[bodyLength-subLength:bodyLength])
+	}
+	return str
+}
+
 func LogRequest(r *http.Request, logger *zerolog.Logger) {
 	if shouldNotLog(logger.GetLevel(), defaultNetworkLogLevel) { // Don't log if logger level is above the threshold
 		return
@@ -108,7 +123,7 @@ func LogRequest(r *http.Request, logger *zerolog.Logger) {
 		return
 	}
 
-	logBody(logger, defaultNetworkLogLevel, logPrefixRequest, getRequestBody(r), r.Header)
+	logBody(logger, defaultNetworkLogLevel, logPrefixRequest, getRequestBody(r), r.Header, maxNumberOfRequestBodyCharacters)
 }
 
 func LogResponse(response *http.Response, logger *zerolog.Logger) {
@@ -126,6 +141,6 @@ func LogResponse(response *http.Response, logger *zerolog.Logger) {
 			return
 		}
 
-		logBody(logger, defaultNetworkLogLevel, logPrefixResponse, getResponseBody(response), response.Header)
+		logBody(logger, defaultNetworkLogLevel, logPrefixResponse, getResponseBody(response), response.Header, maxNumberOfResponseBodyCharacters)
 	}
 }

pkg/networking/logging_test.go

@@ -109,6 +109,26 @@ func Test_LogRequest_happyPath_server_request(t *testing.T) {
 	assert.Equal(t, expectedBody, string(actualBody))
 }
 
+func Test_LogRequest_happyPath_server_request_limited(t *testing.T) {
+	inputBody := "this is a longer text, that will not be logged fully. It'll just stop at some point and show the end of the text as well, since start and end of a message might be the most interesting part"
+	expectedBody := "this is a longer text, that wi [...shortened...] t be the most interesting part"
+	body := io.NopCloser(bytes.NewBufferString(inputBody))
+
+	logBuffer := bytes.Buffer{}
+	logger := zerolog.New(&logBuffer).Level(zerolog.TraceLevel)
+	request, err := http.NewRequest(http.MethodGet, "http://localhost/", body)
+	assert.NoError(t, err)
+
+	// method under test
+	LogRequest(request, &logger)
+	assert.Contains(t, logBuffer.String(), expectedBody)
+
+	// ensure that the request body can still be read
+	actualBody, err := io.ReadAll(request.Body)
+	assert.NoError(t, err)
+	assert.Equal(t, inputBody, string(actualBody))
+}
+
 func Test_LogRequest_happyPath_client_request(t *testing.T) {
 	expectedBody := "hello world"
 	body := io.NopCloser(bytes.NewBufferString(expectedBody))