Instrustment handlers for logging/error handling

This refactors a bit of the http handler code.
Moves error handling for handler functions to a generic handler.
This also has a side-effect of being able to propagate errors from the
provider to send the correct status code, provided the error type
matches a pre-defined interface.

vkubelet/apiserver.go

@@ -12,13 +12,15 @@ import (
 	"time"
 
 	"github.com/Sirupsen/logrus"
+	"github.com/cpuguy83/strongerrors"
+	"github.com/cpuguy83/strongerrors/status"
 	"github.com/gorilla/mux"
 	"github.com/pkg/errors"
 	"github.com/virtual-kubelet/virtual-kubelet/log"
 	"k8s.io/kubernetes/pkg/kubelet/server/remotecommand"
 )
 
-func loggingContext(r *http.Request) context.Context {
+func instrumentContext(r *http.Request) context.Context {
 	ctx := r.Context()
 	logger := log.G(ctx).WithFields(logrus.Fields{
 		"uri":  r.RequestURI,
@@ -29,19 +31,50 @@ func loggingContext(r *http.Request) context.Context {
 
 // NotFound provides a handler for cases where the requested endpoint doesn't exist
 func NotFound(w http.ResponseWriter, r *http.Request) {
-	logger := log.G(loggingContext(r))
+	logger := log.G(instrumentContext(r))
 	log.Trace(logger, "404 request not found")
 	http.Error(w, "404 request not found", http.StatusNotFound)
 }
 
 // NotImplemented provides a handler for cases where a provider does not implement a given API
 func NotImplemented(w http.ResponseWriter, r *http.Request) {
-	logger := log.G(loggingContext(r))
+	logger := log.G(instrumentContext(r))
 	log.Trace(logger, "501 not implemented")
 	http.Error(w, "501 not implemented", http.StatusNotImplemented)
 }
 
-// KubeletServertStart starts the virtual kubelet HTTP server.
+type handlerFunc func(http.ResponseWriter, *http.Request) error
+
+// InstrumentHandler wraps an http.Handler and injects instrumentation into the request context.
+func InstrumentHandler(h http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+		ctx := instrumentContext(req)
+		req = req.WithContext(ctx)
+		h.ServeHTTP(w, req)
+	})
+}
+
+func handleError(f handlerFunc) http.HandlerFunc {
+	return func(w http.ResponseWriter, req *http.Request) {
+		err := f(w, req)
+		if err == nil {
+			return
+		}
+
+		code, _ := status.HTTPCode(err)
+		w.WriteHeader(code)
+		io.WriteString(w, err.Error())
+		logger := log.G(req.Context()).WithError(err).WithField("httpStatusCode", code)
+
+		if code >= 500 {
+			logger.Error("Internal server error on request")
+		} else {
+			log.Trace(logger, "Error on request")
+		}
+	}
+}
+
+// KubeletServerStart starts the virtual kubelet HTTP server.
 func KubeletServerStart(p Provider) {
 	certFilePath := os.Getenv("APISERVER_CERT_LOCATION")
 	keyFilePath := os.Getenv("APISERVER_KEY_LOCATION")
@@ -53,7 +86,7 @@ func KubeletServerStart(p Provider) {
 	r.HandleFunc("/exec/{namespace}/{pod}/{container}", PodExecHandlerFunc(p)).Methods("POST")
 	r.NotFoundHandler = http.HandlerFunc(NotFound)
 
-	if err := http.ListenAndServeTLS(addr, certFilePath, keyFilePath, r); err != nil {
+	if err := http.ListenAndServeTLS(addr, certFilePath, keyFilePath, InstrumentHandler(r)); err != nil {
 		log.G(context.TODO()).WithError(err).Error("error setting up http server")
 	}
 }
@@ -72,49 +105,43 @@ func MetricsServerStart(p Provider, addr string) {
 		r.HandleFunc("/stats/summary/", PodMetricsHandlerFunc(mp)).Methods("GET")
 	}
 	r.NotFoundHandler = http.HandlerFunc(NotFound)
-	if err := http.ListenAndServe(addr, r); err != nil {
+	if err := http.ListenAndServe(addr, InstrumentHandler(r)); err != nil {
 		log.G(context.TODO()).WithError(err).Error("Error starting http server")
 	}
 }
 
 // PodMetricsHandlerFunc makes an HTTP handler for implementing the kubelet summary stats endpoint
 func PodMetricsHandlerFunc(mp MetricsProvider) http.HandlerFunc {
-	return func(w http.ResponseWriter, req *http.Request) {
-		ctx := loggingContext(req)
-
+	return handleError(func(w http.ResponseWriter, req *http.Request) error {
 		stats, err := mp.GetStatsSummary(req.Context())
 		if err != nil {
 			if errors.Cause(err) == context.Canceled {
-				return
+				return strongerrors.Cancelled(err)
 			}
-			log.G(ctx).Error("Error getting stats from provider:", err)
-			http.Error(w, err.Error(), http.StatusInternalServerError)
-			return
+			return strongerrors.Unknown(errors.Wrap(err, "error getting status from provider"))
 		}
 
 		b, err := json.Marshal(stats)
 		if err != nil {
-			log.G(ctx).WithError(err).Error("Could not marshal stats")
-			http.Error(w, "could not marshal stats: "+err.Error(), http.StatusInternalServerError)
-			return
+			return strongerrors.Unknown(errors.Wrap(err, "error marshalling stats"))
 		}
 
 		if _, err := w.Write(b); err != nil {
-			log.G(ctx).WithError(err).Debug("Could not write to client")
+			return strongerrors.Unknown(errors.Wrap(err, "could not write to client"))
 		}
-	}
+		return nil
+	})
 }
 
 // PodLogsHandlerFunc creates an http handler function from a provider to serve logs from a pod
 func PodLogsHandlerFunc(p Provider) http.HandlerFunc {
-	return func(w http.ResponseWriter, req *http.Request) {
+	return handleError(func(w http.ResponseWriter, req *http.Request) error {
 		vars := mux.Vars(req)
 		if len(vars) != 3 {
-			NotFound(w, req)
-			return
+			return strongerrors.NotFound(errors.New("not found"))
 		}
 
-		ctx := loggingContext(req)
+		ctx := req.Context()
 
 		namespace := vars["namespace"]
 		pod := vars["pod"]
@@ -125,25 +152,21 @@ func PodLogsHandlerFunc(p Provider) http.HandlerFunc {
 		if queryTail := q.Get("tailLines"); queryTail != "" {
 			t, err := strconv.Atoi(queryTail)
 			if err != nil {
-				logger := log.G(context.TODO()).WithError(err)
-				log.Trace(logger, "could not parse tailLines")
-				http.Error(w, fmt.Sprintf("could not parse \"tailLines\": %v", err), http.StatusBadRequest)
-				return
+				return strongerrors.InvalidArgument(errors.Wrap(err, "could not parse \"tailLines\""))
 			}
 			tail = t
 		}
 
 		podsLogs, err := p.GetContainerLogs(ctx, namespace, pod, container, tail)
 		if err != nil {
-			log.G(ctx).WithError(err).Error("error getting container logs")
-			http.Error(w, fmt.Sprintf("error while getting container logs: %v", err), http.StatusInternalServerError)
-			return
+			return errors.Wrap(err, "error getting container logs?)")
 		}
 
 		if _, err := io.WriteString(w, podsLogs); err != nil {
-			log.G(ctx).WithError(err).Warn("error writing response to client")
+			return strongerrors.Unknown(errors.Wrap(err, "error writing response to client"))
 		}
-	}
+		return nil
+	})
 }
 
 // PodExecHandlerFunc makes an http handler func from a Provider which execs a command in a pod's container