上篇内容我们介绍了排查Https请求超时的大体思路，主要强调了自查的重要性，以及一般情况下超时问题的排查流程与关注点。
下篇我们将内容聚焦到超时自查中一块十分重要的内容：在请求通过网卡发出之前，如何有效获取Https请求各阶段Trace记录。目的是为了更好的进行问题归因和为后续排查收集关键信息。
客户端发起Https请求的流程
我们还是以Golang语言作为背景，其标准库客户端请求流程如下：
对于上面每个步骤来说，我们既需要关注耗时，还需要关注它们是否存在错误，特别针对DNS解析我们还需额外关注DNS解析的结果。
每个步骤的目地和原理这里不做介绍，比如：链接复用是什么；DNS解析是做什么用的，解析结果会影响什么等等。这里我们更加聚焦于怎么Trace每个步骤需要关注的信息。
Trace方案
1、使用curl -w或者curl –trace
安装即用，无需编写代码。curl -w能够获取Http请求时的关键步骤数据，一些重要的数据指标按需要进行自定义格式打印，使用方式可以参考这里。
curl –trace相关命令可以格式化的打印出https请求重要步骤的毫秒时间戳与内容，会少了DNS解析的内容，多了其他的细节，使用方式可以参考这里。
2、使用Golang自带的HttpTrace库：https://pkg.go.dev/net/http/httptrace（推荐）
这种方案相信比较curl而言，能收集到的信息会少一些，但是关键信息是足够的。
其核心原理是利用context.Context机制，将请求时对想要关注的步骤进行Hook，在步骤触发时插入自己的处理逻辑。其核心的结构体里面均是预设好的Hook函数，官方库使用如下：
//ref：https://pkg.go.dev/net/http/httptrace
//中文翻译版
type ClientTrace struct {
//GetConn在链接创建前或者从空闲池复用前调用，还会在已有可用的空闲缓存链接使用时调用；
//参数hostPort表示当前链接或者代理的地址和端口，形如host:port；
GetConn func(hostPort string)
//GotConn在成功链接后调用；
//这里并没有提供对于链接失败的钩子，若想获取这部分信息可以从Transport.RoundTrip入手；
GotConn func(GotConnInfo)
//当链接被放回到空闲池时，PutIdleConn会被调用，参数err用来描述调用时发生的错误；
//如果链接复用被Transport.DisableKeepAlives禁止，那么PutIdleConn不会被调用；
//逻辑上，PutIdleConn调用在Response.Body.Close返回前；
//对于HTTP/2，这个勾子目前不再使用；
PutIdleConn func(err error)
//GotFirstResponseByte在收到第一个有效的http头信息返回时调用；
GotFirstResponseByte func()
//Got100Continue在收到服务端回复的100状态码时调用；
Got100Continue func()
//Got1xxResponse在最终非1xx状态码返回前，每次收到1xx状态码返回时均会调用；
//即使实现了Got100Continue，Got1xxResponse在收到“100 Continue”也会被调用；
//如果返回值error被赋值，客户端请求会被中止；
Got1xxResponse func(code int, header textproto.MIMEHeader) error
//DNSStart在DNS寻址前调用；
DNSStart func(DNSStartInfo)
//DNSDone在DNS寻址结束后调用；
DNSDone func(DNSDoneInfo)
//ConnectStart调用发生在连接准备建立时；
//如果开启了net.Dialer.DualStack支持，它可能被调用多次；
ConnectStart func(network, addr string)
//ConnectDone调用发生在链接建立完成，err参数可以用来判断链接是否成功建立；
//如果开启了net.Dialer.DualStack支持，它可能被调用多次；
ConnectDone func(network, addr string, err error)
//TLSHandshakeStart调用发生在TLS握手开始；
//若我们通过一个Http代理去访问Https站点，TLS握手发生在代理处理完链接请求之后；
TLSHandshakeStart func()
//TLSHandshakeDone调用发生在TLS握手结束；
//成功的握手会返回状态信息，失败的原因会赋值到error；
TLSHandshakeDone func(tls.ConnectionState, error)
//WroteHeaderField调用发生在Transport写入每一个请求头时；
//在调用的时候，请求头内容可能还在缓存里，还没有被发送出去；
WroteHeaderField func(key string, value []string)
//WroteHeaders调用发生在Transport写入了所有请求头内容；
WroteHeaders func()
//Wait100Continue调用发生在写入请求体之前，若请求头存在“Expect: 100-continue”，
//Transport已经写入请求头后等待“100 Continue”返回时；
Wait100Continue func()
//WroteRequest调用发生在写入请求body后，携带写入结果。若存在请求重试，它可能被调用多次；
WroteRequest func(WroteRequestInfo)
}
还有一些其他语言其他工具的方案，核心也是围绕Https的请求流程展开，可能会有一些信息侧重点的不同。但只要掌握了请求流程，知晓了排查方法，根据实际需要选取合适的工具或者代码库即可。
示例代码
最后附一个Golang方案的代码例子：
package main
import (
"crypto/tls"
"fmt"
"net"
"net/http"
"net/http/httptrace"
"time"
)
func GetStampMicro() string {
return time.Now().Format(time.StampMilli)
}
type HttpTraceSample struct {
TraceId string
GetConnStart string
GetConnHostPort string
GetConnEnd string
GetConnReuse bool
GetConnIdle bool
DNSStart string
DNSHost string
DNSEnd string
DNSAddr []net.IPAddr
DNSErr error
TCPConnStart string
TCPConnStartNet string
TCPConnStartAddr string
TCPConnEnd string
TCPConnEndNet string
TCPConnEndAddr string
TCPConnErr error
TLSStart string
TLSEnd string
TLSErr error
WroteHeaders string
WroteRequest string
WroteRequestErr error
GotFirstResponseByte string
}
func NewHttpTrace(TraceId string) (*httptrace.ClientTrace, *HttpTraceSample) {
sample := &HttpTraceSample{
TraceId: TraceId,
}
trace := &httptrace.ClientTrace{
GetConn: func(hostPort string) {
sample.GetConnStart = GetStampMicro()
sample.GetConnHostPort = hostPort
},
GotConn: func(info httptrace.GotConnInfo) {
sample.GetConnEnd = GetStampMicro()
sample.GetConnReuse = info.Reused
sample.GetConnIdle = info.WasIdle
},
DNSStart: func(info httptrace.DNSStartInfo) {
sample.DNSStart = GetStampMicro()
sample.DNSHost = info.Host
},
DNSDone: func(info httptrace.DNSDoneInfo) {
sample.DNSEnd = GetStampMicro()
sample.DNSAddr = info.Addrs
sample.DNSErr = info.Err
},
ConnectStart: func(network, addr string) {
sample.TCPConnStart = GetStampMicro()
sample.TCPConnStartNet = network
sample.TCPConnStartAddr = addr
},
ConnectDone: func(network, addr string, err error) {
sample.TCPConnEnd = GetStampMicro()
sample.TCPConnEndNet = network
sample.TCPConnEndAddr = addr
sample.TCPConnErr = err
},
TLSHandshakeStart: func() {
sample.TLSStart = GetStampMicro()
},
TLSHandshakeDone: func(status tls.ConnectionState, err error) {
sample.TLSEnd = GetStampMicro()
sample.TLSErr = err
},
WroteHeaders: func() {
sample.WroteHeaders = GetStampMicro()
},
WroteRequest: func(info httptrace.WroteRequestInfo) {
sample.WroteRequest = GetStampMicro()
sample.WroteRequestErr = info.Err
},
GotFirstResponseByte: func() {
sample.GotFirstResponseByte = GetStampMicro()
},
}
return trace, sample
}
func (ht HttpTraceSample) LogFormat() string {
log := fmt.Sprintf("[TraceID]:%s\n", ht.TraceId)
log += fmt.Sprintf("[GetIdleConn]start:%s hostport:%s\n", ht.GetConnStart, ht.GetConnHostPort)
log += fmt.Sprintf("[GetIdleConn]end:%s isreused:%t isIdle:%t\n", ht.GetConnEnd, ht.GetConnReuse, ht.GetConnIdle)
log += fmt.Sprintf("[DNS]start:%s, host:%s\n", ht.DNSStart, ht.DNSHost)
log += fmt.Sprintf("[DNS]end:%s, error:%v addr:%v\n", ht.DNSEnd, ht.DNSErr, ht.DNSAddr)
log += fmt.Sprintf("[TCPConn]start:%s net:%s, addr:%s\n", ht.TCPConnStart, ht.TCPConnStartNet, ht.TCPConnStartAddr)
log += fmt.Sprintf("[TCPConn]end:%s error:%v net:%s, addr:%s\n", ht.TCPConnEnd, ht.TCPConnErr, ht.TCPConnEndNet, ht.TCPConnEndAddr)
log += fmt.Sprintf("[TLS]start:%s\n", ht.TLSStart)
log += fmt.Sprintf("[TLS]end:%s error:%v\n", ht.TLSEnd, ht.TLSErr)
log += fmt.Sprintf("[WroteHeaders]%s\n", ht.WroteHeaders)
log += fmt.Sprintf("[WroteRequest]%s error:%v\n", ht.WroteRequest, ht.WroteRequestErr)
log += fmt.Sprintf("[GotFirstResponseByte]%s\n", ht.GotFirstResponseByte)
return log
}
func HttpGetTest(client *http.Client) {
req, err := http.NewRequest("GET", "https://lanindex.com", nil)
if err != nil {
panic(err)
}
trace, sample := NewHttpTrace("142857") //fake traceid
req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace))
defer func() {
fmt.Printf("%s\n", sample.LogFormat())
}()
rsp, err := client.Do(req)
if err != nil {
panic(err)
}
defer rsp.Body.Close()
}
func main() {
client := &http.Client{
Timeout: 5 * time.Second,
}
for {
HttpGetTest(client)
time.Sleep(5 * time.Second)
}
}
（全文结束）
转载文章请注明出处：漫漫路 - lanindex.com