Go: Tracing HTTP requests

By Thiago Nache Carvalho

- 7 minutes read - 1391 words

The HTTP protocol is fast, secure, and reliable. However, it needs other protocols and services to work properly, and when things don’t go well it is necessary to have access to detailed information about the time spent in each step.

The steps to make an HTTP call are as follows:

  1. DNS Lookup
    1. The client sends a DNS query to the DNS server.
    2. The DNS server responds with the IP for the name.
  2. TCP connection
    1. The client sends the SYN packet.
    2. Web server responds with SYN-ACK packet.
    3. The client establishes the (triple handshake) connection with the ACK packet.
  3. Send
    1. The client sends the HTTP request to the web server.
  4. Wait
    1. The client waits until the web server responds to the request.
    2. The web server processes the request and sends the response to the client which receives the HTTP response headers and content.
  5. Load
    1. The client loads the response content.
  6. Close
    1. The client sends a FIN packet to close the TCP connection.

This is just one of the possible cases for an HTTP request, as we are not addressing persistent connections, connection pooling, or other protocol features.

Go has the net/http/httptrace package so that we can collect detailed information about an HTTP request which will be the subject of this article.

That said, how long does it take to translate the name to IP. Download the simple-main.go file.

func main() {
   var start, dns time.Time
   var took, dnsTook time.Duration

   ct := &httptrace.ClientTrace{
   DNSStart: func(info httptrace.DNSStartInfo) {
         dns = time.Now()
      },
   DNSDone:  func(info httptrace.DNSDoneInfo) {
         dnsTook = time.Since(dns)
      },
   }
   req, _ := http.NewRequest(http.MethodGet, "https://httpbin.org/", nil)
   ctCtx := httptrace.WithClientTrace(req.Context(), ct)
   req = req.WithContext(ctCtx)
   start = time.Now()
   _, err := http.DefaultClient.Do(req)
   if err != nil {
   log.Fatal(err)
   }
   took = time.Since(start)
   fmt.Printf("total %dms, dns %dms\n",
      took.Milliseconds(), dnsTook.Milliseconds()
   )
}

Running the code above you will see a result similar to the one below:

MacBook-Pro:hi thiagocarvalho$ go run main.go
total 612ms, dns 2ms
MacBook-Pro:hi thiagocarvalho$

The total request time was 612ms while DNS took 2ms.

HTTP Client

Before we start talking about httptrace let’s remember a little bit about the client of the package net/http or more specifically about the type http.Client.

type Client struct {
   // Transport specifies the mechanism by which individual
   // HTTP requests are made.
   // If nil, DefaultTransport is used.
   Transport RoundTripper
   ...
   Timeout time.Duration
}

For this article, we will only contain the Transport field of the struct which is a http.RoundTripper which is nothing more than an interface to a function that receives a pointer to http.Request and returns a pointer to http.Response and an error. This is quite convenient since basically everything in an HTTP client call involves a request, a response and if there was an error in the process.

RoundTripper

According to the Go documentation, a RoundTrip is "the ability to execute a single HTTP transaction, obtaining the Response for a given Request.". In a simplistic way, we can say that RoundTrip is nothing more than a middleware for your HTTP call. You generally don’t need to worry about this until you have to add a default behavior to all calls made by your application, such as serving a page from cache instead of fetching from the server or implement retries.

The DefaultRoundTrip is the following variable:

var DefaultTransport RoundTripper = &Transport{
    Proxy: ProxyFromEnvironment,
    DialContext: defaultTransportDialContext(&net.Dialer{
        Timeout: 30 * time.Second,
        KeepAlive: 30 * time.Second,
    }),
    ForceAttemptHTTP2: true,
    MaxIdleConns: 100,
    IdleConnTimeout: 90 * time.Second,
    TLSHandshakeTimeout: 10 * time.Second,
    ExpectContinueTimeout: 1 * time.Second,
}

The transport of an HTTP call is basically what controls the communication between the client and the server, that is, transporting the data in the best possible way. I won’t go into details about everything that involves the transport layer of the protocol as it would be too big and I don’t have all the necessary knowledge without doing a lot of research, but you can infer a lot just by paying attention to the names as they are quite explicit. Special thanks to everyone who takes the time to decide the best name for each thing in their code.

Back to business, DefaultTransport manages network connections, that is, it is responsible for creating new connections as needed, creating a cache to be reused in future requests, as well as honoring the $HTTP_PROXY and $NO_PROXY environment variables.

Last thing about transport for what it’s worth quoting something from the documentation about http.Response.Body:

...
// The default HTTP client's Transport
// may not reuse HTTP/1.x "keep-alive" TCP connections
// if the Body is not read to completion and closed.
...
Body io.ReadCloser

The connection will not be reused until the body is read!

HTTPTrace

In Go 1.7 the net/http/httptrace package was created to collect information through the lifecycle of an HTTP client call. The package is small and introduces us to a new type ClientTrace and a function WithClientTrace.

ClientTrace Type

