Implement transport.LogRequests() (#9)

* Implement transport.LogRequests()

- Remove external dependencies (implement our own CURL printer)
- Switch to slog.Logger (requires Go 1.21)
- Require new opts param (this is technically breaking change, but we're under v0.0.0-, so it's fine).

* Fix tests

* Update README

* Remove unused code; PR feedback

README.md

@@ -20,13 +20,13 @@ authClient := http.Client{
 }
 ```
 
-Or debug all outgoing requests globally within your application:
+Or debug all outgoing requests as `curl` globally within your application:
 ```go
 debugMode := os.Getenv("DEBUG") == "true"
 
 http.DefaultTransport = transport.Chain(
     http.DefaultTransport,
-    transport.If(debugMode, transport.LogRequests),
+    transport.If(debugMode, transport.LogRequests(transport.LogOptions{Concise: true, CURL: true})),
 )
 ```
 

curl.go

@@ -0,0 +1,35 @@
+package transport
+
+import (
+	"bytes"
+	"fmt"
+	"net/http"
+	"strings"
+)
+
+func curl(r *http.Request, body *bytes.Buffer) string {
+	var b strings.Builder
+
+	fmt.Fprintf(&b, "curl")
+	if r.Method != "GET" && r.Method != "POST" {
+		fmt.Fprintf(&b, " -X %s", r.Method)
+	}
+
+	fmt.Fprintf(&b, " %s", singleQuoted(r.URL.String()))
+
+	if r.Method == "POST" {
+		fmt.Fprintf(&b, " --data-raw %s", singleQuoted(body.String()))
+	}
+
+	for name, vals := range r.Header {
+		for _, val := range vals {
+			fmt.Fprintf(&b, " -H %s", singleQuoted(fmt.Sprintf("%s: %s", name, val)))
+		}
+	}
+
+	return b.String()
+}
+
+func singleQuoted(v string) string {
+	return fmt.Sprintf("'%s'", strings.ReplaceAll(v, "'", `'\''`))
+}

go.mod

@@ -2,6 +2,4 @@ module github.com/go-chi/transport
 
 go 1.14
 
-require moul.io/http2curl/v2 v2.3.0
-
 require golang.org/x/sync v0.4.0

go.sum

@@ -1,35 +1,2 @@
-github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
-github.com/pkg/diff v0.0.0-20200914180035-5b29258ca4f7/go.mod h1:zO8QMzTeZd5cpnIkz/Gn6iK0jDfGicM1nynOkkPIl28=
-github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
-github.com/sergi/go-diff v1.0.0/go.mod h1:0CfEIISq7TuYL3j771MWULgwwjU+GofnZX9QAmXWZgo=
-github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
-github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4=
-github.com/tailscale/depaware v0.0.0-20210622194025-720c4b409502/go.mod h1:p9lPsd+cx33L3H9nNoecRRxPssFKUwwI50I3pZ0yT+8=
-github.com/yuin/goldmark v1.2.1/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74=
-golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
-golang.org/x/crypto v0.0.0-20191011191535-87dc89f01550/go.mod h1:yigFU9vqHzYiE8UmvKecakEJjdnWj3jj499lnFckfCI=
-golang.org/x/crypto v0.0.0-20200622213623-75b288015ac9/go.mod h1:LzIPMQfyMNhhGPhUkYOs5KpL4U8rLKemX1yGLhDgUto=
-golang.org/x/mod v0.3.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
-golang.org/x/mod v0.4.0/go.mod h1:s0Qsj1ACt9ePp/hMypM3fl4fZqREWJwdYDEqhRiZZUA=
-golang.org/x/net v0.0.0-20190404232315-eb5bcb51f2a3/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg=
-golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s=
-golang.org/x/net v0.0.0-20201021035429-f5854403a974/go.mod h1:sp8m0HH+o8qH0wwXwYZr8TS3Oi6o0r6Gce1SSxlDquU=
-golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
-golang.org/x/sync v0.0.0-20201020160332-67f06af15bc9/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM=
 golang.org/x/sync v0.4.0 h1:zxkM55ReGkDlKSM+Fu41A+zmbZuaPVbGMzvvdUPznYQ=
 golang.org/x/sync v0.4.0/go.mod h1:FU7BRWz2tNW+3quACPkgCx/L+uEAv1htQ0V83Z9Rj+Y=
-golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
-golang.org/x/sys v0.0.0-20190412213103-97732733099d/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20200930185726-fdedc70b468f/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-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/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.0.0-20201211185031-d93e913c1a58/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
-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=
-gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
-gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
-moul.io/http2curl/v2 v2.3.0 h1:9r3JfDzWPcbIklMOs2TnIFzDYvfAZvjeavG6EzP7jYs=
-moul.io/http2curl/v2 v2.3.0/go.mod h1:RW4hyBjTWSYDOxapodpNEtX0g5Eb16sxklBqmd2RHcE=

logRequests.go

@@ -1,30 +1,64 @@
+//go:build go1.21
+
 package transport
 
 import (
-	"log"
+	"bytes"
+	"fmt"
+	"io"
 	"net/http"
 	"time"
 
-	"moul.io/http2curl/v2"
+	"log/slog"
 )
 
-func LogRequests(next http.RoundTripper) http.RoundTripper {
-	return RoundTripFunc(func(req *http.Request) (resp *http.Response, err error) {
-		r := CloneRequest(req)
+type LogOptions struct {
+	Concise bool
+	CURL    bool
+}
 
-		curlCommand, _ := http2curl.GetCurlCommand(r)
-		log.Printf("%v", curlCommand)
-		log.Printf("request: %s %s", r.Method, r.URL)
+func LogRequests(opts LogOptions) func(next http.RoundTripper) http.RoundTripper {
+	return func(next http.RoundTripper) http.RoundTripper {
+		return RoundTripFunc(func(req *http.Request) (resp *http.Response, err error) {
+			ctx := req.Context()
+			r := CloneRequest(req)
 
-		startTime := time.Now()
-		defer func() {
-			if resp != nil {
-				log.Printf("response (HTTP %v): %v %s", time.Since(startTime), resp.Status, r.URL)
-			} else {
-				log.Printf("response (<nil>): %v %s", time.Since(startTime), r.URL)
+			var buf bytes.Buffer
+			if opts.CURL && r.Body != nil {
+				r.Body = io.NopCloser(io.TeeReader(r.Body, &buf))
 			}
-		}()
 
-		return next.RoundTrip(r)
-	})
+			slog.LogAttrs(ctx, slog.LevelDebug, fmt.Sprintf("Request: %v %s", r.Method, r.URL.String()))
+
+			startTime := time.Now()
+			defer func() {
+				level := slog.LevelError
+				var statusCode int
+				if resp != nil {
+					statusCode = resp.StatusCode
+					if statusCode >= 200 && statusCode < 400 {
+						level = slog.LevelInfo
+					}
+				}
+
+				attrs := []slog.Attr{}
+				if opts.CURL {
+					attrs = append(attrs, slog.String("curl", curl(r, &buf)))
+				}
+
+				if opts.Concise {
+					slog.LogAttrs(ctx, level, fmt.Sprintf("Request: %v %s => HTTP %v (%v)", r.Method, r.URL.String(), statusCode, time.Since(startTime)), attrs...)
+				} else {
+					attrs = append(attrs,
+						slog.String("url", r.URL.String()),
+						slog.Duration("duration", time.Since(startTime)),
+						slog.Int("status", statusCode),
+					)
+					slog.LogAttrs(ctx, level, fmt.Sprintf("Request"), attrs...)
+				}
+			}()
+
+			return next.RoundTrip(r)
+		})
+	}
 }

setHeaderFunc_test.go

@@ -34,7 +34,7 @@ func TestSetHeaderFunc(t *testing.T) {
 		Transport: transport.Chain(
 			http.DefaultTransport,
 			transport.SetHeaderFunc("Authorization", issueRandomAuthToken),
-			transport.LogRequests,
+			transport.LogRequests(transport.LogOptions{}),
 		),
 		Timeout: 15 * time.Second,
 	}

setHeader_test.go

@@ -45,7 +45,7 @@ func TestSetHeader(t *testing.T) {
 			transport.SetHeader("User-Agent", userAgent),
 			transport.SetHeader("Authorization", authHeader),
 			transport.SetHeader("x-extra", "value"),
-			transport.LogRequests,
+			transport.LogRequests(transport.LogOptions{}),
 		),
 		Timeout: 15 * time.Second,
 	}

transport_test.go

@@ -1,11 +1,13 @@
-package transport
+package transport_test
 
 import (
 	"fmt"
 	"net/http"
 	"net/http/httptest"
 	"testing"
 	"time"
+
+	"github.com/go-chi/transport"
 )
 
 func TestChain(t *testing.T) {
@@ -16,16 +18,21 @@ func TestChain(t *testing.T) {
 			return
 		}
 
+		if r.Header.Get("Accept-Encoding") != "gzip" {
+			w.WriteHeader(500)
+			return
+		}
+
 		fmt.Fprintf(w, expected)
 	}))
 	defer server.Close()
 
 	client := &http.Client{
 		Timeout: 15 * time.Second,
-		Transport: Chain(
+		Transport: transport.Chain(
 			nil,
-			SetHeader("User-Agent", "transport-chain/v1.0.0"),
-			LogRequests,
+			transport.SetHeader("User-Agent", "transport-chain/v1.0.0"),
+			transport.SetHeader("Accept-Encoding", "gzip"),
 		),
 	}
 
@@ -61,10 +68,10 @@ func TestChainWithRetries(t *testing.T) {
 
 	client := &http.Client{
 		Timeout: 15 * time.Second,
-		Transport: Chain(
+		Transport: transport.Chain(
 			http.DefaultTransport,
-			Retry(http.DefaultTransport, 5),
-			LogRequests,
+			transport.Retry(http.DefaultTransport, 5),
+			transport.LogRequests(transport.LogOptions{}),
 		),
 	}
 
@@ -101,10 +108,10 @@ func TestChainWithRetryAfter(t *testing.T) {
 
 	client := &http.Client{
 		Timeout: 15 * time.Second,
-		Transport: Chain(
+		Transport: transport.Chain(
 			http.DefaultTransport,
-			Retry(http.DefaultTransport, 5),
-			LogRequests,
+			transport.Retry(http.DefaultTransport, 5),
+			transport.LogRequests(transport.LogOptions{}),
 		),
 	}