Package httptrace is a new addition in Go 1.7 that allows users to trace the steps of a HTTP request. This package also models an interesting design pattern around adding optional debugging to a library. However, it’s not the only way to accomplish this goal. I’ll briefly overview the package and provide alternative implementations for httptrace.

httptrace Link to heading

The basic idea of httptrace is that a laundry list of callbacks are optionally attached to a Context object that is added to a HTTP request. During the inner workings of the request, if any of these callbacks are set, they are called during different stages of the request.

An illustrative example of httptrace is below, with a playground link here.

package main

import (
    "fmt"
    "io"
    "net/http"
    "net/http/httptest"
    "net/http/httptrace"
    "os"
)

func main() {
    server := httptest.NewServer(http.HandlerFunc(http.NotFound))
    defer server.Close()
    c := http.Client{}
    req, err := http.NewRequest("GET", server.URL, nil)
    if err != nil {
        panic(err)
    }

    trace := &httptrace.ClientTrace{
        GotConn: func(connInfo httptrace.GotConnInfo) {
            fmt.Println("Got Conn")
        },
        ConnectStart: func(network, addr string) {
            fmt.Println("Dial start")
        },
        ConnectDone: func(network, addr string, err error) {
            fmt.Println("Dial done")
        },
        GotFirstResponseByte: func() {
            fmt.Println("First response byte!")
        },
        WroteHeaders: func() {
            fmt.Println("Wrote headers")
        },
        WroteRequest: func(wr httptrace.WroteRequestInfo) {
            fmt.Println("Wrote request", wr)
        },
    }
    req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace))
    fmt.Println("Starting request!")
    resp, err := c.Do(req)
    if err != nil {
        panic(err)
    }
    io.Copy(os.Stdout, resp.Body)
    fmt.Println("Done!")
}

Output Link to heading

Starting request!
Dial start
Dial done
Got Conn
Wrote headers
Wrote request {<nil>}
First response byte!
404 page not found
Done!

The trace object on line 21 is the important object, with it being attached on line 41. The full ClientTrace object is interesting to look at and pretty self-explanatory:

type ClientTrace struct {
    // GetConn is called before a connection is created or
    // retrieved from an idle pool. The hostPort is the
    // "host:port" of the target or proxy. GetConn is called even
    // if there's already an idle cached connection available.
    GetConn func(hostPort string)

    // GotConn is called after a successful connection is
    // obtained. There is no hook for failure to obtain a
    // connection; instead, use the error from
    // Transport.RoundTrip.
    GotConn func(GotConnInfo)

    // PutIdleConn is called when the connection is returned to
    // the idle pool. If err is nil, the connection was
    // successfully returned to the idle pool. If err is non-nil,
    // it describes why not. PutIdleConn is not called if
    // connection reuse is disabled via Transport.DisableKeepAlives.
    // PutIdleConn is called before the caller's Response.Body.Close
    // call returns.
    // For HTTP/2, this hook is not currently used.
    PutIdleConn func(err error)

    // GotFirstResponseByte is called when the first byte of the response
    // headers is available.
    GotFirstResponseByte func()

    // Got100Continue is called if the server replies with a "100
    // Continue" response.
    Got100Continue func()

    // DNSStart is called when a DNS lookup begins.
    DNSStart func(DNSStartInfo)

    // DNSDone is called when a DNS lookup ends.
    DNSDone func(DNSDoneInfo)

    // ConnectStart is called when a new connection's Dial begins.
    // If net.Dialer.DualStack (IPv6 "Happy Eyeballs") support is
    // enabled, this may be called multiple times.
    ConnectStart func(network, addr string)

    // ConnectDone is called when a new connection's Dial
    // completes. The provided err indicates whether the
    // connection completedly successfully.
    // If net.Dialer.DualStack ("Happy Eyeballs") support is
    // enabled, this may be called multiple times.
    ConnectDone func(network, addr string, err error)

    // WroteHeaders is called after the Transport has written
    // the request headers.
    WroteHeaders func()

    // Wait100Continue is called if the Request specified
    // "Expected: 100-continue" and the Transport has written the
    // request headers but is waiting for "100 Continue" from the
    // server before writing the request body.
    Wait100Continue func()

    // WroteRequest is called with the result of writing the
    // request and any body.
    WroteRequest func(WroteRequestInfo)
}