type ClientTrace struct {
    ...
    GetConn func(hostPort string)
    ...
    DNSStart func(DNSStartInfo)
    ...
    ConnectDone func(network, addr string, err error)
    ...
    TLSHandshakeStart func()
    ...
    WroteRequest func(WroteRequestInfo)
}

The new type introduced by the package is basically a collection of functions that are injected (hooks) by various http.RoundTriper.

You are responsible for writing the functions, what you get from the package is the automatic injection of the function at the right time with more data. For example, when the library is going to send the packet to resolve the name via DNS automatically the DNSStart field is injected and you get DNSStartInfo and when the response is received from the server automatically the DNSDone field is injected and you get DNSDoneInfo.

WithClientTrace Function

old := ContextClientTrace(ctx)
trace.compose(old)

ctx = context.WithValue(ctx, clientEventContextKey{}, trace)
if trace.hasNetHooks() {
   ...
   ctx = context.WithValue(ctx, nettrace.TraceKey{}, nt)
}
return ctx

The WithClientTrace function does the following:

  1. Copy the old context.
  2. Create a new context based on the parent context and add the trace values ​​to the context.
  3. Checks if there is any hook related to the network layer to be injected into the ClientTrace object.
  4. If found, functions are injected into the context.

Trace and http.Client

Let’s now create the code to trace an HTTP call and give us detailed information about the time spent in each step.

  1. We need to write the functions to create the ClientTrace. Eg.:

    func dnsStart(info httptrace.DNSStartInfo) {
   fmt.Printf("quering %q to DNS\n", info.Host)
}
func dnsDone(info httptrace.DNSDoneInfo) {
   fmt.Println("DNS info",info)
}

  2. Instantiate the ClientTrace object with the created functions.

    clientTrace := &httptrace.ClientTrace{
   DNSStart: dnsStart,
   DNSDone: dnsDone,
}

  3. Instantiate the request object.

    req, _ := http.NewRequest(http.MethodGet, "https://httpbin.org/redirect-to?url=https://example.com&status_code=307", nil)

  4. Instantiate a new context with trace.

    clientTraceCtx := httptrace.WithClientTrace(req.Context(), clientTrace)

  5. Associate the new context with the request object.

    req = req.WithContext(clientTraceCtx)

  6. Make the HTTP call.

    resp, err := http.DefaultClient.Do(req)
if err != nil {
    log.Fatal(err)
}

  7. Download the response content and close reader.

    _, err = io.Copy(io.Discard, resp.Body)
if err != nil {
    log.Fatal(err)
}
resp.Body.Close()

Access the complete code at link, read it carefully and run it from your computer. You should see something similar to the content below.

2022/06/03 17:18:15 [TRACE] - starting to create conn to "releases.ubuntu.com:443"
2022/06/03 17:18:15 [TRACE] - quering "releases.ubuntu.com" to DNS
2022/06/03 17:18:15 [TRACE] - ip addresses:
2022/06/03 17:18:15 [TRACE] - - 2620:2d:4000:1::1a
2022/06/03 17:18:15 [TRACE] - - 2001:67c:1562::28
2022/06/03 17:18:15 [TRACE] - - 2620:2d:4000:1::17
2022/06/03 17:18:15 [TRACE] - - 2001:67c:1562::25
2022/06/03 17:18:15 [TRACE] - - 91.189.91.123
2022/06/03 17:18:15 [TRACE] - - 91.189.91.124
2022/06/03 17:18:15 [TRACE] - - 185.125.190.40
2022/06/03 17:18:15 [TRACE] - - 185.125.190.37
2022/06/03 17:18:15 [TRACE] - starting tcp connection to "[2620:2d:4000:1::1a]:443"
2022/06/03 17:18:15 [TRACE] - tcp connection created to [2620:2d:4000:1::1a]:443, err: <nil>
06/03/2022 17:18:15 [TRACE] - starting tls negotiation
2022/06/03 17:18:15 [TRACE] - tls negotiated to "releases.ubuntu.com", error: <nil>
2022/06/03 17:18:15 [TRACE] - connection established. reused: false idle: false idle time: 0ms
2022/06/03 17:18:15 [TRACE] - sending header "Host" and value [releases.ubuntu.com]
2022/06/03 17:18:15 [TRACE] - sending header "User-Agent" and value [Go-http-client/1.1]
2022/06/03 17:18:15 [TRACE] - sending header "Accept-Encoding" and value [gzip]
2022/06/03 17:18:15 [TRACE] - headers written
2022/06/03 17:18:15 [TRACE] - starting to wait for server response
2022/06/03 17:18:16 [TRACE] - got first response byte
2022/06/03 17:18:17 [TRACE] - put conn idle, err: <nil>
Statistics in ms
DNS     Connect TLS     Send  Wait    Transfer Total
269.808 214.251 226.744 0.005 213.591 1605.033 2530.235

Conclusion

HTTP tracing is a very valuable new feature in Go for those who want to have latency information for HTTP calls and write tools for troubleshooting outbound traffic.