diff --git a/docs/content/docs.md b/docs/content/docs.md index d05832e44..ef1faa341 100644 --- a/docs/content/docs.md +++ b/docs/content/docs.md @@ -3289,6 +3289,13 @@ The available flags are: the other HTTP debugging flags (e.g. `requests`, `bodies`). By default the auth will be masked - use with `auth` to have the curl commands with authentication too. +- `errors` only dumps the HTTP transactions which fail with a retryable + error - that is a transport error, an HTTP 429 (too many requests) or an + HTTP 5xx server error. The other dump flags control what is dumped, so + for example use `--dump errors,bodies` to dump the headers and bodies of + failed transactions only. On its own `--dump errors` dumps the headers. + This lets you capture first-failure diagnostics without the noise of + dumping every transaction. May contain sensitive info. ## Filtering diff --git a/fs/dump.go b/fs/dump.go index a2c974419..234f32214 100644 --- a/fs/dump.go +++ b/fs/dump.go @@ -15,6 +15,7 @@ const ( DumpOpenFiles DumpMapper DumpCurl + DumpErrors ) type dumpChoices struct{} @@ -31,6 +32,7 @@ func (dumpChoices) Choices() []BitsChoicesInfo { {uint64(DumpOpenFiles), "openfiles"}, {uint64(DumpMapper), "mapper"}, {uint64(DumpCurl), "curl"}, + {uint64(DumpErrors), "errors"}, } } diff --git a/fs/fshttp/dump_test.go b/fs/fshttp/dump_test.go new file mode 100644 index 000000000..c0f60d499 --- /dev/null +++ b/fs/fshttp/dump_test.go @@ -0,0 +1,144 @@ +package fshttp + +import ( + "bytes" + "context" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "sync" + "testing" + + "github.com/rclone/rclone/fs" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestIsRetryableResponse(t *testing.T) { + for _, test := range []struct { + name string + status int + err error + want bool + }{ + {name: "transport error", err: http.ErrHandlerTimeout, want: true}, + {name: "200 OK", status: 200, want: false}, + {name: "301 redirect", status: 301, want: false}, + {name: "404 not found", status: 404, want: false}, + {name: "429 too many requests", status: 429, want: true}, + {name: "500 server error", status: 500, want: true}, + {name: "503 unavailable", status: 503, want: true}, + {name: "509 bandwidth", status: 509, want: true}, + } { + t.Run(test.name, func(t *testing.T) { + var resp *http.Response + if test.err == nil { + resp = &http.Response{StatusCode: test.status} + } + got := isRetryableResponse(resp, test.err) + assert.Equal(t, test.want, got) + }) + } + + // nil response with nil error is not retryable + assert.False(t, isRetryableResponse(nil, nil)) +} + +// captureBuf is a concurrency safe buffer to capture log output into +type captureBuf struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (c *captureBuf) Write(p []byte) (int, error) { + c.mu.Lock() + defer c.mu.Unlock() + return c.buf.Write(p) +} + +func (c *captureBuf) String() string { + c.mu.Lock() + defer c.mu.Unlock() + return c.buf.String() +} + +// TestDumpErrors checks that --dump errors only dumps the transactions +// which fail with a retryable error, and that the other dump flags +// control what is dumped. +func TestDumpErrors(t *testing.T) { + // Server returns the status code asked for in the path + srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + switch r.URL.Path { + case "/500": + w.WriteHeader(http.StatusInternalServerError) + case "/429": + w.WriteHeader(http.StatusTooManyRequests) + case "/404": + w.WriteHeader(http.StatusNotFound) + default: + w.WriteHeader(http.StatusOK) + } + _, _ = w.Write([]byte("response body\n")) + })) + defer srv.Close() + + // run makes a request to path with the dump flags set and returns + // the captured log output. + run := func(t *testing.T, dump fs.DumpFlags, path string) string { + capture := &captureBuf{} + fs.SetLogger(slog.NewTextHandler(capture, &slog.HandlerOptions{Level: slog.LevelDebug})) + defer fs.SetLogger(slog.NewTextHandler(io.Discard, nil)) + + // The dump logging is emitted at Debug level and filtered + // against the global config, so set that up for the test. + ci := fs.GetConfig(context.Background()) + oldDump, oldLevel := ci.Dump, ci.LogLevel + ci.Dump = dump + ci.LogLevel = fs.LogLevelDebug + defer func() { ci.Dump = oldDump; ci.LogLevel = oldLevel }() + + client := NewClientCustom(context.Background(), nil) + req, err := http.NewRequest("GET", srv.URL+path, strings.NewReader("request body\n")) + require.NoError(t, err) + resp, err := client.Do(req) + require.NoError(t, err) + _, _ = io.Copy(io.Discard, resp.Body) + _ = resp.Body.Close() + return capture.String() + } + + // Successful and non-retryable error requests should not be dumped + for _, path := range []string{"/200", "/404"} { + out := run(t, fs.DumpErrors|fs.DumpBodies, path) + assert.NotContains(t, out, "HTTP REQUEST", path) + assert.NotContains(t, out, "HTTP RESPONSE", path) + } + + // Retryable errors should dump the request and response + out500 := run(t, fs.DumpErrors|fs.DumpBodies, "/500") + assert.Contains(t, out500, "HTTP REQUEST") + assert.Contains(t, out500, "HTTP RESPONSE") + assert.Contains(t, out500, "500 Internal Server Error") + // bodies are included because of the bodies flag + assert.Contains(t, out500, "request body") + assert.Contains(t, out500, "response body") + + out429 := run(t, fs.DumpErrors|fs.DumpBodies, "/429") + assert.Contains(t, out429, "429 Too Many Requests") + + // --dump errors on its own dumps the headers but not the bodies + headersOnly := run(t, fs.DumpErrors, "/500") + assert.Contains(t, headersOnly, "HTTP REQUEST") + assert.Contains(t, headersOnly, "HTTP RESPONSE") + assert.Contains(t, headersOnly, "500 Internal Server Error") + assert.NotContains(t, headersOnly, "response body") + + // --dump curl is also gated by errors: the curl command is only + // logged for failed transactions + curlOK := run(t, fs.DumpErrors|fs.DumpCurl, "/200") + assert.NotContains(t, curlOK, "curl") + curl500 := run(t, fs.DumpErrors|fs.DumpCurl, "/500") + assert.Contains(t, curl500, "curl") +} diff --git a/fs/fshttp/http.go b/fs/fshttp/http.go index 626cdcab2..44a02c2a7 100644 --- a/fs/fshttp/http.go +++ b/fs/fshttp/http.go @@ -32,6 +32,9 @@ import ( const ( separatorReq = ">>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>" separatorResp = "<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<" + + // dumpReqResp is the set of dump flags which dump the request and response + dumpReqResp = fs.DumpHeaders | fs.DumpBodies | fs.DumpAuth | fs.DumpRequests | fs.DumpResponses ) var ( @@ -274,7 +277,7 @@ func NewTransportCustom(ctx context.Context, customize func(*http.Transport)) *T t.IdleConnTimeout = 60 * time.Second t.ExpectContinueTimeout = time.Duration(ci.ExpectContinueTimeout) - if ci.Dump&(fs.DumpHeaders|fs.DumpBodies|fs.DumpAuth|fs.DumpRequests|fs.DumpResponses) != 0 { + if ci.Dump&(dumpReqResp|fs.DumpErrors) != 0 { fs.Debugf(nil, "You have specified to dump information. Please be noted that the "+ "Accept-Encoding as shown may not be correct in the request and the response may not show "+ "Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case"+ @@ -475,6 +478,18 @@ func (t *Transport) reloadCertificates() { t.TLSClientConfig.Certificates = []tls.Certificate{cert} } +// isRetryableResponse reports whether a round trip failed in a way which +// would trigger a low level retry - a transport error, HTTP 429 or HTTP 5xx. +func isRetryableResponse(resp *http.Response, err error) bool { + if err != nil { + return true + } + if resp == nil { + return false + } + return resp.StatusCode == 429 || resp.StatusCode >= 500 +} + // RoundTrip implements the RoundTripper interface. func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error) { // Check if certificates are being used and the certificates are expired @@ -494,21 +509,36 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error if t.filterRequest != nil { t.filterRequest(req) } - // Logf request - if t.dump&(fs.DumpHeaders|fs.DumpBodies|fs.DumpAuth|fs.DumpRequests|fs.DumpResponses) != 0 { - buf, _ := httputil.DumpRequestOut(req, t.dump&(fs.DumpBodies|fs.DumpRequests) != 0) - if t.dump&fs.DumpAuth == 0 { - buf = cleanAuths(buf) - } - logMutex.Lock() + // --dump errors only dumps failed transactions; the other flags say what to dump + wantDump := t.dump&(dumpReqResp|fs.DumpErrors) != 0 + onError := t.dump&fs.DumpErrors != 0 + // reqDump holds the request so it can be logged after the round trip on error + var reqDump []byte + dumpReq := func() { fs.Debugf(nil, "%s", separatorReq) fs.Debugf(nil, "%s (req %p)", "HTTP REQUEST", req) - fs.Debugf(nil, "%s", string(buf)) + fs.Debugf(nil, "%s", string(reqDump)) fs.Debugf(nil, "%s", separatorReq) - logMutex.Unlock() + } + // Dump request + if wantDump { + reqDump, _ = httputil.DumpRequestOut(req, t.dump&(fs.DumpBodies|fs.DumpRequests) != 0) + if t.dump&fs.DumpAuth == 0 { + reqDump = cleanAuths(reqDump) + } + // Log the request now unless we are waiting to see if it errors + if !onError { + logMutex.Lock() + dumpReq() + logMutex.Unlock() + } } // Dump curl request - if t.dump&(fs.DumpCurl) != 0 { + var curlCmd *http2curl.CurlCommand + dumpCurl := func() { + fs.Debugf(nil, "HTTP REQUEST: %v", curlCmd) + } + if t.dump&fs.DumpCurl != 0 { cmd, err := http2curl.GetCurlCommand(req) if err != nil { fs.Debugf(nil, "Failed to create curl command: %v", err) @@ -524,14 +554,24 @@ func (t *Transport) RoundTrip(req *http.Request) (resp *http.Response, err error if t.dump&fs.DumpAuth == 0 { cleanCurl(cmd) } - fs.Debugf(nil, "HTTP REQUEST: %v", cmd) + curlCmd = cmd + // Log the curl command now unless we are waiting to see if it errors + if !onError { + dumpCurl() + } } } // Do round trip resp, err = t.Transport.RoundTrip(req) - // Logf response - if t.dump&(fs.DumpHeaders|fs.DumpBodies|fs.DumpAuth|fs.DumpRequests|fs.DumpResponses) != 0 { + // Dump response, and the request too if we deferred it for --dump errors + if wantDump && (!onError || isRetryableResponse(resp, err)) { logMutex.Lock() + if onError { + dumpReq() + if curlCmd != nil { + dumpCurl() + } + } fs.Debugf(nil, "%s", separatorResp) fs.Debugf(nil, "%s (req %p)", "HTTP RESPONSE", req) if err != nil {