fshttp: add --dump errors to dump only failed HTTP transactions - fixes #9471

The new "errors" dump flag makes the HTTP dump conditional on the
transaction failing with a retryable error (a transport error, HTTP 429
or HTTP 5xx), so first-failure diagnostics can be captured without the
noise of dumping every transaction. The existing dump flags continue to
control what is dumped, for example --dump errors,bodies, and on its own
--dump errors dumps the headers.

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
 

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"},
 	}
 }
 

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")
+}

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 {