Add {upstream} placeholder when proxy middleware is used (closes #531)

Middlewares can now make their own placeholders that may be useful in
logging, on a per-request basis. Proxy is the first one to do this.

dist/CHANGES.txt

@@ -4,6 +4,7 @@ CHANGES
 - New pprof directive for exposing process performance profile
 - Toggle case-sensitive path matching with environment variable
 - proxy: New max_conns setting to limit max connections per upstream
+- proxy: Enables replaceable value for name of upstream host
 - Internal improvements, restructuring, and bug fixes
 
 0.8.2 (February 25, 2016)

middleware/log/log.go

-// Package log implements basic but useful request (access) logging middleware.
+// Package log implements request (access) logging middleware.
 package log
 
 import (
@@ -19,8 +19,17 @@ type Logger struct {
 func (l Logger) ServeHTTP(w http.ResponseWriter, r *http.Request) (int, error) {
 	for _, rule := range l.Rules {
 		if middleware.Path(r.URL.Path).Matches(rule.PathScope) {
+			// Record the response
 			responseRecorder := middleware.NewResponseRecorder(w)
+
+			// Attach the Replacer we'll use so that other middlewares can
+			// set their own placeholders if they want to.
+			rep := middleware.NewReplacer(r, responseRecorder, CommonLogEmptyValue)
+			responseRecorder.Replacer = rep
+
+			// Bon voyage, request!
 			status, err := l.Next.ServeHTTP(responseRecorder, r)
+
 			if status >= 400 {
 				// There was an error up the chain, but no response has been written yet.
 				// The error must be handled here so the log entry will record the response size.
@@ -33,8 +42,10 @@ func (l Logger) ServeHTTP(w http.ResponseWriter, r *http.Request) (int, error) {
 				}
 				status = 0
 			}
-			rep := middleware.NewReplacer(r, responseRecorder, CommonLogEmptyValue)
+
+			// Write log entry
 			rule.Log.Println(rep.Replace(rule.Format))
+
 			return status, err
 		}
 	}

middleware/log/log_test.go

@@ -7,11 +7,16 @@ import (
 	"net/http/httptest"
 	"strings"
 	"testing"
+
+	"github.com/mholt/caddy/middleware"
 )
 
 type erroringMiddleware struct{}
 
 func (erroringMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request) (int, error) {
+	if rr, ok := w.(*middleware.ResponseRecorder); ok {
+		rr.Replacer.Set("testval", "foobar")
+	}
 	return http.StatusNotFound, nil
 }
 
@@ -20,7 +25,7 @@ func TestLoggedStatus(t *testing.T) {
 	var next erroringMiddleware
 	rule := Rule{
 		PathScope: "/",
-		Format:    DefaultLogFormat,
+		Format:    DefaultLogFormat + " {testval}",
 		Log:       log.New(&f, "", 0),
 	}
 
@@ -38,11 +43,20 @@ func TestLoggedStatus(t *testing.T) {
 
 	status, err := logger.ServeHTTP(rec, r)
 	if status != 0 {
-		t.Error("Expected status to be 0 - was", status)
+		t.Errorf("Expected status to be 0, but was %d", status)
+	}
+
+	if err != nil {
+		t.Errorf("Expected error to be nil, instead got: %v", err)
 	}
 
 	logged := f.String()
 	if !strings.Contains(logged, "404 13") {
-		t.Error("Expected 404 to be logged. Logged string -", logged)
+		t.Errorf("Expected log entry to contain '404 13', but it didn't: %s", logged)
+	}
+
+	// check custom placeholder
+	if !strings.Contains(logged, "foobar") {
+		t.Errorf("Expected the log entry to contain 'foobar' (custom placeholder), but it didn't: %s", logged)
 	}
 }

middleware/proxy/proxy.go

@@ -89,6 +89,9 @@ func (p Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) (int, error) {
 				}
 				proxy := host.ReverseProxy
 				r.Host = host.Name
+				if rr, ok := w.(*middleware.ResponseRecorder); ok && rr.Replacer != nil {
+					rr.Replacer.Set("upstream", host.Name)
+				}
 
 				if baseURL, err := url.Parse(host.Name); err == nil {
 					r.Host = baseURL.Host

middleware/proxy/proxy_test.go

@@ -18,6 +18,8 @@ import (
 	"testing"
 	"time"
 
+	"github.com/mholt/caddy/middleware"
+
 	"golang.org/x/net/websocket"
 )
 
@@ -53,6 +55,16 @@ func TestReverseProxy(t *testing.T) {
 	if !requestReceived {
 		t.Error("Expected backend to receive request, but it didn't")
 	}
+
+	// Make sure {upstream} placeholder is set
+	rr := middleware.NewResponseRecorder(httptest.NewRecorder())
+	rr.Replacer = middleware.NewReplacer(r, rr, "-")
+
+	p.ServeHTTP(rr, r)
+
+	if got, want := rr.Replacer.Replace("{upstream}"), backend.URL; got != want {
+		t.Errorf("Expected custom placeholder {upstream} to be set (%s), but it wasn't; got: %s", want, got)
+	}
 }
 
 func TestReverseProxyInsecureSkipVerify(t *testing.T) {

middleware/recorder.go

@@ -8,17 +8,24 @@ import (
 	"time"
 )
 
-// ResponseRecorder is a type of ResponseWriter that captures
+// ResponseRecorder is a type of http.ResponseWriter that captures
 // the status code written to it and also the size of the body
 // written in the response. A status code does not have
 // to be written, however, in which case 200 must be assumed.
 // It is best to have the constructor initialize this type
 // with that default status code.
+//
+// Setting the Replacer field allows middlewares to type-assert
+// the http.ResponseWriter to ResponseRecorder and set their own
+// placeholder values for logging utilities to use.
+//
+// Beware when accessing the Replacer value; it may be nil!
 type ResponseRecorder struct {
 	http.ResponseWriter
-	status int
-	size   int
-	start  time.Time
+	Replacer Replacer
+	status   int
+	size     int
+	start    time.Time
 }
 
 // NewResponseRecorder makes and returns a new responseRecorder,

middleware/replacer.go

@@ -12,26 +12,38 @@ import (
 
 // Replacer is a type which can replace placeholder
 // substrings in a string with actual values from a
-// http.Request and responseRecorder. Always use
-// NewReplacer to get one of these.
+// http.Request and ResponseRecorder. Always use
+// NewReplacer to get one of these. Any placeholders
+// made with Set() should overwrite existing values if
+// the key is already used.
 type Replacer interface {
 	Replace(string) string
 	Set(key, value string)
 }
 
+// replacer implements Replacer. customReplacements
+// is used to store custom replacements created with
+// Set() until the time of replacement, at which point
+// they will be used to overwrite other replacements
+// if there is a name conflict.
 type replacer struct {
-	replacements map[string]string
-	emptyValue   string
+	replacements       map[string]string
+	customReplacements map[string]string
+	emptyValue         string
+	responseRecorder   *ResponseRecorder
 }
 
-// NewReplacer makes a new replacer based on r and rr.
-// Do not create a new replacer until r and rr have all
-// the needed values, because this function copies those
-// values into the replacer. rr may be nil if it is not
-// available. emptyValue should be the string that is used
-// in place of empty string (can still be empty string).
+// NewReplacer makes a new replacer based on r and rr which
+// are used for request and response placeholders, respectively.
+// Request placeholders are created immediately, whereas
+// response placeholders are not created until Replace()
+// is invoked. rr may be nil if it is not available.
+// emptyValue should be the string that is used in place
+// of empty string (can still be empty string).
 func NewReplacer(r *http.Request, rr *ResponseRecorder, emptyValue string) Replacer {
-	rep := replacer{
+	rep := &replacer{
+		responseRecorder:   rr,
+		customReplacements: make(map[string]string),
 		replacements: map[string]string{
 			"{method}": r.Method,
 			"{scheme}": func() string {
@@ -66,9 +78,7 @@ func NewReplacer(r *http.Request, rr *ResponseRecorder, emptyValue string) Repla
 			}(),
 			"{uri}":         r.URL.RequestURI(),
 			"{uri_escaped}": url.QueryEscape(r.URL.RequestURI()),
-			"{when}": func() string {
-				return time.Now().Format(timeFormat)
-			}(),
+			"{when}":        time.Now().Format(timeFormat),
 			"{file}": func() string {
 				_, file := path.Split(r.URL.Path)
 				return file
@@ -80,11 +90,6 @@ func NewReplacer(r *http.Request, rr *ResponseRecorder, emptyValue string) Repla
 		},
 		emptyValue: emptyValue,
 	}
-	if rr != nil {
-		rep.replacements["{status}"] = strconv.Itoa(rr.status)
-		rep.replacements["{size}"] = strconv.Itoa(rr.size)
-		rep.replacements["{latency}"] = time.Since(rr.start).String()
-	}
 
 	// Header placeholders (case-insensitive)
 	for header, values := range r.Header {
@@ -96,7 +101,19 @@ func NewReplacer(r *http.Request, rr *ResponseRecorder, emptyValue string) Repla
 
 // Replace performs a replacement of values on s and returns
 // the string with the replaced values.
-func (r replacer) Replace(s string) string {
+func (r *replacer) Replace(s string) string {
+	// Make response placeholders now
+	if r.responseRecorder != nil {
+		r.replacements["{status}"] = strconv.Itoa(r.responseRecorder.status)
+		r.replacements["{size}"] = strconv.Itoa(r.responseRecorder.size)
+		r.replacements["{latency}"] = time.Since(r.responseRecorder.start).String()
+	}
+
+	// Include custom placeholders, overwriting existing ones if necessary
+	for key, val := range r.customReplacements {
+		r.replacements[key] = val
+	}
+
 	// Header replacements - these are case-insensitive, so we can't just use strings.Replace()
 	for strings.Contains(s, headerReplacer) {
 		idxStart := strings.Index(s, headerReplacer)
@@ -125,9 +142,9 @@ func (r replacer) Replace(s string) string {
 	return s
 }
 
-// Set sets key to value in the replacements map.
-func (r replacer) Set(key, value string) {
-	r.replacements["{"+key+"}"] = value
+// Set sets key to value in the r.customReplacements map.
+func (r *replacer) Set(key, value string) {
+	r.customReplacements["{"+key+"}"] = value
 }
 
 const (

middleware/replacer_test.go

@@ -16,23 +16,27 @@ func TestNewReplacer(t *testing.T) {
 	if err != nil {
 		t.Fatal("Request Formation Failed\n")
 	}
-	replaceValues := NewReplacer(request, recordRequest, "")
-
-	switch v := replaceValues.(type) {
-	case replacer:
+	rep := NewReplacer(request, recordRequest, "")
 
+	switch v := rep.(type) {
+	case *replacer:
 		if v.replacements["{host}"] != "localhost" {
 			t.Error("Expected host to be localhost")
 		}
 		if v.replacements["{method}"] != "POST" {
 			t.Error("Expected request method  to be POST")
 		}
-		if v.replacements["{status}"] != "200" {
-			t.Error("Expected status to be 200")
-		}
 
+		// Response placeholders should only be set after call to Replace()
+		if got, want := v.replacements["{status}"], ""; got != want {
+			t.Errorf("Expected status to NOT be set before Replace() is called; was: %s", got)
+		}
+		rep.Replace("foobar")
+		if got, want := v.replacements["{status}"], "200"; got != want {
+			t.Errorf("Expected status to be %s, was: %s", want, got)
+		}
 	default:
-		t.Fatal("Return Value from New Replacer expected pass type assertion into a replacer type\n")
+		t.Fatalf("Expected *replacer underlying Replacer type, got: %#v", rep)
 	}
 }