feat(httpx): implement optional body logging also on http error (#651)

1. we want optionally to log the body (we don't want to log the body
when we're fetching psiphon secrets or tor targets)

2. we want body logging to _also_ happen on error since this is quite
useful to debug possible errors when accessing the API

This diff adds the above functionality, which were previously
described in https://github.com/ooni/probe/issues/1951.

This diff also adds comprehensive testing.

internal/engine/experiment/webconnectivity/control.go

@@ -62,7 +62,7 @@ func Control(
 	sess.Logger().Infof("control for %s...", creq.HTTPRequest)
 	// make sure error is wrapped
 	err = legacyerrorsx.SafeErrWrapperBuilder{
-		Error:     clnt.Build().PostJSON(ctx, "/", creq, &out),
+		Error:     clnt.WithBodyLogging().Build().PostJSON(ctx, "/", creq, &out),
 		Operation: netxlite.TopLevelOperation,
 	}.MaybeBuild()
 	sess.Logger().Infof("control for %s... %+v", creq.HTTPRequest, err)

internal/engine/experiment/websteps/control.go

@@ -20,7 +20,7 @@ func Control(
 	}
 	// make sure error is wrapped
 	err = errorsxlegacy.SafeErrWrapperBuilder{
-		Error:     clnt.Build().PostJSON(ctx, resourcePath, creq, &out),
+		Error:     clnt.WithBodyLogging().Build().PostJSON(ctx, resourcePath, creq, &out),
 		Operation: netxlite.TopLevelOperation,
 	}.MaybeBuild()
 	return

internal/engine/geolocate/avast.go

@@ -24,7 +24,7 @@ func avastIPLookup(
 		HTTPClient: httpClient,
 		Logger:     logger,
 		UserAgent:  userAgent,
-	}).Build().GetJSON(ctx, "/v1/info", &v)
+	}).WithBodyLogging().Build().GetJSON(ctx, "/v1/info", &v)
 	if err != nil {
 		return DefaultProbeIP, err
 	}

internal/engine/geolocate/ipconfig.go

@@ -21,7 +21,7 @@ func ipConfigIPLookup(
 		HTTPClient: httpClient,
 		Logger:     logger,
 		UserAgent:  httpheader.CLIUserAgent(),
-	}).Build().FetchResource(ctx, "/")
+	}).WithBodyLogging().Build().FetchResource(ctx, "/")
 	if err != nil {
 		return DefaultProbeIP, err
 	}

internal/engine/geolocate/ipinfo.go

@@ -26,7 +26,7 @@ func ipInfoIPLookup(
 		HTTPClient: httpClient,
 		Logger:     logger,
 		UserAgent:  httpheader.CLIUserAgent(), // we must be a CLI client
-	}).Build().GetJSON(ctx, "/", &v)
+	}).WithBodyLogging().Build().GetJSON(ctx, "/", &v)
 	if err != nil {
 		return DefaultProbeIP, err
 	}

internal/engine/geolocate/ubuntu.go

@@ -25,7 +25,7 @@ func ubuntuIPLookup(
 		HTTPClient: httpClient,
 		Logger:     logger,
 		UserAgent:  userAgent,
-	}).Build().FetchResource(ctx, "/lookup")
+	}).WithBodyLogging().Build().FetchResource(ctx, "/lookup")
 	if err != nil {
 		return DefaultProbeIP, err
 	}

internal/engine/httpx/httpx.go

