diff --git a/client_test.go b/client_test.go index fd20620..edcc1b6 100644 --- a/client_test.go +++ b/client_test.go @@ -1762,6 +1762,52 @@ func TestOutgoingTLS(t *testing.T) { testBody(t, resp.Body, []byte("Hello, world!")) } +func TestOutgoingTLSPrintOrder(t *testing.T) { + t.Parallel() + for _, flusher := range []Flusher{NoBuffer, OnReady, OnEnd} { + ts := httptest.NewTLSServer(&helloHandler{}) + defer ts.Close() + + logger := &Logger{ + TLS: true, + RequestHeader: true, + RequestBody: true, + ResponseHeader: true, + ResponseBody: true, + } + logger.SetFlusher(flusher) + 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.Fatalf("cannot create request: %v", err) + } + req.Host = "example.com" + resp, err := client.Do(req) + if err != nil { + t.Fatalf("cannot connect to server: %v", err) + } + resp.Body.Close() + + got := buf.String() + tlsIdx := strings.Index(got, "* TLS connection using ") + reqIdx := strings.Index(got, "> GET / HTTP/1.1") + respIdx := strings.Index(got, "< HTTP/1.1 200 OK") + if tlsIdx == -1 || reqIdx == -1 || respIdx == -1 { + t.Fatalf("flusher %v: missing expected log sections in output:\n%s", flusher, got) + } + if tlsIdx >= reqIdx { + t.Errorf("flusher %v: TLS info at index %d should appear before request header at index %d", flusher, tlsIdx, reqIdx) + } + if reqIdx >= respIdx { + t.Errorf("flusher %v: request header at index %d should appear before response header at index %d", flusher, reqIdx, respIdx) + } + } +} + func TestOutgoingTLSIPSAN(t *testing.T) { t.Parallel() ts := httptest.NewTLSServer(&helloHandler{}) diff --git a/httpretty.go b/httpretty.go index 6fb2b26..b914186 100644 --- a/httpretty.go +++ b/httpretty.go @@ -95,8 +95,6 @@ type Logger struct { Time bool // TLS information, such as certificates and ciphers. - // BUG(henvic): Currently, the TLS information prints after the response header, although it - // should be printed before the request header. TLS bool // RequestHeader set by the client or received from the server. @@ -311,18 +309,31 @@ func (r roundTripper) RoundTrip(req *http.Request) (resp *http.Response, err err // please remember http.Request.TLS is ignored by the HTTP client. p.printOutgoingClientTLS(tlsClientConfig) } - p.printRequest(req) + var reqP printer + if l.TLS { + reqP = printer{ + logger: l, + flusher: OnEnd, + } + reqP.printRequest(req) + } else { + p.printRequest(req) + } defer func() { + if l.TLS { + if resp != nil { + p.printTLSInfo(resp.TLS, false) + p.printTLSServer(req.Host, resp.TLS) + } + p.print(reqP.buf.String()) + p.maybeOnReady() + } if err != nil { p.printf("* %s\n", p.format(color.FgRed, err.Error())) if resp == nil { return } } - if l.TLS { - p.printTLSInfo(resp.TLS, false) - p.printTLSServer(req.Host, resp.TLS) - } p.printResponse(resp) }() return tripper.RoundTrip(req) diff --git a/httpretty_test.go b/httpretty_test.go index 3fd884c..4fa62c6 100644 --- a/httpretty_test.go +++ b/httpretty_test.go @@ -393,7 +393,6 @@ func newTransport() *http.Transport { DialContext: (&net.Dialer{ Timeout: 30 * time.Second, KeepAlive: 30 * time.Second, - DualStack: true, }).DialContext, ForceAttemptHTTP2: true, MaxIdleConns: 100, diff --git a/testdata/log.txtar b/testdata/log.txtar index ec535b9..3e6f4ed 100644 --- a/testdata/log.txtar +++ b/testdata/log.txtar @@ -540,9 +540,6 @@ form received \* start date: Sat Jan 25 20:12:36 UTC 2020 \* expire date: Mon Jan 1 20:12:36 UTC 2120 \* issuer: CN=User,OU=User,O=Client,L=Rotterdam,ST=Zuid-Holland,C=NL -> GET /mutual-tls-test HTTP/1\.1 -> Host: localhost:%s - \* TLS connection using TLS \d+\.\d+ / \w+ \* ALPN: h2 accepted \* Server certificate: @@ -552,6 +549,9 @@ form received \* 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\. +> GET /mutual-tls-test HTTP/1\.1 +> Host: localhost:%s + < HTTP/2\.0 200 OK < Content-Length: 13 < Content-Type: text/plain; charset=utf-8 @@ -740,10 +740,6 @@ Hello, world! Hello, world! -- TestOutgoingTLS -- ^\* Request to %s -> GET / HTTP/1\.1 -> Host: example\.com -> User-Agent: Robot/0\.1 crawler@example\.com - \* TLS connection using TLS \d+\.\d+ / \w+ \* Server certificate: \* subject: O=Acme Co @@ -752,6 +748,10 @@ Hello, world! \* subjectAltName: "example\.com" matches cert's "example\.com" \* issuer: O=Acme Co \* TLS certificate verify ok\. +> GET / HTTP/1\.1 +> Host: example\.com +> User-Agent: Robot/0\.1 crawler@example\.com + < HTTP/1\.1 200 OK < Content-Length: 13 < Content-Type: text/plain; charset=utf-8 @@ -771,10 +771,6 @@ Hello, world! * 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 @@ -783,6 +779,10 @@ Hello, world! \* subjectAltName: "127\.0\.0\.1" matches cert's IP address! \* issuer: O=Acme Co \* TLS certificate verify ok\. +> GET / HTTP/1\.1 +> Host: 127\.0\.0\.1 +> User-Agent: Robot/0\.1 crawler@example\.com + < HTTP/1\.1 200 OK < Content-Length: 13 < Content-Type: text/plain; charset=utf-8 @@ -791,10 +791,6 @@ Hello, world! -- TestOutgoingTLSInsecureSkipVerify -- ^\* Request to %s \* Skipping TLS verification: connection is susceptible to man-in-the-middle attacks\. -> GET / HTTP/1\.1 -> Host: example\.com -> User-Agent: Robot/0\.1 crawler@example\.com - \* TLS connection using TLS \d+\.\d+ / \w+ \(insecure=true\) \* Server certificate: \* subject: O=Acme Co @@ -803,6 +799,10 @@ Hello, world! \* subjectAltName: "example\.com" matches cert's "example\.com" \* issuer: O=Acme Co \* TLS certificate verify ok\. +> GET / HTTP/1\.1 +> Host: example\.com +> User-Agent: Robot/0\.1 crawler@example\.com + < HTTP/1\.1 200 OK < Content-Length: 13 < Content-Type: text/plain; charset=utf-8