Format the failure dump instead of serializing it

e2e_dump_test.go

@@ -0,0 +1,91 @@
+package main_test
+
+import (
+	"strings"
+	"testing"
+)
+
+// The failure dump is the only thing a person reads when an assertion fails,
+// so what it contains is part of the contract.
+//
+// It used to be produced by http.Response.Write, an HTTP wire serializer. That
+// honours Content-Length and Transfer-Encoding, which describe the body that
+// arrived rather than the rendering that replaces it -- so a rendering longer
+// than the original body was cut to the original's length, and a chunked
+// response had its framing interleaved with the text (#18). Each test below
+// failed before that was fixed.
+
+func TestE2EFailureDump(t *testing.T) {
+	// /500 returns a four-byte body, which used to cut the twenty-five byte
+	// placeholder down to "  <<".
+	t.Run("omitted placeholder is not cut to the body length", func(t *testing.T) {
+		r := run(t, nil, "-s", "--assert-ok", url("/500"))
+		assertExit(t, r, exitRequestFail)
+		assertContains(t, r, "  << Payload is omitted >>")
+	})
+
+	// Eight raw bytes used to render as the offset "00000000" and nothing
+	// else, from a dumper whose entire purpose is showing the bytes.
+	t.Run("binary body keeps its hex dump and ascii gutter", func(t *testing.T) {
+		r := run(t, nil, "--assert-body-eq", "never-matches", url("/binary"))
+		assertExit(t, r, exitRequestFail)
+		assertContains(t, r, "00000000")
+		assertContains(t, r, "00 01 02 03 ff fe 07 08")
+		assertContains(t, r, "|")
+	})
+
+	// A chunked response has no Content-Length, so instead of truncating, the
+	// serializer re-framed the rendering: a hex length, then the text, then a
+	// zero terminator, plus a Transfer-Encoding header it invented.
+	t.Run("chunked response is dumped without transfer framing", func(t *testing.T) {
+		r := run(t, nil, "-v", "--assert-body-eq", "never-matches", url("/chunked"))
+		assertExit(t, r, exitRequestFail)
+		assertContains(t, r, "first chunk second chunk")
+		assertNotContains(t, r, "Transfer-Encoding")
+
+		// "18" is the chunk length the serializer used to emit for this body.
+		// Anchored to line starts so a chunk length is not confused with the
+		// same digits inside a header value or a timing.
+		dump, _, _ := strings.Cut(r.Output(), "first chunk")
+		for line := range strings.SplitSeq(dump, "\n") {
+			if strings.TrimSpace(line) == "18" || strings.TrimSpace(line) == "0" {
+				t.Fatalf("chunk framing leaked into the dump:\n%s", r.Output())
+			}
+		}
+	})
+
+	// unicode.IsPrint answers false for '\n', so a body with a line break in it
+	// -- pretty-printed JSON, HTML, a log excerpt -- was shown as a hex dump.
+	t.Run("multi-line text body is shown as text", func(t *testing.T) {
+		r := run(t, nil, "--assert-body-eq", "never-matches", url("/multiline"))
+		assertExit(t, r, exitRequestFail)
+		assertContains(t, r, "\"status\": \"success\"")
+		assertNotContains(t, r, "00000000")
+	})
+
+	// Cropping is a property of the renderer, not of the transport, and has to
+	// survive the change.
+	t.Run("large body is still cropped and says so", func(t *testing.T) {
+		r := run(t, nil, "--assert-body-eq", "never-matches", url("/big"))
+		assertExit(t, r, exitRequestFail)
+		assertContains(t, r, "Payload is cropped")
+		assertContains(t, r, "bytes are hidden")
+	})
+
+	// Wire line endings in a human-readable report show up as ^M in pagers and
+	// some CI log viewers.
+	t.Run("dump uses newlines rather than wire line endings", func(t *testing.T) {
+		r := run(t, nil, "-s", "--assert-ok", url("/500"))
+		assertExit(t, r, exitRequestFail)
+
+		// The request half is still serialized by http.Request.Write and keeps
+		// its CRLFs; #19 replaces it. Only the response half is checked here.
+		_, dump, found := strings.Cut(r.Output(), "HTTP/1.1 500")
+		if !found {
+			t.Fatalf("no response status line in the dump\n%s", r.Output())
+		}
+		if strings.Contains(dump, "\r") {
+			t.Errorf("response dump contains a carriage return: %q", dump)
+		}
+	})
+}

