trace requests per route (#189)

* trace requests per route

* minor tweak on the option

* use pattern and method for tracing

* change the naming pattern for the resources

* add logger and debug flag for tracing

* use a logrus to take LD from info to debug

* don't log errors that are expected

Author: rybit

featureflag/featureflag.go

@@ -37,9 +37,7 @@ func NewClient(cfg *Config, logger logrus.FieldLogger) (Client, error) {
 		config.SendEvents = false
 	}
 
-	if logger == nil {
-		logger = noopLogger()
-	}
+	config.Loggers.SetBaseLogger(wrapLogger(logger))
 
 	if cfg.RelayHost != "" {
 		config.BaseUri = cfg.RelayHost
@@ -99,8 +97,23 @@ func (c *ldClient) AllEnabledFlags(key string) []string {
 	return flags
 }
 
-func noopLogger() *logrus.Logger {
-	l := logrus.New()
-	l.SetOutput(ioutil.Discard)
-	return l
+func wrapLogger(logger logrus.FieldLogger) infoToDebugLogger {
+	if logger == nil {
+		l := logrus.New()
+		l.SetOutput(ioutil.Discard)
+		logger = l
+	}
+
+	return infoToDebugLogger{logger.WithField("component", "launch_darkly")}
+}
+
+type infoToDebugLogger struct {
+	log logrus.FieldLogger
+}
+
+func (l infoToDebugLogger) Println(values ...interface{}) {
+	l.log.Debugln(values...)
+}
+func (l infoToDebugLogger) Printf(format string, values ...interface{}) {
+	l.log.Debugf(format, values...)
 }

nconf/args.go

@@ -53,7 +53,7 @@ func (args *RootArgs) Setup(config interface{}, serviceName, version string) (lo
 	}
 
 	// Handles the 'enabled' flag itself
-	tracing.Configure(&rootConfig.Tracing, serviceName)
+	tracing.Configure(&rootConfig.Tracing, log, serviceName)
 
 	if err := featureflag.Init(rootConfig.FeatureFlag, log); err != nil {
 		return nil, errors.Wrap(err, "Failed to configure featureflags")

router/errors.go

@@ -86,40 +86,40 @@ func httpError(code int, fmtString string, args ...interface{}) *HTTPError {
 	}
 }
 
-// HandleError will handle an error
+// HandleError will handle any error. If it is of type *HTTPError then it will
+// log anything of a 50x or an InternalError. It will write the right error response
+// to the client. This way if you return a BadRequestError, it will simply write to the client.
+// Any non-HTTPError will be treated as unhandled and result in a 50x
 func HandleError(err error, w http.ResponseWriter, r *http.Request) {
+	if err == nil || reflect.ValueOf(err).IsNil() {
+		return
+	}
+
 	log := tracing.GetLogger(r)
 	errorID := tracing.GetRequestID(r)
 
 	var notifyBugsnag bool
 
 	switch e := err.(type) {
-	case nil:
-		return
 	case *HTTPError:
-		// assert to *HTTPError to check nil intrface
-		httpErr := err.(*HTTPError)
-		if httpErr == nil {
-			return
-		}
-
+		e.ErrorID = errorID
 		if e.Code >= http.StatusInternalServerError {
-			e.ErrorID = errorID
-			// this will get us the stack trace too
-			log.WithError(e.Cause()).Error(e.Error())
 			notifyBugsnag = true
-		} else {
-			log.WithError(e.Cause()).Infof("unexpected error: %s", e.Error())
+			elog := log.WithError(e)
+			if e.InternalError != nil {
+				elog = elog.WithField("internal_err", e.InternalError.Error())
+			}
+
+			elog.Errorf("internal server error: %s", e.InternalMessage)
+		} else if e.InternalError != nil {
+			notifyBugsnag = true
+			log.WithError(e).Infof("unexpected error: %s", e.InternalMessage)
 		}
 
 		if jsonErr := SendJSON(w, e.Code, e); jsonErr != nil {
 			log.WithError(jsonErr).Error("Failed to write the JSON error response")
 		}
 	default:
-		// this is 5ns slower than using unsafe but a unhandled internal server error should not happen that often
-		if reflect.ValueOf(err).IsNil() {
-			return
-		}
 		notifyBugsnag = true
 		metriks.Inc("unhandled_errors", 1)
 		log.WithError(e).Errorf("Unhandled server error: %s", e.Error())
@@ -129,6 +129,7 @@ func HandleError(err error, w http.ResponseWriter, r *http.Request) {
 			log.WithError(writeErr).Error("Error writing generic error message")
 		}
 	}
+
 	if notifyBugsnag {
 		bugsnag.Notify(err, r, r.Context(), bugsnag.MetaData{
 			"meta": map[string]interface{}{

router/errors_test.go

@@ -25,6 +25,7 @@ func TestHandleError_ErrorIsNil(t *testing.T) {
 		httptest.NewRequest(http.MethodGet, "/", nil),
 		logger,
 		"test",
+		"test",
 	)
 
 	HandleError(nil, w, r)
@@ -40,6 +41,7 @@ func TestHandleError_ErrorIsNilPointerToTypeHTTPError(t *testing.T) {
 		httptest.NewRequest(http.MethodGet, "/", nil),
 		logger,
 		"test",
+		"test",
 	)
 
 	h := func(_ http.ResponseWriter, _ *http.Request) *HTTPError {
@@ -52,13 +54,34 @@ func TestHandleError_ErrorIsNilPointerToTypeHTTPError(t *testing.T) {
 	assert.Empty(t, w.Header())
 }
 
+func TestHandleError_ErrorIsNilInterface(t *testing.T) {
+	logger, loggerOutput := test.NewNullLogger()
+	w, r, _ := tracing.NewTracer(
+		httptest.NewRecorder(),
+		httptest.NewRequest(http.MethodGet, "/", nil),
+		logger,
+		"test",
+		"test",
+	)
+
+	h := func(_ http.ResponseWriter, _ *http.Request) error {
+		return nil
+	}
+
+	HandleError(h(w, r), w, r)
+
+	assert.Empty(t, loggerOutput.AllEntries())
+	assert.Empty(t, w.Header())
+}
+
 func TestHandleError_StandardError(t *testing.T) {
 	logger, loggerOutput := test.NewNullLogger()
 	w, r, _ := tracing.NewTracer(
 		httptest.NewRecorder(),
 		httptest.NewRequest(http.MethodGet, "/", nil),
 		logger,
 		"test",
+		"test",
 	)
 
 	HandleError(errors.New("random error"), w, r)
@@ -76,6 +99,7 @@ func TestHandleError_HTTPError(t *testing.T) {
 		httptest.NewRequest(http.MethodGet, "/", nil),
 		logger,
 		"test",
+		"test",
 	)
 
 	httpErr := &HTTPError{
@@ -95,7 +119,33 @@ func TestHandleError_HTTPError(t *testing.T) {
 	assert.Equal(t, expectedBody, string(b))
 
 	require.Len(t, loggerOutput.AllEntries(), 1)
-	assert.Equal(t, httpErr.InternalMessage, loggerOutput.AllEntries()[0].Message)
+	assert.Equal(t, "internal server error: "+httpErr.InternalMessage, loggerOutput.AllEntries()[0].Message)
+}
+
+func TestHandleError_NoLogForNormalErrors(t *testing.T) {
+	logger, loggerOutput := test.NewNullLogger()
+	recorder := httptest.NewRecorder()
+	w, r, _ := tracing.NewTracer(
+		recorder,
+		httptest.NewRequest(http.MethodGet, "/", nil),
+		logger,
+		"test",
+		"test",
+	)
+
+	httpErr := BadRequestError("not found yo.")
+
+	HandleError(httpErr, w, r)
+
+	resp := recorder.Result()
+	b, err := ioutil.ReadAll(resp.Body)
+	require.NoError(t, err)
+
+	expectedBody := fmt.Sprintf(`{"code":400,"msg":"not found yo.","error_id":"%s"}`, tracing.GetRequestID(r))
+	assert.Equal(t, expectedBody, string(b))
+
+	// we shouldn't log anything, this is a normal error
+	require.Len(t, loggerOutput.AllEntries(), 0)
 }
 
 type OtherError struct {
@@ -113,6 +163,7 @@ func TestHandleError_ErrorIsNilPointerToTypeOtherError(t *testing.T) {
 		httptest.NewRequest(http.MethodGet, "/", nil),
 		logger,
 		"test",
+		"test",
 	)
 
 	var oe *OtherError

router/middleware.go

@@ -146,3 +146,11 @@ func BugSnag() Middleware {
 		next.ServeHTTP(w, r.WithContext(ctx))
 	})
 }
+
+func TrackAllRequests(log logrus.FieldLogger, service string) Middleware {
+	return MiddlewareFunc(func(w http.ResponseWriter, r *http.Request, next http.Handler) {
+		// This is to maintain some legacy span work. It will cause the APM requests
+		// to show up as the method on the top level
+		tracing.TrackRequest(w, r, log, service, r.Method, next)
+	})
+}

router/middleware_test.go

@@ -134,6 +134,7 @@ func TestRecoveryInternalTracer(t *testing.T) {
 		httptest.NewRequest(http.MethodGet, "/", nil),
 		logger,
 		t.Name(),
+		"some_resource",
 	)
 	mw := Recoverer(logrus.New())
 	handler := mw(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {

router/options.go

@@ -1,9 +1,5 @@
 package router
 
-import (
-	"github.com/sirupsen/logrus"
-)
-
 type Option func(r *chiWrapper)
 
 func OptEnableCORS(r *chiWrapper) {
@@ -27,7 +23,7 @@ func OptVersionHeader(svcName, version string) Option {
 	}
 }
 
-func OptTracingMiddleware(log logrus.FieldLogger, svcName string) Option {
+func OptEnableTracing(svcName string) Option {
 	return func(r *chiWrapper) {
 		r.svcName = svcName
 		r.enableTracing = true

router/router.go

@@ -2,6 +2,7 @@ package router
 
 import (
 	"net/http"
+	"strings"
 
 	"github.com/netlify/netlify-commons/tracing"
 	"github.com/rs/cors"
@@ -14,8 +15,10 @@ import (
 type chiWrapper struct {
 	chi chi.Router
 
-	version string
-	svcName string
+	version       string
+	svcName       string
+	tracingPrefix string
+	rootLogger    logrus.FieldLogger
 
 	healthEndpoint string
 	healthHandler  APIHandler
@@ -51,11 +54,12 @@ type Router interface {
 	ServeHTTP(http.ResponseWriter, *http.Request)
 }
 
-//  creates a router with sensible defaults (xff, request id, cors)
+// New creates a router with sensible defaults (xff, request id, cors)
 func New(log logrus.FieldLogger, options ...Option) Router {
 	r := &chiWrapper{
-		chi:     chi.NewRouter(),
-		version: "unknown",
+		chi:        chi.NewRouter(),
+		version:    "unknown",
+		rootLogger: log,
 	}
 
 	xffmw, _ := xff.Default()
@@ -81,43 +85,44 @@ func New(log logrus.FieldLogger, options ...Option) Router {
 	if r.healthEndpoint != "" {
 		r.Use(HealthCheck(r.healthEndpoint, r.healthHandler))
 	}
-	if r.enableTracing {
-		r.Use(tracing.Middleware(log, r.svcName))
-	}
 
 	return r
 }
 
 // Route allows creating a generic route
 func (r *chiWrapper) Route(pattern string, fn func(Router)) {
 	r.chi.Route(pattern, func(c chi.Router) {
-		fn(&chiWrapper{chi: c})
+		wrapper := new(chiWrapper)
+		*wrapper = *r
+		wrapper.chi = c
+		wrapper.tracingPrefix = sanitizePattern(pattern)
+		fn(wrapper)
 	})
 }
 
 // Method adds a routes for a `pattern` that matches the `method` HTTP method.
 func (r *chiWrapper) Method(method, pattern string, h APIHandler) {
-	r.chi.Method(method, pattern, HandlerFunc(h))
+	r.chi.Method(method, pattern, r.traceRequest(method, pattern, h))
 }
 
 // Get adds a GET route
 func (r *chiWrapper) Get(pattern string, fn APIHandler) {
-	r.chi.Get(pattern, HandlerFunc(fn))
+	r.chi.Get(pattern, r.traceRequest(http.MethodGet, pattern, fn))
 }
 
 // Post adds a POST route
 func (r *chiWrapper) Post(pattern string, fn APIHandler) {
-	r.chi.Post(pattern, HandlerFunc(fn))
+	r.chi.Post(pattern, r.traceRequest(http.MethodPost, pattern, fn))
 }
 
 // Put adds a PUT route
 func (r *chiWrapper) Put(pattern string, fn APIHandler) {
-	r.chi.Put(pattern, HandlerFunc(fn))
+	r.chi.Put(pattern, r.traceRequest(http.MethodPut, pattern, fn))
 }
 
 // Delete adds a DELETE route
 func (r *chiWrapper) Delete(pattern string, fn APIHandler) {
-	r.chi.Delete(pattern, HandlerFunc(fn))
+	r.chi.Delete(pattern, r.traceRequest(http.MethodDelete, pattern, fn))
 }
 
 // WithBypass adds an inline chi middleware for an endpoint handler
@@ -138,6 +143,11 @@ func (r *chiWrapper) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 
 // Mount attaches another http.Handler along ./pattern/*
 func (r *chiWrapper) Mount(pattern string, h http.Handler) {
+	if r.enableTracing {
+		h = http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+			tracing.TrackRequest(w, req, r.rootLogger, r.svcName, pattern, h)
+		})
+	}
 	r.chi.Mount(pattern, h)
 }
 
@@ -154,3 +164,32 @@ func HandlerFunc(fn APIHandler) http.HandlerFunc {
 		}
 	}
 }
+
+func (r *chiWrapper) traceRequest(method, pattern string, fn APIHandler) http.HandlerFunc {
+	f := HandlerFunc(fn)
+	if r.enableTracing {
+		pattern = sanitizePattern(pattern)
+		if r.tracingPrefix != "" {
+			pattern = r.tracingPrefix + "." + pattern
+		}
+
+		resourceName := strings.ToUpper(method)
+		if pattern != "" {
+			resourceName += "::" + pattern
+		}
+
+		return func(w http.ResponseWriter, req *http.Request) {
+			tracing.TrackRequest(w, req, r.rootLogger, r.svcName, resourceName, f)
+		}
+	}
+	return f
+}
+
+func sanitizePattern(pattern string) string {
+	pattern = strings.TrimPrefix(pattern, "/")
+	pattern = strings.ReplaceAll(pattern, "{", "")
+	pattern = strings.ReplaceAll(pattern, "}", "")
+	pattern = strings.ReplaceAll(pattern, "/", ".")
+	pattern = strings.TrimSuffix(pattern, ".")
+	return pattern
+}