issues/184: Use roundTripper for logging (#185)

What:
- Use roundTripper for logging

Why:
- Fixes: #184

.github/workflows/ci.yml

@@ -14,7 +14,7 @@ jobs:
     timeout-minutes: 1
     strategy:
       matrix:
-        go-version: ['>1.19.1']
+        go-version: ['>1.19.3']
         platform: [ubuntu-22.04]
     runs-on: ${{ matrix.platform }}
     steps:
@@ -61,7 +61,7 @@ jobs:
     timeout-minutes: 7
     strategy:
       matrix:
-        go-version: ['>1.19.1']
+        go-version: ['>1.19.3']
         platform: [ubuntu-22.04]
     runs-on: ${{ matrix.platform }}
     steps:
@@ -103,7 +103,7 @@ jobs:
     timeout-minutes: 5
     strategy:
       matrix:
-        go-version: ['>1.19.1']
+        go-version: ['>1.19.3']
         platform: [ubuntu-22.04]
     runs-on: ${{ matrix.platform }}
     steps:
@@ -205,7 +205,7 @@ jobs:
   #   timeout-minutes: 2
   #   strategy:
   #     matrix:
-  #       go-version: ['>1.19.1']
+  #       go-version: ['>1.19.3']
   #       platform: [ubuntu-22.04]
   #   runs-on: ${{ matrix.platform }}
   #   steps:

CHANGELOG.md

@@ -3,6 +3,9 @@
 Most recent version is listed first.  
 
 
+## v0.0.25
+- ong/client: Use roundTripper for logging: https://github.com/komuw/ong/pull/185
+
 ## v0.0.24
 - Set session cookie only if non-empty: https://github.com/komuw/ong/pull/170
 - Add ReloadProtector middleware: https://github.com/komuw/ong/pull/171

client/client.go

@@ -3,53 +3,42 @@
 package client
 
 import (
-	"context"
 	"fmt"
-	"io"
 	"net"
 	"net/http"
 	"net/netip"
-	"net/url"
 	"os"
-	"strings"
 	"syscall"
 	"time"
 
 	"github.com/komuw/ong/log"
 )
 
-const logIDHeader = string(log.CtxKey)
+const (
+	logIDHeader = string(log.CtxKey)
+	errPrefix   = "ong/client:"
+)
 
 // Most of the code here is insipired by(or taken from):
 //   (a) https://www.agwa.name/blog/post/preventing_server_side_request_forgery_in_golang whose license(CC0 Public Domain) can be found here: https://creativecommons.org/publicdomain/zero/1.0
 //   (b) https://www.agwa.name/blog/post/preventing_server_side_request_forgery_in_golang/media/ipaddress.go
 // as of 9th/september/2022
 //
 
-// Safe creates a client that is safe from the server-side request forgery (SSRF) security vulnerability.
-func Safe(l log.Logger) *Client {
+// Safe creates a http client that has some good defaults & is safe from server-side request forgery (SSRF).
+// It also logs requests and responses using [log.Logger]
+func Safe(l log.Logger) *http.Client {
 	return new(true, l)
 }
 
-// Unsafe creates a client that is NOT safe from the server-side request forgery (SSRF) security vulnerability.
-func Unsafe(l log.Logger) *Client {
+// Unsafe creates a http client that has some good defaults & is NOT safe from server-side request forgery (SSRF).
+// It also logs requests and responses using [log.Logger]
+func Unsafe(l log.Logger) *http.Client {
 	return new(false, l)
 }
 
-// Client is a [http.Client] that has some good defaults. It also logs requests and responses using [log.Logger]
-//
-// Use either [Safe] or [Unsafe] to get a valid client.
-//
-// Clients should be reused instead of created as needed. Clients are safe for concurrent use by multiple goroutines.
-//
-// see [http.Client]
-type Client struct {
-	cli *http.Client
-	l   log.Logger
-}
-
 // new creates a client. Use [Safe] or [Unsafe] instead.
-func new(ssrfSafe bool, l log.Logger) *Client {
+func new(ssrfSafe bool, l log.Logger) *http.Client {
 	// The wikipedia monitoring dashboards are public: https://grafana.wikimedia.org/?orgId=1
 	// In there we can see that the p95 response times for http GET requests is ~700ms: https://grafana.wikimedia.org/d/RIA1lzDZk/application-servers-red?orgId=1
 	// and the p95 response times for http POST requests is ~3seconds:
@@ -79,120 +68,48 @@ func new(ssrfSafe bool, l log.Logger) *Client {
 		TLSHandshakeTimeout:   timeout,
 		ExpectContinueTimeout: 1 * time.Second,
 	}
-	cli := &http.Client{
-		Transport: transport,
-		Timeout:   timeout,
-	}
-
-	return &Client{
-		cli: cli,
-		l:   l.WithFields(log.F{"pid": os.Getpid()}),
-	}
-}
-
-// CloseIdleConnections closes any connections on its Transport which were previously connected from previous requests but are now sitting idle in a "keep-alive" state.
-//
-// It does not interrupt any connections currently in use.
-//
-// see [http.Client.CloseIdleConnections]
-func (c *Client) CloseIdleConnections() {
-	c.cli.CloseIdleConnections()
-}
-
-// Do sends an HTTP request and returns an HTTP response, following policy (such as redirects, cookies, auth) as configured on the client.
-//
-// see [http.Client.Do]
-func (c *Client) Do(ctx context.Context, req *http.Request) (resp *http.Response, err error) {
-	end := c.log(ctx, req.URL.EscapedPath(), req.Method)
-	defer func() {
-		end(resp, err)
-	}()
-
-	req = req.WithContext(ctx)
-	req.Header.Set(logIDHeader, log.GetId(ctx))
-	return c.cli.Do(req)
-}
-
-// Get issues a GET to the specified URL.
-//
-// see [http.Client.Get]
-func (c *Client) Get(ctx context.Context, url string) (resp *http.Response, err error) {
-	req, err := http.NewRequest(http.MethodGet, url, nil)
-	if err != nil {
-		return nil, err
-	}
-
-	return c.Do(ctx, req)
-}
 
-// Head issues a HEAD to the specified URL.
-//
-// see [http.Client.Head]
-func (c *Client) Head(ctx context.Context, url string) (resp *http.Response, err error) {
-	req, err := http.NewRequest(http.MethodHead, url, nil)
-	if err != nil {
-		return nil, err
+	lr := &loggingRT{
+		RoundTripper: transport,
+		l:            l.WithFields(log.F{"pid": os.Getpid()}),
 	}
 
-	return c.Do(ctx, req)
-}
-
-// Post issues a POST to the specified URL.
-//
-// see [http.Client.Post]
-func (c *Client) Post(ctx context.Context, url, contentType string, body io.Reader) (resp *http.Response, err error) {
-	req, err := http.NewRequest(http.MethodPost, url, body)
-	if err != nil {
-		return nil, err
+	return &http.Client{
+		Transport: lr,
+		Timeout:   timeout,
 	}
-	req.Header.Set("Content-Type", contentType)
-
-	return c.Do(ctx, req)
 }
 
-// PostForm issues a POST to the specified URL, with data's keys and values URL-encoded as the request body.
-//
-// see [http.Client.PostForm]
-func (c *Client) PostForm(ctx context.Context, url string, data url.Values) (resp *http.Response, err error) {
-	return c.Post(ctx, url, "application/x-www-form-urlencoded", strings.NewReader(data.Encode()))
+// loggingRT is a [http.RoundTripper] that logs requests and responses.
+type loggingRT struct {
+	l log.Logger
+	http.RoundTripper
 }
 
-func (c *Client) log(ctx context.Context, url, method string) func(resp *http.Response, err error) {
-	l := c.l.WithCtx(ctx)
-	l.Info(log.F{
-		"msg":     "http_client",
-		"process": "request",
-		"method":  method,
-		"url":     url,
-	})
-
+func (lr *loggingRT) RoundTrip(req *http.Request) (res *http.Response, err error) {
+	ctx := req.Context()
 	start := time.Now()
-
-	return func(resp *http.Response, err error) {
+	defer func() {
+		l := lr.l.WithCtx(ctx)
 		flds := log.F{
 			"msg":        "http_client",
-			"process":    "response",
-			"method":     "GET",
-			"url":        url,
+			"method":     req.Method,
+			"url":        req.URL.Redacted(),
 			"durationMS": time.Since(start).Milliseconds(),
 		}
-		if resp != nil {
-			flds["code"] = resp.StatusCode
-			flds["status"] = resp.Status
-
-			if resp.StatusCode >= http.StatusBadRequest {
-				// both client and server errors.
-				l.Error(err, flds)
-			} else {
-				l.Info(flds)
-			}
-		} else {
+		if err != nil {
 			l.Error(err, flds)
+		} else {
+			flds["code"] = res.StatusCode
+			flds["status"] = res.Status
+			l.Info(flds)
 		}
-	}
-}
+	}()
 
-const errPrefix = "ong/client:"
+	req.Header.Set(logIDHeader, log.GetId(ctx))
+
+	return lr.RoundTripper.RoundTrip(req)
+}
 
 func ssrfSocketControl(ssrfSafe bool) func(network, address string, conn syscall.RawConn) error {
 	if !ssrfSafe {

client/client_test.go

@@ -2,14 +2,12 @@ package client
 
 import (
 	"bytes"
-	"context"
 	"net/http"
 	"strings"
 	"testing"
 
-	"github.com/komuw/ong/log"
-
 	"github.com/akshayjshah/attest"
+	"github.com/komuw/ong/log"
 )
 
 func getLogger() log.Logger {
@@ -43,18 +41,17 @@ func TestClient(t *testing.T) {
 	t.Run("ssrf safe", func(t *testing.T) {
 		t.Parallel()
 
-		ctx := context.Background()
 		cli := Safe(getLogger())
 
 		for _, url := range urlsInPrivate {
-			res, err := cli.Get(ctx, url) // nolint:bodyclose
+			res, err := cli.Get(url) // nolint:bodyclose
 			clean(res)
 			attest.Error(t, err)
 			attest.True(t, strings.Contains(err.Error(), errPrefix))
 		}
 
 		for _, url := range urlsInPublic {
-			res, err := cli.Get(ctx, url) // nolint:bodyclose
+			res, err := cli.Get(url) // nolint:bodyclose
 			clean(res)
 			attest.Ok(t, err)
 			attest.Equal(t, res.StatusCode, http.StatusOK, attest.Sprintf("url=%s", url))
@@ -64,7 +61,6 @@ func TestClient(t *testing.T) {
 	t.Run("ssrf unsafe", func(t *testing.T) {
 		t.Parallel()
 
-		ctx := context.Background()
 		cli := Unsafe(getLogger())
 
 		for _, url := range urlsInPrivate {
@@ -74,14 +70,14 @@ func TestClient(t *testing.T) {
 				// and gets a 404.
 				break
 			}
-			res, err := cli.Get(ctx, url) // nolint:bodyclose
+			res, err := cli.Get(url) // nolint:bodyclose
 			clean(res)
 			attest.Error(t, err)
 			attest.False(t, strings.Contains(err.Error(), errPrefix))
 		}
 
 		for _, url := range urlsInPublic {
-			res, err := cli.Get(ctx, url) // nolint:bodyclose
+			res, err := cli.Get(url) // nolint:bodyclose
 			clean(res)
 			attest.Ok(t, err)
 			attest.Equal(t, res.StatusCode, http.StatusOK, attest.Sprintf("url=%s", url))
@@ -99,7 +95,7 @@ func TestClient(t *testing.T) {
 
 			cli := Safe(l)
 
-			res, err := cli.Get(context.Background(), "https://ajmsmsYnns.com") // nolint:bodyclose
+			res, err := cli.Get("https://ajmsmsYnns.com") // nolint:bodyclose
 			clean(res)
 			attest.Zero(t, res)
 			attest.Error(t, err)
@@ -115,7 +111,7 @@ func TestClient(t *testing.T) {
 
 			cli := Safe(l)
 
-			res, err := cli.Get(context.Background(), "https://example.com") // nolint:bodyclose
+			res, err := cli.Get("https://example.com") // nolint:bodyclose
 			clean(res)
 			attest.NotZero(t, res)
 			attest.Ok(t, err)
@@ -136,7 +132,7 @@ func TestClient(t *testing.T) {
 			cli := Safe(l)
 
 			b := strings.NewReader(`{"key":"value"}`)
-			res, err := cli.Post(context.Background(), "https://ajmsmsYnns.com", "application/json", b) // nolint:bodyclose
+			res, err := cli.Post("https://ajmsmsYnns.com", "application/json", b) // nolint:bodyclose
 			clean(res)
 			attest.Zero(t, res)
 			attest.Error(t, err)
@@ -153,7 +149,7 @@ func TestClient(t *testing.T) {
 			cli := Safe(l)
 
 			b := strings.NewReader(`{"key":"value"}`)
-			res, err := cli.Post(context.Background(), "https://example.com", "application/json", b) // nolint:bodyclose
+			res, err := cli.Post("https://example.com", "application/json", b) // nolint:bodyclose
 			clean(res)
 			attest.NotZero(t, res)
 			attest.Ok(t, err)

client/example_test.go

@@ -1,22 +1,20 @@
 package client_test
 
 import (
-	"context"
 	"os"
 
 	"github.com/komuw/ong/client"
 	"github.com/komuw/ong/log"
 )
 
-func ExampleClient_Get() {
+func ExampleSafe() {
 	l := log.New(os.Stdout, 7)
 
 	cli := client.Safe(l)
 	// This is the AWS metadata url.
 	url := "http://169.254.169.254/latest/meta-data"
-	_, _ = cli.Get(context.Background(), url)
+	_, _ = cli.Get(url)
 
 	// This will log something like:
-	// {"level":"info","logID":"Z5X7qXm8HkT8kZ83xQyrrQ","method":"GET","msg":"http_client","pid":11776,"process":"request","timestamp":"2022-10-09T12:03:33.851543383Z","url":"http://169.254.169.254/latest/meta-data"}
-	// {"durationMS":0,"err":"Get \"http://169.254.169.254/latest/meta-data\": dial tcp 169.254.169.254:80: ong/client: address 169.254.169.254 IsLinkLocalUnicast","level":"error","logID":"Z5X7qXm8HkT8kZ83xQyrrQ","method":"GET","msg":"http_client","pid":11776,"process":"response","timestamp":"2022-10-09T12:03:33.851889217Z","url":"http://169.254.169.254/latest/meta-data"}
+	// {"durationMS":0,"err":"dial tcp 169.254.169.254:80: ong/client: address 169.254.169.254 IsLinkLocalUnicast","level":"error","logID":"yHSDRXAJP7QKx3AJQKNt7w","method":"GET","msg":"http_client","pid":325431,"timestamp":"2022-12-08T08:43:42.151691969Z","url":"http://169.254.169.254/latest/meta-data"}
 }