Log response body in PostJSONWithTimeout error case (#40509)

<!-- Add the related story/sub-task/bug number, like Resolves #123, or
remove if NA -->
# Checklist for submitter


- [x] Changes file added for user-visible changes in `changes/`,
`orbit/changes/` or `ee/fleetd-chrome/changes`.
See [Changes
files](https://github.com/fleetdm/fleet/blob/main/docs/Contributing/guides/committing-changes.md#changes-files)
for more information.

## Testing

- [ ] QA'd all new/changed functionality manually

changes/14276-post-json-redact-response-body

@@ -0,0 +1 @@
+* Changed PostJSONWithTimeout to log response body in error case.

cmd/fleet/cron.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"log/slog"
 	"net/url"
 	"os"
 	"strconv"
@@ -1285,6 +1286,7 @@ func newUsageStatisticsSchedule(ctx context.Context, instanceID string, ds fleet
 		name            = string(fleet.CronUsageStatistics)
 		defaultInterval = 1 * time.Hour
 	)
+	slogLogger := logger.SlogLogger()
 	s := schedule.New(
 		ctx, name, instanceID, defaultInterval, ds, ds,
 		schedule.WithLogger(logger.With("cron", name)),
@@ -1293,7 +1295,7 @@ func newUsageStatisticsSchedule(ctx context.Context, instanceID string, ds fleet
 			func(ctx context.Context) error {
 				// NOTE(mna): this is not a route from the fleet server (not in server/service/handler.go) so it
 				// will not automatically support the /latest/ versioning. Leaving it as /v1/ for that reason.
-				return trySendStatistics(ctx, ds, fleet.StatisticsFrequency, "https://fleetdm.com/api/v1/webhooks/receive-usage-analytics", config)
+				return trySendStatistics(ctx, ds, fleet.StatisticsFrequency, "https://fleetdm.com/api/v1/webhooks/receive-usage-analytics", config, slogLogger)
 			},
 		),
 	)
@@ -1301,7 +1303,7 @@ func newUsageStatisticsSchedule(ctx context.Context, instanceID string, ds fleet
 	return s, nil
 }
 
-func trySendStatistics(ctx context.Context, ds fleet.Datastore, frequency time.Duration, url string, config config.FleetConfig) error {
+func trySendStatistics(ctx context.Context, ds fleet.Datastore, frequency time.Duration, url string, config config.FleetConfig, logger *slog.Logger) error {
 	ac, err := ds.AppConfig(ctx)
 	if err != nil {
 		return err
@@ -1320,7 +1322,7 @@ func trySendStatistics(ctx context.Context, ds fleet.Datastore, frequency time.D
 		return nil
 	}
 
-	if err := server.PostJSONWithTimeout(ctx, url, stats); err != nil {
+	if err := server.PostJSONWithTimeout(ctx, url, stats, logger); err != nil {
 		return err
 	}
 

cmd/fleet/serve.go

@@ -1813,7 +1813,9 @@ func createActivityBoundedContext(svc fleet.Service, dbConns *common_mysql.DBCon
 		dbConns,
 		activityAuthorizer,
 		activityACLAdapter,
-		server.PostJSONWithTimeout,
+		func(ctx context.Context, url string, payload any) error {
+			return server.PostJSONWithTimeout(ctx, url, payload, logger)
+		},
 		logger,
 	)
 	// Create auth middleware for activity bounded context

cmd/fleet/serve_test.go

@@ -7,6 +7,7 @@ import (
 	"encoding/json"
 	"errors"
 	"io"
+	"log/slog"
 	"net/http"
 	"net/http/httptest"
 	"os"
@@ -137,7 +138,7 @@ func TestMaybeSendStatistics(t *testing.T) {
 	}
 
 	ctx := license.NewContext(context.Background(), &fleet.LicenseInfo{Tier: fleet.TierPremium})
-	err := trySendStatistics(ctx, ds, fleet.StatisticsFrequency, ts.URL, fleetConfig)
+	err := trySendStatistics(ctx, ds, fleet.StatisticsFrequency, ts.URL, fleetConfig, slog.Default())
 	require.NoError(t, err)
 	assert.True(t, recorded)
 	require.True(t, cleanedup)
@@ -175,7 +176,7 @@ func TestMaybeSendStatisticsSkipsSendingIfNotNeeded(t *testing.T) {
 	}
 
 	ctx := license.NewContext(context.Background(), &fleet.LicenseInfo{Tier: fleet.TierPremium})
-	err := trySendStatistics(ctx, ds, fleet.StatisticsFrequency, ts.URL, fleetConfig)
+	err := trySendStatistics(ctx, ds, fleet.StatisticsFrequency, ts.URL, fleetConfig, slog.Default())
 	require.NoError(t, err)
 	assert.False(t, recorded)
 	assert.False(t, cleanedup)
@@ -199,7 +200,7 @@ func TestMaybeSendStatisticsSkipsIfNotConfigured(t *testing.T) {
 	}
 
 	ctx := license.NewContext(context.Background(), &fleet.LicenseInfo{Tier: fleet.TierFree})
-	err := trySendStatistics(ctx, ds, fleet.StatisticsFrequency, ts.URL, fleetConfig)
+	err := trySendStatistics(ctx, ds, fleet.StatisticsFrequency, ts.URL, fleetConfig, slog.Default())
 	require.NoError(t, err)
 	assert.False(t, called)
 }
@@ -229,7 +230,7 @@ func TestMaybeSendStatisticsSendsIfNotConfiguredForPremium(t *testing.T) {
 	ds.RecordStatisticsSentFunc = func(ctx context.Context) error { return nil }
 
 	ctx := license.NewContext(context.Background(), &fleet.LicenseInfo{Tier: fleet.TierPremium})
-	err := trySendStatistics(ctx, ds, fleet.StatisticsFrequency, ts.URL, fleetConfig)
+	err := trySendStatistics(ctx, ds, fleet.StatisticsFrequency, ts.URL, fleetConfig, slog.Default())
 	require.NoError(t, err)
 	assert.True(t, called)
 }

ee/server/service/devices.go

@@ -81,7 +81,7 @@ func (svc *Service) TriggerMigrateMDMDevice(ctx context.Context, host *fleet.Hos
 	p.Host.UUID = host.UUID
 	p.Host.HardwareSerial = host.HardwareSerial
 
-	if err := server.PostJSONWithTimeout(ctx, ac.MDM.MacOSMigration.WebhookURL, p); err != nil {
+	if err := server.PostJSONWithTimeout(ctx, ac.MDM.MacOSMigration.WebhookURL, p, svc.logger.SlogLogger()); err != nil {
 		return ctxerr.Wrap(ctx, err, "posting macOS migration webhook")
 	}
 

server/datastore/mysql/testing_utils.go

@@ -1032,7 +1032,10 @@ func NewTestActivityService(t testing.TB, ds *Datastore) activity_api.Service {
 	aclAdapter := activityacl.NewFleetServiceAdapter(lookupSvc)
 
 	// Create service via bootstrap (the public API for creating the bounded context)
-	svc, _ := activity_bootstrap.New(dbConns, &testingAuthorizer{}, aclAdapter, server.PostJSONWithTimeout, slog.New(slog.DiscardHandler))
+	discardLogger := slog.New(slog.DiscardHandler)
+	svc, _ := activity_bootstrap.New(dbConns, &testingAuthorizer{}, aclAdapter, func(ctx context.Context, url string, payload any) error {
+		return server.PostJSONWithTimeout(ctx, url, payload, discardLogger)
+	}, discardLogger)
 	return svc
 }
 

server/fleet/calendar.go

@@ -3,6 +3,7 @@ package fleet
 import (
 	"context"
 	"fmt"
+	"log/slog"
 	"time"
 	_ "time/tzdata" // embed timezone information in the program
 
@@ -102,6 +103,7 @@ func FireCalendarWebhook(
 	hostDisplayName string,
 	failingCalendarPolicies []PolicyCalendarData,
 	err string,
+	logger *slog.Logger,
 ) error {
 	if err := server.PostJSONWithTimeout(context.Background(), webhookURL, &CalendarWebhookPayload{
 		Timestamp:        time.Now(),
@@ -110,7 +112,7 @@ func FireCalendarWebhook(
 		HostSerialNumber: hostHardwareSerial,
 		FailingPolicies:  failingCalendarPolicies,
 		Error:            err,
-	}); err != nil {
+	}, logger); err != nil {
 		return fmt.Errorf("POST to %q: %w", server.MaskSecretURLParams(webhookURL), server.MaskURLError(err))
 	}
 	return nil

server/logging/webhook.go

@@ -45,7 +45,7 @@ func (w *webhookLogWriter) Write(ctx context.Context, logs []json.RawMessage) er
 		"url", server.MaskSecretURLParams(w.url),
 	)
 
-	if err := server.PostJSONWithTimeout(ctx, w.url, payload); err != nil {
+	if err := server.PostJSONWithTimeout(ctx, w.url, payload, w.logger.SlogLogger()); err != nil {
 		level.Error(w.logger).Log(
 			"msg", fmt.Sprintf("failed to send automation webhook to %s", server.MaskSecretURLParams(w.url)),
 			"err", server.MaskURLError(err).Error(),

server/service/activities_test.go

@@ -213,7 +213,10 @@ func TestActivityWebhooks(t *testing.T) {
 			}, nil
 		},
 	}
-	realActivitySvc := activity_bootstrap.NewForUnitTests(providers, fleetserver.PostJSONWithTimeout, slog.New(slog.DiscardHandler))
+	discardLogger := slog.New(slog.DiscardHandler)
+	realActivitySvc := activity_bootstrap.NewForUnitTests(providers, func(ctx context.Context, url string, payload any) error {
+		return fleetserver.PostJSONWithTimeout(ctx, url, payload, discardLogger)
+	}, discardLogger)
 	opts.ActivityMock.Delegate = realActivitySvc
 
 	var activityUser *activity_api.User

server/service/osquery.go

@@ -1373,6 +1373,7 @@ func processCalendarPolicies(
 				if err := fleet.FireCalendarWebhook(
 					team.Config.Integrations.GoogleCalendar.WebhookURL,
 					host.ID, host.HardwareSerial, host.DisplayName(), failingCalendarPolicies, "",
+					logger.SlogLogger(),
 				); err != nil {
 					var statusCoder kithttp.StatusCoder
 					if errors.As(err, &statusCoder) && statusCoder.StatusCode() == http.StatusTooManyRequests {

server/service/testing_utils.go

@@ -486,12 +486,15 @@ func RunServerForTestsWithServiceWithDS(t *testing.T, ctx context.Context, ds fl
 		require.NoError(t, err)
 		activityAuthorizer := authz.NewAuthorizerAdapter(legacyAuthorizer)
 		activityACLAdapter := activityacl.NewFleetServiceAdapter(svc)
+		slogLogger := logger.SlogLogger()
 		activitySvc, activityRoutesFn := activity_bootstrap.New(
 			opts[0].DBConns,
 			activityAuthorizer,
 			activityACLAdapter,
-			server.PostJSONWithTimeout,
-			logger.SlogLogger(),
+			func(ctx context.Context, url string, payload any) error {
+				return server.PostJSONWithTimeout(ctx, url, payload, slogLogger)
+			},
+			slogLogger,
 		)
 		svc.SetActivityService(activitySvc)
 		if opts[0].ActivityModule != nil {

server/utils.go

@@ -13,6 +13,7 @@ import (
 	"fmt"
 	"html/template"
 	"io"
+	"log/slog"
 	"net/http"
 	"strings"
 	"time"
@@ -64,7 +65,7 @@ func (e *errWithStatus) StatusCode() int {
 	return e.statusCode
 }
 
-func PostJSONWithTimeout(ctx context.Context, url string, v interface{}) error {
+func PostJSONWithTimeout(ctx context.Context, url string, v any, logger *slog.Logger) error {
 	jsonBytes, err := json.Marshal(v)
 	if err != nil {
 		return err
@@ -86,7 +87,16 @@ func PostJSONWithTimeout(ctx context.Context, url string, v interface{}) error {
 
 	if !httpSuccessStatus(resp.StatusCode) {
 		body, _ := io.ReadAll(resp.Body)
-		return &errWithStatus{err: fmt.Sprintf("error posting to %s: %d. %s", MaskSecretURLParams(url), resp.StatusCode, string(body)), statusCode: resp.StatusCode}
+		bodyStr := string(body)
+		if len(bodyStr) > 512 {
+			bodyStr = bodyStr[:512]
+		}
+		logger.DebugContext(ctx, "non-success response from POST",
+			"url", MaskSecretURLParams(url),
+			"status_code", resp.StatusCode,
+			"body", bodyStr,
+		)
+		return &errWithStatus{err: fmt.Sprintf("error posting to %s", MaskSecretURLParams(url)), statusCode: resp.StatusCode}
 	}
 
 	return nil

server/webhooks/failing_policies.go

@@ -79,7 +79,7 @@ func SendFailingPoliciesBatchedPOSTs(
 			jsonBytes = endpointer.DuplicateJSONKeys(jsonBytes, rules, endpointer.DuplicateJSONKeysOpts{Compact: true})
 		}
 
-		if err := server.PostJSONWithTimeout(ctx, webhookURL.String(), json.RawMessage(jsonBytes)); err != nil {
+		if err := server.PostJSONWithTimeout(ctx, webhookURL.String(), json.RawMessage(jsonBytes), logger); err != nil {
 			return ctxerr.Wrapf(ctx, server.MaskURLError(err), "posting to %q", server.MaskSecretURLParams(webhookURL.String()))
 		}
 		if err := failingPoliciesSet.RemoveHosts(policy.ID, batch); err != nil {

server/webhooks/host_status.go

@@ -34,10 +34,10 @@ func triggerGlobalHostStatusWebhook(ctx context.Context, ds fleet.Datastore, log
 
 	logger.DebugContext(ctx, "host status webhook triggered", "global", true)
 
-	return processWebhook(ctx, ds, nil, appConfig.WebhookSettings.HostStatusWebhook)
+	return processWebhook(ctx, ds, nil, appConfig.WebhookSettings.HostStatusWebhook, logger)
 }
 
-func processWebhook(ctx context.Context, ds fleet.Datastore, teamID *uint, settings fleet.HostStatusWebhookSettings) error {
+func processWebhook(ctx context.Context, ds fleet.Datastore, teamID *uint, settings fleet.HostStatusWebhookSettings, logger *slog.Logger) error {
 	total, unseen, err := ds.TotalAndUnseenHostsSince(ctx, teamID, settings.DaysCount)
 	if err != nil {
 		return ctxerr.Wrap(ctx, err, "getting total and unseen hosts")
@@ -67,7 +67,7 @@ func processWebhook(ctx context.Context, ds fleet.Datastore, teamID *uint, setti
 			payload["data"].(map[string]any)["team_id"] = *teamID
 		}
 
-		err = server.PostJSONWithTimeout(ctx, url, &payload)
+		err = server.PostJSONWithTimeout(ctx, url, &payload, logger)
 		if err != nil {
 			return ctxerr.Wrapf(ctx, err, "posting to %s", url)
 		}
@@ -94,7 +94,7 @@ func triggerTeamHostStatusWebhook(ctx context.Context, ds fleet.Datastore, logge
 			continue
 		}
 		logger.DebugContext(ctx, "host status webhook triggered", "fleet_id", id)
-		err = processWebhook(ctx, ds, &id, *team.Config.WebhookSettings.HostStatusWebhook)
+		err = processWebhook(ctx, ds, &id, *team.Config.WebhookSettings.HostStatusWebhook, logger)
 		if err != nil {
 			multiErr = multierror.Append(multiErr, ctxerr.Wrap(ctx, err, "processing webhook"))
 		}

server/webhooks/vulnerabilities.go

@@ -52,7 +52,7 @@ func TriggerVulnerabilitiesWebhook(
 				limit = batchSize
 			}
 			payload := mapper.GetPayload(serverURL, hosts[:limit], cve, args.Meta[cve])
-			if err := sendVulnerabilityHostBatch(ctx, targetURL, payload, args.Time); err != nil {
+			if err := sendVulnerabilityHostBatch(ctx, targetURL, payload, args.Time, logger); err != nil {
 				return ctxerr.Wrap(ctx, err, "send vulnerability host batch")
 			}
 			hosts = hosts[limit:]
@@ -62,13 +62,13 @@ func TriggerVulnerabilitiesWebhook(
 	return nil
 }
 
-func sendVulnerabilityHostBatch(ctx context.Context, targetURL string, vuln WebhookPayload, now time.Time) error {
+func sendVulnerabilityHostBatch(ctx context.Context, targetURL string, vuln WebhookPayload, now time.Time, logger *slog.Logger) error {
 	payload := map[string]interface{}{
 		"timestamp":     now,
 		"vulnerability": vuln,
 	}
 
-	if err := server.PostJSONWithTimeout(ctx, targetURL, &payload); err != nil {
+	if err := server.PostJSONWithTimeout(ctx, targetURL, &payload, logger); err != nil {
 		return ctxerr.Wrapf(ctx, err, "posting to %s", targetURL)
 	}
 	return nil