e2e_known_issues_test.go

@@ -46,31 +46,6 @@ func TestIssue17BadPatternIsRejected(t *testing.T) {
 	})
 }
 
-// TestKnownIssue18PayloadTruncated: the response dump replaces the body with a
-// rendered form but leaves Content-Length untouched, so http.Response.Write
-// truncates whatever it renders to the original byte count.
-func TestKnownIssue18PayloadTruncated(t *testing.T) {
-	t.Run("silent mode truncates the placeholder", func(t *testing.T) {
-		characterizes(t, 18, "'<< Payload is omitted >>' is cut to the body's length")
-
-		// The body is "boom" (4 bytes), so only 4 bytes of the placeholder survive.
-		r := run(t, nil, "-s", "--assert-ok", url("/500"))
-		assertExit(t, r, exitRequestFail)
-		assertContains(t, r, "  <<")
-		assertNotContains(t, r, "Payload is omitted >>")
-	})
-
-	t.Run("binary body truncates the hex dump", func(t *testing.T) {
-		characterizes(t, 18, "an 8-byte binary body renders as a single hex offset")
-
-		r := run(t, nil, "--assert-body-eq", "never-matches", url("/binary"))
-		assertExit(t, r, exitRequestFail)
-		assertContains(t, r, "00000000")
-		// The real dump would carry the bytes and an ASCII gutter.
-		assertNotContains(t, r, "|")
-	})
-}
-
 // 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) {

e2e_server_test.go

@@ -92,6 +92,22 @@ func testHandler() http.Handler {
 		write(w, http.StatusOK, []byte{0x00, 0x01, 0x02, 0x03, 0xff, 0xfe, 0x07, 0x08}, nil)
 	})
 
