Show the request body in the failure dump

e2e_known_issues_test.go

@@ -1,9 +1,6 @@
 package main_test
 
-import (
-	"strings"
-	"testing"
-)
+import "testing"
 
 // This file pins behaviour that is currently WRONG. Each test asserts what the
 // tool does today and names the issue tracking the defect.
@@ -46,25 +43,6 @@ func TestIssue17BadPatternIsRejected(t *testing.T) {
 	})
 }
 
-// TestKnownIssue19RequestBodyMissing: the request is dumped after the transport
-// has drained its body, so Content-Length advertises bytes that are not shown.
-func TestKnownIssue19RequestBodyMissing(t *testing.T) {
-	characterizes(t, 19, "the request dump omits the -d payload it advertises")
-
-	r := run(t, nil, "-X", "POST", "-d", "sent-but-not-shown", "--assert-status", "999", url("/echo"))
-	assertExit(t, r, exitRequestFail)
-
-	// The echoed response proves the body reached the server...
-	assertContains(t, r, "sent-but-not-shown")
-	// ...while the request dump advertises its length and shows nothing.
-	assertContains(t, r, "Content-Length: 18")
-
-	reqDump, _, _ := strings.Cut(r.Output(), "HTTP/1.1 200 OK")
-	if strings.Contains(reqDump, "sent-but-not-shown") {
-		t.Fatal("request dump now includes the body; #19 is fixed -- update this test")
-	}
-}
-
 // TestKnownIssue20AssertOkAcceptsRedirects: --assert-ok is documented as "2xx"
 // but implemented as 200-399.
 func TestKnownIssue20AssertOkAcceptsRedirects(t *testing.T) {

main.go

@@ -899,14 +899,55 @@ func (c Client) writeHttpDetails(w io.Writer, req *http.Request, res *httpRespon
 	if res != nil && res.Request != nil && res.Request.URL.String() != req.URL.String() {
 		_, _ = fmt.Fprintf(w, "Followed to: %s %s\n\n", res.Request.Method, res.Request.URL)
 	}
-	_ = req.Write(w)
+	writeRequest(w, req)
 	_, _ = w.Write([]byte("\n\n"))
 	if res != nil {
 		res.writeTo(w, c.LogLevel >= LInfo)
 		_, _ = w.Write([]byte("\n\n"))
 	}
 }
 
+// writeRequest renders the request for a person reading a failure report, the
+// way writeTo renders the response.
+//
+// http.Request.Write alone gets this wrong twice. Its body has already been
+// consumed by the send, so it emits headers claiming a Content-Length with
+// nothing behind them -- the first question after a failed POST is "what did I
+// send?", and that was the one thing the dump left out (#19). And it is a
+// wire-format serializer, so a long or binary payload would land in the report
+// raw: the same mistake #18 fixed on the response side.
+//
+// So the headers come from Write, which knows what actually goes on the wire
+// (Host, User-Agent, Content-Length are none of them in req.Header), and the
+// body goes through the shared renderer that crops and hex-dumps.
+func writeRequest(w io.Writer, req *http.Request) {
+	// A fresh clone replays the body; without GetBody there is nothing to
+	// replay and the dump is no worse than it was.
+	dump := req
+	if fresh, err := cloneForAttempt(req); err == nil {
+		dump = fresh
+	}
+
+	var b bytes.Buffer
+	if err := dump.Write(&b); err != nil {
+		// A failed dump must not replace the failure being reported, so
+		// whatever was rendered before the error still goes out.
+		_, _ = w.Write(b.Bytes())
+		return
+	}
+
+	head, body, found := bytes.Cut(b.Bytes(), []byte("\r\n\r\n"))
+	_, _ = w.Write(head)
+	_, _ = w.Write([]byte("\r\n\r\n"))
+	if !found || len(body) == 0 {
+		return
+	}
+
+	if cropped := printPayload(w, body, maxPayloadBytes); cropped > 0 {
+		_, _ = fmt.Fprintf(w, "\n\n  << Payload is cropped: %d bytes are hidden >>", cropped)
+	}
+}
+
 func (c Client) getHttpClient() *http.Client {
 	dialer := &net.Dialer{
 		Timeout:   10 * time.Second,

render_test.go

@@ -1,6 +1,7 @@
 package main
 
 import (
+	"io"
 	"net/http"
 	"strings"
 	"testing"
@@ -124,3 +125,123 @@ func Test_writeTo_ignoresTransportFraming(t *testing.T) {
 		}
 	}
 }
+
+// Test_writeRequest covers the request half of the failure dump.
+//
+// http.Request.Write was used directly, and by then the transport had drained
+// the body -- so the dump advertised a Content-Length with nothing behind it,
+// which is both useless (the first question after a failed POST is what was
+// sent) and self-contradictory as an HTTP message (#19).
+func Test_writeRequest(t *testing.T) {
+	t.Parallel()
+
+	request := func(t *testing.T, method, body string) *http.Request {
+		t.Helper()
+
+		var r io.Reader = http.NoBody
+		if body != "" {
+			r = strings.NewReader(body)
+		}
+		req, err := http.NewRequest(method, "http://example.com/things", r)
+		if err != nil {
+			t.Fatalf("cannot build the request: %s", err)
+		}
+		return req
+	}
+
+	// sent drains the body the way http.Client does, so the request under test
+	// is in the state the dump actually receives.
+	sent := func(t *testing.T, req *http.Request) *http.Request {
+		t.Helper()
+
+		attempt, err := cloneForAttempt(req)
+		if err != nil {
+			t.Fatalf("cannot clone: %s", err)
+		}
+		if _, err := io.ReadAll(attempt.Body); err != nil {
+			t.Fatalf("cannot drain: %s", err)
+		}
+		_ = attempt.Body.Close()
+		return attempt
+	}
+
+	t.Run("the body survives having been sent", func(t *testing.T) {
+		req := sent(t, request(t, "POST", "PAYLOAD"))
+
+		var b strings.Builder
+		writeRequest(&b, req)
+
+		out := b.String()
+		if !strings.Contains(out, "PAYLOAD") {
+			t.Errorf("the dump omits the body it says it sent:\n%s", out)
+		}
+		if !strings.Contains(out, "Content-Length: 7") {
+			t.Errorf("the dump lost Content-Length:\n%s", out)
+		}
+	})
+
+	t.Run("a request with no body dumps cleanly", func(t *testing.T) {
+		req := sent(t, request(t, "GET", ""))
+
+		var b strings.Builder
+		writeRequest(&b, req)
+
+		out := b.String()
+		if !strings.Contains(out, "GET /things HTTP/1.1") {
+			t.Errorf("the request line is missing:\n%s", out)
+		}
+		// No payload section, and nothing pretending there is one.
+		if strings.Contains(out, "Payload is cropped") {
+			t.Errorf("an empty body was reported as cropped:\n%s", out)
+		}
+	})
+
+	// The other half of #18's lesson, which was applied to the response and
+	// not to the request: a wire-format serializer puts the whole payload in
+	// the report, however long it is.
+	t.Run("a long body is cropped", func(t *testing.T) {
+		body := strings.Repeat("x", maxPayloadBytes+44)
+		req := sent(t, request(t, "POST", body))
+
+		var b strings.Builder
+		writeRequest(&b, req)
+
+		out := b.String()
+		if !strings.Contains(out, "<< Payload is cropped: 44 bytes are hidden >>") {
+			t.Errorf("a %d-byte body was not cropped:\n%s", len(body), out)
+		}
+		// Counted in the body only -- the Host header carries an "x" of its own.
+		_, payload, found := strings.Cut(out, "\r\n\r\n")
+		if !found {
+			t.Fatalf("no header/body separator in the dump:\n%s", out)
+		}
+		if n := strings.Count(payload, "x"); n != maxPayloadBytes {
+			t.Errorf("%d body bytes reached the dump, want %d", n, maxPayloadBytes)
+		}
+	})
+
+	t.Run("a non-printable body is hex-dumped", func(t *testing.T) {
+		req := sent(t, request(t, "POST", "\xff\xfe\x07\x08"))
+
+		var b strings.Builder
+		writeRequest(&b, req)
+
+		if out := b.String(); !strings.Contains(out, "ff fe 07 08") {
+			t.Errorf("a binary body was not hex-dumped:\n%s", out)
+		}
+	})
+
+	// Without GetBody there is nothing to replay. The dump must still render
+	// the headers rather than failing outright.
+	t.Run("a body that cannot be replayed still dumps its headers", func(t *testing.T) {
+		req := sent(t, request(t, "POST", "PAYLOAD"))
+		req.GetBody = nil
+
+		var b strings.Builder
+		writeRequest(&b, req)
+
+		if out := b.String(); !strings.Contains(out, "POST /things HTTP/1.1") {
+			t.Errorf("the headers went missing along with the body:\n%s", out)
+		}
+	})
+}