You can see where it’s actually used inside request.go. For example, this code is right after the request sends the final “\r\n” for the request headers.

    if trace != nil && trace.WroteHeaders != nil {
        trace.WroteHeaders()
    }

Is this appropriate use of Context.Value? Link to heading

My previous post, How to correctly use context.Context in Go 1.7, talks a bit about how to correctly use context.Value. In particular, the primary point is that the content of context.Value is for maintainers not users. This point fits perfectly with the implementation of httptrace. The intended use of httptrace is purely for debugging and tracking, allowing the caller to time functions or debug a misbehaving http request.

Poorly designed implementations of httptrace Link to heading

It was possible to design httptrace in a way that it did more than inform. For example, consider the following implementation.

type ClientTrace struct {
    // Called before a connection is established.  If it returns a
    // non nil object, that object is used instead for the Connection.
    GetConn func(hostPort string) *net.Conn
}

This alternative implementation modifies the original GetConn callback to allow users to change the net.Conn the client uses. Unfortunately, this allows a large amount of control over the request and moves use of ClientTrace from inform to control. With such strong control of the request, this API would make more sense in the http.Request object than inside Context.Value. Consider another implementation.

type ClientTrace struct {
    // Called before a connection is established.  The returned context is used
    // to finish processing the request.
    GetConn func(ctx context.Context, hostPort string) context.Context
}

This debugging implementation allows users to modify the context during a callback, maybe adding values to it. While initially useful, it also injects logic into the current request. This is less bad than the above situation, but still closer to control than inform.

Again, the important part of httptrace’s implementation is that the callbacks don’t situate themselves for injecting logic control.

Alternatives to httptrace’s implementation Link to heading

Put ClientTrace on the request Link to heading

One alternative implementation is to put ClientTrace on the http.Request object rather than hide it in the Context.

type Request struct {
    Method string
    URL *url.URL
    // ...
    // Trace callbacks are executed if they are set
    Trace ClientTrace
}

This would have accomplished the same goal. Unfortunately, exposing debugging so prominently in an API looks ugly to our human eyes. There is a reasonable goal of making http.Client as simple as possible, and one aspect of simplicity is limiting options. Debugging isn’t a requirement of Client’s API, but it’s a reality of needing to understand why your system isn’t working. Putting it in the context hides this option from view. In other words, quoting my previous context article.

Putting this debug information in a Context object is a compromise between the perfect API that would never need maintenance and the realities of wanting to thread debug information across an API.

Even given this justification of putting HttpTrace inside a context, it still would have been reasonable to place it in the Request object directly.

Use a logger Link to heading

Imagine if ClientTrace looked like the following.

type ClientTrace struct {
    Log(state string)
}

In this case, rather than call ClientTrace.GetConn, the library calls ClientTrace.Log(“GetConn”). Many third-party libraries in Go do something similar, attaching an optional debug logger inside the context of a request. The Log function can either print out GetConn, or just do a time.Now() request to see how long it took to get to the state GetConn. Log and Callback designs are the same goal, but on a spectrum. In your own libraries, you could remove all loggers and just do what ClientTrace does, replacing them all with Callbacks at each specific Log statement. This is not commonly done because it can get a bit tedious to iterate on. Consider the following questions when deciding between a Log based and Callback based design for debugging.

Callback based designs require a more stable API. Log based designs can be more flexible.
Users don’t get all new callbacks implicitly. With Log designs, any new Log statements are all captured
Callback designs tend to be more strongly typed.
Callback designs are documented. While you could document the exact Log statements you will call, generally what things are logged is implied as unstable API.
Callback designs are more tedious to capture all of them. A single logger would get all Log statements, but to get all Callbacks you need many lines of code.

Add your own debuggers Link to heading

Debugging and understanding the performance and flow of code is critical to maintaining software. Adding debugging callbacks to your own requests goes a long way to helping people understand what is going on when they use your library. Deciding between a log based or callback based design is up to you. Where to attach these hooks, on the Context or a request object, is also up to you. But please, let me debug your library!