Feature: new HTTP server metrics with full status code (#411)

README.md

@@ -4,7 +4,7 @@ Patron is a framework for creating microservices, originally created by Sotiris
 
 `Patron` is french for `template` or `pattern`, but it means also `boss` which we found out later (no pun intended).
 
-The entry point of the framework is the `Service`. The `Service` uses `Components` to handle the processing of sync and async requests. The `Service` starts by default an `HTTP Component` which hosts the debug, alive, ready and metric endpoints. Any other endpoints will be added to the default `HTTP Component` as `Routes`. Alongside `Routes` one can specify middleware functions to be applied ordered to all routes as `MiddlewareFunc`. The service set's up by default logging with `zerolog`, tracing and metrics with `jaeger` and `prometheus`.
+The entry point of the framework is the `Service`. The `Service` uses `Components` to handle the processing of sync and async requests. The `Service` starts by default an `HTTP Component` which hosts the `/debug`, `/alive`, `/ready` and `/metrics` endpoints. Any other endpoints will be added to the default `HTTP Component` as `Routes`. Alongside `Routes` one can specify middleware functions to be applied ordered to all routes as `MiddlewareFunc`. The service sets up by default logging with [zerolog](https://github.com/rs/zerolog), tracing and metrics with [Jaeger](https://www.jaegertracing.io/) and [prometheus](https://prometheus.io/).
 
 `Patron` provides abstractions for the following functionality of the framework:
 

component/http/cache/route.go

@@ -34,7 +34,7 @@ func NewRouteCache(ttlCache cache.TTLCache, age Age) (*RouteCache, []error) {
 	}
 
 	if hasNoAgeConfig(age.Min.Milliseconds(), age.Max.Milliseconds()) {
-		log.Warnf("route cache for %s is disabled because of empty Age property %v ")
+		log.Warnf("route cache disabled because of empty Age property %v", age)
 	}
 
 	return &RouteCache{

component/http/middleware.go

@@ -1,9 +1,9 @@
 package http
 
 import (
+	"bytes"
 	"compress/flate"
 	"compress/gzip"
-	"context"
 	"errors"
 	"fmt"
 	"io"
@@ -14,6 +14,8 @@ import (
 	"sort"
 	"strconv"
 	"strings"
+	"sync"
+	"time"
 
 	"golang.org/x/time/rate"
 
@@ -27,6 +29,7 @@ import (
 	"github.com/opentracing/opentracing-go"
 	"github.com/opentracing/opentracing-go/ext"
 	tracinglog "github.com/opentracing/opentracing-go/log"
+	"github.com/prometheus/client_golang/prometheus"
 )
 
 const (
@@ -43,12 +46,19 @@ const (
 type responseWriter struct {
 	status              int
 	statusHeaderWritten bool
-	payload             []byte
+	capturePayload      bool
+	responsePayload     bytes.Buffer
 	writer              http.ResponseWriter
 }
 
-func newResponseWriter(w http.ResponseWriter) *responseWriter {
-	return &responseWriter{status: -1, statusHeaderWritten: false, writer: w}
+var (
+	httpStatusTracingInit          sync.Once
+	httpStatusTracingHandledMetric *prometheus.CounterVec
+	httpStatusTracingLatencyMetric *prometheus.HistogramVec
+)
+
+func newResponseWriter(w http.ResponseWriter, capturePayload bool) *responseWriter {
+	return &responseWriter{status: -1, statusHeaderWritten: false, writer: w, capturePayload: capturePayload}
 }
 
 // Status returns the http response status.
@@ -68,7 +78,9 @@ func (w *responseWriter) Write(d []byte) (int, error) {
 		return value, err
 	}
 
-	w.payload = d
+	if w.capturePayload {
+		w.responsePayload.Write(d)
+	}
 
 	if !w.statusHeaderWritten {
 		w.status = http.StatusOK
@@ -133,17 +145,62 @@ func NewAuthMiddleware(auth auth.Authenticator) MiddlewareFunc {
 }
 
 // NewLoggingTracingMiddleware creates a MiddlewareFunc that continues a tracing span and finishes it.
-// It also logs the HTTP request on debug logging level
+// It uses Jaeger and OpenTracing and will also log the HTTP request on debug level if configured so.
 func NewLoggingTracingMiddleware(path string, statusCodeLogger statusCodeLoggerHandler) MiddlewareFunc {
 	return func(next http.Handler) http.Handler {
 		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 			corID := getOrSetCorrelationID(r.Header)
 			sp, r := span(path, corID, r)
-			lw := newResponseWriter(w)
+			lw := newResponseWriter(w, true)
 			next.ServeHTTP(lw, r)
-			finishSpan(sp, lw.Status(), lw.payload)
+			finishSpan(sp, lw.Status(), &lw.responsePayload)
 			logRequestResponse(corID, lw, r)
-			statusCodeErrorLogging(r.Context(), statusCodeLogger, lw.Status(), lw.payload, path)
+			if log.Enabled(log.ErrorLevel) && statusCodeLogger.shouldLog(lw.status) {
+				log.FromContext(r.Context()).Errorf("%s %d error: %v", path, lw.status, lw.responsePayload.String())
+			}
+		})
+	}
+}
+
+func initHTTPServerMetrics() {
+	httpStatusTracingHandledMetric = prometheus.NewCounterVec(
+		prometheus.CounterOpts{
+			Namespace: "component",
+			Subsystem: "http",
+			Name:      "handled_total",
+			Help:      "Total number of HTTP responses served by the server.",
+		},
+		[]string{"method", "path", "status_code"},
+	)
+	prometheus.MustRegister(httpStatusTracingHandledMetric)
+	httpStatusTracingLatencyMetric = prometheus.NewHistogramVec(
+		prometheus.HistogramOpts{
+			Namespace: "component",
+			Subsystem: "http",
+			Name:      "handled_seconds",
+			Help:      "Latency of a completed HTTP response served by the server.",
+		},
+		[]string{"method", "path", "status_code"})
+	prometheus.MustRegister(httpStatusTracingLatencyMetric)
+}
+
+// NewRequestObserverMiddleware creates a MiddlewareFunc that captures status code and duration metrics about the responses returned;
+// metrics are exposed via Prometheus.
+// This middleware is enabled by default.
+func NewRequestObserverMiddleware(method, path string) MiddlewareFunc {
+	// register Promethus metrics on first use
+	httpStatusTracingInit.Do(initHTTPServerMetrics)
+
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			now := time.Now()
+			lw := newResponseWriter(w, false)
+			next.ServeHTTP(lw, r)
+
+			// collect metrics about HTTP server-side handling and latency
+			status := strconv.Itoa(lw.Status())
+			httpStatusTracingHandledMetric.WithLabelValues(method, path, status).Inc()
+			httpStatusTracingLatencyMetric.WithLabelValues(method, path, status).Observe(time.Since(now).Seconds())
 		})
 	}
 }
@@ -434,16 +491,6 @@ func logRequestResponse(corID string, w *responseWriter, r *http.Request) {
 	log.Sub(info).Debug()
 }
 
-func statusCodeErrorLogging(ctx context.Context, statusCodeLogger statusCodeLoggerHandler, statusCode int, payload []byte, path string) {
-	if !log.Enabled(log.ErrorLevel) {
-		return
-	}
-
-	if statusCodeLogger.shouldLog(statusCode) {
-		log.FromContext(ctx).Errorf("%s %d error: %v", path, statusCode, string(payload))
-	}
-}
-
 func getOrSetCorrelationID(h http.Header) string {
 	cor, ok := h[correlation.HeaderID]
 	if !ok {
@@ -499,11 +546,11 @@ func stripQueryString(path string) (string, error) {
 	return path[:len(path)-len(u.RawQuery)-1], nil
 }
 
-func finishSpan(sp opentracing.Span, code int, payload []byte) {
+func finishSpan(sp opentracing.Span, code int, responsePayload *bytes.Buffer) {
 	ext.HTTPStatusCode.Set(sp, uint16(code))
 	isError := code >= http.StatusInternalServerError
-	if isError && len(payload) != 0 {
-		sp.LogFields(tracinglog.String(fieldNameError, string(payload)))
+	if isError && responsePayload.Len() != 0 {
+		sp.LogFields(tracinglog.String(fieldNameError, responsePayload.String()))
 	}
 	ext.Error.Set(sp, isError)
 	sp.Finish()

component/http/middleware_test.go

@@ -71,7 +71,7 @@ func TestMiddlewareChain(t *testing.T) {
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
 			rc := httptest.NewRecorder()
-			rw := newResponseWriter(rc)
+			rw := newResponseWriter(rc, true)
 			tt.args.next = MiddlewareChain(tt.args.next, tt.args.mws...)
 			tt.args.next.ServeHTTP(rw, r)
 			assert.Equal(t, tt.expectedCode, rw.Status())
@@ -111,7 +111,7 @@ func TestMiddlewares(t *testing.T) {
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
 			rc := httptest.NewRecorder()
-			rw := newResponseWriter(rc)
+			rw := newResponseWriter(rc, true)
 			tt.args.next = MiddlewareChain(tt.args.next, tt.args.mws...)
 			tt.args.next.ServeHTTP(rw, r)
 			assert.Equal(t, tt.expectedCode, rw.Status())
@@ -155,7 +155,7 @@ func TestSpanLogError(t *testing.T) {
 		t.Run(tt.name, func(t *testing.T) {
 			mtr.Reset()
 			rc := httptest.NewRecorder()
-			rw := newResponseWriter(rc)
+			rw := newResponseWriter(rc, true)
 			tt.args.next = MiddlewareChain(tt.args.next, tt.args.mws...)
 			tt.args.next.ServeHTTP(rw, r)
 			assert.Equal(t, tt.expectedCode, rw.Status())
@@ -172,7 +172,7 @@ func TestSpanLogError(t *testing.T) {
 
 func TestResponseWriter(t *testing.T) {
 	rc := httptest.NewRecorder()
-	rw := newResponseWriter(rc)
+	rw := newResponseWriter(rc, true)
 
 	_, err := rw.Write([]byte("test"))
 	assert.NoError(t, err)

component/http/route.go

@@ -46,7 +46,7 @@ func (r Route) Handler() http.HandlerFunc {
 type RouteBuilder struct {
 	method        string
 	path          string
-	trace         bool
+	jaegerTrace   bool
 	rateLimiter   *rate.Limiter
 	middlewares   []MiddlewareFunc
 	authenticator auth.Authenticator
@@ -55,9 +55,10 @@ type RouteBuilder struct {
 	errors        []error
 }
 
-// WithTrace enables route tracing.
+// WithTrace enables route tracing that uses Jaeger/OpenTracing.
+// It requires Jaeger enabled on the Patron service.
 func (rb *RouteBuilder) WithTrace() *RouteBuilder {
-	rb.trace = true
+	rb.jaegerTrace = true
 	return rb
 }
 
@@ -150,6 +151,7 @@ func (rb *RouteBuilder) MethodTrace() *RouteBuilder {
 
 // Build a route.
 func (rb *RouteBuilder) Build() (Route, error) {
+	// parse a list of HTTP numeric status codes that must be logged
 	cfg, _ := os.LookupEnv("PATRON_HTTP_STATUS_ERROR_LOGGING")
 	statusCodeLogger, err := newStatusCodeLoggerHandler(cfg)
 	if err != nil {
@@ -165,9 +167,15 @@ func (rb *RouteBuilder) Build() (Route, error) {
 	}
 
 	var middlewares []MiddlewareFunc
-	if rb.trace {
+	if rb.jaegerTrace {
+		// uses Jaeger/OpenTracing and Patron's response logging
 		middlewares = append(middlewares, NewLoggingTracingMiddleware(rb.path, statusCodeLogger))
 	}
+
+	// uses a custom Patron metric for HTTP responses (with complete status code)
+	// it does not use Jaeger/OpenTracing
+	middlewares = append(middlewares, NewRequestObserverMiddleware(rb.method, rb.path))
+
 	if rb.rateLimiter != nil {
 		middlewares = append(middlewares, NewRateLimitingMiddleware(rb.rateLimiter))
 	}

component/http/route_cache_test.go

@@ -91,7 +91,7 @@ func TestCachingMiddleware(t *testing.T) {
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
 			rc := httptest.NewRecorder()
-			rw := newResponseWriter(rc)
+			rw := newResponseWriter(rc, true)
 			tt.args.next = MiddlewareChain(tt.args.next, tt.args.mws...)
 			tt.args.next.ServeHTTP(rw, tt.r)
 			assert.Equal(t, tt.expectedCode, rw.Status())

component/http/route_test.go

@@ -98,7 +98,7 @@ func TestRouteBuilder_WithMethodOptions(t *testing.T) {
 
 func TestRouteBuilder_WithTrace(t *testing.T) {
 	rb := NewRawRouteBuilder("/", func(http.ResponseWriter, *http.Request) {}).WithTrace()
-	assert.True(t, rb.trace)
+	assert.True(t, rb.jaegerTrace)
 }
 
 func TestRouteBuilder_WithMiddlewares(t *testing.T) {
@@ -399,7 +399,7 @@ func TestRoute_Getters(t *testing.T) {
 
 	assert.Equal(t, path, r.Path())
 	assert.Equal(t, http.MethodPost, r.Method())
-	assert.Len(t, r.Middlewares(), 1)
+	assert.Len(t, r.Middlewares(), 2)
 
 	// the only way to test do we get the same handler that we provided initially, is to run it explicitly,
 	// since all we have in Route itself is a wrapper function

docs/components/HTTP.md

@@ -94,6 +94,22 @@ Both can return either a `200 OK` or a `503 Service Unavailable` status code (de
 
 It is possible to customize their behaviour by injecting an `http.AliveCheck` and/or an `http.ReadyCheck` `OptionFunc` to the HTTP component constructor.
 
+## Metrics
+
+The following metrics are automatically provided by default:
+* `component_http_handled_total`
+* `component_http_handled_seconds`
+
+Example of the associated labels: `status_code="200"`, `method="GET"`, `path="/hello/world"`
+
+### Jaeger-provided metrics
+
+When using `WithTrace()` the following metrics are automatically provided via Jaeger (they are populated together with the spans):
+* `{microservice_name}_http_requests_total`
+* `{microservice_name}_http_requests_latency`
+
+They have labels `endpoint="GET-/hello/world"` and `status_code="2xx"`.
+
 ## HTTP Middlewares
 
 A `MiddlewareFunc` preserves the default net/http middleware pattern.
@@ -143,11 +159,18 @@ func NewAuthMiddleware(auth auth.Authenticator) MiddlewareFunc {
 }
 
 // NewLoggingTracingMiddleware creates a MiddlewareFunc that continues a tracing span and finishes it.
-// It also logs the HTTP request on debug logging level.
+// It uses Jaeger and OpenTracing and will also log the HTTP request on debug level if configured so.
 func NewLoggingTracingMiddleware(path string) MiddlewareFunc {
     // ...
 }
 
+// NewRequestObserverMiddleware creates a MiddlewareFunc that captures status code and duration metrics about the responses returned;
+// metrics are exposed via Prometheus.
+// This middleware is enabled by default.
+func NewRequestObserverMiddleware(method, path string) MiddlewareFunc {
+	// ...
+}
+
 // NewCachingMiddleware creates a cache layer as a middleware.
 // when used as part of a middleware chain any middleware later in the chain,
 // will not be executed, but the headers it appends will be part of the cache.

docs/components/gRPC.md

@@ -7,4 +7,12 @@ As the server implements the Patron `component` interface, it also handles grace
 
 Setting up a gRPC component is done via the Builder (which follows the builder pattern), and supports various configuration values in the form of the `grpc.ServerOption` struct during setup.
 
-Check out the [examples/](/examples) folder for an hands-on tutorial on setting up a server and working with gRPC in Patron.
+Check out the [examples/](/examples) folder for an hands-on tutorial on setting up a server and working with gRPC in Patron.
+
+## Metrics
+
+The following metrics are automatically provided when using `WithTrace()`:
+* `component_grpc_handled_total`
+* `component_grpc_handled_seconds`
+
+Example of the associated labels: `grpc_code="OK"`, `grpc_method="CreateMyEvent"`, `grpc_service="myservice.Service"`, `grpc_type="unary"`.

examples/check/main.go

@@ -33,7 +33,11 @@ func main() {
 		log.Fatal(err)
 	}
 	if resp.StatusCode != http.StatusCreated {
-		log.Fatalf("Response supposed to be status code %d instead it is %d", http.StatusCreated, resp.StatusCode)
+		body, err := ioutil.ReadAll(resp.Body)
+		if err != nil {
+			log.Fatal(err)
+		}
+		log.Fatalf("Response supposed to be status code %d instead it is %d (body: %q)", http.StatusCreated, resp.StatusCode, string(body))
 	}
 
 	// wait 1 second so that metrics can be flushed to http endpoint