fix(go): correctly log response Body in SDK Logger

.github/workflows/test.yaml

@@ -9,16 +9,16 @@ on:
 jobs:
   test:
     runs-on: ubuntu-latest
-    timeout-minutes: 2
+    timeout-minutes: 5
     steps:
-      - uses: actions/checkout@v2
+      - uses: actions/checkout@v4
       - name: Setup Go
-        uses: actions/setup-go@v2
+        uses: actions/setup-go@v5
         with:
           go-version: '1.18'
       - name: Run Static Check
-        uses: dominikh/staticcheck-action@v1.3.0
+        uses: dominikh/staticcheck-action@v1
         with:
-          version: "2022.1.3"
+          version: "latest"
       - name: Build and Test
         run: go test ./...

internal/mockingServer.go

@@ -1,6 +1,7 @@
 package internal
 
 import (
+	"io"
 	"net/http"
 	"net/http/httptest"
 )
@@ -14,8 +15,18 @@ func GetTestingServer() *httptest.Server {
 			case "/response/integer":
 				_, _ = w.Write([]byte(`4`))
 			case "/template/abc/def", "/template/1/2/3/4/5", "/response/binary":
-				_, _ = w.Write([]byte(`"passed": true,
-				"message": "It's a hit!",`))
+				_, _ = w.Write([]byte(`"passed": true, "message": "It's a hit!",`))
+			case "/response/binary/customHeader":
+				if r.Header.Get("custom-header") == "CustomHeaderValue" {
+					_, _ = w.Write([]byte(`"passed": true, "message": "It's a hit!",`))
+				} else {
+					w.WriteHeader(http.StatusBadRequest)
+				}
+			case "/response/empty":
+				w.WriteHeader(http.StatusOK)
+			case "/response/invalid":
+				reqBody, _ := io.ReadAll(r.Body)
+				_, _ = w.Write(reqBody)
 			case "/error/400":
 				w.WriteHeader(http.StatusBadRequest)
 			case "/error/500":

logger/level_test.go

@@ -48,11 +48,19 @@ func TestLevelEnumValueTRACE(t *testing.T) {
 }
 
 func TestLevelEnumValueInvalid(t *testing.T) {
-	level := logger.Level("Invalid")
+	var level logger.Level
+	_ = json.Unmarshal([]byte(`"invalid"`), &level)
 	validateLevelEnumValues(level, new(testing.T))
 }
 
 func TestLevelEnumValueInvalid2(t *testing.T) {
-	level := logger.Level("nil")
+	var level logger.Level
+	_ = json.Unmarshal([]byte(`nil`), &level)
+	validateLevelEnumValues(level, new(testing.T))
+}
+
+func TestLevelEnumValueInvalid3(t *testing.T) {
+	var level logger.Level
+	_ = json.Unmarshal([]byte(`{"key": "value"}`), &level)
 	validateLevelEnumValues(level, new(testing.T))
 }

logger/sdkLogger.go

@@ -1,7 +1,8 @@
 package logger
 
 import (
-	"encoding/json"
+	"bytes"
+	"io"
 	"net/http"
 	"strings"
 )
@@ -93,12 +94,17 @@ func (a *SdkLogger) _applyLogRequestOptions(level Level, request *http.Request)
 	}
 
 	if logOp.body {
-		if bodyBytes, err := json.Marshal(request.Body); err == nil {
-			a.logger.Log(level, "Request body %{body}",
-				map[string]any{"body": string(bodyBytes)},
-			)
+		if request.Body == nil {
+			a.logger.Log(level, "Request body %{body}", map[string]any{"body": nil})
+			return
+		}
+		bodyBytes, err := io.ReadAll(request.Body)
+		request.Body = io.NopCloser(bytes.NewBuffer(bodyBytes))
+		if err != nil {
+			a.logger.Log(level, "Error reading request body %{body}", map[string]any{"body": err})
+		} else {
+			a.logger.Log(level, "Request body %{body}", map[string]any{"body": string(bodyBytes)})
 		}
-
 	}
 }
 
