Does httptrace allow to track when a connection is closed and/or returned back to the pool?

Viewed 136

I want to capture some statistics on the connection pool which backs the http client. Is it possible to track when a connection is closed or returned to the pool using the httptrace package?

I have this contrived example (doesn't work on go playground because of the http request):

package main

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

func main() {
    trace := &httptrace.ClientTrace{
        GotConn: func(info httptrace.GotConnInfo) {
            log.Printf("GotConn(%+v)", info)
        },
        PutIdleConn: func(err error) {
            log.Printf("PutIdleConn(%+v)", err)
        },
    }

    client := http.DefaultClient

    for i := 0; i < 10; i++ {
        req, err := http.NewRequest("GET", "https://golang.org/", nil)
        if err != nil {
            log.Fatal(err)
        }

        ctx := httptrace.WithClientTrace(req.Context(), trace)
        req = req.WithContext(ctx)

        res, err := client.Do(req)
        if err != nil {
            log.Fatal(err)
        }

        if _, err := io.Copy(ioutil.Discard, res.Body); err != nil {
            log.Fatal(err)
        }
        res.Body.Close()

        time.Sleep(10 * time.Millisecond)
    }

    time.Sleep(1000 * time.Millisecond)
}

Which prints:

2021/09/03 13:41:40 GotConn({Conn:0xc00020a000 Reused:false WasIdle:false IdleTime:0s})
2021/09/03 13:41:40 GotConn({Conn:0xc00020a000 Reused:true WasIdle:true IdleTime:10.389029ms})
2021/09/03 13:41:40 GotConn({Conn:0xc00020a000 Reused:true WasIdle:true IdleTime:10.305419ms})
2021/09/03 13:41:40 GotConn({Conn:0xc00020a000 Reused:true WasIdle:true IdleTime:10.874064ms})
2021/09/03 13:41:40 GotConn({Conn:0xc00020a000 Reused:true WasIdle:true IdleTime:10.303527ms})
2021/09/03 13:41:41 GotConn({Conn:0xc00020a000 Reused:true WasIdle:true IdleTime:10.815831ms})
2021/09/03 13:41:41 GotConn({Conn:0xc00020a000 Reused:true WasIdle:true IdleTime:10.679228ms})
2021/09/03 13:41:41 GotConn({Conn:0xc00020a000 Reused:true WasIdle:true IdleTime:10.580963ms})
2021/09/03 13:41:41 GotConn({Conn:0xc00020a000 Reused:true WasIdle:true IdleTime:10.95814ms})
2021/09/03 13:41:41 GotConn({Conn:0xc00020a000 Reused:true WasIdle:true IdleTime:10.788015ms})

The problem is that PutIdleConn is never called, even though we can see the connection is being reused.

I've expected that PutIdleConn will be called when the connection is returned back to the pool, possibly with an error, is the pool is full and then connection needs to be closed.

Related, is it possible to tell that the connection was closed using httptrace?

1 Answers

The documentation of PutIdleConn hook for go 1.17 says it's not currently used for HTTP/2, and the response for https://golang.org/ is HTTP/2.0, try logging it with

log.Printf("Got response with proto: %s", res.Proto)
Related