diff --git a/go.mod b/go.mod index c67d647a1..45d95bdac 100644 --- a/go.mod +++ b/go.mod @@ -30,8 +30,8 @@ require ( golang.org/x/term v0.0.0-20210615171337-6886f2dfbf5b golang.org/x/time v0.0.0-20210723032227-1f47c861a9ac google.golang.org/protobuf v1.26.0 - k8s.io/api v0.0.0-20211001003357-dd4141958dfc - k8s.io/apimachinery v0.0.0-20211001003147-df63df3af3fc + k8s.io/api v0.0.0-20211005163402-965a3d4efac6 + k8s.io/apimachinery v0.0.0-20211005152320-968be710e37a k8s.io/klog/v2 v2.20.0 k8s.io/kube-openapi v0.0.0-20210817084001-7fbd8d59e5b8 k8s.io/utils v0.0.0-20210930125809-cb0fa318a74b @@ -40,6 +40,6 @@ require ( ) replace ( - k8s.io/api => k8s.io/api v0.0.0-20211001003357-dd4141958dfc - k8s.io/apimachinery => k8s.io/apimachinery v0.0.0-20211001003147-df63df3af3fc + k8s.io/api => k8s.io/api v0.0.0-20211005163402-965a3d4efac6 + k8s.io/apimachinery => k8s.io/apimachinery v0.0.0-20211005152320-968be710e37a ) diff --git a/go.sum b/go.sum index 12064a80e..81a973a7f 100644 --- a/go.sum +++ b/go.sum @@ -599,10 +599,10 @@ honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc/go.mod h1:rf3lG4BRIbNafJWh honnef.co/go/tools v0.0.1-2019.2.3/go.mod h1:a3bituU0lyd329TUQxRnasdCoJDkEUEAqEt0JzvZhAg= honnef.co/go/tools v0.0.1-2020.1.3/go.mod h1:X/FiERA/W4tHapMX5mGpAtMSVEeEUOyHaw9vFzvIQ3k= honnef.co/go/tools v0.0.1-2020.1.4/go.mod h1:X/FiERA/W4tHapMX5mGpAtMSVEeEUOyHaw9vFzvIQ3k= -k8s.io/api v0.0.0-20211001003357-dd4141958dfc h1:mEvk8nUryhzsFO3gvz1GOCHKAk9SwmCy1E+TfTtrPdM= -k8s.io/api v0.0.0-20211001003357-dd4141958dfc/go.mod h1:X/EFj3T8/b6pT7Vu0CQfs8hKQGD/NpK6nituBPxPypM= -k8s.io/apimachinery v0.0.0-20211001003147-df63df3af3fc h1:xWJbWTw1QtGvoHnsdF1oI10d2gEBl2yqipw/m1DQjLU= -k8s.io/apimachinery v0.0.0-20211001003147-df63df3af3fc/go.mod h1:RAdi3McqM+9tkYHOyceb4XOeJWm9BCAF4BhZki5iiok= +k8s.io/api v0.0.0-20211005163402-965a3d4efac6 h1:4nid4gaGt4QFtlvh0BuRJukvljt+Mwp7mhFhtNl5A80= +k8s.io/api v0.0.0-20211005163402-965a3d4efac6/go.mod h1:uigk499NtRe0ine9Jz9mxVwAjascSPD/Ojn9xYSyB58= +k8s.io/apimachinery v0.0.0-20211005152320-968be710e37a h1:vUbAbtv8pmpeY1rOEQZjy/ALaYwNKdUi3d6pyq9B7Os= +k8s.io/apimachinery v0.0.0-20211005152320-968be710e37a/go.mod h1:RAdi3McqM+9tkYHOyceb4XOeJWm9BCAF4BhZki5iiok= k8s.io/gengo v0.0.0-20200413195148-3a45101e95ac/go.mod h1:ezvh/TsK7cY6rbqRK0oQQ8IAqLxYwwyPxAX1Pzy0ii0= k8s.io/klog/v2 v2.0.0/go.mod h1:PBfzABfn139FHAV07az/IF9Wp1bkk3vpT2XSJ76fSDE= k8s.io/klog/v2 v2.20.0 h1:tlyxlSvd63k7axjhuchckaRJm+a92z5GSOrTOQY5sHw= diff --git a/transport/round_trippers.go b/transport/round_trippers.go index 4f2976da7..5e9eb4910 100644 --- a/transport/round_trippers.go +++ b/transport/round_trippers.go @@ -17,9 +17,12 @@ limitations under the License. package transport import ( + "crypto/tls" "fmt" "net/http" + "net/http/httptrace" "strings" + "sync" "time" "golang.org/x/oauth2" @@ -69,7 +72,7 @@ func HTTPWrappersForConfig(config *Config, rt http.RoundTripper) (http.RoundTrip func DebugWrappers(rt http.RoundTripper) http.RoundTripper { switch { case bool(klog.V(9).Enabled()): - rt = NewDebuggingRoundTripper(rt, DebugCurlCommand, DebugURLTiming, DebugResponseHeaders) + rt = NewDebuggingRoundTripper(rt, DebugCurlCommand, DebugDetailedTiming, DebugResponseHeaders) case bool(klog.V(8).Enabled()): rt = NewDebuggingRoundTripper(rt, DebugJustURL, DebugRequestHeaders, DebugResponseStatus, DebugResponseHeaders) case bool(klog.V(7).Enabled()): @@ -320,6 +323,14 @@ type requestInfo struct { ResponseHeaders http.Header ResponseErr error + muTrace sync.Mutex // Protect trace fields + DNSLookup time.Duration + Dialing time.Duration + GetConnection time.Duration + TLSHandshake time.Duration + ServerProcessing time.Duration + ConnectionReused bool + Duration time.Duration } @@ -380,6 +391,8 @@ const ( DebugResponseStatus // DebugResponseHeaders will add to the debug output the HTTP response headers. DebugResponseHeaders + // DebugDetailedTiming will add to the debug output the duration of the HTTP requests events. + DebugDetailedTiming ) // NewDebuggingRoundTripper allows to display in the logs output debug information @@ -451,6 +464,74 @@ func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, e } startTime := time.Now() + + if rt.levels[DebugDetailedTiming] { + var getConn, dnsStart, dialStart, tlsStart, serverStart time.Time + var host string + trace := &httptrace.ClientTrace{ + // DNS + DNSStart: func(info httptrace.DNSStartInfo) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + dnsStart = time.Now() + host = info.Host + }, + DNSDone: func(info httptrace.DNSDoneInfo) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + reqInfo.DNSLookup = time.Now().Sub(dnsStart) + klog.Infof("HTTP Trace: DNS Lookup for %s resolved to %v", host, info.Addrs) + }, + // Dial + ConnectStart: func(network, addr string) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + dialStart = time.Now() + }, + ConnectDone: func(network, addr string, err error) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + reqInfo.Dialing = time.Now().Sub(dialStart) + if err != nil { + klog.Infof("HTTP Trace: Dial to %s:%s failed: %v", network, addr, err) + } else { + klog.Infof("HTTP Trace: Dial to %s:%s succeed", network, addr) + } + }, + // TLS + TLSHandshakeStart: func() { + tlsStart = time.Now() + }, + TLSHandshakeDone: func(_ tls.ConnectionState, _ error) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + reqInfo.TLSHandshake = time.Now().Sub(tlsStart) + }, + // Connection (it can be DNS + Dial or just the time to get one from the connection pool) + GetConn: func(hostPort string) { + getConn = time.Now() + }, + GotConn: func(info httptrace.GotConnInfo) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + reqInfo.GetConnection = time.Now().Sub(getConn) + reqInfo.ConnectionReused = info.Reused + }, + // Server Processing (time since we wrote the request until first byte is received) + WroteRequest: func(info httptrace.WroteRequestInfo) { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + serverStart = time.Now() + }, + GotFirstResponseByte: func() { + reqInfo.muTrace.Lock() + defer reqInfo.muTrace.Unlock() + reqInfo.ServerProcessing = time.Now().Sub(serverStart) + }, + } + req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace)) + } + response, err := rt.delegatedRoundTripper.RoundTrip(req) reqInfo.Duration = time.Since(startTime) @@ -459,6 +540,24 @@ func (rt *debuggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, e if rt.levels[DebugURLTiming] { klog.Infof("%s %s %s in %d milliseconds", reqInfo.RequestVerb, reqInfo.RequestURL, reqInfo.ResponseStatus, reqInfo.Duration.Nanoseconds()/int64(time.Millisecond)) } + if rt.levels[DebugDetailedTiming] { + stats := "" + if !reqInfo.ConnectionReused { + stats += fmt.Sprintf(`DNSLookup %d ms Dial %d ms TLSHandshake %d ms`, + reqInfo.DNSLookup.Nanoseconds()/int64(time.Millisecond), + reqInfo.Dialing.Nanoseconds()/int64(time.Millisecond), + reqInfo.TLSHandshake.Nanoseconds()/int64(time.Millisecond), + ) + } else { + stats += fmt.Sprintf(`GetConnection %d ms`, reqInfo.GetConnection.Nanoseconds()/int64(time.Millisecond)) + } + if reqInfo.ServerProcessing != 0 { + stats += fmt.Sprintf(` ServerProcessing %d ms`, reqInfo.ServerProcessing.Nanoseconds()/int64(time.Millisecond)) + } + stats += fmt.Sprintf(` Duration %d ms`, reqInfo.Duration.Nanoseconds()/int64(time.Millisecond)) + klog.Infof("HTTP Statistics: %s", stats) + } + if rt.levels[DebugResponseStatus] { klog.Infof("Response Status: %s in %d milliseconds", reqInfo.ResponseStatus, reqInfo.Duration.Nanoseconds()/int64(time.Millisecond)) }