squeezing all the info out of a clienttrace

johnmuth · Sep 3, 2017 · e0a9c14 · e0a9c14
1 parent c99fc93
commit e0a9c14
Show file tree

Hide file tree

Showing 10 changed files with 295 additions and 59 deletions.
diff --git a/docker-compose.yml b/docker-compose.yml
@@ -7,12 +7,12 @@ services:
       - SERVICE_BASE_URL=http://fake-service:9090/service
       - ENV_NAME=local
       - LOG_LEVEL=debug
-      - HTTP_CLIENT_MAX_IDLE_CONNS_PER_HOST=1
-      - HTTP_CLIENT_MAX_IDLE_CONNS=1
-      - HTTP_CLIENT_DIALER_TIMEOUT_MS=30000
+      - HTTP_CLIENT_MAX_IDLE_CONNS_PER_HOST=100
+      - HTTP_CLIENT_MAX_IDLE_CONNS=100
+      - HTTP_CLIENT_DIALER_TIMEOUT_MS=500
       - HTTP_CLIENT_DIALER_KEEPALIVE_MS=30000
-      - HTTP_CLIENT_IDLE_CONN_TIMEOUT_MS=90000
-      - HTTP_CLIENT_TLS_HANDSHAKE_TIMEOUT_MS=10000
+      - HTTP_CLIENT_IDLE_CONN_TIMEOUT_MS=60000
+      - HTTP_CLIENT_TLS_HANDSHAKE_TIMEOUT_MS=1000
       - HTTP_CLIENT_EXPECT_CONTINUE_TIMEOUT_MS=1000
       - HTTP_CLIENT_TIMEOUT_MS=1500
 

diff --git a/fakes/fake-service.yml b/fakes/fake-service.yml
@@ -6,7 +6,7 @@
     method: POST
     headers:
       content-type: application/json
-    body: '{"foo":"abc","bar":"def"}'
+    body: '*'
   response:
     code: 200
-    body: '{"qux":"flubber"}'
+    body: '{"uuid":"6ba7b810-9dad-11d1-80b4-00c04fd430c8","qux":"flubber"}'
diff --git a/handler.go b/handler.go
@@ -4,6 +4,7 @@ import (
 	"fmt"
 	log "github.com/sirupsen/logrus"
 	"net/http"
+	"github.com/satori/go.uuid"
 )
 
 // Handler handles requests
@@ -13,10 +14,13 @@ type Handler struct {
 
 // ServeHTTP serves HTTP
 func (handler Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
-	serviceRequest := &ServiceRequest{Foo:"abc", Bar:"def"}
+	u1 := uuid.NewV4()
+	serviceRequest := &ServiceRequest{UUID: u1.String()}
+	log.WithField("uuid", serviceRequest.UUID).Info("About to do service.Call")
 	serviceResponse, err := handler.Service.Call(*serviceRequest)
+	log.WithField("uuid", serviceRequest.UUID).Info("Got response from service.Call")
 	if err != nil {
-		log.Error("Error calling service", err)
+		log.WithField("uuid", serviceRequest.UUID).Error("Error calling service", err)
 		w.WriteHeader(500)
 		return
 	}

diff --git a/service.go b/service.go
@@ -22,75 +22,88 @@ type HttpClient interface {
 }
 
 func (svc Service) Call(serviceRequest ServiceRequest) (serviceResponse ServiceResponse, err error) {
-
-	trace := &httptrace.ClientTrace{
-		GetConn: func(hostPort string) {
-			log.Info("About to get connection")
-		},
-		PutIdleConn: func(err error) {
-			if err != nil {
-				log.Info(fmt.Sprintf("Put idle connection failed. err=%v", err))
-			} else {
-				log.Info("Put idle connection succeeded.")
-			}
-		},
-		Got100Continue : func() {
-			log.Info("Got 100 Continue")
-		},
-		GotConn: func(connInfo httptrace.GotConnInfo) {
-			log.Info("Got connection")
-		},
-		ConnectStart: func(network, addr string) {
-			log.Info("Dial start")
-		},
-		DNSStart: func(info httptrace.DNSStartInfo) {
-			log.Info("DNS start", info.Host)
-		},
-		DNSDone: func(info httptrace.DNSDoneInfo) {
-			log.Info("DNS done")
-		},
-		ConnectDone: func(network, addr string, err error) {
-			log.Info("Dial done")
-		},
-		GotFirstResponseByte: func() {
-			log.Info("First response byte!")
-		},
-		WroteHeaders: func() {
-			log.Info("Wrote headers")
-		},
-		WroteRequest: func(wr httptrace.WroteRequestInfo) {
-			log.Info("Wrote request")
-		},
-	}
 	var resp *http.Response
-	log.Info(fmt.Sprintf("About to send request: POST %s with body %s", svc.BaseURL, serviceRequest.String()))
 	req, err := http.NewRequest("POST", svc.BaseURL, strings.NewReader(serviceRequest.String()))
 	if err != nil {
-		log.Error("Error creating request to service", err)
+		log.WithField("uuid", serviceRequest.UUID).Error("Error creating request to service", err)
 		return
 	}
 	req.Header.Set("Content-type", "application/json")
-	req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace))
+	req = req.WithContext(httptrace.WithClientTrace(req.Context(), clientTrace(serviceRequest)))
+	log.WithField("uuid", serviceRequest.UUID).Info("About to send request to service")
 	resp, err = svc.HttpClient.Do(req)
 	if err != nil {
-		log.Error("Error sending request to service", err)
+		log.WithField("uuid", serviceRequest.UUID).Error("Error sending request to service", err)
 		return
 	}
+	defer resp.Body.Close()
 	if resp.StatusCode != 200 {
 		var respBody string
 		if resp.Body != nil {
 			respErrorBody, _ := ioutil.ReadAll(resp.Body)
 			respBody = string(respErrorBody)
-			resp.Body.Close()
 		}
 		errorMsg := fmt.Sprintf("Request to service returned status: %d and body: %s ", resp.StatusCode, respBody)
-		log.Error(errorMsg)
+		log.WithField("uuid", serviceRequest.UUID).Error(errorMsg)
 		return serviceResponse, errors.New(errorMsg)
 	}
 	err = json.NewDecoder(resp.Body).Decode(&serviceResponse)
-	resp.Body.Close()
 	if err != nil {
-		log.Error("Error parsing response from Service.", err)
+		log.WithField("uuid", serviceRequest.UUID).Error("Error parsing response from Service.", err)
 	}
+	serviceResponse.UUID = serviceRequest.UUID
 	return
 }
