diff --git a/internal/engine/experiment/webconnectivity/control.go b/internal/engine/experiment/webconnectivity/control.go index ff5136b..2e69055 100644 --- a/internal/engine/experiment/webconnectivity/control.go +++ b/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) diff --git a/internal/engine/experiment/websteps/control.go b/internal/engine/experiment/websteps/control.go index 2cbe07e..db0c18f 100644 --- a/internal/engine/experiment/websteps/control.go +++ b/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 diff --git a/internal/engine/geolocate/avast.go b/internal/engine/geolocate/avast.go index 3bb5500..4261c55 100644 --- a/internal/engine/geolocate/avast.go +++ b/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 } diff --git a/internal/engine/geolocate/ipconfig.go b/internal/engine/geolocate/ipconfig.go index ebf7ebe..a5d466d 100644 --- a/internal/engine/geolocate/ipconfig.go +++ b/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 } diff --git a/internal/engine/geolocate/ipinfo.go b/internal/engine/geolocate/ipinfo.go index 9d70764..703d19a 100644 --- a/internal/engine/geolocate/ipinfo.go +++ b/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 } diff --git a/internal/engine/geolocate/ubuntu.go b/internal/engine/geolocate/ubuntu.go index 20e42c3..3cc48e4 100644 --- a/internal/engine/geolocate/ubuntu.go +++ b/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 } diff --git a/internal/engine/httpx/httpx.go b/internal/engine/httpx/httpx.go index 1f08a89..fb37a9f 100644 --- a/internal/engine/httpx/httpx.go +++ b/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) } diff --git a/internal/engine/httpx/httpx_test.go b/internal/engine/httpx/httpx_test.go index dc32470..b151667 100644 --- a/internal/engine/httpx/httpx_test.go +++ b/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) + } + }) + }) } diff --git a/internal/engine/probeservices/bouncer.go b/internal/engine/probeservices/bouncer.go index 9a1f0ff..7ddc3fd 100644 --- a/internal/engine/probeservices/bouncer.go +++ b/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 } diff --git a/internal/engine/probeservices/checkreportid.go b/internal/engine/probeservices/checkreportid.go index a16755a..20e1bed 100644 --- a/internal/engine/probeservices/checkreportid.go +++ b/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 } diff --git a/internal/engine/probeservices/collector.go b/internal/engine/probeservices/collector.go index b363360..3504dbb 100644 --- a/internal/engine/probeservices/collector.go +++ b/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, diff --git a/internal/engine/probeservices/measurementmeta.go b/internal/engine/probeservices/measurementmeta.go index 915e7b4..8d03a3d 100644 --- a/internal/engine/probeservices/measurementmeta.go +++ b/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 } diff --git a/internal/engine/probeservices/urls.go b/internal/engine/probeservices/urls.go index abdb06a..e28e198 100644 --- a/internal/engine/probeservices/urls.go +++ b/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