+	// A multi-line text body: the shape most real responses have, and the one
+	// that used to reach the hex dumper because '\n' is not unicode.IsPrint.
+	mux.HandleFunc("/multiline", func(w http.ResponseWriter, _ *http.Request) {
+		write(w, http.StatusOK, []byte("{\n  \"status\": \"success\"\n}"), nil)
+	})
+
+	// Flushes before the response buffer fills, which forces chunked transfer
+	// and leaves Content-Length unset. The failure dump must show the body
+	// without the framing that carried it (#18).
+	mux.HandleFunc("/chunked", func(w http.ResponseWriter, _ *http.Request) {
+		w.Header().Set("Content-Type", "text/plain")
+		_, _ = w.Write([]byte("first chunk "))
+		w.(http.Flusher).Flush()
+		_, _ = w.Write([]byte("second chunk"))
+	})
+
 	// Larger than the 256-byte crop threshold used when printing payloads.
 	mux.HandleFunc("/big", func(w http.ResponseWriter, _ *http.Request) {
 		body := make([]byte, 5000)

main.go

@@ -38,15 +38,16 @@
 package main
 
 import (
-	"bytes"
 	"context"
 	"crypto/tls"
 	"errors"
 	"fmt"
 	"io"
+	"maps"
 	"net"
 	"net/http"
 	"os"
+	"slices"
 	"strconv"
 	"strings"
 	"time"
@@ -496,21 +497,45 @@ type httpResponse struct {
 	BodyBytes []byte
 }
 
+// maxPayloadBytes is how much of a body the failure dump shows before cropping.
+const maxPayloadBytes = 256
+
+// writeTo renders the response for a person reading a failure report.
+//
+// Deliberately not http.Response.Write. That is a wire-format serializer: it
+// honours ContentLength and Transfer-Encoding, which describe the body that
+// arrived rather than the rendering that replaces it here. A placeholder or a
+// hex dump longer than the original body was cut to the original's length, and
+// a chunked response had its framing interleaved with the rendering (#18).
+//
+// Go reported the mismatch on every such run -- "http: ContentLength=4 with
+// Body length 26" -- and the caller discarded it. Nothing to discard now: the
+// bytes below are the whole output.
+//
+// Write errors are ignored, following utils.go, because every caller renders
+// into an in-memory strings.Builder that cannot fail.
 func (r httpResponse) writeTo(w io.Writer, withBody bool) {
-	// Ensure to close previous body
-	b := r.Body
-	defer func() { _ = b.Close() }()
-	if withBody {
-		var b bytes.Buffer
-		croppedBytes := printPayload(&b, r.BodyBytes, 256)
-		if croppedBytes > 0 {
-			fmt.Fprintf(&b, "\n\n  << Payload is cropped: %d bytes are hidden >>", croppedBytes)
+	_, _ = fmt.Fprintf(w, "%s %s\n", r.Proto, r.Status)
+	writeHeaders(w, r.Header)
+	_, _ = fmt.Fprintln(w)
+
+	if !withBody {
+		_, _ = fmt.Fprint(w, "  << Payload is omitted >>")
+		return
+	}
+	if cropped := printPayload(w, r.BodyBytes, maxPayloadBytes); cropped > 0 {
+		_, _ = fmt.Fprintf(w, "\n\n  << Payload is cropped: %d bytes are hidden >>", cropped)
+	}
+}
+
+// writeHeaders renders headers one per line, sorted by name so that two dumps
+// of the same response can be compared.
+func writeHeaders(w io.Writer, h http.Header) {
+	for _, name := range slices.Sorted(maps.Keys(h)) {
+		for _, value := range h[name] {
+			_, _ = fmt.Fprintf(w, "%s: %s\n", name, value)
 		}
-		r.Body = io.NopCloser(&b)
-	} else {
-		r.Body = io.NopCloser(strings.NewReader("  << Payload is omitted >>"))
 	}
-	_ = r.Write(w)
 }
 
 type hostMapping struct {

render_test.go

@@ -0,0 +1,126 @@
+package main
+
+import (
+	"net/http"
+	"strings"
+	"testing"
+)
+
+// response builds the shape Client.Do hands to the renderer: a real
+// *http.Response plus the body already read off the wire.
+func response(status string, header http.Header, body string) httpResponse {
+	return httpResponse{
+		Response: &http.Response{
+			Proto:  "HTTP/1.1",
+			Status: status,
+			Header: header,
+			// Set deliberately, and deliberately inconsistent with the body
+			// below: the renderer must describe what it prints, not what the
+			// transport said would arrive (#18).
+			ContentLength:    int64(len(body)),
+			TransferEncoding: []string{"chunked"},
+		},
+		BodyBytes: []byte(body),
+	}
+}
+
+func Test_httpResponse_writeTo(t *testing.T) {
+	t.Parallel()
+
+	plain := http.Header{"Content-Type": {"text/plain"}}
+
+	tests := []struct {
+		Name     string
+		Response httpResponse
+		WithBody bool
+		Want     string
+	}{{
+		Name:     "status line, headers, body",
+		Response: response("200 OK", plain, "hello"),
+		WithBody: true,
+		Want: "HTTP/1.1 200 OK\n" +
+			"Content-Type: text/plain\n" +
+			"\n" +
+			"hello",
+	}, {
+		// The case #18 opens with: the placeholder is longer than the body it
+		// stands in for, and used to be cut to the body's length.
+		Name:     "omitted payload survives a shorter body",
+		Response: response("500 Internal Server Error", plain, "boom"),
+		WithBody: false,
+		Want: "HTTP/1.1 500 Internal Server Error\n" +
+			"Content-Type: text/plain\n" +
+			"\n" +
+			"  << Payload is omitted >>",
+	}, {
+		Name:     "headers are sorted and repeated values kept",
+		Response: response("200 OK", http.Header{"Set-Cookie": {"a=1", "b=2"}, "Allow": {"GET"}}, ""),
+		WithBody: true,
+		Want: "HTTP/1.1 200 OK\n" +
+			"Allow: GET\n" +
+			"Set-Cookie: a=1\n" +
+			"Set-Cookie: b=2\n" +
+			"\n",
+	}, {
+		Name:     "no headers still leaves the blank separator",
+		Response: response("204 No Content", http.Header{}, ""),
+		WithBody: true,
+		Want:     "HTTP/1.1 204 No Content\n\n",
+	}, {
+		// A body of raw bytes goes to the hex dumper, gutter and all -- the
+		// whole point of the dumper, and what truncation used to remove.
+		Name:     "binary body renders as a full hex dump",
+		Response: response("200 OK", http.Header{}, "\x00\x01\x02\xff"),
+		WithBody: true,
+		Want: "HTTP/1.1 200 OK\n" +
+			"\n" +
+			"00000000  00 01 02 ff                                       |....|\n",
+	}}
+
+	for _, tc := range tests {
+		t.Run(tc.Name, func(t *testing.T) {
+			var b strings.Builder
+			tc.Response.writeTo(&b, tc.WithBody)
+
+			if got := b.String(); got != tc.Want {
+				t.Errorf("writeTo()\n got: %q\nwant: %q", got, tc.Want)
+			}
+		})
+	}
+}
+
+// Test_httpResponse_writeToCrops covers the branch that reports hidden bytes.
+// It is separate because the expected text depends on the crop limit.
+func Test_httpResponse_writeToCrops(t *testing.T) {
+	t.Parallel()
+
+	body := strings.Repeat("x", maxPayloadBytes+17)
+	var b strings.Builder
+	response("200 OK", http.Header{}, body).writeTo(&b, true)
+
+	got := b.String()
+	if want := strings.Repeat("x", maxPayloadBytes); !strings.Contains(got, want) {
+		t.Errorf("writeTo() did not render the first %d bytes", maxPayloadBytes)
+	}
+	if want := "<< Payload is cropped: 17 bytes are hidden >>"; !strings.Contains(got, want) {
+		t.Errorf("writeTo() = %q, want it to contain %q", got, want)
+	}
+}
+
+// Test_writeTo_ignoresTransportFraming states the property #18 is really about:
+// nothing describing how the body travelled may reach the reader. The response
+// above advertises chunked transfer and a ContentLength that contradicts the
+// rendering, and neither may show up.
+func Test_writeTo_ignoresTransportFraming(t *testing.T) {
+	t.Parallel()
+
+	var b strings.Builder
+	response("200 OK", http.Header{"Content-Type": {"text/plain"}}, "boom").
+		writeTo(&b, false)
+
+	for _, unwanted := range []string{"chunked", "Transfer-Encoding", "\r"} {
+		if strings.Contains(b.String(), unwanted) {
+			t.Errorf("writeTo() leaked %q into the dump:\n%s", unwanted, b.String())
+		}
+	}
+}

utils.go

@@ -43,9 +43,22 @@ func printPayload(w io.Writer, bs []byte, maxSize int) (croppedBytes int) {
 	return
 }
 
+// isPrintable reports whether bs should be shown as text rather than dumped as
+// hex.
+//
+// Whitespace counts as text. unicode.IsPrint answers false for '\n', '\t' and
+// '\r', so testing it alone sent every multi-line body -- pretty-printed JSON,
+// HTML, a log excerpt, anything with a line break in the first 256 bytes -- to
+// the hex dumper, which is the least readable way to show text a human was
+// about to read.
+//
+// Known gap: bytes that are not valid UTF-8 decode to U+FFFD, which is itself
+// printable, so a body of high bytes still reads as text. Cropping happens
+// before this check and can split a multi-byte rune, so the obvious utf8.Valid
+// guard would misfile legitimate text; tracked separately.
 func isPrintable(bs []byte) bool {
 	nonPrintableIdx := bytes.IndexFunc(bs, func(r rune) bool {
-		return !unicode.IsPrint(r)
+		return !unicode.IsPrint(r) && !unicode.IsSpace(r)
 	})
 	return nonPrintableIdx < 0
 }