From 79ba3559d8c259d2756b12ec697afab85729c1fd Mon Sep 17 00:00:00 2001 From: Nicolas Beauvais Date: Wed, 18 Jun 2025 01:12:59 +0200 Subject: [PATCH 1/2] Fix negative trace substraction when using SetTimeout --- request.go | 21 ++++++++++++++++++--- request_test.go | 22 ++++++++++++++++++++++ trace.go | 20 ++++++++++++++++++++ 3 files changed, 60 insertions(+), 3 deletions(-) diff --git a/request.go b/request.go index ed475e52..ef95b483 100644 --- a/request.go +++ b/request.go @@ -1241,16 +1241,31 @@ func (r *Request) TraceInfo() TraceInfo { return TraceInfo{} } + ct.lock.RLock() + defer ct.lock.RUnlock() + ti := TraceInfo{ - DNSLookup: ct.dnsDone.Sub(ct.dnsStart), - TLSHandshake: ct.tlsHandshakeDone.Sub(ct.tlsHandshakeStart), - ServerTime: ct.gotFirstResponseByte.Sub(ct.gotConn), + DNSLookup: 0, + TCPConnTime: 0, + ServerTime: 0, IsConnReused: ct.gotConnInfo.Reused, IsConnWasIdle: ct.gotConnInfo.WasIdle, ConnIdleTime: ct.gotConnInfo.IdleTime, RequestAttempt: r.Attempt, } + if !ct.dnsStart.IsZero() && !ct.dnsDone.IsZero() { + ti.DNSLookup = ct.dnsDone.Sub(ct.dnsStart) + } + + if !ct.tlsHandshakeDone.IsZero() && !ct.tlsHandshakeStart.IsZero() { + ti.TLSHandshake = ct.tlsHandshakeDone.Sub(ct.tlsHandshakeStart) + } + + if !ct.gotFirstResponseByte.IsZero() && !ct.gotConn.IsZero() { + ti.ServerTime = ct.gotFirstResponseByte.Sub(ct.gotConn) + } + // Calculate the total time accordingly when connection is reused, // and DNS start and get conn time may be zero if the request is invalid. // See issue #1016. diff --git a/request_test.go b/request_test.go index 215e04f1..ef013ddb 100644 --- a/request_test.go +++ b/request_test.go @@ -1927,6 +1927,28 @@ func TestTraceInfoOnTimeout(t *testing.T) { assertEqual(t, true, tr.TotalTime == resp.Duration()) } +func TestTraceInfoOnTimeoutWithSetTimeout(t *testing.T) { + client := New(). + SetTimeout(1 * time.Millisecond). + SetBaseURL("http://resty-nowhere.local"). + EnableTrace() + + resp, err := client.R().Get("/") + assertNotNil(t, err) + assertNotNil(t, resp) + + tr := resp.Request.TraceInfo() + + assertEqual(t, true, tr.DNSLookup == 0) + assertEqual(t, true, tr.ConnTime == 0) + assertEqual(t, true, tr.TLSHandshake == 0) + assertEqual(t, true, tr.TCPConnTime == 0) + assertEqual(t, true, tr.ServerTime == 0) + assertEqual(t, true, tr.ResponseTime == 0) + assertEqual(t, true, tr.TotalTime > 0) + assertEqual(t, true, tr.TotalTime == resp.Duration()) +} + func TestDebugLoggerRequestBodyTooLarge(t *testing.T) { formTs := createFormPostServer(t) defer formTs.Close() diff --git a/trace.go b/trace.go index 26db2871..7d054b08 100644 --- a/trace.go +++ b/trace.go @@ -10,6 +10,7 @@ import ( "crypto/tls" "fmt" "net/http/httptrace" + "sync" "time" ) @@ -95,6 +96,7 @@ func (ti TraceInfo) Clone() *TraceInfo { // with the same naming for easy understanding. Plus additional insights // [Request]. type clientTrace struct { + lock sync.RWMutex getConn time.Time dnsStart time.Time dnsDone time.Time @@ -112,37 +114,55 @@ func (t *clientTrace) createContext(ctx context.Context) context.Context { ctx, &httptrace.ClientTrace{ DNSStart: func(_ httptrace.DNSStartInfo) { + t.lock.Lock() t.dnsStart = time.Now() + t.lock.Unlock() }, DNSDone: func(_ httptrace.DNSDoneInfo) { + t.lock.Lock() t.dnsDone = time.Now() + t.lock.Unlock() }, ConnectStart: func(_, _ string) { + t.lock.Lock() if t.dnsDone.IsZero() { t.dnsDone = time.Now() } if t.dnsStart.IsZero() { t.dnsStart = t.dnsDone } + t.lock.Unlock() }, ConnectDone: func(net, addr string, err error) { + t.lock.Lock() t.connectDone = time.Now() + t.lock.Unlock() }, GetConn: func(_ string) { + t.lock.Lock() t.getConn = time.Now() + t.lock.Unlock() }, GotConn: func(ci httptrace.GotConnInfo) { + t.lock.Lock() t.gotConn = time.Now() t.gotConnInfo = ci + t.lock.Unlock() }, GotFirstResponseByte: func() { + t.lock.Lock() t.gotFirstResponseByte = time.Now() + t.lock.Unlock() }, TLSHandshakeStart: func() { + t.lock.Lock() t.tlsHandshakeStart = time.Now() + t.lock.Unlock() }, TLSHandshakeDone: func(_ tls.ConnectionState, _ error) { + t.lock.Lock() t.tlsHandshakeDone = time.Now() + t.lock.Unlock() }, }, ) From d7109017e72bed4e2000f291df5263e84d178ea3 Mon Sep 17 00:00:00 2001 From: Nicolas Beauvais Date: Mon, 17 Nov 2025 10:28:21 +0100 Subject: [PATCH 2/2] Add trace info testing for coverage of DNS lookup time calculation --- request_test.go | 59 +++++++++++++++++++++++++++++++++++-------------- 1 file changed, 43 insertions(+), 16 deletions(-) diff --git a/request_test.go b/request_test.go index ef013ddb..784bc5dd 100644 --- a/request_test.go +++ b/request_test.go @@ -1928,25 +1928,52 @@ func TestTraceInfoOnTimeout(t *testing.T) { } func TestTraceInfoOnTimeoutWithSetTimeout(t *testing.T) { - client := New(). - SetTimeout(1 * time.Millisecond). - SetBaseURL("http://resty-nowhere.local"). - EnableTrace() + t.Run("timeout with very short timeout", func(t *testing.T) { + client := New(). + SetTimeout(1 * time.Millisecond). + SetBaseURL("http://resty-nowhere.local"). + EnableTrace() - resp, err := client.R().Get("/") - assertNotNil(t, err) - assertNotNil(t, resp) + resp, err := client.R().Get("/") + assertNotNil(t, err) + assertNotNil(t, resp) - tr := resp.Request.TraceInfo() + tr := resp.Request.TraceInfo() - assertEqual(t, true, tr.DNSLookup == 0) - assertEqual(t, true, tr.ConnTime == 0) - assertEqual(t, true, tr.TLSHandshake == 0) - assertEqual(t, true, tr.TCPConnTime == 0) - assertEqual(t, true, tr.ServerTime == 0) - assertEqual(t, true, tr.ResponseTime == 0) - assertEqual(t, true, tr.TotalTime > 0) - assertEqual(t, true, tr.TotalTime == resp.Duration()) + assertEqual(t, true, tr.DNSLookup == 0) + assertEqual(t, true, tr.ConnTime == 0) + assertEqual(t, true, tr.TLSHandshake == 0) + assertEqual(t, true, tr.TCPConnTime == 0) + assertEqual(t, true, tr.ServerTime == 0) + assertEqual(t, true, tr.ResponseTime == 0) + assertEqual(t, true, tr.TotalTime > 0) + assertEqual(t, true, tr.TotalTime == resp.Duration()) + }) + + t.Run("successful request with SetTimeout", func(t *testing.T) { + ts := createGetServer(t) + defer ts.Close() + + client := New(). + SetTimeout(5 * time.Second). + SetBaseURL(ts.URL). + EnableTrace() + + resp, err := client.R().Get("/") + assertNil(t, err) + assertNotNil(t, resp) + + tr := resp.Request.TraceInfo() + + assertEqual(t, true, tr.DNSLookup >= 0) + assertEqual(t, true, tr.ConnTime >= 0) + assertEqual(t, true, tr.TLSHandshake >= 0) + assertEqual(t, true, tr.TCPConnTime >= 0) + assertEqual(t, true, tr.ServerTime >= 0) + assertEqual(t, true, tr.ResponseTime >= 0) + assertEqual(t, true, tr.TotalTime > 0) + assertEqual(t, true, tr.TotalTime == resp.Duration()) + }) } func TestDebugLoggerRequestBodyTooLarge(t *testing.T) {