@@ -117,11 +123,16 @@ func (a *SdkLogger) _applyLogResponseOptions(level Level, response *http.Respons
 	}
 
 	if logOp.body {
-
-		if bodyBytes, err := json.Marshal(response.Body); err == nil {
-			a.logger.Log(level, "Response body %{body}",
-				map[string]any{"body": string(bodyBytes)},
-			)
+		if response.Body == http.NoBody {
+			a.logger.Log(level, "Response body %{body}", map[string]any{"body": nil})
+			return
+		}
+		bodyBytes, err := io.ReadAll(response.Body)
+		response.Body = io.NopCloser(bytes.NewBuffer(bodyBytes))
+		if err != nil {
+			a.logger.Log(level, "Error reading response body %{body}", map[string]any{"body": err})
+		} else {
+			a.logger.Log(level, "Response body %{body}", map[string]any{"body": string(bodyBytes)})
 		}
 	}
 }
@@ -175,7 +186,9 @@ func (a *SdkLogger) _extractHeadersToLog(
 			headersToExclude,
 		)
 	} else {
-		filteredHeaders = headers
+		for key, values := range headers {
+			filteredHeaders[key] = values
+		}
 	}
 
 	return a._maskSensitiveHeaders(filteredHeaders, headersToWhitelist)

logger/sdkLogger_test.go

@@ -14,6 +14,8 @@ var callBuilder https.CallBuilderFactory
 var ctx = context.Background()
 var serverUrl = internal.GetTestingServer().URL
 
+var _testsErrorFormat = "Failed:\nExpected: %v\nGot: %v"
+
 func init() {
 
 	client := https.NewHttpClient(https.NewHttpConfiguration())
@@ -36,7 +38,7 @@ func _callRequestAsJson(t *testing.T, request https.CallBuilder) {
 	}
 	expected := 200
 	if response.StatusCode != expected {
-		t.Errorf("Failed:\nExpected: %v\nGot: %v", expected, response)
+		t.Errorf(_testsErrorFormat, expected, response)
 	}
 }
 
