Merged pull request #513 from influxdata/nc-http-logging

feat: Add optional http logging to handler

cmd/fluxd/main.go

@@ -117,6 +117,7 @@ func fluxF(cmd *cobra.Command, args []string) {
 
 	handler := http.NewHandlerFromRegistry("query", reg)
 	handler.Handler = queryHandler
+	handler.Logger = logger
 
 	logger.Info("listening", zap.String("transport", "http"), zap.String("addr", bindAddr))
 	if err := nethttp.ListenAndServe(bindAddr, handler); err != nil {

http/handler.go

@@ -11,6 +11,7 @@ import (
 	"github.com/influxdata/platform/kit/prom"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
+	"go.uber.org/zap"
 )
 
 const (
@@ -34,6 +35,9 @@ type Handler struct {
 
 	requests   *prometheus.CounterVec
 	requestDur *prometheus.HistogramVec
+
+	// Logger if set will log all HTTP requests as they are served
+	Logger *zap.Logger
 }
 
 // NewHandler creates a new handler with the given name.
@@ -73,21 +77,31 @@ func (h *Handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	w = statusW
 
 	// TODO: This could be problematic eventually. But for now it should be fine.
-	defer func() {
+	defer func(start time.Time) {
+		duration := time.Since(start)
+		statusClass := statusW.statusCodeClass()
+		statusCode := statusW.code()
 		h.requests.With(prometheus.Labels{
 			"handler": h.name,
 			"method":  r.Method,
 			"path":    r.URL.Path,
-			"status":  statusW.statusCodeClass(),
+			"status":  statusClass,
 		}).Inc()
-	}()
-	defer func(start time.Time) {
 		h.requestDur.With(prometheus.Labels{
 			"handler": h.name,
 			"method":  r.Method,
 			"path":    r.URL.Path,
-			"status":  statusW.statusCodeClass(),
+			"status":  statusClass,
-		}).Observe(time.Since(start).Seconds())
+		}).Observe(duration.Seconds())
+		if h.Logger != nil {
+			h.Logger.Info("served http request",
+				zap.String("handler", h.name),
+				zap.String("method", r.Method),
+				zap.String("path", r.URL.Path),
+				zap.Int("status", statusCode),
+				zap.Int("duration_ns", int(duration)),
+			)
+		}
 	}(time.Now())
 
 	switch {

http/status.go

@@ -19,13 +19,21 @@ func (w *statusResponseWriter) WriteHeader(statusCode int) {
 	w.ResponseWriter.WriteHeader(statusCode)
 }
 
+func (w *statusResponseWriter) code() int {
+	code := w.statusCode
+	if code == 0 {
+		// When statusCode is 0 then WriteHeader was never called and we can assume that
+		// the ResponseWriter wrote an http.StatusOK.
+		code = http.StatusOK
+	}
+	return code
+}
 func (w *statusResponseWriter) statusCodeClass() string {
 	class := "XXX"
-	switch w.statusCode / 100 {
+	switch w.code() / 100 {
 	case 1:
 		class = "1XX"
-	case 0, 2:
+	case 2:
-		// When statusCode is 0 then WriteHeader was never called and we can assume that the ResponseWriter wrote an http.StatusOK.
 		class = "2XX"
 	case 3:
 		class = "3XX"