wip: Add timings

proxy/handler/request_handler.go

@@ -2,6 +2,7 @@ package handler
 
 import (
 	"bufio"
+	"code.cloudfoundry.org/gorouter/proxy/fails"
 	"crypto/tls"
 	"errors"
 	"fmt"
@@ -208,8 +209,14 @@ func (h *RequestHandler) serveTcp(
 ) (int, error) {
 	var err error
 	var backendConnection net.Conn
+	var backendStatusCode int
 	var endpoint *route.Endpoint
 
+	reqInfo, err := handlers.ContextRequestInfo(h.request)
+	if err != nil {
+		return 0, err
+	}
+
 	if onConnectionSucceeded == nil {
 		onConnectionSucceeded = nilConnSuccessCB
 	}
@@ -221,14 +228,9 @@ func (h *RequestHandler) serveTcp(
 		Timeout: h.endpointDialTimeout, // untested
 	}
 
-	reqInfo, err := handlers.ContextRequestInfo(h.request)
-	if err != nil {
-		return 0, err
-	}
 	reqInfo.AppRequestStartedAt = time.Now()
 
-	retry := 0
-	for {
+	for attempt := 1; attempt <= h.maxAttempts || h.maxAttempts == 0; attempt++ {
 		endpoint = iter.Next()
 		if endpoint == nil {
 			err = NoEndpointsAvailable
@@ -238,31 +240,40 @@ func (h *RequestHandler) serveTcp(
 
 		iter.PreRequest(endpoint)
 
+		// unfortunately, internal.nettrace and internal.tlstrace are not exposed, so we can't register trace callbacks
+		reqInfo.DialStartedAt = time.Now()
 		if endpoint.IsTLS() {
 			tlsConfigLocal := utils.TLSConfigWithServerName(endpoint.ServerCertDomainSAN, h.tlsConfigTemplate, false)
+			reqInfo.TlsHandshakeStartedAt = time.Now()
 			backendConnection, err = tls.DialWithDialer(dialer, "tcp", endpoint.CanonicalAddr(), tlsConfigLocal)
+			reqInfo.TlsHandshakeFinishedAt = time.Now()
 		} else {
 			backendConnection, err = net.DialTimeout("tcp", endpoint.CanonicalAddr(), h.endpointDialTimeout)
 		}
+		reqInfo.DialFinishedAt = time.Now()
 
-		if err == nil {
-			defer iter.PostRequest(endpoint)
-			break
-		} else {
-			iter.PostRequest(endpoint)
-		}
+		if err != nil {
+			reqInfo.FailedAttempts++
+			reqInfo.LastFailedAttemptFinishedAt = time.Now()
 
-		iter.EndpointFailed(err)
-		onConnectionFailed(err)
+			retriable, err := h.isRetriable(h.request, err)
 
-		retry++
-		if retry == h.maxAttempts {
-			return 0, err
+			iter.PostRequest(endpoint)
+			iter.EndpointFailed(err)
+			onConnectionFailed(err)
+
+			if retriable {
+				continue
+			}
 		}
+
+		break
 	}
 	if backendConnection == nil {
-		return 0, nil
+		reqInfo.AppRequestFinishedAt = reqInfo.LastFailedAttemptFinishedAt
+		return 0, err
 	}
+	defer iter.PostRequest(endpoint)
 	defer backendConnection.Close()
 
 	err = onConnectionSucceeded(backendConnection, endpoint)
@@ -278,7 +289,7 @@ func (h *RequestHandler) serveTcp(
 
 	// Any status code has already been sent to the client,
 	// but this is the value that gets written to the access logs
-	backendStatusCode, err := h.forwarder.ForwardIO(client, backendConnection)
+	backendStatusCode, err = h.forwarder.ForwardIO(client, backendConnection)
 
 	// add X-Cf-RouterError header to improve traceability in access log
 	if err != nil {
@@ -287,7 +298,6 @@ func (h *RequestHandler) serveTcp(
 	}
 
 	reqInfo.AppRequestFinishedAt = time.Now()
-
 	return backendStatusCode, nil
 }
 
@@ -332,3 +342,13 @@ func SetRequestXCfInstanceId(request *http.Request, endpoint *route.Endpoint) {
 func (h *RequestHandler) hijack() (client net.Conn, io *bufio.ReadWriter, err error) {
 	return h.response.Hijack()
 }
+
+func (h *RequestHandler) isRetriable(request *http.Request, err error) (bool, error) {
+	// if the context has been cancelled we do not perform further retries
+	if request.Context().Err() != nil {
+		return false, fmt.Errorf("%w (%w)", request.Context().Err(), err)
+	}
+
+	retriable := fails.RetriableClassifiers.Classify(err)
+	return retriable, err
+}