@@ -33,6 +33,9 @@ type APIClientTemplate struct {
 	// to implement, e.g., cloudfronting.
 	Host string
 
+	// LogBody is the OPTIONAL flag to force logging the bodies.
+	LogBody bool
+
 	// Logger is MANDATORY the logger to use.
 	Logger model.DebugLogger
 
@@ -40,6 +43,13 @@ type APIClientTemplate struct {
 	UserAgent string
 }
 
+// WithBodyLogging enables logging of request and response bodies.
+func (tmpl *APIClientTemplate) WithBodyLogging() *APIClientTemplate {
+	out := APIClientTemplate(*tmpl)
+	out.LogBody = true
+	return &out
+}
+
 // Build creates an APIClient from the APIClientTemplate.
 func (tmpl *APIClientTemplate) Build() APIClient {
 	return tmpl.BuildWithAuthorization(tmpl.Authorization)
@@ -99,6 +109,9 @@ type apiClient struct {
 	// to implement, e.g., cloudfronting.
 	Host string
 
+	// LogBody is the OPTIONAL flag to force logging the bodies.
+	LogBody bool
+
 	// Logger is MANDATORY the logger to use.
 	Logger model.DebugLogger
 
@@ -114,7 +127,10 @@ func (c *apiClient) newRequestWithJSONBody(
 	if err != nil {
 		return nil, err
 	}
-	c.Logger.Debugf("httpx: request body: %d bytes", len(data))
+	c.Logger.Debugf("httpx: request body length: %d bytes", len(data))
+	if c.LogBody {
+		c.Logger.Debugf("httpx: request body: %s", string(data))
+	}
 	request, err := c.newRequest(
 		ctx, method, resourcePath, query, bytes.NewReader(data))
 	if err != nil {
@@ -162,14 +178,20 @@ func (c *apiClient) do(request *http.Request) ([]byte, error) {
 		return nil, err
 	}
 	defer response.Body.Close()
-	if response.StatusCode >= 400 {
-		return nil, fmt.Errorf("%w: %s", ErrRequestFailed, response.Status)
-	}
+	// Implementation note: always read and log the response body since
+	// it's quite useful to see the response JSON on API error.
 	r := io.LimitReader(response.Body, DefaultMaxBodySize)
 	data, err := netxlite.ReadAllContext(request.Context(), r)
 	if err != nil {
 		return nil, err
 	}
+	c.Logger.Debugf("httpx: response body length: %d bytes", len(data))
+	if c.LogBody {
+		c.Logger.Debugf("httpx: response body: %s", string(data))
+	}
+	if response.StatusCode >= 400 {
+		return nil, fmt.Errorf("%w: %s", ErrRequestFailed, response.Status)
+	}
 	return data, nil
 }
 
@@ -180,7 +202,6 @@ func (c *apiClient) doJSON(request *http.Request, output interface{}) error {
 	if err != nil {
 		return err
 	}
-	c.Logger.Debugf("httpx: response body: %d bytes", len(data))
 	return json.Unmarshal(data, output)
 }
 

internal/engine/httpx/httpx_test.go

@@ -24,6 +24,21 @@ import (
 var userAgent = fmt.Sprintf("ooniprobe-cli/%s", version.Version)
 
 func TestAPIClientTemplate(t *testing.T) {
+	t.Run("WithBodyLogging", func(t *testing.T) {
+		tmpl := &APIClientTemplate{
+			HTTPClient: http.DefaultClient,
+			LogBody:    false, // explicit default initialization for clarity
+			Logger:     model.DiscardLogger,
+		}
+		child := tmpl.WithBodyLogging()
+		if !child.LogBody {
+			t.Fatal("expected body logging to be enabled")
+		}
+		if tmpl.LogBody {
+			t.Fatal("expected body logging to still be disabled")
+		}
+	})
+
 	t.Run("normal constructor", func(t *testing.T) {
 		// Implementation note: the fakefiller will ignore the
 		// fields it does not know how to fill, so we are filling
@@ -418,4 +433,180 @@ func TestAPIClient(t *testing.T) {
 			t.Fatal("unexpected data")
 		}
 	})
+
+	t.Run("body logging", func(t *testing.T) {
+		t.Run("logging enabled and 200 Ok", func(t *testing.T) {
+			server := httptest.NewServer(http.HandlerFunc(
+				func(w http.ResponseWriter, r *http.Request) {
+					w.Write([]byte("[]"))
+				},
+			))
+			logs := make(chan string, 1024)
+			defer server.Close()
+			var (
+				input  []string
+				output []string
+			)
+			ctx := context.Background()
+			err := (&apiClient{
+				BaseURL:    server.URL,
+				HTTPClient: http.DefaultClient,
+				LogBody:    true,
+				Logger: &mocks.Logger{
+					MockDebugf: func(format string, v ...interface{}) {
+						logs <- fmt.Sprintf(format, v...)
+					},
+				},
+			}).PostJSON(ctx, "/", input, &output)
+			var found int
+			close(logs)
+			for entry := range logs {
+				if strings.HasPrefix(entry, "httpx: request body: ") {
+					found |= 1 << 0
+					continue
+				}
+				if strings.HasPrefix(entry, "httpx: response body: ") {
+					found |= 1 << 1
+					continue
+				}
+			}
+			if found != (1<<0 | 1<<1) {
+				t.Fatal("did not find logs")
+			}
+			if err != nil {
+				t.Fatal(err)
+			}
+		})
+
+		t.Run("logging enabled and 401 Unauthorized", func(t *testing.T) {
+			server := httptest.NewServer(http.HandlerFunc(
+				func(w http.ResponseWriter, r *http.Request) {
+					w.WriteHeader(401)
+					w.Write([]byte("[]"))
+				},
+			))
+			logs := make(chan string, 1024)
+			defer server.Close()
+			var (
+				input  []string
+				output []string
+			)
+			ctx := context.Background()
+			err := (&apiClient{
+				BaseURL:    server.URL,
+				HTTPClient: http.DefaultClient,
+				LogBody:    true,
+				Logger: &mocks.Logger{
+					MockDebugf: func(format string, v ...interface{}) {
+						logs <- fmt.Sprintf(format, v...)
+					},
+				},
+			}).PostJSON(ctx, "/", input, &output)
+			var found int
+			close(logs)
+			for entry := range logs {
+				if strings.HasPrefix(entry, "httpx: request body: ") {
+					found |= 1 << 0
+					continue
+				}
+				if strings.HasPrefix(entry, "httpx: response body: ") {
+					found |= 1 << 1
+					continue
+				}
+			}
+			if found != (1<<0 | 1<<1) {
+				t.Fatal("did not find logs")
+			}
+			if !errors.Is(err, ErrRequestFailed) {
+				t.Fatal("unexpected err", err)
+			}
+		})
+
+		t.Run("logging NOT enabled and 200 Ok", func(t *testing.T) {
+			server := httptest.NewServer(http.HandlerFunc(
+				func(w http.ResponseWriter, r *http.Request) {
+					w.Write([]byte("[]"))
+				},
+			))
+			logs := make(chan string, 1024)
+			defer server.Close()
+			var (
+				input  []string
+				output []string
+			)
+			ctx := context.Background()
+			err := (&apiClient{
+				BaseURL:    server.URL,
+				HTTPClient: http.DefaultClient,
+				LogBody:    false, // explicit initialization
+				Logger: &mocks.Logger{
+					MockDebugf: func(format string, v ...interface{}) {
+						logs <- fmt.Sprintf(format, v...)
+					},
+				},
+			}).PostJSON(ctx, "/", input, &output)
+			var found int
+			close(logs)
+			for entry := range logs {
+				if strings.HasPrefix(entry, "httpx: request body: ") {
+					found |= 1 << 0
+					continue
+				}
+				if strings.HasPrefix(entry, "httpx: response body: ") {
+					found |= 1 << 1
+					continue
+				}
+			}
+			if found != 0 {
+				t.Fatal("did find logs")
+			}
+			if err != nil {
+				t.Fatal(err)
+			}
+		})
+
+		t.Run("logging NOT enabled and 401 Unauthorized", func(t *testing.T) {
+			server := httptest.NewServer(http.HandlerFunc(
+				func(w http.ResponseWriter, r *http.Request) {
+					w.WriteHeader(401)
+					w.Write([]byte("[]"))
+				},
+			))
+			logs := make(chan string, 1024)
+			defer server.Close()
+			var (
+				input  []string
+				output []string
+			)
+			ctx := context.Background()
+			err := (&apiClient{
+				BaseURL:    server.URL,
+				HTTPClient: http.DefaultClient,
+				LogBody:    false, // explicit initialization
+				Logger: &mocks.Logger{
+					MockDebugf: func(format string, v ...interface{}) {
+						logs <- fmt.Sprintf(format, v...)
+					},
+				},
+			}).PostJSON(ctx, "/", input, &output)
+			var found int
+			close(logs)
+			for entry := range logs {
+				if strings.HasPrefix(entry, "httpx: request body: ") {
+					found |= 1 << 0
+					continue
+				}
+				if strings.HasPrefix(entry, "httpx: response body: ") {
+					found |= 1 << 1
+					continue
+				}
+			}
+			if found != 0 {
+				t.Fatal("did find logs")
+			}
+			if !errors.Is(err, ErrRequestFailed) {
+				t.Fatal("unexpected err", err)
+			}
+		})
+	})
 }

internal/engine/probeservices/bouncer.go

@@ -9,6 +9,6 @@ import (
 // GetTestHelpers is like GetCollectors but for test helpers.
 func (c Client) GetTestHelpers(
 	ctx context.Context) (output map[string][]model.OOAPIService, err error) {
-	err = c.APIClientTemplate.Build().GetJSON(ctx, "/api/v1/test-helpers", &output)
+	err = c.APIClientTemplate.WithBodyLogging().Build().GetJSON(ctx, "/api/v1/test-helpers", &output)
 	return
 }

internal/engine/probeservices/checkreportid.go

@@ -21,7 +21,7 @@ func (c Client) CheckReportID(ctx context.Context, reportID string) (bool, error
 		HTTPClient: c.HTTPClient,
 		Logger:     c.Logger,
 		UserAgent:  c.UserAgent,
-	}).Build().GetJSONWithQuery(ctx, "/api/_/check_report_id", query, &response)
+	}).WithBodyLogging().Build().GetJSONWithQuery(ctx, "/api/_/check_report_id", query, &response)
 	if err != nil {
 		return false, err
 	}

internal/engine/probeservices/collector.go

@@ -105,7 +105,7 @@ func (c Client) OpenReport(ctx context.Context, rt ReportTemplate) (ReportChanne
 		return nil, ErrUnsupportedFormat
 	}
 	var cor collectorOpenResponse
-	if err := c.APIClientTemplate.Build().PostJSON(ctx, "/report", rt, &cor); err != nil {
+	if err := c.APIClientTemplate.WithBodyLogging().Build().PostJSON(ctx, "/report", rt, &cor); err != nil {
 		return nil, err
 	}
 	for _, format := range cor.SupportedFormats {
@@ -144,7 +144,7 @@ func (r reportChan) CanSubmit(m *model.Measurement) bool {
 func (r reportChan) SubmitMeasurement(ctx context.Context, m *model.Measurement) error {
 	var updateResponse collectorUpdateResponse
 	m.ReportID = r.ID
-	err := r.client.APIClientTemplate.Build().PostJSON(
+	err := r.client.APIClientTemplate.WithBodyLogging().Build().PostJSON(
 		ctx, fmt.Sprintf("/report/%s", r.ID), collectorUpdateRequest{
 			Format:  "json",
 			Content: m,

internal/engine/probeservices/measurementmeta.go

@@ -59,7 +59,7 @@ func (c Client) GetMeasurementMeta(
 		HTTPClient: c.HTTPClient,
 		Logger:     c.Logger,
 		UserAgent:  c.UserAgent,
-	}).Build().GetJSONWithQuery(ctx, "/api/v1/measurement_meta", query, &response)
+	}).WithBodyLogging().Build().GetJSONWithQuery(ctx, "/api/v1/measurement_meta", query, &response)
 	if err != nil {
 		return nil, err
 	}

internal/engine/probeservices/urls.go

@@ -28,7 +28,7 @@ func (c Client) FetchURLList(ctx context.Context, config model.OOAPIURLListConfi
 		query.Set("category_codes", strings.Join(config.Categories, ","))
 	}
 	var response urlListResult
-	err := c.APIClientTemplate.Build().GetJSONWithQuery(ctx,
+	err := c.APIClientTemplate.WithBodyLogging().Build().GetJSONWithQuery(ctx,
 		"/api/v1/test-list/urls", query, &response)
 	if err != nil {
 		return nil, err