renamed uuid to requestid

README.md

@@ -2,5 +2,66 @@
 
 The purpose of this project to help me understand [Go http client](https://golang.org/pkg/net/http/) configuration and its effects on performance.
 
-It contains a single webapp that calls another microservice and return its response.
+It contains a single webapp that calls another service and return its response.
+
+The other service is [fake-service](https://github.com/johnmuth/fake-service), which returns a hard-coded response after a random delay.
+
+## http-client-test endpoints
+
+- /api
+    - response: `{"requestid":"6ba7b810-9dad-11d1-80b4-00c04fd430c8","qux":"flubber"}`
+        - requestid is a unique id to help correlate events in the logs
+        - qux is from the response from fake-service. 
+
+- /internal/healtcheck
+    - for load balancer
+
+## net/http Client
+
+To send HTTP requests from within your Go code, the standard way is to use Go's [net/http package](https://golang.org/pkg/net/http/).
+
+It provides convenient methods for sending requests:
+
+```go
+resp1, err := http.Get("http://example.com/")
+resp2, err := http.Post("http://example.com/upload", "image/jpeg", &buf)
+resp3, err := http.PostForm("http://example.com/form",url.Values{"key": {"Value"}, "id": {"123"}})
+```
+
+When you use those methods you're using a default `http.Client` with default values for a bunch of options that you might want to override:
+
+```go
+	httpClient := &http.Client{
+		Transport: &http.Transport{
+			MaxIdleConnsPerHost: 2,
+			DialContext: (&net.Dialer{
+        		Timeout:   30 * time.Second,
+		        KeepAlive: 30 * time.Second,
+			}).DialContext,
+			MaxIdleConns:          100,
+			IdleConnTimeout:       90 * time.Second,
+			TLSHandshakeTimeout:   10 * time.Second,
+			ExpectContinueTimeout: 1 * time.Second,
+
+		},
+		Timeout: 0,
+	}
+```
+
+All of those options are configurable in this project via environment variables. Look at [docker-compose.yml](docker-compose.yml) to see them all. Read the [net/http package](https://golang.org/pkg/net/http/) source to understand what they all mean.
+
+## httptrace
+
+The [httptrace package](https://golang.org/pkg/net/http/httptrace) provides a nice way to add logging and/or metrics to events within HTTP client requests.
+
+Here's an example of tracing the life of a single request, starting with "get connection" and ending with "put idle connection" - returning the connection to the connection pool:
+
+```bash
+{"level":"info","msg":"About to get connection","requestid":"0519190b-0bb6-4618-a974-7492776b40d9","time":"2017-09-03T13:13:26.283405633Z"}
+{"idletime":6797540509,"level":"info","msg":"Got connection","requestid":"0519190b-0bb6-4618-a974-7492776b40d9","reused":true,"time":"2017-09-03T13:13:26.283481947Z","wasidle":true}
+{"level":"info","msg":"Wrote headers","requestid":"0519190b-0bb6-4618-a974-7492776b40d9","time":"2017-09-03T13:13:26.28354208Z"}
+{"level":"info","msg":"Wrote request","requestid":"0519190b-0bb6-4618-a974-7492776b40d9","time":"2017-09-03T13:13:26.28358753Z"}
+{"level":"info","msg":"First response byte!","requestid":"0519190b-0bb6-4618-a974-7492776b40d9","time":"2017-09-03T13:13:26.284466249Z"}
+{"err":null,"level":"info","msg":"Put idle connection","requestid":"0519190b-0bb6-4618-a974-7492776b40d9","time":"2017-09-03T13:13:26.285229498Z"}
+```
 

app.go

@@ -2,17 +2,17 @@ package main
 
 import (
 	"fmt"
+	"github.com/kelseyhightower/envconfig"
+	log "github.com/sirupsen/logrus"
+	"net"
 	"net/http"
 	"os"
 	"time"
-	log "github.com/sirupsen/logrus"
-	"github.com/kelseyhightower/envconfig"
-	"net"
 )
 
 func main() {
 
-	log.SetFormatter(&log.JSONFormatter{TimestampFormat:time.RFC3339Nano})
+	log.SetFormatter(&log.JSONFormatter{TimestampFormat: time.RFC3339Nano})
 
 	config, err := LoadAppConfig()
 	if err != nil {
@@ -32,7 +32,6 @@ func main() {
 			IdleConnTimeout:       time.Duration(config.HTTPClientIdleConnTimeoutMS) * time.Millisecond,
 			TLSHandshakeTimeout:   time.Duration(config.HTTPClientTLSHandshakeTimeoutMS) * time.Millisecond,
 			ExpectContinueTimeout: time.Duration(config.HTTPClientExpectContinueTimeoutMS) * time.Millisecond,
-
 		},
 		Timeout: time.Duration(config.HTTPClientTimeoutMS) * time.Millisecond,
 	}

config.go

@@ -1,17 +1,17 @@
 package main
 
 type AppConfig struct {
-	Port                          int    `default:"8000"`
-	ServiceBaseURL                string `envconfig:"SERVICE_BASE_URL" required:"true"`
-	Env                           string `envconfig:"ENV_NAME" required:"true"`
-	HTTPClientMaxIdleConnsPerHost int `envconfig:"HTTP_CLIENT_MAX_IDLE_CONNS_PER_HOST" required:"true"`
-	HTTPClientMaxIdleConns int `envconfig:"HTTP_CLIENT_MAX_IDLE_CONNS" required:"true"`
-	HTTPClientDialerTimeoutMS int `envconfig:"HTTP_CLIENT_DIALER_TIMEOUT_MS" required:"true"`
-	HTTPClientDialerKeepAliveMS int `envconfig:"HTTP_CLIENT_DIALER_KEEPALIVE_MS" required:"true"`
-	HTTPClientIdleConnTimeoutMS int `envconfig:"HTTP_CLIENT_IDLE_CONN_TIMEOUT_MS" required:"true"`
-	HTTPClientTLSHandshakeTimeoutMS int `envconfig:"HTTP_CLIENT_TLS_HANDSHAKE_TIMEOUT_MS" required:"true"`
-	HTTPClientExpectContinueTimeoutMS int `envconfig:"HTTP_CLIENT_EXPECT_CONTINUE_TIMEOUT_MS" required:"true"`
-	HTTPClientTimeoutMS int `envconfig:"HTTP_CLIENT_TIMEOUT_MS" required:"true"`
+	Port                              int    `default:"8000"`
+	ServiceBaseURL                    string `envconfig:"SERVICE_BASE_URL" required:"true"`
+	Env                               string `envconfig:"ENV_NAME" required:"true"`
+	HTTPClientMaxIdleConnsPerHost     int    `envconfig:"HTTP_CLIENT_MAX_IDLE_CONNS_PER_HOST" required:"true"`
+	HTTPClientMaxIdleConns            int    `envconfig:"HTTP_CLIENT_MAX_IDLE_CONNS" required:"true"`
+	HTTPClientDialerTimeoutMS         int    `envconfig:"HTTP_CLIENT_DIALER_TIMEOUT_MS" required:"true"`
+	HTTPClientDialerKeepAliveMS       int    `envconfig:"HTTP_CLIENT_DIALER_KEEPALIVE_MS" required:"true"`
+	HTTPClientIdleConnTimeoutMS       int    `envconfig:"HTTP_CLIENT_IDLE_CONN_TIMEOUT_MS" required:"true"`
+	HTTPClientTLSHandshakeTimeoutMS   int    `envconfig:"HTTP_CLIENT_TLS_HANDSHAKE_TIMEOUT_MS" required:"true"`
+	HTTPClientExpectContinueTimeoutMS int    `envconfig:"HTTP_CLIENT_EXPECT_CONTINUE_TIMEOUT_MS" required:"true"`
+	HTTPClientTimeoutMS               int    `envconfig:"HTTP_CLIENT_TIMEOUT_MS" required:"true"`
 }
 
 func (c *AppConfig) IsLocal() bool {

fakes/fake-service.yml

@@ -9,4 +9,4 @@
     body: '*'
   response:
     code: 200
-    body: '{"uuid":"6ba7b810-9dad-11d1-80b4-00c04fd430c8","qux":"flubber"}'
+    body: '{"requestid":"6ba7b810-9dad-11d1-80b4-00c04fd430c8","qux":"flubber"}'

handler.go

@@ -2,9 +2,9 @@ package main
 
 import (
 	"fmt"
+	"github.com/satori/go.uuid"
 	log "github.com/sirupsen/logrus"
 	"net/http"
-	"github.com/satori/go.uuid"
 )
 
 // Handler handles requests
@@ -15,12 +15,12 @@ type Handler struct {
 // ServeHTTP serves HTTP
 func (handler Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	u1 := uuid.NewV4()
-	serviceRequest := &ServiceRequest{UUID: u1.String()}
-	log.WithField("uuid", serviceRequest.UUID).Info("About to do service.Call")
+	serviceRequest := &ServiceRequest{RequestID: u1.String()}
+	log.WithField("requestid", serviceRequest.RequestID).Info("About to do service.Call")
 	serviceResponse, err := handler.Service.Call(*serviceRequest)
-	log.WithField("uuid", serviceRequest.UUID).Info("Got response from service.Call")
+	log.WithField("requestid", serviceRequest.RequestID).Info("Got response from service.Call")
 	if err != nil {
-		log.WithField("uuid", serviceRequest.UUID).Error("Error calling service", err)
+		log.WithField("requestid", serviceRequest.RequestID).Error("Error calling service", err)
 		w.WriteHeader(500)
 		return
 	}

router.go

@@ -1,8 +1,8 @@
 package main
 
 import (
-	"net/http"
 	"fmt"
+	"net/http"
 )
 
 func NewRouter(handler *Handler) http.Handler {

scripts/docker-run.sh

@@ -3,6 +3,8 @@
 set -e
 set -u
 
+sudo docker ps -f name=http-client-test -qa | xargs sudo docker rm -f
+
 sudo docker run -d -p '8000:8000' \
     -e 'ENV_NAME=test' \
     -e 'SERVICE_BASE_URL=http://ec2-54-197-30-116.compute-1.amazonaws.com:8001/service' \

service.go

@@ -2,13 +2,12 @@ package main
 
 import (
 	"encoding/json"
-	"fmt"
-	"io/ioutil"
-	"net/http"
-	"strings"
 	"errors"
 	log "github.com/sirupsen/logrus"
+	"io/ioutil"
+	"net/http"
 	"net/http/httptrace"
+	"strings"
 )
 
 // Service sends requests to a remote HTTP API
@@ -22,18 +21,19 @@ type HttpClient interface {
 }
 
 func (svc Service) Call(serviceRequest ServiceRequest) (serviceResponse ServiceResponse, err error) {
+	serviceResponse.RequestID = serviceRequest.RequestID
 	var resp *http.Response
 	req, err := http.NewRequest("POST", svc.BaseURL, strings.NewReader(serviceRequest.String()))
 	if err != nil {
-		log.WithField("uuid", serviceRequest.UUID).Error("Error creating request to service", err)
+		log.WithField("requestid", serviceRequest.RequestID).Error("Error creating request to service", err)
 		return
 	}
 	req.Header.Set("Content-type", "application/json")
 	req = req.WithContext(httptrace.WithClientTrace(req.Context(), clientTrace(serviceRequest)))
-	log.WithField("uuid", serviceRequest.UUID).Info("About to send request to service")
+	log.WithField("requestid", serviceRequest.RequestID).Info("About to send request to service")
 	resp, err = svc.HttpClient.Do(req)
 	if err != nil {
-		log.WithField("uuid", serviceRequest.UUID).Error("Error sending request to service", err)
+		log.WithField("requestid", serviceRequest.RequestID).Error("Error sending request to service", err)
 		return
 	}
 	defer resp.Body.Close()
@@ -43,67 +43,72 @@ func (svc Service) Call(serviceRequest ServiceRequest) (serviceResponse ServiceR
 			respErrorBody, _ := ioutil.ReadAll(resp.Body)
 			respBody = string(respErrorBody)
 		}
-		errorMsg := fmt.Sprintf("Request to service returned status: %d and body: %s ", resp.StatusCode, respBody)
-		log.WithField("uuid", serviceRequest.UUID).Error(errorMsg)
-		return serviceResponse, errors.New(errorMsg)
+		log.WithFields(map[string]interface{}{
+			"statuscode": resp.StatusCode,
+			"body":       respBody,
+			"requestid":  serviceRequest.RequestID,
+		}).Error("Service returned non-200 response")
+		return serviceResponse, errors.New("Service returned non-200 response")
 	}
 	err = json.NewDecoder(resp.Body).Decode(&serviceResponse)
 	if err != nil {
-		log.WithField("uuid", serviceRequest.UUID).Error("Error parsing response from Service.", err)
+		log.WithFields(map[string]interface{}{
+			"err":       err,
+			"requestid": serviceRequest.RequestID,
+		}).Error("Error parsing response from Service.")
 	}
-	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")
+			log.WithField("requestid", serviceRequest.RequestID).Info("About to get connection")
 		},
 		PutIdleConn: func(err error) {
 			log.WithFields(map[string]interface{}{
-				"uuid": serviceRequest.UUID,
-				"err": err,
+				"requestid": serviceRequest.RequestID,
+				"err":       err,
 			}).Info("Put idle connection")
 		},
-		Got100Continue : func() {
-			log.WithField("uuid", serviceRequest.UUID).Info("Got 100 Continue")
+		Got100Continue: func() {
+			log.WithField("requestid", serviceRequest.RequestID).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,
+				"requestid": serviceRequest.RequestID,
+				"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")
+			log.WithField("requestid", serviceRequest.RequestID).Info("Dial start")
 		},
 		DNSStart: func(info httptrace.DNSStartInfo) {
-			log.WithField("uuid", serviceRequest.UUID).Info("DNS start", info.Host)
+			log.WithField("requestid", serviceRequest.RequestID).Info("DNS start", info.Host)
 		},
 		DNSDone: func(info httptrace.DNSDoneInfo) {
 			log.WithFields(map[string]interface{}{
-				"uuid": serviceRequest.UUID,
+				"requestid": serviceRequest.RequestID,
 				"coalesced": info.Coalesced,
-				"err": info.Err,
+				"err":       info.Err,
 			}).Info("DNS done")
 		},
 		ConnectDone: func(network, addr string, err error) {
 			log.WithFields(map[string]interface{}{
-				"uuid": serviceRequest.UUID,
-				"err": err,
+				"requestid": serviceRequest.RequestID,
+				"err":       err,
 			}).Info("Dial done")
 		},
 		GotFirstResponseByte: func() {
-			log.WithField("uuid", serviceRequest.UUID).Info("First response byte!")
+			log.WithField("requestid", serviceRequest.RequestID).Info("First response byte!")
 		},
 		WroteHeaders: func() {
-			log.WithField("uuid", serviceRequest.UUID).Info("Wrote headers")
+			log.WithField("requestid", serviceRequest.RequestID).Info("Wrote headers")
 		},
 		WroteRequest: func(wr httptrace.WroteRequestInfo) {
-			log.WithField("uuid", serviceRequest.UUID).Info("Wrote request")
+			log.WithField("requestid", serviceRequest.RequestID).Info("Wrote request")
 		},
 	}
-}
+}

servicerequest.go

@@ -5,7 +5,7 @@ import (
 )
 
 type ServiceRequest struct {
-	UUID string `json:"uuid,omitempty"`
+	RequestID string `json:"requestid,omitempty"`
 }
 
 func (req ServiceRequest) String() string {

serviceresponse.go

@@ -5,8 +5,8 @@ import (
 )
 
 type ServiceResponse struct {
-	Qux string `json:"qux"`
-	UUID string `json:"uuid"`
+	Qux  string `json:"qux"`
+	RequestID string `json:"requestid"`
 }
 
 func (sr ServiceResponse) String() string {