RoundTrip Logging Within Go’s http.Client

Ok, so let’s say you have an HTTP client where you need to get information from the request and response calls for logging or debugging reasons. One way to do this is to create a custom RoundTripper to handle said logging.

What is a RoundTripper?

A RoundTripper is an interface that implements the RoundTrip function which makes the HTTP request and response on behalf of the http.Client, within the client’s Do() function. There is a field on the client called Transport that holds the implementation. Go will use the default version if no custom RoundTripper is provided.

Why it might not be okay to log using RoundTripper

Well, it is okay, but it might not appear that way when looking at the docs. When looking at the documentation, you’ll see this:

The first sentence of each comment block says not to modify the request or the response. Interpret? Hmm. If we want to log specific values from the request or response, does that count as interpreting? Well, it depends. Let’s look at some code and get to the bottom of it.

Creating the custom RoundTripper

To start, let’s go over a basic implementation. Our custom roundtripper would start like this:

type CustomRoundTripper struct{}

In order for us to be able to use this with our http.Client that we’ll create later on, we need to implement the RoundTrip function. Here’s the skeleton version:

func (ct CustomRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) { 
    return http.DefaultTransport.RoundTrip(req) 
}

At a minimum, this http.DefaultTransport.Roundtrip call will make the HTTP network request under the hood while closing the body of the request. This is the same function where our custom logging will be, so we’ll need to make some changes here.

The pointer to the http.Request, req, has some useful information that we could log like the URL, HTTP method, and HTTP header info. We could add a log line as simple as this to our function:

log.Printf("url: %s | method: %s", req.URL.String(), req.Method)

Then you have the other parts of the request like the content length, the body, and authentication information as well (sidenote: be careful about logging anything too sensitive like API keys, etc). The key here is to log these values at the end of the function so you don’t potentially disrupt the network call itself. One way to do this is to modify the return line and explicitly catch the error.

Once we catch the error, we can actually use a copy of the request object to log the same things like this:

resp, err := http.DefaultTransport.RoundTrip(req)
if err != nil {
	return nil, err
}

log.Printf("url: %s | method: %s", resp.Request.URL.String(), resp.Request.Method)

Anything beyond this and we’re flirting with modifying/reusing the request, which Go says not to do! And so we end with something like this where we now pass our custom RoundTripper into an http.Client:

package main

import (
	"log"
	"net/http"
	"time"
)

type CustomRoundTripper struct{}

func main() {

	rt := CustomRoundTripper{}

	client := http.Client{
		Transport: rt,
		Timeout:   time.Second * 60,
	}

	req, err := http.NewRequest(http.MethodGet, "https://www.google.com", nil)
	if err != nil {
		panic(err)
	}

	_, err = client.Do(req)
	if err != nil {
		panic(err)
	}

}

func (ct CustomRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
	resp, err := http.DefaultTransport.RoundTrip(req)
	if err != nil {
		return nil, err
	}

	log.Printf("url: %s | method: %s", resp.Request.URL.String(), resp.Request.Method)

	return resp, nil
}

When running our main function, we create a http.Client that makes a call to Google’s home page and log some details in the process:

[log timestamp] url: https://www.google.com | method: GET

What about logging http.Response information?

This is where it gets tricky. HTTP status and header information are okay here, but you have to watch out for logging the response body.

Why is this? because you’ll accidentally read the information from the response before your application code actually gets to use it. Let’s demonstrate this with the following code:

package main

import (
	"io"
	"log"
	"net/http"
	"time"
)

type CustomRoundTripper struct{}

func main() {

	rt := CustomRoundTripper{}

	client := http.Client{
		Transport: rt,
		Timeout:   time.Second * 60,
	}

	req, err := http.NewRequest(http.MethodGet, "https://www.google.com", nil)
	if err != nil {
		panic(err)
	}

	resp, err := client.Do(req)
	if err != nil {
		panic(err)
	}

	bytes, err := io.ReadAll(resp.Body)
	if err != nil {
		panic(err)
	}

	log.Println("number of bytes:", len(bytes))
	log.Printf("value %s\n", string(bytes))
}

func (ct CustomRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
	resp, err := http.DefaultTransport.RoundTrip(req)
	if err != nil {
		return nil, err
	}

	log.Printf("url: %s | method: %s", resp.Request.URL.String(), resp.Request.Method)

	data, err := io.ReadAll(resp.Body)
	if err != nil {
		return nil, err
	}

	log.Println("number of bytes in tripper:", len(data))

	log.Printf("value in tripper: %s\n", string(data))
	return resp, nil
}

This is pretty much the same example as before, but with two changes. We’re reading the contents of the HTTP response body twice, once within the RoundTrip function and once again in the main function. There’s also some logging to help determine which function is able to consume the response body.

If you ended up running this, you’d see the on the first io.ReadAll within the roundtripper, we are able to see the content length and print out the entire response body. You’d also see opposite by the time we get to the bottom of the main function and try the same thing again. Why is that?

Essentially, the response body may appear empty after consuming its content using io.ReadAll because the response body is an io.ReadCloser, and reading the entire content consumes the data from the reader. After consuming the data, the reader’s position is at the end of the stream, and subsequent read operations will start from that position, resulting in no available data to read. Hence what we see at the bottom of main().

Conclusion

If you are going to do any logging here, request information is okay after the actual network call has been completed. Request body information is best saved for use at the caller level. That way you get some better flexibility with the custom roundtripper down the road, plus you get some better error handling by reading the body at the caller level. One other thing about the RoundTrip function is it has to return an *http.Response according to the documentation. You can’t do that if you encounter an error on reading the body itself.

• Go
• Http