@@ -46,7 +48,7 @@ type fmtLogger struct {
 
 func (c *fmtLogger) AssertLogEntries(t *testing.T, expected ...string) {
 	if !reflect.DeepEqual(c.entries, expected) {
-		t.Errorf("Failed:\nExpected: %v\nGot: %v", expected, c.entries)
+		t.Errorf(_testsErrorFormat, expected, c.entries)
 	}
 }
 
@@ -101,6 +103,48 @@ func TestSDKLoggerWithCustomConfig(t *testing.T) {
 	_callRequestAsJson(t, request)
 }
 
+func TestSDKLoggerWithEmptyResponse(t *testing.T) {
+	request := callBuilder(ctx, "GET", "//response/")
+	request.AppendPath("/empty")
+
+	request.Logger(NewSdkLogger(NewLoggerConfiguration(
+		WithLevel("debug"),
+		WithRequestConfiguration(
+			WithRequestBody(true),
+		),
+		WithResponseConfiguration(
+			WithResponseBody(true),
+		),
+	)))
+	request.Json("Apimatic")
+	_, response, _ := request.CallAsJson()
+	expected := 200
+	if response.StatusCode != expected {
+		t.Errorf(_testsErrorFormat, expected, response)
+	}
+}
+
+func TestSDKLoggerWithInvalidResponse(t *testing.T) {
+	request := callBuilder(ctx, "GET", "//response/")
+	request.AppendPath("/invalid")
+
+	request.Logger(NewSdkLogger(NewLoggerConfiguration(
+		WithLevel("debug"),
+		WithRequestConfiguration(
+			WithRequestBody(true),
+		),
+		WithResponseConfiguration(
+			WithResponseBody(true),
+		),
+	)))
+	request.Json("Apimatic")
+	_, response, _ := request.CallAsJson()
+	expected := 200
+	if response.StatusCode != expected {
+		t.Errorf(_testsErrorFormat, expected, response)
+	}
+}
+
 func TestSDKLoggerWithCustomLoggerDefaultConfig(t *testing.T) {
 	request := callBuilder(ctx, "GET", "//response/")
 	request.AppendPath("/binary")
@@ -116,15 +160,16 @@ func TestSDKLoggerWithCustomLoggerDefaultConfig(t *testing.T) {
 	expected := []string{
 		"info, Request %{method} %{url} %{contentType}, map[contentType: method:GET url:" + serverUrl + "/response/binary]",
 		"info, Request headers %{headers}, map[headers:map[]]",
-		"info, Response %{statusCode} %{contentLength} %{contentType}, map[contentLength:45 contentType:text/plain; charset=utf-8 statusCode:200]",
+		"info, Response %{statusCode} %{contentLength} %{contentType}, map[contentLength:41 contentType:text/plain; charset=utf-8 statusCode:200]",
 	}
 	logger.AssertLogEntries(t, expected...)
 }
 
 func TestSDKLoggerWithCustomLoggerDefaultConfigWithHeaders(t *testing.T) {
 	request := callBuilder(ctx, "GET", "//response/")
-	request.AppendPath("/binary")
+	request.AppendPath("/binary/customHeader")
 	request.Header("Content-Type", "application/file")
+	request.Header("custom-header", "CustomHeaderValue")
 	logger := &fmtLogger{}
 	request.Logger(NewSdkLogger(NewLoggerConfiguration(
 		WithLogger(logger),
@@ -135,9 +180,9 @@ func TestSDKLoggerWithCustomLoggerDefaultConfigWithHeaders(t *testing.T) {
 	_callRequestAsJson(t, request)
 
 	expected := []string{
-		"info, Request %{method} %{url} %{contentType}, map[contentType:application/file method:GET url:" + serverUrl + "/response/binary]",
-		"info, Request headers %{headers}, map[headers:map[Content-Type:[application/file]]]",
-		"info, Response %{statusCode} %{contentLength} %{contentType}, map[contentLength:45 contentType:text/plain; charset=utf-8 statusCode:200]",
+		"info, Request %{method} %{url} %{contentType}, map[contentType:application/file method:GET url:" + serverUrl + "/response/binary/customHeader]",
+		"info, Request headers %{headers}, map[headers:map[Content-Type:[application/file] Custom-Header:[**Redacted**]]]",
+		"info, Response %{statusCode} %{contentLength} %{contentType}, map[contentLength:41 contentType:text/plain; charset=utf-8 statusCode:200]",
 	}
 	logger.AssertLogEntries(t, expected...)
 }
@@ -174,10 +219,10 @@ func TestSDKLoggerWithCustomLoggerCustomConfig(t *testing.T) {
 	expected := []string{
 		"debug, Request %{method} %{url} %{contentType}, map[contentType:application/file method:GET url:" + serverUrl + "/response/binary]",
 		"debug, Request headers %{headers}, map[headers:map[Authorization:[**Redacted**] Content-Type:[application/file]]]",
-		"debug, Request body %{body}, map[body:null]",
-		"debug, Response %{statusCode} %{contentLength} %{contentType}, map[contentLength:45 contentType:text/plain; charset=utf-8 statusCode:200]",
+		"debug, Request body %{body}, map[body:<nil>]",
+		"debug, Response %{statusCode} %{contentLength} %{contentType}, map[contentLength:41 contentType:text/plain; charset=utf-8 statusCode:200]",
 		"debug, Response headers %{headers}, map[headers:map[Content-Type:[text/plain; charset=utf-8]]]",
-		"debug, Response body %{body}, map[body:{}]",
+		"debug, Response body %{body}, map[body:\"passed\": true, \"message\": \"It's a hit!\",]",
 	}
 	logger.AssertLogEntries(t, expected...)
 }