From 6dbde523ae1824df8b1f5c29bfad0f53acacae98 Mon Sep 17 00:00:00 2001 From: Spike Curtis Date: Wed, 12 Nov 2025 14:37:22 +0400 Subject: [PATCH] fix: omit body field from SDK client request/response logs when not logging bodies (#20729) In SDK request logs, when we don't enable LogBodies, before this change it looks in the logs like we are sending empty bodies. ``` 2025-11-08 01:03:54.710 [debu] sdk request method=POST url=https://coder.example/api/v2/workspaceagents/aws-instance-identity body="" 2025-11-08 01:03:54.765 [debu] sdk response method=POST url=https://coder.example/api/v2/workspaceagents/aws-instance-identity status=400 body="" trace_id="" span_id="" ``` This changes our request and response logging so we omit the `body` field when not logging bodies, rather than show a misleading empty string. --- codersdk/client.go | 21 +++++++++-------- codersdk/client_internal_test.go | 39 ++++++++++++++++++++++++++++++++ 2 files changed, 51 insertions(+), 9 deletions(-) diff --git a/codersdk/client.go b/codersdk/client.go index 42ad51286f..72dd7ac4b6 100644 --- a/codersdk/client.go +++ b/codersdk/client.go @@ -251,16 +251,17 @@ func (c *Client) RequestWithoutSessionToken(ctx context.Context, method, path st } // Copy the request body so we can log it. - var reqBody []byte + var reqLogFields []any c.mu.RLock() logBodies := c.logBodies c.mu.RUnlock() if r != nil && logBodies { - reqBody, err = io.ReadAll(r) + reqBody, err := io.ReadAll(r) if err != nil { return nil, xerrors.Errorf("read request body: %w", err) } r = bytes.NewReader(reqBody) + reqLogFields = append(reqLogFields, slog.F("body", string(reqBody))) } req, err := http.NewRequestWithContext(ctx, method, serverURL.String(), r) @@ -291,7 +292,7 @@ func (c *Client) RequestWithoutSessionToken(ctx context.Context, method, path st slog.F("url", req.URL.String()), ) tracing.RunWithoutSpan(ctx, func(ctx context.Context) { - c.Logger().Debug(ctx, "sdk request", slog.F("body", string(reqBody))) + c.Logger().Debug(ctx, "sdk request", reqLogFields...) }) resp, err := c.HTTPClient.Do(req) @@ -324,11 +325,11 @@ func (c *Client) RequestWithoutSessionToken(ctx context.Context, method, path st span.SetStatus(httpconv.ClientStatus(resp.StatusCode)) // Copy the response body so we can log it if it's a loggable mime type. - var respBody []byte + var respLogFields []any if resp.Body != nil && logBodies { mimeType := parseMimeType(resp.Header.Get("Content-Type")) if _, ok := loggableMimeTypes[mimeType]; ok { - respBody, err = io.ReadAll(resp.Body) + respBody, err := io.ReadAll(resp.Body) if err != nil { return nil, xerrors.Errorf("copy response body for logs: %w", err) } @@ -337,16 +338,18 @@ func (c *Client) RequestWithoutSessionToken(ctx context.Context, method, path st return nil, xerrors.Errorf("close response body: %w", err) } resp.Body = io.NopCloser(bytes.NewReader(respBody)) + respLogFields = append(respLogFields, slog.F("body", string(respBody))) } } // See above for why this is not logged to the span. tracing.RunWithoutSpan(ctx, func(ctx context.Context) { c.Logger().Debug(ctx, "sdk response", - slog.F("status", resp.StatusCode), - slog.F("body", string(respBody)), - slog.F("trace_id", resp.Header.Get("X-Trace-Id")), - slog.F("span_id", resp.Header.Get("X-Span-Id")), + append(respLogFields, + slog.F("status", resp.StatusCode), + slog.F("trace_id", resp.Header.Get("X-Trace-Id")), + slog.F("span_id", resp.Header.Get("X-Span-Id")), + )..., ) }) diff --git a/codersdk/client_internal_test.go b/codersdk/client_internal_test.go index cfd8bdbf26..415e88ac9c 100644 --- a/codersdk/client_internal_test.go +++ b/codersdk/client_internal_test.go @@ -162,6 +162,45 @@ func Test_Client(t *testing.T) { require.Contains(t, logStr, strings.ReplaceAll(resBody, `"`, `\"`)) } +func Test_Client_LogBodiesFalse(t *testing.T) { + t.Parallel() + + const method = http.MethodPost + const path = "/ok" + const reqBody = `{"msg": "request body"}` + const resBody = `{"status": "ok"}` + + s := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", jsonCT) + w.WriteHeader(http.StatusOK) + _, _ = io.WriteString(w, resBody) + })) + + u, err := url.Parse(s.URL) + require.NoError(t, err) + client := New(u) + + logBuf := bytes.NewBuffer(nil) + client.SetLogger(slog.Make(sloghuman.Sink(logBuf)).Leveled(slog.LevelDebug)) + client.SetLogBodies(false) + + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitLong) + defer cancel() + + resp, err := client.Request(ctx, method, path, []byte(reqBody)) + require.NoError(t, err) + defer resp.Body.Close() + + body, err := io.ReadAll(resp.Body) + require.NoError(t, err) + require.Equal(t, resBody, string(body)) + + logStr := logBuf.String() + require.Contains(t, logStr, "sdk request") + require.Contains(t, logStr, "sdk response") + require.NotContains(t, logStr, "body") +} + func Test_readBodyAsError(t *testing.T) { t.Parallel()