+
+func clientTrace(serviceRequest ServiceRequest) *httptrace.ClientTrace {
+	return &httptrace.ClientTrace{
+		GetConn: func(hostPort string) {
+			log.WithField("uuid", serviceRequest.UUID).Info("About to get connection")
+		},
+		PutIdleConn: func(err error) {
+			log.WithFields(map[string]interface{}{
+				"uuid": serviceRequest.UUID,
+				"err": err,
+			}).Info("Put idle connection")
+		},
+		Got100Continue : func() {
+			log.WithField("uuid", serviceRequest.UUID).Info("Got 100 Continue")
+		},
+		GotConn: func(connInfo httptrace.GotConnInfo) {
+			log.WithFields(map[string]interface{}{
+				"uuid": serviceRequest.UUID,
+				"reused": connInfo.Reused,
+				"idletime": connInfo.IdleTime,
+				"wasidle": connInfo.WasIdle,
+			}).Info("Got connection")
+		},
+		ConnectStart: func(network, addr string) {
+			log.WithField("uuid", serviceRequest.UUID).Info("Dial start")
+		},
+		DNSStart: func(info httptrace.DNSStartInfo) {
+			log.WithField("uuid", serviceRequest.UUID).Info("DNS start", info.Host)
+		},
+		DNSDone: func(info httptrace.DNSDoneInfo) {
+			log.WithFields(map[string]interface{}{
+				"uuid": serviceRequest.UUID,
+				"coalesced": info.Coalesced,
+				"err": info.Err,
+			}).Info("DNS done")
+		},
+		ConnectDone: func(network, addr string, err error) {
+			log.WithFields(map[string]interface{}{
+				"uuid": serviceRequest.UUID,
+				"err": err,
+			}).Info("Dial done")
+		},
+		GotFirstResponseByte: func() {
+			log.WithField("uuid", serviceRequest.UUID).Info("First response byte!")
+		},
+		WroteHeaders: func() {
+			log.WithField("uuid", serviceRequest.UUID).Info("Wrote headers")
+		},
+		WroteRequest: func(wr httptrace.WroteRequestInfo) {
+			log.WithField("uuid", serviceRequest.UUID).Info("Wrote request")
+		},
+	}
+}
diff --git a/servicerequest.go b/servicerequest.go
@@ -5,8 +5,7 @@ import (
 )
 
 type ServiceRequest struct {
-	Foo string `json:"foo,omitempty"`
-	Bar string `json:"bar,omitempty"`
+	UUID string `json:"uuid,omitempty"`
 }
 
 func (req ServiceRequest) String() string {

diff --git a/serviceresponse.go b/serviceresponse.go
@@ -6,6 +6,7 @@ import (
 
 type ServiceResponse struct {
 	Qux string `json:"qux"`
+	UUID string `json:"uuid"`
 }
 
 func (sr ServiceResponse) String() string {

diff --git a/vendor/github.com/nu7hatch/gouuid/COPYING b/vendor/github.com/nu7hatch/gouuid/COPYING
diff --git a/vendor/github.com/nu7hatch/gouuid/README.md b/vendor/github.com/nu7hatch/gouuid/README.md