Replaced Macaron logger with custom logger enabling query statistics

api/api.go

@@ -76,7 +76,6 @@ func (s *Server) BindPrioritySetter(p PrioritySetter) {
 func NewServer() (*Server, error) {
 
 	m := macaron.New()
-	m.Use(macaron.Logger())
 	m.Use(macaron.Recovery())
 	// route pprof to where it belongs, except for our own extensions
 	m.Use(func(ctx *macaron.Context) {

api/config.go

@@ -8,6 +8,7 @@ import (
 	"time"
 
 	"github.com/grafana/globalconf"
+	"github.com/grafana/metrictank/api/middleware"
 	"github.com/grafana/metrictank/expr"
 	log "github.com/sirupsen/logrus"
 )
@@ -53,6 +54,7 @@ func ConfigSetup() {
 	apiCfg.Float64Var(&speculationThreshold, "speculation-threshold", 1, "ratio of peer responses after which speculation is used. Set to 1 to disable.")
 	apiCfg.BoolVar(&optimizations.PreNormalization, "pre-normalization", true, "enable pre-normalization optimization")
 	apiCfg.BoolVar(&optimizations.MDP, "mdp-optimization", false, "enable MaxDataPoints optimization (experimental)")
+	apiCfg.BoolVar(&middleware.LogHeaders, "log-headers", false, "output query headers in logs")
 	globalconf.Register("http", apiCfg, flag.ExitOnError)
 }
 

api/middleware/logger.go

@@ -0,0 +1,123 @@
+package middleware
+
+import (
+	"bytes"
+	"context"
+	"fmt"
+	"net/http"
+	"net/url"
+	"strings"
+	"time"
+
+	opentracing "github.com/opentracing/opentracing-go"
+	log "github.com/sirupsen/logrus"
+	jaeger "github.com/uber/jaeger-client-go"
+	macaron "gopkg.in/macaron.v1"
+)
+
+var (
+	LogHeaders = false
+)
+
+type LoggingResponseWriter struct {
+	macaron.ResponseWriter
+	errBody []byte // the body in case it is an error
+}
+
+func (rw *LoggingResponseWriter) Write(b []byte) (int, error) {
+	if rw.ResponseWriter.Status() >= 400 {
+		rw.errBody = make([]byte, len(b))
+		copy(rw.errBody, b)
+	}
+	return rw.ResponseWriter.Write(b)
+}
+
+func Logger() macaron.Handler {
+	return func(ctx *Context) {
+		start := time.Now()
+		rw := &LoggingResponseWriter{
+			ResponseWriter: ctx.Resp,
+		}
+		ctx.Resp = rw
+		ctx.MapTo(ctx.Resp, (*http.ResponseWriter)(nil))
+		ctx.Next()
+
+		// Only log:
+		// - requests that resulted in errors
+		// - requests on /render path
+		if rw.Status() >= 200 && rw.Status() < 300 && !strings.HasPrefix(ctx.Req.URL.Path, "/render") {
+			return
+		}
+
+		var content strings.Builder
+		fmt.Fprintf(&content, "ts=%s", time.Now().Format(time.RFC3339Nano))
+
+		traceID, _ := extractTraceID(ctx.Req.Context())
+		if traceID != "" {
+			fmt.Fprintf(&content, " traceID=%s", traceID)
+		}
+
+		err := ctx.Req.ParseForm()
+		if err != nil {
+			log.Errorf("Could not parse http request: %v", err)
+		}
+		paramsAsString := ""
+		if len(ctx.Req.Form) > 0 {
+			paramsAsString += "?"
+			paramsAsString += ctx.Req.Form.Encode()
+		}
+		fmt.Fprintf(&content, " msg=\"%s %s%s (%v) %v\" orgID=%d", ctx.Req.Method, ctx.Req.URL.Path, paramsAsString, rw.Status(), time.Since(start), ctx.OrgId)
+
+		referer := ctx.Req.Referer()
+		if referer != "" {
+			fmt.Fprintf(&content, " referer=%s", referer)
+		}
+		sourceIP := ctx.RemoteAddr()
+		if sourceIP != "" {
+			fmt.Fprintf(&content, " sourceIP=\"%s\"", sourceIP)
+		}
+
+		if rw.Status() < 200 || rw.Status() >= 300 {
+			errorMsg := url.PathEscape(string(rw.errBody))
+			fmt.Fprintf(&content, " error=\"%s\"", errorMsg)
+		}
+
+		if LogHeaders {
+			headers, err := extractHeaders(ctx.Req.Request)
+			if err != nil {
+				log.Errorf("Could not extract request headers: %v", err)
+			}
+			fmt.Fprintf(&content, " headers=\"%s\"", string(headers))
+		}
+
+		log.Println(content.String())
+	}
+}
+
+func extractHeaders(req *http.Request) (string, error) {
+	var b bytes.Buffer
+
+	// Exclude some headers for security, or just that we don't need them when debugging
+	err := req.Header.WriteSubset(&b, map[string]bool{
+		"Cookie":        true,
+		"X-Csrf-Token":  true,
+		"Authorization": true,
+	})
+	if err != nil {
+		return "", err
+	}
+	return url.PathEscape(string(b.Bytes())), nil
+}
+
+func extractTraceID(ctx context.Context) (string, bool) {
+	sp := opentracing.SpanFromContext(ctx)
+	if sp == nil {
+		return "", false
+	}
+	sctx, ok := sp.Context().(jaeger.SpanContext)
+	if !ok {
+		return "", false
+	}
+
+	return sctx.TraceID().String(), true
+}

api/routes.go

@@ -18,6 +18,7 @@ func (s *Server) RegisterRoutes() {
 	r.Use(middleware.Tracer(s.Tracer))
 	r.Use(macaron.Renderer())
 	r.Use(middleware.OrgMiddleware(multiTenant))
+	r.Use(middleware.Logger())
 	r.Use(middleware.CorsHandler())
 	bind := binding.Bind
 	withOrg := middleware.RequireOrg()

docker/docker-chaos/metrictank.ini

@@ -248,6 +248,8 @@ speculation-threshold = 1
 pre-normalization = true
 # enable MaxDataPoints optimization (experimental)
 mdp-optimization = false
+# output query headers in logs
+log-headers = false
 
 ## metric data inputs ##
 

docker/docker-cluster-query/metrictank.ini

@@ -248,6 +248,8 @@ speculation-threshold = 1
 pre-normalization = true
 # enable MaxDataPoints optimization (experimental)
 mdp-optimization = false
+# output query headers in logs
+log-headers = false
 
 ## metric data inputs ##
 

docker/docker-cluster/metrictank.ini

@@ -248,6 +248,8 @@ speculation-threshold = 1
 pre-normalization = true
 # enable MaxDataPoints optimization (experimental)
 mdp-optimization = false
+# output query headers in logs
+log-headers = false
 
 ## metric data inputs ##
 

docker/docker-dev-custom-cfg-kafka/metrictank.ini

@@ -248,6 +248,8 @@ speculation-threshold = 1
 pre-normalization = true
 # enable MaxDataPoints optimization (experimental)
 mdp-optimization = false
+# output query headers in logs
+log-headers = false
 
 ## metric data inputs ##
 

docs/config.md

@@ -297,6 +297,8 @@ speculation-threshold = 1
 pre-normalization = true
 # enable MaxDataPoints optimization (experimental)
 mdp-optimization = false
+# output query headers in logs
+log-headers = false
 ```
 
 ## metric data inputs ##

metrictank-sample.ini

@@ -252,6 +252,8 @@ speculation-threshold = 1
 pre-normalization = true
 # enable MaxDataPoints optimization (experimental)
 mdp-optimization = false
+# output query headers in logs
+log-headers = false
 
 ## metric data inputs ##
 

scripts/config/metrictank-docker.ini

@@ -248,6 +248,8 @@ speculation-threshold = 1
 pre-normalization = true
 # enable MaxDataPoints optimization (experimental)
 mdp-optimization = false
+# output query headers in logs
+log-headers = false
 
 ## metric data inputs ##
 

scripts/config/metrictank-package.ini

@@ -248,6 +248,8 @@ speculation-threshold = 1
 pre-normalization = true
 # enable MaxDataPoints optimization (experimental)
 mdp-optimization = false
+# output query headers in logs
+log-headers = false
 
 ## metric data inputs ##