diff --git a/.gitattributes b/.gitattributes new file mode 100644 index 0000000..58bf706 --- /dev/null +++ b/.gitattributes @@ -0,0 +1,4 @@ +# Golden files are embedded and compared byte-for-byte against logger output, +# so they must keep LF line endings on checkout (Windows defaults to CRLF). +*.golden text eol=lf +*.txtar text eol=lf diff --git a/.github/workflows/codeql.yml b/.github/workflows/codeql.yml index 74ea26b..fade8da 100644 --- a/.github/workflows/codeql.yml +++ b/.github/workflows/codeql.yml @@ -21,12 +21,12 @@ jobs: steps: - name: Check out code - uses: actions/checkout@v4 + uses: actions/checkout@v7 - name: Initialize CodeQL - uses: github/codeql-action/init@v3 + uses: github/codeql-action/init@v4 with: languages: go - name: Perform CodeQL Analysis - uses: github/codeql-action/analyze@v3 + uses: github/codeql-action/analyze@v4 diff --git a/.github/workflows/go.yml b/.github/workflows/go.yml index 05f74b4..bfccd7c 100644 --- a/.github/workflows/go.yml +++ b/.github/workflows/go.yml @@ -13,30 +13,33 @@ jobs: strategy: matrix: os: [ubuntu-latest, macos-latest, windows-latest] - go: [1.23.x, 1.22.x] # when updating versions, update it below too. + go: [1.25.x, 1.26.x] # when updating versions, update it below too. runs-on: ${{ matrix.os }} name: Test steps: - name: Set up Go ${{ matrix.go }} - uses: actions/setup-go@v5 + uses: actions/setup-go@v6 with: go-version: ${{ matrix.go }} - name: Check out code - uses: actions/checkout@v4 + uses: actions/checkout@v7 - name: Test - # TODO(henvic): Skip generating code coverage when not sending it to Coveralls to speed up testing. + if: ${{ matrix.os != 'ubuntu-latest' || matrix.go != '1.26.x' }} + run: go test -race ./... + + - name: Test with code coverage + if: ${{ matrix.os == 'ubuntu-latest' && matrix.go == '1.26.x' }} # Remove example directory from code coverage explicitly since after #26 it # started being considered on the code coverage report and we don't want that. - continue-on-error: ${{ matrix.os != 'ubuntu-latest' || matrix.go != '1.23.x' }} run: | go test -race -covermode atomic -coverprofile=profile.cov ./... sed -i '/^github\.com\/henvic\/httpretty\/example\//d' profile.cov - name: Code coverage - if: ${{ matrix.os == 'ubuntu-latest' && matrix.go == '1.23.x' }} + if: ${{ matrix.os == 'ubuntu-latest' && matrix.go == '1.26.x' }} uses: shogo82148/actions-goveralls@v1 with: path-to-profile: profile.cov diff --git a/.github/workflows/lint.yml b/.github/workflows/lint.yml index 77ba7df..a1335e5 100644 --- a/.github/workflows/lint.yml +++ b/.github/workflows/lint.yml @@ -16,12 +16,12 @@ jobs: steps: - name: Set up Go 1.x - uses: actions/setup-go@v5 + uses: actions/setup-go@v6 with: - go-version: "1.23.x" + go-version: "1.26.x" - name: Check out code - uses: actions/checkout@v4 + uses: actions/checkout@v7 - name: Verify dependencies run: | diff --git a/binary_test.go b/binary_test.go index 08b480d..16483e0 100644 --- a/binary_test.go +++ b/binary_test.go @@ -50,6 +50,21 @@ func TestIsBinary(t *testing.T) { data: bytes.Repeat([]byte{1, 2, 3, 4, 5, 6, 7, 8}, 65), binary: true, }, + { + desc: "Binary header (exactly 512 bytes) with text trailer", + data: append(bytes.Repeat([]byte{1, 2, 3, 4, 5, 6, 7, 8}, 64), []byte("plain text trailer")...), + binary: true, + }, + { + desc: "Text over 512 bytes with binary trailer", + data: append(bytes.Repeat([]byte("plain text "), 50), []byte{1, 2, 3, 4, 5}...), + binary: false, + }, + { + desc: "Large text with leading UTF-8 BOM and binary trailer", // https://www.unicode.org/faq/utf_bom#BOM + data: append(append([]byte("\xEF\xBB\xBF"), bytes.Repeat([]byte("plain text "), 50)...), []byte{1, 2, 3, 4, 5}...), + binary: false, + }, { desc: "JPEG image", data: []byte("\xFF\xD8\xFF"), diff --git a/client_test.go b/client_test.go index 30ca788..fd20620 100644 --- a/client_test.go +++ b/client_test.go @@ -17,6 +17,7 @@ import ( "net/http" "net/http/httptest" "net/http/httputil" + "net/textproto" "net/url" "os" "regexp" @@ -149,7 +150,7 @@ func TestOutgoingConcurrency(t *testing.T) { var wg sync.WaitGroup concurrency := 100 wg.Add(concurrency) - for i := 0; i < concurrency; i++ { + for range concurrency { go outgoingGet(t, client, ts, wg.Done) time.Sleep(time.Millisecond) // let's slow down just a little bit ("too many files descriptors open" on a slow machine, more realistic traffic, and so on) } @@ -163,6 +164,40 @@ func TestOutgoingConcurrency(t *testing.T) { } } +func TestOutgoingOnReadyFlusher(t *testing.T) { + t.Parallel() + ts := httptest.NewServer(helloHandler{}) + defer ts.Close() + + logger := &Logger{ + RequestHeader: true, + ResponseHeader: true, + ResponseBody: true, + } + logger.SetFlusher(OnReady) + var buf bytes.Buffer + logger.SetOutput(&buf) + + client := &http.Client{Transport: logger.RoundTripper(newTransport())} + req, err := http.NewRequest(http.MethodGet, ts.URL, nil) + if err != nil { + t.Fatalf("cannot create request: %v", err) + } + resp, err := client.Do(req) + if err != nil { + t.Fatalf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + testBody(t, resp.Body, []byte("Hello, world!")) + + got := buf.String() + for _, want := range []string{"> GET / HTTP/1.1", "< HTTP/1.1 200 OK", "Hello, world!"} { + if !strings.Contains(got, want) { + t.Errorf("OnReady output does not contain %q\n%s", want, got) + } + } +} + func TestOutgoingMinimal(t *testing.T) { t.Parallel() ts := httptest.NewServer(&helloHandler{}) @@ -417,6 +452,39 @@ func TestOutgoingSkipHeader(t *testing.T) { } } +func TestOutgoingTransferEncoding(t *testing.T) { + t.Parallel() + ts := httptest.NewServer(&helloHandler{}) + defer ts.Close() + + logger := &Logger{ + RequestHeader: true, + RequestBody: true, + ResponseHeader: true, + ResponseBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + client := &http.Client{ + Transport: logger.RoundTripper(newTransport()), + } + + req, err := http.NewRequest(http.MethodPut, ts.URL, strings.NewReader("ping")) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + // Transfer-Encoding lives in its own field on http.Request rather than in Header. + req.TransferEncoding = []string{"chunked"} + + if _, err = client.Do(req); err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + + if want, got := "> Transfer-Encoding: chunked\n", buf.String(); !strings.Contains(got, want) { + t.Errorf("logged HTTP request %q; want it to contain %q", got, want) + } +} + func TestOutgoingBodyFilter(t *testing.T) { t.Parallel() ts := httptest.NewServer(&jsonHandler{}) @@ -1148,7 +1216,7 @@ func TestOutgoingLongResponseUnknownLengthTooLong(t *testing.T) { } } -func multipartTestdata(writer *multipart.Writer, body *bytes.Buffer) { +func multipartTestdata(writer *multipart.Writer) { params := []struct { name string value string @@ -1174,6 +1242,54 @@ func multipartTestdata(writer *multipart.Writer, body *bytes.Buffer) { } } +// multipartMixedBoundary is fixed, rather than random, so golden files can rely on it. +const multipartMixedBoundary = "f0f4a3b1c2d5" + +// multipartMixedBody is a multipart/mixed body with a plain text and a JSON part. +func multipartMixedBody(t *testing.T) []byte { + t.Helper() + var body bytes.Buffer + writer := multipart.NewWriter(&body) + if err := writer.SetBoundary(multipartMixedBoundary); err != nil { + t.Fatalf("cannot set multipart boundary: %v", err) + } + parts := []struct { + mediatype string + content string + }{ + {"text/plain", "Hello, world!"}, + {"application/json", `{"result":"Hello, world!","number":3.14}`}, + } + for _, p := range parts { + part, err := writer.CreatePart(textproto.MIMEHeader{ + "Content-Type": []string{p.mediatype}, + }) + if err != nil { + t.Fatalf("cannot create %s part: %v", p.mediatype, err) + } + if _, err := io.WriteString(part, p.content); err != nil { + t.Fatalf("cannot write %s part: %v", p.mediatype, err) + } + } + if err := writer.Close(); err != nil { + t.Fatalf("cannot close multipart writer: %v", err) + } + return body.Bytes() +} + +// multipartMixedHandler responds with the multipart/mixed body above. +type multipartMixedHandler struct { + body []byte +} + +func (h multipartMixedHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + w.Header().Set("Content-Type", "multipart/mixed; boundary="+multipartMixedBoundary) + if _, err := w.Write(h.body); err != nil { + panic(err) + } +} + type multipartHandler struct { t *testing.T } @@ -1218,8 +1334,8 @@ func TestOutgoingMultipartForm(t *testing.T) { defer ts.Close() logger := &Logger{ - RequestHeader: true, - // TODO(henvic): print request body once support for printing out multipart/formdata body is added. + RequestHeader: true, + RequestBody: true, ResponseHeader: true, ResponseBody: true, Formatters: []Formatter{ @@ -1235,7 +1351,7 @@ func TestOutgoingMultipartForm(t *testing.T) { uri := fmt.Sprintf("%s/multipart-upload", ts.URL) body := &bytes.Buffer{} writer := multipart.NewWriter(body) - multipartTestdata(writer, body) + multipartTestdata(writer) req, err := http.NewRequest(http.MethodPost, uri, body) if err != nil { t.Errorf("cannot create request: %v", err) @@ -1244,12 +1360,322 @@ func TestOutgoingMultipartForm(t *testing.T) { if _, err = client.Do(req); err != nil { t.Errorf("cannot connect to the server: %v", err) } + want := fmt.Sprintf(golden(t.Name()), uri, ts.Listener.Addr(), writer.FormDataContentType(), petition) + if got := buf.String(); got != want { + t.Errorf("logged HTTP request %s; want %s", got, want) + } +} + +// TestOutgoingMultipartMixed verifies each part of a multipart body is formatted, and +// checked for binary content, on its own: a binary part doesn't hide the whole body. +func TestOutgoingMultipartMixed(t *testing.T) { + t.Parallel() + ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + fmt.Fprint(w, "upload received") + })) + defer ts.Close() + + logger := &Logger{ + RequestHeader: true, + RequestBody: true, + Formatters: []Formatter{ + &JSONFormatter{}, + }, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + client := &http.Client{ + Transport: logger.RoundTripper(newTransport()), + } + + uri := fmt.Sprintf("%s/multipart-upload", ts.URL) + body := &bytes.Buffer{} + writer := multipart.NewWriter(body) + metadata, err := writer.CreatePart(textproto.MIMEHeader{ + "Content-Disposition": []string{`form-data; name="metadata"`}, + "Content-Type": []string{"application/json"}, + }) + if err != nil { + t.Fatalf("cannot create metadata part: %v", err) + } + if _, err := metadata.Write([]byte(`{"result":"Hello, world!","number":3.14}`)); err != nil { + t.Fatalf("cannot write metadata part: %v", err) + } + file, err := writer.CreateFormFile("file", "image.png") + if err != nil { + t.Fatalf("cannot create file part: %v", err) + } + if _, err := file.Write([]byte("\x89PNG\x0d\x0a\x1a\x0a")); err != nil { + t.Fatalf("cannot write file part: %v", err) + } + if err := writer.Close(); err != nil { + t.Fatalf("cannot close multipart writer: %v", err) + } + req, err := http.NewRequest(http.MethodPost, uri, body) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + req.Header.Set("Content-Type", writer.FormDataContentType()) + resp, err := client.Do(req) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() want := fmt.Sprintf(golden(t.Name()), uri, ts.Listener.Addr(), writer.FormDataContentType()) if got := buf.String(); got != want { t.Errorf("logged HTTP request %s; want %s", got, want) } } +// TestOutgoingMultipartInvalid verifies a body that cannot be split into parts — +// malformed, truncated, or carrying no parts — is printed as-is, rather than +// partially printed or dropped. +func TestOutgoingMultipartInvalid(t *testing.T) { + t.Parallel() + ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + fmt.Fprint(w, "upload received") + })) + defer ts.Close() + + testCases := []struct { + name string + body string + }{ + {"malformed", "not really a multipart body"}, + {"truncated", "--8ef4ab7d2a1c\r\nContent-Type: text/plain\r\n\r\ntruncated: no closing boundary"}, + {"noparts", "--8ef4ab7d2a1c--\r\n"}, + } + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + logger := &Logger{ + RequestHeader: true, + RequestBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + client := &http.Client{ + Transport: logger.RoundTripper(newTransport()), + } + + uri := fmt.Sprintf("%s/multipart-upload", ts.URL) + req, err := http.NewRequest(http.MethodPost, uri, strings.NewReader(tc.body)) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + req.Header.Set("Content-Type", "multipart/form-data; boundary=8ef4ab7d2a1c") + resp, err := client.Do(req) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + want := fmt.Sprintf(golden("TestOutgoingMultipartInvalid"), uri, ts.Listener.Addr(), len(tc.body), tc.body) + if got := buf.String(); got != want { + t.Errorf("logged HTTP request %s; want %s", got, want) + } + }) + } +} + +// TestOutgoingMultipartResponse verifies a multipart response body is printed part by +// part, just like a request body is. +func TestOutgoingMultipartResponse(t *testing.T) { + t.Parallel() + body := multipartMixedBody(t) + ts := httptest.NewServer(multipartMixedHandler{body}) + defer ts.Close() + + logger := &Logger{ + ResponseHeader: true, + ResponseBody: true, + Formatters: []Formatter{ + &JSONFormatter{}, + }, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + client := &http.Client{ + Transport: logger.RoundTripper(newTransport()), + } + + resp, err := client.Get(ts.URL) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + want := fmt.Sprintf(golden(t.Name()), ts.URL, len(body)) + if got := buf.String(); got != want { + t.Errorf("logged HTTP request %s; want %s", got, want) + } + testBody(t, resp.Body, body) +} + +// multipartFormatter formats a whole multipart/mixed body, rather than each of its parts. +type multipartFormatter struct{} + +func (f *multipartFormatter) Match(mediatype string) bool { + return mediatype == "multipart/mixed" +} + +func (f *multipartFormatter) Format(w io.Writer, src []byte) error { + _, err := fmt.Fprintf(w, "%d bytes of multipart data", len(src)) + return err +} + +// TestOutgoingMultipartFormatter verifies a formatter matching a multipart media type +// takes precedence over printing the body part by part. +func TestOutgoingMultipartFormatter(t *testing.T) { + t.Parallel() + body := multipartMixedBody(t) + ts := httptest.NewServer(multipartMixedHandler{body}) + defer ts.Close() + + logger := &Logger{ + ResponseHeader: true, + ResponseBody: true, + Formatters: []Formatter{ + &multipartFormatter{}, + }, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + client := &http.Client{ + Transport: logger.RoundTripper(newTransport()), + } + + resp, err := client.Get(ts.URL) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + want := fmt.Sprintf(golden(t.Name()), ts.URL, len(body), len(body)) + if got := buf.String(); got != want { + t.Errorf("logged HTTP request %s; want %s", got, want) + } +} + +// nestedMultipartBody returns a multipart body nested depth levels deep, with a plain +// text part at the innermost level, and the content type of the outermost level. +// Boundaries are nested1 (outermost) through nested. +func nestedMultipartBody(t *testing.T, depth int) (body []byte, contentType string) { + t.Helper() + body = []byte("innermost part reached") + contentType = "text/plain" + for i := depth; i >= 1; i-- { + var buf bytes.Buffer + writer := multipart.NewWriter(&buf) + if err := writer.SetBoundary(fmt.Sprintf("nested%d", i)); err != nil { + t.Fatalf("cannot set multipart boundary: %v", err) + } + part, err := writer.CreatePart(textproto.MIMEHeader{ + "Content-Type": []string{contentType}, + }) + if err != nil { + t.Fatalf("cannot create nested part: %v", err) + } + if _, err := part.Write(body); err != nil { + t.Fatalf("cannot write nested part: %v", err) + } + if err := writer.Close(); err != nil { + t.Fatalf("cannot close multipart writer: %v", err) + } + body = buf.Bytes() + contentType = "multipart/mixed; boundary=" + writer.Boundary() + } + return body, contentType +} + +// TestOutgoingMultipartNested verifies nested multipart bodies are split into parts +// only up to maxMultipartDepth, and deeper levels are printed as a regular body, +// so a deeply nested body cannot amplify memory use. +func TestOutgoingMultipartNested(t *testing.T) { + t.Parallel() + ts := httptest.NewServer(&helloHandler{}) + defer ts.Close() + + logger := &Logger{ + RequestHeader: true, + RequestBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + client := &http.Client{ + Transport: logger.RoundTripper(newTransport()), + } + + body, contentType := nestedMultipartBody(t, maxMultipartDepth+2) + req, err := http.NewRequest(http.MethodPost, ts.URL, bytes.NewReader(body)) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + req.Header.Set("Content-Type", contentType) + resp, err := client.Do(req) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + got := buf.String() + if count := strings.Count(got, "* multipart/mixed body with 1 part"); count != maxMultipartDepth { + t.Errorf("split %d levels of nested multipart body, wanted %d", count, maxMultipartDepth) + } + // Boundaries of split levels are consumed; the level past the depth limit is + // printed as a regular body, so its boundary delimiters show up as-is. + if boundary := fmt.Sprintf("--nested%d", maxMultipartDepth); strings.Contains(got, boundary) { + t.Errorf("boundary %s of a split level should not be printed", boundary) + } + if boundary := fmt.Sprintf("--nested%d", maxMultipartDepth+1); !strings.Contains(got, boundary) { + t.Errorf("boundary %s should be printed as part of a regular body", boundary) + } + if !strings.Contains(got, "innermost part reached") { + t.Error("innermost part body should be printed") + } +} + +// TestOutgoingMultipartEmptyPart verifies a part carrying no body doesn't print one. +func TestOutgoingMultipartEmptyPart(t *testing.T) { + t.Parallel() + ts := httptest.NewServer(&helloHandler{}) + defer ts.Close() + + logger := &Logger{ + RequestHeader: true, + RequestBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + client := &http.Client{ + Transport: logger.RoundTripper(newTransport()), + } + + uri := fmt.Sprintf("%s/multipart-upload", ts.URL) + body := &bytes.Buffer{} + writer := multipart.NewWriter(body) + if err := writer.SetBoundary(multipartMixedBoundary); err != nil { + t.Fatalf("cannot set multipart boundary: %v", err) + } + if err := writer.WriteField("empty", ""); err != nil { + t.Fatalf("cannot write empty field: %v", err) + } + if err := writer.Close(); err != nil { + t.Fatalf("cannot close multipart writer: %v", err) + } + req, err := http.NewRequest(http.MethodPost, uri, body) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + req.Header.Set("Content-Type", writer.FormDataContentType()) + resp, err := client.Do(req) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + want := fmt.Sprintf(golden(t.Name()), uri, ts.Listener.Addr()) + if got := buf.String(); got != want { + t.Errorf("logged HTTP request %s; want %s", got, want) + } +} + func TestOutgoingProxy(t *testing.T) { t.Parallel() ts := httptest.NewServer(&helloHandler{}) @@ -1336,6 +1762,135 @@ func TestOutgoingTLS(t *testing.T) { testBody(t, resp.Body, []byte("Hello, world!")) } +func TestOutgoingTLSIPSAN(t *testing.T) { + t.Parallel() + ts := httptest.NewTLSServer(&helloHandler{}) + defer ts.Close() + + logger := &Logger{ + TLS: true, + RequestHeader: true, + RequestBody: true, + ResponseHeader: true, + ResponseBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + client := ts.Client() + client.Transport = logger.RoundTripper(client.Transport) + + req, err := http.NewRequest(http.MethodGet, ts.URL, nil) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + req.Host = "127.0.0.1" // hit the IP SAN path; the httptest cert has 127.0.0.1 in IPAddresses + req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com") + resp, err := client.Do(req) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + want := fmt.Sprintf(golden(t.Name()), ts.URL) + if got := buf.String(); !regexp.MustCompile(want).MatchString(got) { + t.Errorf("logged HTTP request %s; want %s", got, want) + } + testBody(t, resp.Body, []byte("Hello, world!")) +} + +// TestOutgoingTLSCertificateSAN checks the subjectAltName matching for a TLS connection. +func TestOutgoingTLSCertificateSAN(t *testing.T) { + t.Parallel() + cert := selfSignedCert(t, []string{"*.example.com"}, nil) + + ts := httptest.NewUnstartedServer(helloHandler{}) + ts.TLS = &tls.Config{Certificates: []tls.Certificate{cert}} + ts.StartTLS() + defer ts.Close() + + pool := x509.NewCertPool() + pool.AddCert(cert.Leaf) + + testCases := []struct { + name string + host string + want []string + notWant []string + }{ + { + name: "wildcard match", + host: "sub.example.com", + want: []string{ + `subjectAltName: "sub.example.com" matches cert's "*.example.com"`, + "TLS certificate verify ok.", + }, + }, + { + name: "label mismatch under wildcard", + host: "sub.other.com", + notWant: []string{"subjectAltName", "TLS certificate verify ok."}, + }, + { + name: "label count mismatch", + host: "a.b.c.example.com", + notWant: []string{"subjectAltName", "TLS certificate verify ok."}, + }, + { + name: "ip without matching san", + host: "10.0.0.1", + notWant: []string{"subjectAltName", "TLS certificate verify ok."}, + }, + { + name: "empty hostname label", + host: ".", + notWant: []string{"subjectAltName", "TLS certificate verify ok."}, + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + logger := &Logger{ + TLS: true, + RequestHeader: true, + ResponseHeader: true, + ResponseBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + + transport := newTransport() + transport.TLSClientConfig = &tls.Config{ + RootCAs: pool, + ServerName: "sub.example.com", + } + client := &http.Client{Transport: logger.RoundTripper(transport)} + + req, err := http.NewRequest(http.MethodGet, ts.URL, nil) + if err != nil { + t.Fatalf("cannot create request: %v", err) + } + req.Host = tc.host + resp, err := client.Do(req) + if err != nil { + t.Fatalf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + testBody(t, resp.Body, []byte("Hello, world!")) + + got := buf.String() + for _, want := range tc.want { + if !strings.Contains(got, want) { + t.Errorf("host %q: TLS log does not contain %q\n%s", tc.host, want, got) + } + } + for _, notWant := range tc.notWant { + if strings.Contains(got, notWant) { + t.Errorf("host %q: TLS log should not contain %q\n%s", tc.host, notWant, got) + } + } + }) + } +} + func TestOutgoingTLSInsecureSkipVerify(t *testing.T) { t.Parallel() ts := httptest.NewTLSServer(&helloHandler{}) @@ -1652,6 +2207,139 @@ func TestOutgoingHTTP2MutualTLSNoSafetyLogging(t *testing.T) { } } +func TestOutgoingTrailers(t *testing.T) { + t.Parallel() + ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + w.Header().Set("Trailer", "X-Checksum") + w.Header().Set("Content-Type", "text/plain") + w.WriteHeader(http.StatusOK) + fmt.Fprint(w, "hello") + w.Header().Set("X-Checksum", "abc123") + })) + defer ts.Close() + + logger := &Logger{ + RequestHeader: true, + ResponseHeader: true, + ResponseBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + client := &http.Client{ + Transport: logger.RoundTripper(newTransport()), + } + + req, err := http.NewRequest(http.MethodGet, ts.URL, nil) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com") + resp, err := client.Do(req) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + testBody(t, resp.Body, []byte("hello")) + got := buf.String() + if !strings.Contains(got, "< Trailers:") { + t.Errorf("expected trailers section in output, got:\n%s", got) + } + if !strings.Contains(got, "X-Checksum") { + t.Errorf("expected X-Checksum trailer in output, got:\n%s", got) + } +} + +func TestOutgoingTrailersDeclaredButEmpty(t *testing.T) { + t.Parallel() + // The server announces a trailer but never sends a value for it. The HTTP + // client pre-populates resp.Trailer with a nil value for the declared key, + // so there is no trailer to print and no trailers section should appear. + ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + w.Header().Set("Trailer", "X-Checksum") + w.Header().Set("Content-Type", "text/plain") + w.WriteHeader(http.StatusOK) + fmt.Fprint(w, "hello") + })) + defer ts.Close() + + logger := &Logger{ + RequestHeader: true, + ResponseHeader: true, + ResponseBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + client := &http.Client{ + Transport: logger.RoundTripper(newTransport()), + } + + req, err := http.NewRequest(http.MethodGet, ts.URL, nil) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + resp, err := client.Do(req) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + testBody(t, resp.Body, []byte("hello")) + + if got := buf.String(); strings.Contains(got, "< Trailers:") { + t.Errorf("expected no trailers section for a declared-but-empty trailer, got:\n%s", got) + } +} + +func TestOutgoingTrailersNotCaptured(t *testing.T) { + t.Parallel() + // The server sends a real trailer value, but the logger does not read the + // response body (ResponseBody is off), so the HTTP client never fills + // resp.Trailer. Rather than drop the announced trailers silently, the logger + // prints an informational note in their place. + ts := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + w.Header().Set("Trailer", "X-Checksum") + w.Header().Set("Content-Type", "text/plain") + w.WriteHeader(http.StatusOK) + fmt.Fprint(w, "hello") + w.Header().Set("X-Checksum", "abc123") + })) + defer ts.Close() + + logger := &Logger{ + RequestHeader: true, + ResponseHeader: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + client := &http.Client{ + Transport: logger.RoundTripper(newTransport()), + } + + req, err := http.NewRequest(http.MethodGet, ts.URL, nil) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + resp, err := client.Do(req) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + testBody(t, resp.Body, []byte("hello")) + + got := buf.String() + if !strings.Contains(got, "trailers announced but not captured") { + t.Errorf("expected an informational note about uncaptured trailers, got:\n%s", got) + } + if strings.Contains(got, "< Trailers:") { + t.Errorf("did not expect a trailers section when trailers were not captured, got:\n%s", got) + } + if strings.Contains(got, "abc123") { + t.Errorf("did not expect the trailer value to be captured, got:\n%s", got) + } +} + // netListener is similar to httptest.newlocalListener() and listens locally in a random port. // See https://github.com/golang/go/blob/5375c71289917ac7b25c6fa4bb0f4fa17be19a07/src/net/http/httptest/server.go#L60-L75 func netListener() (net.Listener, error) { diff --git a/go.mod b/go.mod index 8f164c1..ccac6bd 100644 --- a/go.mod +++ b/go.mod @@ -1,5 +1,5 @@ module github.com/henvic/httpretty -go 1.22 +go 1.25.0 -require golang.org/x/tools v0.14.0 +require golang.org/x/tools v0.48.0 diff --git a/go.sum b/go.sum index abb29e5..fb0ee67 100644 --- a/go.sum +++ b/go.sum @@ -1,28 +1,2 @@ -github.com/yuin/goldmark v1.4.1/go.mod h1:mwnBkeHKe2W/ZEtQ+71ViKU8L12m81fl3OWwC1Zlc8k= -golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= -golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc= -golang.org/x/mod v0.6.0-dev.0.20220106191415-9b9b3d81d5e3/go.mod h1:3p9vT2HGsQu2K1YbXdKPJLVgG5VJdoTa1poYQBtP1AY= -golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= -golang.org/x/net v0.0.0-20210226172049-e18ecbb05110/go.mod h1:m0MpNAwzfU5UDzcl9v0D8zg8gWTRqZa9RBIspLL5mdg= -golang.org/x/net v0.0.0-20211015210444-4f30a5c0130f/go.mod h1:9nx3DQGgdP8bBQD5qxJ1jj9UTztislL4KSBs9R2vV5Y= -golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= -golang.org/x/sync v0.0.0-20210220032951-036812b2e83c/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= -golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= -golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= -golang.org/x/sys v0.0.0-20210423082822-04245dca01da/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= -golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.0.0-20211019181941-9d821ace8654/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= -golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= -golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= -golang.org/x/text v0.3.6/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= -golang.org/x/text v0.3.7/go.mod h1:u+2+/6zg+i71rQMx5EYifcz6MCKuco9NR6JIITiCfzQ= -golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= -golang.org/x/tools v0.0.0-20191119224855-298f0cb1881e/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo= -golang.org/x/tools v0.1.10 h1:QjFRCZxdOhBJ/UNgnBZLbNV13DlbnK0quyivTnXJM20= -golang.org/x/tools v0.1.10/go.mod h1:Uh6Zz+xoGYZom868N8YTex3t7RhtHDBrE8Gzo9bV56E= -golang.org/x/tools v0.14.0 h1:jvNa2pY0M4r62jkRQ6RwEZZyPcymeL9XZMLBbV7U2nc= -golang.org/x/tools v0.14.0/go.mod h1:uYBEerGOWcJyEORxN+Ek8+TT266gXkNlHdJBwexUsBg= -golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= -golang.org/x/xerrors v0.0.0-20191011141410-1b5146add898/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= -golang.org/x/xerrors v0.0.0-20200804184101-5ec99f83aff1/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= +golang.org/x/tools v0.48.0 h1:3+hClM1aLL5mjMKm5ovokw9epgRXPuu2tILgismM6RE= +golang.org/x/tools v0.48.0/go.mod h1:08xX0orndb/F7jJxGDicx061tyd5pcMto75YMAXr6lk= diff --git a/httpretty.go b/httpretty.go index 3bedebb..6fb2b26 100644 --- a/httpretty.go +++ b/httpretty.go @@ -106,6 +106,10 @@ type Logger struct { RequestBody bool // ResponseHeader received by the client or set by the HTTP handlers. + // + // A received response's trailers are logged only when ResponseBody is also + // enabled and the body is read in full; otherwise httpretty notes that they + // were announced but not captured. ResponseHeader bool // ResponseBody received by the client or set by the server. @@ -325,6 +329,21 @@ func (r roundTripper) RoundTrip(req *http.Request) (resp *http.Response, err err } // Middleware for logging incoming requests to a HTTP server. +// +// The http.ResponseWriter passed to the wrapped handler is a recorder that +// captures the response for logging. +// It forwards http.Flusher when the underlying writer supports it, +// so handlers can flush as usual. However, http.Hijacker and http.Pusher +// are not reachable through a direct type assertion. +// +// To reach them, or to set read/write deadlines, use http.NewResponseController(w), +// which unwraps the recorder and operates on the original ResponseWriter: +// +// rc := http.NewResponseController(w) +// conn, brw, err := rc.Hijack() +// +// Once a connection is hijacked the response bypasses the recorder, so +// httpretty cannot log its status or body. func (l *Logger) Middleware(next http.Handler) http.Handler { return httpHandler{ logger: l, @@ -364,7 +383,11 @@ func (h httpHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) { buf: &bytes.Buffer{}, } defer p.printServerResponse(req, rec) - h.next.ServeHTTP(rec, req) + var rw http.ResponseWriter = rec + if _, ok := w.(http.Flusher); ok { + rw = &flushingRecorder{rec} + } + h.next.ServeHTTP(rw, req) } // PrintRequest prints a request, even when WithHide is used to hide it. diff --git a/httpretty_test.go b/httpretty_test.go index 5feca64..3fd884c 100644 --- a/httpretty_test.go +++ b/httpretty_test.go @@ -2,8 +2,16 @@ package httpretty import ( "bytes" + "crypto/ecdsa" + "crypto/elliptic" + "crypto/rand" + "crypto/tls" + "crypto/x509" + "crypto/x509/pkix" _ "embed" + "errors" "io" + "math/big" "net" "net/http" "net/url" @@ -51,6 +59,32 @@ func TestPrintRequest(t *testing.T) { } } +// errReader always fails, simulating a request body that cannot be read. +type errReader struct{} + +func (errReader) Read([]byte) (int, error) { return 0, errors.New("read failure") } + +func TestPrintRequestBodyReadError(t *testing.T) { + t.Parallel() + req, err := http.NewRequest(http.MethodPost, "http://www.example.com/", io.NopCloser(errReader{})) + if err != nil { + panic(err) + } + req.ContentLength = 10 + + logger := &Logger{ + RequestBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + logger.PrintRequest(req) + + want := "* cannot read body: read failure\n" + if got := buf.String(); got != want { + t.Errorf("PrintRequest(req) = %v, wanted %v", got, want) + } +} + func TestPrintRequestWithAlign(t *testing.T) { t.Parallel() var req, err = http.NewRequest(http.MethodPost, "http://wxww.example.com/", nil) @@ -248,6 +282,46 @@ func TestPrintResponseNil(t *testing.T) { } } +func TestStatusColor(t *testing.T) { + t.Parallel() + // proto is always blue+bold; only the status text color varies by class. + const proto = "\x1b[34;1mHTTP/1.1\x1b[0m" + testCases := []struct { + desc string + status string + want string // expected colored status text, hardcoded + }{ + {"empty status", "", "\x1b[31m\x1b[0m"}, + {"informational 1xx", "100 Continue", "\x1b[34m100 Continue\x1b[0m"}, + {"success 2xx", "200 OK", "\x1b[32m200 OK\x1b[0m"}, + {"redirect 3xx", "301 Moved Permanently", "\x1b[33m301 Moved Permanently\x1b[0m"}, + {"client error 4xx", "404 Not Found", "\x1b[31m404 Not Found\x1b[0m"}, + {"server error 5xx", "500 Internal Server Error", "\x1b[1;31m500 Internal Server Error\x1b[0m"}, + {"non-standard 6xx", "678 Teapot Overheated", "\x1b[34m678 Teapot Overheated\x1b[0m"}, + {"non-numeric status", "OK", "\x1b[31mOK\x1b[0m"}, + } + for _, tc := range testCases { + t.Run(tc.desc, func(t *testing.T) { + t.Parallel() + logger := &Logger{ + ResponseHeader: true, + Colors: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + logger.PrintResponse(&http.Response{ + Proto: "HTTP/1.1", + Status: tc.status, + Header: http.Header{}, + }) + want := "< " + proto + " " + tc.want + "\n\n" + if got := buf.String(); got != want { + t.Errorf("PrintResponse(%q) status line = %q, want %q", tc.status, got, want) + } + }) + } +} + func testBody(t *testing.T, r io.Reader, want []byte) { t.Helper() got, err := io.ReadAll(r) @@ -272,6 +346,42 @@ func TestJSONFormatterWriterError(t *testing.T) { } } +// selfSignedCert builds a self-signed certificate carrying the given SANs. +// It is its own CA, so the client can both present and trust it. +// Tests use it for a throwaway httptest certificate. +func selfSignedCert(t *testing.T, dnsNames []string, ips []net.IP) tls.Certificate { + t.Helper() + key, err := ecdsa.GenerateKey(elliptic.P256(), rand.Reader) + if err != nil { + t.Fatalf("cannot generate key: %v", err) + } + template := &x509.Certificate{ + SerialNumber: big.NewInt(1), + Subject: pkix.Name{CommonName: "httpretty test"}, + NotBefore: time.Now().Add(-time.Hour), + NotAfter: time.Now().Add(time.Hour), + KeyUsage: x509.KeyUsageDigitalSignature | x509.KeyUsageCertSign, + ExtKeyUsage: []x509.ExtKeyUsage{x509.ExtKeyUsageServerAuth}, + BasicConstraintsValid: true, + IsCA: true, + DNSNames: dnsNames, + IPAddresses: ips, + } + der, err := x509.CreateCertificate(rand.Reader, template, template, &key.PublicKey, key) + if err != nil { + t.Fatalf("cannot create certificate: %v", err) + } + leaf, err := x509.ParseCertificate(der) + if err != nil { + t.Fatalf("cannot parse certificate: %v", err) + } + return tls.Certificate{ + Certificate: [][]byte{der}, + PrivateKey: key, + Leaf: leaf, + } +} + // newTransport creates a new HTTP Transport. // // BUG(henvic): this function is mostly used at this moment because of a data race condition on the standard library. diff --git a/internal/color/color.go b/internal/color/color.go index fb8a6db..637ace1 100644 --- a/internal/color/color.go +++ b/internal/color/color.go @@ -84,7 +84,7 @@ const ( // Format text for terminal. // You can pass an arbitrary number of Attribute or []Attribute followed by any other values, // that can either be a string or something else (that is converted to string using fmt.Sprint). -func Format(s ...interface{}) string { +func Format(s ...any) string { if len(s) == 0 { return "" } @@ -117,12 +117,12 @@ func Format(s ...interface{}) string { return wrap(params, fmt.Sprint(s[in:]...)) } -func printExtraColorAttribute(v interface{}) string { +func printExtraColorAttribute(v any) string { return fmt.Sprintf("(EXTRA color.Attribute=%v)", v) } // StripAttributes from input arguments and return unformatted text. -func StripAttributes(s ...interface{}) (raw string) { +func StripAttributes(s ...any) (raw string) { in := -1 for i, v := range s { switch v.(type) { @@ -144,7 +144,7 @@ func StripAttributes(s ...interface{}) (raw string) { // Escape text for terminal. func Escape(s string) string { - return strings.Replace(s, escape, unescape, -1) + return strings.ReplaceAll(s, escape, unescape) } // sequence returns a formated SGR sequence to be plugged into a "\x1b[...m" diff --git a/internal/color/color_test.go b/internal/color/color_test.go index 9455991..bf2de42 100644 --- a/internal/color/color_test.go +++ b/internal/color/color_test.go @@ -61,7 +61,7 @@ func TestNoFormat(t *testing.T) { func TestFormatStartingWithNumber(t *testing.T) { want := "\x1b[102;95m100 forks\x1b[0m" number := 100 - if reflect.TypeOf(number).String() != "int" { + if reflect.TypeFor[int]().String() != "int" { t.Errorf("Must be integer; not a similar like Attribute") } if got := Format(BgHiGreen, FgHiMagenta, number, " forks"); got != want { diff --git a/printer.go b/printer.go index b85b28f..4d523ce 100644 --- a/printer.go +++ b/printer.go @@ -6,7 +6,9 @@ import ( "crypto/x509" "fmt" "io" + "maps" "mime" + "mime/multipart" "net" "net/http" "slices" @@ -50,7 +52,7 @@ func (p *printer) flush() { fmt.Fprint(w, p.buf.String()) } -func (p *printer) print(a ...interface{}) { +func (p *printer) print(a ...any) { p.logger.mu.Lock() defer p.logger.mu.Unlock() w := p.logger.getWriter() @@ -61,7 +63,7 @@ func (p *printer) print(a ...interface{}) { fmt.Fprint(&p.buf, a...) } -func (p *printer) println(a ...interface{}) { +func (p *printer) println(a ...any) { p.logger.mu.Lock() defer p.logger.mu.Unlock() w := p.logger.getWriter() @@ -72,7 +74,7 @@ func (p *printer) println(a ...interface{}) { fmt.Fprintln(&p.buf, a...) } -func (p *printer) printf(format string, a ...interface{}) { +func (p *printer) printf(format string, a ...any) { p.logger.mu.Lock() defer p.logger.mu.Unlock() w := p.logger.getWriter() @@ -111,7 +113,7 @@ func (p *printer) printRequestInfo(req *http.Request) { } } -// checkFilter checkes if the request is filtered and if the Request value is nil. +// checkFilter checks if the request is filtered and if the Request value is nil. func (p *printer) checkFilter(req *http.Request) (skip bool) { filter := p.logger.getFilter() if req == nil { @@ -148,10 +150,24 @@ func (p *printer) printResponse(resp *http.Response) { p.printResponseHeader(resp.Proto, resp.Status, resp.Header) p.maybeOnReady() } + + // The client only fills resp.Trailer once the body is read to EOF by httpretty. + // When the body is left unread, too large, binary, or filtered we don't capture trailers. + var readToEnd bool if p.logger.ResponseBody && resp.Body != nil && (resp.Request == nil || resp.Request.Method != http.MethodHead) { - p.printResponseBodyOut(resp) + readToEnd = p.printResponseBodyOut(resp) p.maybeOnReady() } + if p.logger.ResponseHeader && len(resp.Trailer) > 0 { + switch { + case hasTrailerValues(resp.Trailer): + p.printTrailers('<', resp.Trailer) + p.maybeOnReady() + case !readToEnd: + p.printf("* %s\n", p.format(color.FgBlue, "trailers announced but not captured")) + p.maybeOnReady() + } + } } func (p *printer) checkBodyFiltered(h http.Header) (skip bool, err error) { @@ -166,31 +182,34 @@ func (p *printer) checkBodyFiltered(h http.Header) (skip bool, err error) { return false, nil } -func (p *printer) printResponseBodyOut(resp *http.Response) { +// printResponseBodyOut prints the client response body and reports whether the +// body was read to EOF. +func (p *printer) printResponseBodyOut(resp *http.Response) (readToEnd bool) { if resp.ContentLength == 0 { - return + return true } skip, err := p.checkBodyFiltered(resp.Header) if err != nil { p.printf("* %s\n", p.format(color.FgRed, "error on response body filter: ", err.Error())) } if skip { - return + return false } if contentType := resp.Header.Get("Content-Type"); contentType != "" && isBinaryMediatype(contentType) { p.println("* body contains binary data") - return + return false } if p.logger.MaxResponseBody > 0 && resp.ContentLength > p.logger.MaxResponseBody { p.printf("* body is too long (%d bytes) to print, skipping (longer than %d bytes)\n", resp.ContentLength, p.logger.MaxResponseBody) - return + return false } contentType := resp.Header.Get("Content-Type") if resp.ContentLength == -1 { - if newBody := p.printBodyUnknownLength(contentType, p.logger.MaxResponseBody, resp.Body); newBody != nil { + newBody, readToEnd := p.printBodyUnknownLength(contentType, p.logger.MaxResponseBody, resp.Body) + if newBody != nil { resp.Body = newBody } - return + return readToEnd } var buf bytes.Buffer tee := io.TeeReader(resp.Body, &buf) @@ -199,13 +218,14 @@ func (p *printer) printResponseBodyOut(resp *http.Response) { resp.Body = io.NopCloser(&buf) }() p.printBodyReader(contentType, tee) + return true } // isBinary uses heuristics to guess if file is binary (actually, "printable" in the terminal). // See discussion at https://groups.google.com/forum/#!topic/golang-nuts/YeLL7L7SwWs func isBinary(body []byte) bool { if len(body) > 512 { - body = body[512:] + body = body[:512] } // If file contains UTF-8 OR UTF-16 BOM, consider it non-binary. // Reference: https://tools.ietf.org/html/draft-ietf-websec-mime-sniff-03#section-5 @@ -243,6 +263,7 @@ var binaryMediatypes = map[string]struct{}{ "video": {}, "application/vnd.ms-fontobject": {}, "font": {}, + "application/gzip": {}, "application/x-gzip": {}, "application/zip": {}, "application/x-rar-compressed": {}, @@ -263,7 +284,8 @@ func isBinaryMediatype(mediatype string) bool { const maxDefaultUnknownReadable = 4096 // bytes -func (p *printer) printBodyUnknownLength(contentType string, maxLength int64, r io.ReadCloser) (newBody io.ReadCloser) { +// printBodyUnknownLength is used for (tentatively) printing a body of unknown length. +func (p *printer) printBodyUnknownLength(contentType string, maxLength int64, r io.ReadCloser) (newBody io.ReadCloser, readToEnd bool) { if maxLength == 0 { maxLength = maxDefaultUnknownReadable } @@ -277,10 +299,12 @@ func (p *printer) printBodyUnknownLength(contentType string, maxLength int64, r // Avoiding returning early to mitigate any risk of bad reader implementations that might // send something even after returning io.EOF if read again. case err == io.EOF && n == 0: + readToEnd = true case err == nil && int64(n) > maxLength: p.printf("* body is too long, skipping (contains more than %d bytes)\n", n-1) case err == io.ErrUnexpectedEOF || err == nil: // cannot pass same bytes reader below because we only read it once. + readToEnd = true p.printBodyReader(contentType, bytes.NewReader(pb)) default: p.printf("* cannot read body: %v (%d bytes read)\n", err, n) @@ -309,14 +333,8 @@ func (p *printer) printTLSInfo(state *tls.ConnectionState, skipVerifyChains bool if state == nil { return } - protocol := tlsProtocolVersions[state.Version] - if protocol == "" { - protocol = fmt.Sprintf("%#v", state.Version) - } - cipher := tlsCiphers[state.CipherSuite] - if cipher == "" { - cipher = fmt.Sprintf("%#v", state.CipherSuite) - } + protocol := tls.VersionName(state.Version) + cipher := tls.CipherSuiteName(state.CipherSuite) p.printf("* TLS connection using %s / %s", p.format(color.FgBlue, protocol), p.format(color.FgBlue, cipher)) if !skipVerifyChains && state.VerifiedChains == nil { p.print(" (insecure=true)") @@ -377,13 +395,24 @@ func (p *printer) printCertificate(hostname string, cert *x509.Certificate) { p.printf(`* subject: %v * start date: %v * expire date: %v -* issuer: %v `, p.format(color.FgBlue, cert.Subject), p.format(color.FgBlue, cert.NotBefore.Format(time.UnixDate)), p.format(color.FgBlue, cert.NotAfter.Format(time.UnixDate)), - p.format(color.FgBlue, cert.Issuer), ) + if hostname != "" { + if san, ok := matchedSAN(hostname, cert); ok { + if san == "" { + p.printf("* subjectAltName: \"%s\" matches cert's IP address!\n", + p.format(color.FgBlue, hostname)) + } else { + p.printf("* subjectAltName: \"%s\" matches cert's \"%s\"\n", + p.format(color.FgBlue, hostname), + p.format(color.FgBlue, san)) + } + } + } + p.printf("* issuer: %v\n", p.format(color.FgBlue, cert.Issuer)) if hostname == "" { return } @@ -394,12 +423,64 @@ func (p *printer) printCertificate(hostname string, cert *x509.Certificate) { p.println("* TLS certificate verify ok.") } +// matchedSAN finds the cert SAN entry that matches hostname, following the +// RFC 6125 wildcard rule (leftmost label only). For IP-literal hostnames it +// scans IPAddresses and returns "" with ok=true to signal an IP match. +func matchedSAN(hostname string, cert *x509.Certificate) (string, bool) { + if ip := net.ParseIP(hostname); ip != nil { + for _, certIP := range cert.IPAddresses { + if certIP.Equal(ip) { + return "", true + } + } + return "", false + } + host := strings.TrimSuffix(strings.ToLower(hostname), ".") + for _, name := range cert.DNSNames { + if matchHostname(strings.ToLower(name), host) { + return name, true + } + } + return "", false +} + +func matchHostname(pattern, host string) bool { + pattern = strings.TrimSuffix(pattern, ".") + if pattern == "" || host == "" { + return false + } + patternParts := strings.Split(pattern, ".") + hostParts := strings.Split(host, ".") + if len(patternParts) != len(hostParts) { + return false + } + for i, part := range patternParts { + if i == 0 && part == "*" { + continue + } + if part != hostParts[i] { + return false + } + } + return true +} + +// printServerResponse prints the headers the handler set. +// Naturally, we do not capture anything added later, such as Date. func (p *printer) printServerResponse(req *http.Request, rec *responseRecorder) { + var trailers http.Header if p.logger.ResponseHeader { - // TODO(henvic): see how httptest.ResponseRecorder adds extra headers due to Content-Type detection - // and other stuff (Date). It would be interesting to show them here too (either as default or opt-in). - p.printResponseHeader(req.Proto, fmt.Sprintf("%d %s", rec.statusCode, http.StatusText(rec.statusCode)), rec.Header()) + var headers http.Header + headers, trailers = splitTrailers(rec.Header()) + p.printResponseHeader(req.Proto, fmt.Sprintf("%d %s", rec.statusCode, http.StatusText(rec.statusCode)), headers) + } + p.printServerResponseBody(rec) + if p.logger.ResponseHeader && hasTrailerValues(trailers) { + p.printTrailers('<', trailers) } +} + +func (p *printer) printServerResponseBody(rec *responseRecorder) { if !p.logger.ResponseBody || rec.size == 0 { return } @@ -410,7 +491,7 @@ func (p *printer) printServerResponse(req *http.Request, rec *responseRecorder) if skip { return } - if mediatype := req.Header.Get("Content-Type"); mediatype != "" && isBinaryMediatype(mediatype) { + if mediatype := rec.Header().Get("Content-Type"); mediatype != "" && isBinaryMediatype(mediatype) { p.println("* body contains binary data") return } @@ -421,40 +502,214 @@ func (p *printer) printServerResponse(req *http.Request, rec *responseRecorder) p.printBodyReader(rec.Header().Get("Content-Type"), rec.buf) } +// statusColor returns color attributes for an HTTP status line +// based on the status class: +// 1xx (informational), 2xx (success) is green, 3xx (redirection) is yellow, +// 4xx (client error) is red, and 5xx (server error) is bold red. +// Any non-standard classes (0xx, 6xx-9xx) are blue, +// and an empty status or one that doesn't start with a digit, is shown red. +func statusColor(status string) []color.Attribute { + if len(status) == 0 { + return []color.Attribute{color.FgRed} + } + switch status[0] { + case '2': + return []color.Attribute{color.FgGreen} + case '3': + return []color.Attribute{color.FgYellow} + case '4': + return []color.Attribute{color.FgRed} + case '5': + return []color.Attribute{color.Bold, color.FgRed} + case '0', '1', '6', '7', '8', '9': + return []color.Attribute{color.FgBlue} + default: + return []color.Attribute{color.FgRed} + } +} + func (p *printer) printResponseHeader(proto, status string, h http.Header) { p.printf("< %s %s\n", p.format(color.FgBlue, color.Bold, proto), - p.format(color.FgRed, status)) + p.format(statusColor(status), status)) p.printHeaders('<', h) p.println() } +// printTrailers that are sent after the body. +func (p *printer) printTrailers(prefix rune, h http.Header) { + p.printf("%c Trailers:\n", prefix) + p.printHeaders(prefix, h) + p.println() +} + +// hasTrailerValues reports whether h carries at least one non-empty value. +// The HTTP client pre-populates resp.Trailer with nil values for each key +// declared in the response's Trailer header before the body is read to EOF, +// so a non-zero len(resp.Trailer) alone does not mean any trailer value is +// actually available to print. +func hasTrailerValues(h http.Header) bool { + for _, v := range h { + if len(v) > 0 { + return true + } + } + return false +} + +// splitTrailers separates a handled server response's recorded header map into +// the headers sent in the header block and the trailers sent after the body. +// +// An http.Server emits trailers two ways, both reconstructed here the same way +// httptest.ResponseRecorder.Result builds its Trailer: keys announced ahead of +// time in the "Trailer" header, and keys written with the http.TrailerPrefix +// magic prefix. Both otherwise linger in the ResponseWriter header map, so they +// are kept out of headers to avoid printing them as if they were sent with the +// header block. The "Trailer" announcement header itself is left in headers. +// +// In the common case where h carries no trailers, h itself is returned along +// with nil trailers, so callers must treat both maps as read-only. +func splitTrailers(h http.Header) (headers, trailers http.Header) { + var announced map[string]struct{} + for _, list := range h["Trailer"] { + for key := range strings.SplitSeq(list, ",") { + if key = http.CanonicalHeaderKey(strings.TrimSpace(key)); key != "" { + if announced == nil { + announced = map[string]struct{}{} + } + announced[key] = struct{}{} + } + } + } + split := false + for key := range h { + if _, ok := announced[key]; ok { + split = true + break + } + if strings.HasPrefix(key, http.TrailerPrefix) { + split = true + break + } + } + if !split { + return h, nil + } + headers = http.Header{} + trailers = http.Header{} + for key, vv := range h { + if _, ok := announced[key]; ok { + trailers[key] = vv + continue + } + if name, ok := strings.CutPrefix(key, http.TrailerPrefix); ok { + for _, v := range vv { + trailers.Add(name, v) + } + continue + } + headers[key] = vv + } + return headers, trailers +} + func (p *printer) printBodyReader(contentType string, r io.Reader) { - mediatype, _, _ := mime.ParseMediaType(contentType) body, err := io.ReadAll(r) if err != nil { p.printf("* cannot read body: %v\n", p.format(color.FgRed, err.Error())) return } + p.printBody(contentType, body, 0) +} + +// maxMultipartDepth bounds how deep nested multipart bodies are split into parts; +// deeper parts are printed as a regular body. Without a bound, a maliciously nested +// multipart body of n bytes would amplify to O(n²) memory, as splitting each level +// copies all the levels nested under it. +const maxMultipartDepth = 2 + +// printBody of a message or of a part of a multipart message, nested depth levels deep. +func (p *printer) printBody(contentType string, body []byte, depth int) { + mediatype, params, _ := mime.ParseMediaType(contentType) + f := p.formatter(mediatype) + // A multipart body is printed part by part, unless a formatter handles it. + if f == nil && depth < maxMultipartDepth && strings.HasPrefix(mediatype, "multipart/") && params["boundary"] != "" && + p.printMultipart(mediatype, params["boundary"], body, depth) { + return + } if isBinary(body) { p.println("* body contains binary data") return } + if f == nil { + p.println(string(body)) + return + } + var formatted bytes.Buffer + if err := p.safeBodyFormat(f, &formatted, body); err != nil { + p.printf("* body cannot be formatted: %v\n%s\n", p.format(color.FgRed, err.Error()), string(body)) + return + } + p.println(formatted.String()) +} + +// formatter returns the first formatter matching the media type, if any. +func (p *printer) formatter(mediatype string) Formatter { for _, f := range p.logger.Formatters { - if ok := p.safeBodyMatch(f, mediatype); !ok { - continue - } - var formatted bytes.Buffer - switch err := p.safeBodyFormat(f, &formatted, body); { - case err != nil: - p.printf("* body cannot be formatted: %v\n%s\n", p.format(color.FgRed, err.Error()), string(body)) - default: - p.println(formatted.String()) + if p.safeBodyMatch(f, mediatype) { + return f } - return } + return nil +} - p.println(string(body)) +// printMultipart prints each part of a multipart body on its own, so parts are +// formatted, and checked for binary content, individually. +// +// It reports whether the body was printed. A body that cannot be parsed (say, a +// truncated one) is left for the caller to print as-is, and nothing is printed here. +func (p *printer) printMultipart(mediatype, boundary string, body []byte, depth int) bool { + type bodyPart struct { + header http.Header + body []byte + } + var parts []bodyPart + mr := multipart.NewReader(bytes.NewReader(body), boundary) + for { + next, err := mr.NextRawPart() + if err == io.EOF { + break + } + if err != nil { + return false + } + b, err := io.ReadAll(next) + if err != nil { + return false + } + parts = append(parts, bodyPart{ + header: http.Header(next.Header), + body: b, + }) + } + if len(parts) == 0 { + return false + } + noun := "parts" + if len(parts) == 1 { + noun = "part" + } + p.printf("* %s body with %d %s\n", mediatype, len(parts), noun) + for i, part := range parts { + p.printf("* part %d\n", i+1) + p.printHeaders('|', part.header) + if len(part.body) == 0 { + continue + } + p.println() + p.printBody(part.header.Get("Content-Type"), part.body, depth+1) + } + return true } func (p *printer) safeBodyMatch(f Formatter, mediatype string) bool { @@ -476,7 +731,7 @@ func (p *printer) safeBodyFormat(f Formatter, w io.Writer, src []byte) (err erro return f.Format(w, src) } -func (p *printer) format(s ...interface{}) string { +func (p *printer) format(s ...any) string { if p.logger.Colors { return color.Format(s...) } @@ -537,14 +792,16 @@ func (p *printer) printRequestHeader(req *http.Request) { // addRequestHeaders returns a copy of the given header with an additional headers set, if known. func addRequestHeaders(req *http.Request) http.Header { cp := http.Header{} - for k, v := range req.Header { - cp[k] = v - } + maps.Copy(cp, req.Header) if len(req.Header.Values("Content-Length")) == 0 && req.ContentLength > 0 { cp.Set("Content-Length", fmt.Sprintf("%d", req.ContentLength)) } + if len(req.Header.Values("Transfer-Encoding")) == 0 && len(req.TransferEncoding) > 0 { + cp.Set("Transfer-Encoding", strings.Join(req.TransferEncoding, ", ")) + } + host := req.Host if host == "" { host = req.URL.Host @@ -571,7 +828,6 @@ func (p *printer) printRequestBody(req *http.Request) { p.println("* body contains binary data") return } - // TODO(henvic): add support for printing multipart/formdata information as body (to responses too). if p.logger.MaxRequestBody > 0 && req.ContentLength > p.logger.MaxRequestBody { p.printf("* body is too long (%d bytes) to print, skipping (longer than %d bytes)\n", req.ContentLength, p.logger.MaxRequestBody) @@ -588,7 +844,7 @@ func (p *printer) printRequestBody(req *http.Request) { p.printBodyReader(contentType, tee) return } - if newBody := p.printBodyUnknownLength(contentType, p.logger.MaxRequestBody, req.Body); newBody != nil { + if newBody, _ := p.printBodyUnknownLength(contentType, p.logger.MaxRequestBody, req.Body); newBody != nil { req.Body = newBody } } diff --git a/recorder.go b/recorder.go index 9b55a65..7079027 100644 --- a/recorder.go +++ b/recorder.go @@ -51,3 +51,20 @@ func (rr *responseRecorder) WriteHeader(statusCode int) { rr.ResponseWriter.WriteHeader(statusCode) rr.statusCode = statusCode } + +// Unwrap returns the underlying ResponseWriter so that callers using +// http.NewResponseController can reach interfaces (Flusher, Hijacker, +// Pusher, deadline setters) implemented by the original writer. +func (rr *responseRecorder) Unwrap() http.ResponseWriter { + return rr.ResponseWriter +} + +// flushingRecorder is used only when the underlying writer implements +// http.Flusher, so that rw.(http.Flusher) works. +type flushingRecorder struct { + *responseRecorder +} + +func (fr *flushingRecorder) Flush() { + fr.ResponseWriter.(http.Flusher).Flush() +} diff --git a/server_test.go b/server_test.go index b820cc9..2bfcd33 100644 --- a/server_test.go +++ b/server_test.go @@ -105,7 +105,7 @@ func TestIncomingNotFound(t *testing.T) { t.Errorf("cannot connect to the server: %v", err) } if resp.StatusCode != http.StatusNotFound { - t.Errorf("got status codem %v, wanted %v", resp.StatusCode, http.StatusNotFound) + t.Errorf("got status code %v, wanted %v", resp.StatusCode, http.StatusNotFound) } }() is.Wait() @@ -241,6 +241,45 @@ func TestIncomingSanitized(t *testing.T) { } } +func TestIncomingSkipSanitize(t *testing.T) { + t.Parallel() + logger := &Logger{ + RequestHeader: true, + RequestBody: true, + ResponseHeader: true, + ResponseBody: true, + SkipSanitize: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + is := inspect(logger.Middleware(helloHandler{}), 1) + + ts := httptest.NewServer(is) + defer ts.Close() + uri := fmt.Sprintf("%s/incoming", ts.URL) + go func() { + client := newServerClient() + req, err := http.NewRequest(http.MethodGet, uri, nil) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + req.Header.Add("User-Agent", "Robot/0.1 crawler@example.com") + req.AddCookie(&http.Cookie{ + Name: "food", + Value: "sorbet", + }) + + if _, err = client.Do(req); err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + }() + is.Wait() + want := fmt.Sprintf(golden(t.Name()), uri, is.req.RemoteAddr, ts.Listener.Addr()) + if got := buf.String(); got != want { + t.Errorf("logged HTTP request %s; want %s", got, want) + } +} + type hideHandler struct { next http.Handler } @@ -385,6 +424,39 @@ func TestIncomingSkipHeader(t *testing.T) { } } +func TestIncomingTransferEncoding(t *testing.T) { + t.Parallel() + logger := &Logger{ + RequestHeader: true, + RequestBody: true, + ResponseHeader: true, + ResponseBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + is := inspect(logger.Middleware(helloHandler{}), 1) + ts := httptest.NewServer(is) + defer ts.Close() + + go func() { + client := newServerClient() + req, err := http.NewRequest(http.MethodPut, ts.URL, strings.NewReader("ping")) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + // Transfer-Encoding lives in its own field on http.Request rather than in Header. + req.TransferEncoding = []string{"chunked"} + if _, err = client.Do(req); err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + }() + is.Wait() + + if want, got := "> Transfer-Encoding: chunked\n", buf.String(); !strings.Contains(got, want) { + t.Errorf("logged HTTP request %q; want it to contain %q", got, want) + } +} + func TestIncomingBodyFilter(t *testing.T) { t.Parallel() logger := &Logger{ @@ -790,6 +862,183 @@ func TestIncomingBinaryBodyNoMediatypeHeader(t *testing.T) { } } +func TestIncomingBinaryResponseTextRequest(t *testing.T) { + t.Parallel() + logger := &Logger{ + RequestHeader: true, + RequestBody: true, + ResponseHeader: true, + ResponseBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + is := inspect(logger.Middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + // Respond with a binary Content-Type but a body that has no binary bytes, + // so only the Content-Type header check can catch it (not the byte-level heuristic). + w.Header().Set("Content-Type", "application/pdf") + fmt.Fprint(w, "not really a pdf") + })), 1) + + ts := httptest.NewServer(is) + defer ts.Close() + go func() { + client := newServerClient() + req, err := http.NewRequest(http.MethodPost, ts.URL, strings.NewReader(`{"query":"convert"}`)) + if err != nil { + t.Errorf("cannot create request: %v", err) + } + req.Header.Set("Content-Type", "application/json") + if _, err = client.Do(req); err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + }() + is.Wait() + got := buf.String() + // The response body should be detected as binary based on the response Content-Type (application/pdf), + // not the request Content-Type (application/json). + if !strings.Contains(got, "* body contains binary data") { + t.Errorf("expected response body to be detected as binary based on response Content-Type, got:\n%s", got) + } + if !strings.Contains(got, `{"query":"convert"}`) { + t.Errorf("expected request body to be printed, but it was missing from:\n%s", got) + } +} + +func TestIncomingFlusher(t *testing.T) { + t.Parallel() + logger := &Logger{ + ResponseHeader: true, + ResponseBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + is := inspect(logger.Middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + w.Header().Set("Content-Type", "text/plain") + // Flush must not panic when the middleware wraps the ResponseWriter. + if f, ok := w.(http.Flusher); ok { + fmt.Fprint(w, "streamed") + f.Flush() + } else { + t.Error("expected ResponseWriter to implement http.Flusher") + } + })), 1) + + ts := httptest.NewServer(is) + defer ts.Close() + go func() { + client := newServerClient() + resp, err := client.Get(ts.URL) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + testBody(t, resp.Body, []byte("streamed")) + }() + is.Wait() + got := buf.String() + if !strings.Contains(got, "200 OK") { + t.Errorf("expected 200 OK in output, got:\n%s", got) + } + if !strings.Contains(got, "streamed") { + t.Errorf("expected streamed body in output, got:\n%s", got) + } +} + +// plainWriter is a minimal http.ResponseWriter that does not implement +// http.Flusher, used to verify the middleware does not falsely advertise +// flushing when the underlying writer cannot. +type plainWriter struct { + h http.Header + statusCode int + body bytes.Buffer +} + +func (p *plainWriter) Header() http.Header { + if p.h == nil { + p.h = http.Header{} + } + return p.h +} +func (p *plainWriter) Write(b []byte) (int, error) { return p.body.Write(b) } +func (p *plainWriter) WriteHeader(c int) { p.statusCode = c } + +func TestIncomingNonFlushableUnderlying(t *testing.T) { + t.Parallel() + logger := &Logger{ + ResponseHeader: true, + ResponseBody: true, + } + var logBuf bytes.Buffer + logger.SetOutput(&logBuf) + + var sawFlusher bool + var rcFlushErr error + handler := logger.Middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _, sawFlusher = w.(http.Flusher) + rcFlushErr = http.NewResponseController(w).Flush() + w.Header().Set("Content-Type", "text/plain") + fmt.Fprint(w, "ok") + })) + + pw := &plainWriter{} + req := httptest.NewRequest(http.MethodGet, "http://example.com/", nil) + handler.ServeHTTP(pw, req) + + if sawFlusher { + t.Error("inner handler should not see http.Flusher when underlying is not flushable") + } + if rcFlushErr == nil { + t.Error("expected http.NewResponseController(w).Flush() to return an error") + } + // A non-flushable writer must not stop the response: it still reaches the + // client and is recorded by the middleware. + if got := pw.body.String(); got != "ok" { + t.Errorf("underlying writer body = %q, want %q", got, "ok") + } + if got := logBuf.String(); !strings.Contains(got, "ok") { + t.Errorf("expected recorded body in log output, got:\n%s", got) + } +} + +func TestIncomingResponseController(t *testing.T) { + t.Parallel() + logger := &Logger{ + ResponseHeader: true, + ResponseBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + is := inspect(logger.Middleware(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + w.Header().Set("Content-Type", "text/plain") + rc := http.NewResponseController(w) + fmt.Fprint(w, "streamed") + if err := rc.Flush(); err != nil { + t.Errorf("rc.Flush(): %v", err) + } + // SetReadDeadline is not on the wrapper; the controller must walk + // Unwrap to reach it on the underlying writer. + if err := rc.SetReadDeadline(time.Time{}); err != nil { + t.Errorf("rc.SetReadDeadline(): %v", err) + } + })), 1) + + ts := httptest.NewServer(is) + defer ts.Close() + go func() { + client := newServerClient() + resp, err := client.Get(ts.URL) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + testBody(t, resp.Body, []byte("streamed")) + }() + is.Wait() +} + func TestIncomingLongRequest(t *testing.T) { t.Parallel() logger := &Logger{ @@ -997,11 +1246,46 @@ func TestIncomingLongResponseUnknownLengthTooLong(t *testing.T) { } } +// TestIncomingMultipartResponse verifies a multipart body a handler responds with is +// printed part by part, just like a request body is. +func TestIncomingMultipartResponse(t *testing.T) { + t.Parallel() + logger := &Logger{ + ResponseHeader: true, + ResponseBody: true, + Formatters: []Formatter{ + &JSONFormatter{}, + }, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + body := multipartMixedBody(t) + is := inspect(logger.Middleware(multipartMixedHandler{body}), 1) + + ts := httptest.NewServer(is) + defer ts.Close() + uri := fmt.Sprintf("%s/multipart-download", ts.URL) + go func() { + client := newServerClient() + resp, err := client.Get(uri) + if err != nil { + t.Errorf("cannot connect to the server: %v", err) + return + } + testBody(t, resp.Body, body) + }() + is.Wait() + want := fmt.Sprintf(golden(t.Name()), uri, is.req.RemoteAddr) + if got := buf.String(); got != want { + t.Errorf("logged HTTP request %s; want %s", got, want) + } +} + func TestIncomingMultipartForm(t *testing.T) { t.Parallel() logger := &Logger{ - RequestHeader: true, - // TODO(henvic): print request body once support for printing out multipart/formdata body is added. + RequestHeader: true, + RequestBody: true, ResponseHeader: true, ResponseBody: true, Formatters: []Formatter{ @@ -1017,7 +1301,7 @@ func TestIncomingMultipartForm(t *testing.T) { uri := fmt.Sprintf("%s/multipart-upload", ts.URL) body := &bytes.Buffer{} writer := multipart.NewWriter(body) - multipartTestdata(writer, body) + multipartTestdata(writer) go func() { client := newServerClient() req, err := http.NewRequest(http.MethodPost, uri, body) @@ -1030,7 +1314,7 @@ func TestIncomingMultipartForm(t *testing.T) { } }() is.Wait() - want := fmt.Sprintf(golden(t.Name()), uri, is.req.RemoteAddr, ts.Listener.Addr(), writer.FormDataContentType()) + want := fmt.Sprintf(golden(t.Name()), uri, is.req.RemoteAddr, ts.Listener.Addr(), writer.FormDataContentType(), petition) if got := buf.String(); got != want { t.Errorf("logged HTTP request %s; want %s", got, want) } @@ -1270,6 +1554,105 @@ func TestIncomingMutualTLSNoSafetyLogging(t *testing.T) { } } +func TestIncomingTrailers(t *testing.T) { + t.Parallel() + logger := &Logger{ + RequestHeader: true, + ResponseHeader: true, + ResponseBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + + handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + w.Header().Set("Trailer", "X-Checksum") // announced trailer + w.Header().Set("Content-Type", "text/plain") + w.WriteHeader(http.StatusOK) + fmt.Fprint(w, "hello") + w.Header().Set("X-Checksum", "abc123") // value for the announced trailer + w.Header().Set(http.TrailerPrefix+"X-Late", "lateval") // unannounced trailer + }) + + ts := httptest.NewServer(logger.Middleware(handler)) + defer ts.Close() + + resp, err := newServerClient().Get(ts.URL) + if err != nil { + t.Fatalf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + testBody(t, resp.Body, []byte("hello")) + + got := buf.String() + // The Trailer announcement stays in the header block. + if !strings.Contains(got, "< Trailer: X-Checksum") { + t.Errorf("expected Trailer announcement header, got:\n%s", got) + } + // The raw http.TrailerPrefix magic key must never be printed. + if leaked := http.TrailerPrefix + "X-Late"; strings.Contains(got, leaked) { + t.Errorf("raw %q key leaked into output:\n%s", leaked, got) + } + trailersAt := strings.Index(got, "< Trailers:") + if trailersAt == -1 { + t.Fatalf("expected trailers section in output, got:\n%s", got) + } + if bodyAt := strings.Index(got, "hello"); bodyAt == -1 || bodyAt > trailersAt { + t.Errorf("expected body to be printed before trailers, got:\n%s", got) + } + // Both trailers (announced and prefix-based) appear in the trailers section, + // i.e. after the "< Trailers:" marker rather than in the header block. + for _, want := range []string{"X-Checksum: abc123", "X-Late: lateval"} { + switch at := strings.Index(got, want); { + case at == -1: + t.Errorf("expected %q in output, got:\n%s", want, got) + case at < trailersAt: + t.Errorf("expected %q in the trailers section, not the header block, got:\n%s", want, got) + } + } +} + +func TestIncomingTrailersDeclaredButEmpty(t *testing.T) { + t.Parallel() + logger := &Logger{ + RequestHeader: true, + ResponseHeader: true, + ResponseBody: true, + } + var buf bytes.Buffer + logger.SetOutput(&buf) + + // The handler announces a trailer but never writes a value for it, so there + // is nothing to print after the body. + handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header()["Date"] = nil + w.Header().Set("Trailer", "X-Checksum") + w.Header().Set("Content-Type", "text/plain") + w.WriteHeader(http.StatusOK) + fmt.Fprint(w, "hello") + }) + + ts := httptest.NewServer(logger.Middleware(handler)) + defer ts.Close() + + resp, err := newServerClient().Get(ts.URL) + if err != nil { + t.Fatalf("cannot connect to the server: %v", err) + } + defer resp.Body.Close() + testBody(t, resp.Body, []byte("hello")) + + got := buf.String() + // The Trailer announcement still appears in the header block. + if !strings.Contains(got, "< Trailer: X-Checksum") { + t.Errorf("expected Trailer announcement header, got:\n%s", got) + } + // With no value sent, there must be no trailers section. + if strings.Contains(got, "< Trailers:") { + t.Errorf("expected no trailers section for a declared-but-empty trailer, got:\n%s", got) + } +} + func newServerClient() *http.Client { return &http.Client{ Transport: newTransport(), diff --git a/testdata/log.txtar b/testdata/log.txtar index 13d36d3..ec535b9 100644 --- a/testdata/log.txtar +++ b/testdata/log.txtar @@ -223,6 +223,24 @@ long request received -- TestIncomingMinimal -- * Request to %s * Request from %s +-- TestIncomingMultipartResponse -- +* Request to %s +* Request from %s +< HTTP/1.1 200 OK +< Content-Type: multipart/mixed; boundary=f0f4a3b1c2d5 + +* multipart/mixed body with 2 parts +* part 1 +| Content-Type: text/plain + +Hello, world! +* part 2 +| Content-Type: application/json + +{ + "result": "Hello, world!", + "number": 3.14 +} -- TestIncomingMultipartForm -- * Request to %s * Request from %s @@ -233,6 +251,20 @@ long request received > Content-Type: %s > User-Agent: Go-http-client/1.1 +* multipart/form-data body with 3 parts +* part 1 +| Content-Disposition: form-data; name="author" + +Frédéric Bastiat +* part 2 +| Content-Disposition: form-data; name="title" + +Candlemakers' Petition +* part 3 +| Content-Disposition: form-data; name="file"; filename="petition" +| Content-Type: application/octet-stream + +%s < HTTP/1.1 200 OK upload received @@ -299,6 +331,18 @@ Hello, world! < HTTP/1.1 200 OK {"result":"Hello, world!","number":3.14} +-- TestIncomingSkipSanitize -- +* Request to %s +* Request from %s +> GET /incoming HTTP/1.1 +> Host: %s +> Accept-Encoding: gzip +> Cookie: food=sorbet +> User-Agent: Robot/0.1 crawler@example.com + +< HTTP/1.1 200 OK + +Hello, world! -- TestIncomingTLS -- ^\* Request to https://example\.com/ \* Request from %s @@ -505,6 +549,7 @@ form received \* subject: CN=localhost,OU=Cloud,O=Plifk,L=Carmel-by-the-Sea,ST=California,C=US \* start date: Wed Aug 12 22:20:45 UTC 2020 \* expire date: Fri Jul 19 22:20:45 UTC 2120 +\* subjectAltName: "localhost" matches cert's "localhost" \* issuer: CN=localhost,OU=Cloud,O=Plifk,L=Carmel-by-the-Sea,ST=California,C=US \* TLS certificate verify ok\. < HTTP/2\.0 200 OK @@ -577,11 +622,89 @@ long request received > Content-Length: 10355 > Content-Type: %s +* multipart/form-data body with 3 parts +* part 1 +| Content-Disposition: form-data; name="author" + +Frédéric Bastiat +* part 2 +| Content-Disposition: form-data; name="title" + +Candlemakers' Petition +* part 3 +| Content-Disposition: form-data; name="file"; filename="petition" +| Content-Type: application/octet-stream + +%s < HTTP/1.1 200 OK < Content-Length: 15 < Content-Type: text/plain; charset=utf-8 upload received +-- TestOutgoingMultipartEmptyPart -- +* Request to %s +> POST /multipart-upload HTTP/1.1 +> Host: %s +> Content-Length: 84 +> Content-Type: multipart/form-data; boundary=f0f4a3b1c2d5 + +* multipart/form-data body with 1 part +* part 1 +| Content-Disposition: form-data; name="empty" +-- TestOutgoingMultipartFormatter -- +* Request to %s +< HTTP/1.1 200 OK +< Content-Length: %d +< Content-Type: multipart/mixed; boundary=f0f4a3b1c2d5 + +%d bytes of multipart data +-- TestOutgoingMultipartResponse -- +* Request to %s +< HTTP/1.1 200 OK +< Content-Length: %d +< Content-Type: multipart/mixed; boundary=f0f4a3b1c2d5 + +* multipart/mixed body with 2 parts +* part 1 +| Content-Type: text/plain + +Hello, world! +* part 2 +| Content-Type: application/json + +{ + "result": "Hello, world!", + "number": 3.14 +} +-- TestOutgoingMultipartInvalid -- +* Request to %s +> POST /multipart-upload HTTP/1.1 +> Host: %s +> Content-Length: %d +> Content-Type: multipart/form-data; boundary=8ef4ab7d2a1c + +%s +-- TestOutgoingMultipartMixed -- +* Request to %s +> POST /multipart-upload HTTP/1.1 +> Host: %s +> Content-Length: 438 +> Content-Type: %s + +* multipart/form-data body with 2 parts +* part 1 +| Content-Disposition: form-data; name="metadata" +| Content-Type: application/json + +{ + "result": "Hello, world!", + "number": 3.14 +} +* part 2 +| Content-Disposition: form-data; name="file"; filename="image.png" +| Content-Type: application/octet-stream + +* body contains binary data -- TestOutgoingSanitized -- * Request to %s > GET / HTTP/1.1 @@ -626,6 +749,7 @@ Hello, world! \* subject: O=Acme Co \* start date: Thu Jan 1 00:00:00 UTC 1970 \* expire date: Sat Jan 29 16:00:00 UTC 2084 +\* subjectAltName: "example\.com" matches cert's "example\.com" \* issuer: O=Acme Co \* TLS certificate verify ok\. < HTTP/1\.1 200 OK @@ -645,6 +769,25 @@ Hello, world! > User-Agent: Robot/0.1 crawler@example.com * remote error: tls: %s +-- TestOutgoingTLSIPSAN -- +^\* Request to %s +> GET / HTTP/1\.1 +> Host: 127\.0\.0\.1 +> User-Agent: Robot/0\.1 crawler@example\.com + +\* TLS connection using TLS \d+\.\d+ / \w+ +\* Server certificate: +\* subject: O=Acme Co +\* start date: Thu Jan 1 00:00:00 UTC 1970 +\* expire date: Sat Jan 29 16:00:00 UTC 2084 +\* subjectAltName: "127\.0\.0\.1" matches cert's IP address! +\* issuer: O=Acme Co +\* TLS certificate verify ok\. +< HTTP/1\.1 200 OK +< Content-Length: 13 +< Content-Type: text/plain; charset=utf-8 + +Hello, world! -- TestOutgoingTLSInsecureSkipVerify -- ^\* Request to %s \* Skipping TLS verification: connection is susceptible to man-in-the-middle attacks\. @@ -657,6 +800,7 @@ Hello, world! \* subject: O=Acme Co \* start date: Thu Jan 1 00:00:00 UTC 1970 \* expire date: Sat Jan 29 16:00:00 UTC 2084 +\* subjectAltName: "example\.com" matches cert's "example\.com" \* issuer: O=Acme Co \* TLS certificate verify ok\. < HTTP/1\.1 200 OK diff --git a/tls.go b/tls.go deleted file mode 100644 index 70c09d1..0000000 --- a/tls.go +++ /dev/null @@ -1,49 +0,0 @@ -package httpretty - -// A list of cipher suite IDs that are, or have been, implemented by the -// crypto/tls package. -// See https://www.iana.org/assignments/tls-parameters/tls-parameters.xml -// See https://github.com/golang/go/blob/c2edcf4b1253fdebc13df8a25979904c3ef01c66/src/crypto/tls/cipher_suites.go -var tlsCiphers = map[uint16]string{ - // TLS 1.0 - 1.2 cipher suites. - 0x0005: "TLS_RSA_WITH_RC4_128_SHA", - 0x000a: "TLS_RSA_WITH_3DES_EDE_CBC_SHA", - 0x002f: "TLS_RSA_WITH_AES_128_CBC_SHA", - 0x0035: "TLS_RSA_WITH_AES_256_CBC_SHA", - 0x003c: "TLS_RSA_WITH_AES_128_CBC_SHA256", - 0x009c: "TLS_RSA_WITH_AES_128_GCM_SHA256", - 0x009d: "TLS_RSA_WITH_AES_256_GCM_SHA384", - 0xc007: "TLS_ECDHE_ECDSA_WITH_RC4_128_SHA", - 0xc009: "TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA", - 0xc00a: "TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA", - 0xc011: "TLS_ECDHE_RSA_WITH_RC4_128_SHA", - 0xc012: "TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA", - 0xc013: "TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA", - 0xc014: "TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA", - 0xc023: "TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256", - 0xc027: "TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256", - 0xc02f: "TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256", - 0xc02b: "TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256", - 0xc030: "TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384", - 0xc02c: "TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384", - 0xcca8: "TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256", - 0xcca9: "TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256", - - // TLS 1.3 cipher suites. - 0x1301: "TLS_AES_128_GCM_SHA256", - 0x1302: "TLS_AES_256_GCM_SHA384", - 0x1303: "TLS_CHACHA20_POLY1305_SHA256", - - // TLS_FALLBACK_SCSV isn't a standard cipher suite but an indicator - // that the client is doing version fallback. See RFC 7507. - 0x5600: "TLS_FALLBACK_SCSV", -} - -// List of TLS protocol versions supported by Go. -// See https://github.com/golang/go/blob/f4a8bf128364e852cff87cf404a5c16c457ef8f6/src/crypto/tls/common.go -var tlsProtocolVersions = map[uint16]string{ - 0x0301: "TLS 1.0", - 0x0302: "TLS 1.1", - 0x0303: "TLS 1.2", - 0x0304: "TLS 1.3", -}