Error: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)

Question

About 3~4minutes,Some Errors would happen in my log.

net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)

I try to find out where it takes time Using httptrace. httptrace.GetConn httptrace.GotConn

I think it runs out of time before httptrace.GotConn. So errors happend request canceled while waiting for connection

My machine is ok.and this is my netstat.

LAST_ACK 2 CLOSE_WAIT 7 ESTABLISHED 108 SYN_SENT 3 TIME_WAIT 43

package main

import (
    "crypto/md5"
    "encoding/hex"
    "fmt"
    "io/ioutil"
    "math/rand"
    "net"
    "net/http"
    "net/http/httptrace"
    "os"
    "sync"
    "time"
)

var Client *http.Client = &http.Client{
    Transport: &http.Transport{
        DisableKeepAlives:true,
        Proxy: http.ProxyFromEnvironment,
        DialContext: (&net.Dialer{
            Timeout:   3 * time.Second, // 连接超时
            KeepAlive: 10 * time.Second,
            DualStack: true,
        }).DialContext,
        IdleConnTimeout:       120 * time.Second,
        ResponseHeaderTimeout: 60 * time.Second,
        ExpectContinueTimeout: 1 * time.Second,
    },
    Timeout: 500 * time.Millisecond,
}

func GenLogId() string {
    h2 := md5.New()
    rand.Seed(time.Now().Unix())
    str := fmt.Sprintf("%d%d%d", os.Getpid(), time.Now().UnixNano(), rand.Int())

    h2.Write([]byte(str))
    uniqid := hex.EncodeToString(h2.Sum(nil))

    return uniqid
}

func main() {
    var (
        wg           sync.WaitGroup
        maxParallel  int       = 50
        parallelChan chan bool = make(chan bool, maxParallel)
    )
    for {
        parallelChan <- true
        wg.Add(1)
        go func() {
            defer func() {
                wg.Done()
                <-parallelChan
            }()
            testHttp2()
        }()
    }
    wg.Wait()
}

func testHttp2() {
    url := "http://10.33.108.39:11222/index.php"
    req, _ := http.NewRequest("GET", url, nil)

    uniqId := GenLogId()
    trace := &httptrace.ClientTrace{
        GetConn: func(hostPort string) {
            fmt.Println("GetConn id:", uniqId, time.Now().UnixNano(), hostPort)
        },
        GotConn: func(connInfo httptrace.GotConnInfo) {
            fmt.Println("GotConn id:", uniqId, time.Now().UnixNano(), connInfo.Conn.LocalAddr())
        },

        ConnectStart: func(network, addr string) {
            fmt.Println("ConnectStart id:", uniqId, time.Now().UnixNano(), network, addr)
        },
        ConnectDone: func(network, addr string, err error) {
            fmt.Println("ConnectDone id:", uniqId, time.Now().UnixNano(), network, addr, err)
        },
    }
    req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace))
    resp, err := Client.Do(req)
    if err != nil {
        fmt.Println("err: id", uniqId, time.Now().UnixNano(), err)
        return
    }

    defer resp.Body.Close()
    body, err := ioutil.ReadAll(resp.Body)

    if err != nil {
        fmt.Println("error", string(body))
    }
    return
}

You can reproduce using my code. I am so confuse about the bug... Thank you.

Answer 1

You need to increase the client Timeout value for your test.

net/http: request canceled (Client.Timeout exceeded while awaiting headers)

This means your Client.Timeout value is less than your server response time, due to many reasons ( e.g. Busy, CPU overload, many requests per second you generated here, ...).

Here a simple way to explain it and regenerate it:

Run this server (which waits for 2 * time.Second then sends back the response):

package main

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

func main() {
    http.HandleFunc(`/`, func(w http.ResponseWriter, r *http.Request) {
        log.Println("wait a couple of seconds ...")
        time.Sleep(2 * time.Second)
        io.WriteString(w, `Hi`)
        log.Println("Done.")
    })
    log.Println(http.ListenAndServe(":8080", nil))
}

Then run this client which times out in 1 * time.Second:

package main

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

func main() {
    log.Println("HTTP GET")
    client := &http.Client{
        Timeout: 1 * time.Second,
    }
    r, err := client.Get(`http://127.0.0.1:8080/`)
    if err != nil {
        log.Fatal(err)
    }
    defer r.Body.Close()
    bs, err := ioutil.ReadAll(r.Body)
    if err != nil {
        log.Fatal(err)
    }
    log.Println("HTTP Done.")
    log.Println(string(bs))
}

The output is (Client.Timeout exceeded while awaiting headers):

2019/10/30 11:05:08 HTTP GET
2019/10/30 11:05:09 Get http://127.0.0.1:8080/: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
exit status 1

---

Note:
You need to change these two settings accordingly (http.Transport.ResponseHeaderTimeout and http.Client.Timeout).

You have set ResponseHeaderTimeout: 60 * time.Second, while Client.Timeout to half a second.