pkg/web: closure-style middlewares (#51238)

* pkg/web: closure-style middlewares

Switches the middleware execution model from web.Handlers in a slice to
web.Middleware.
Middlewares are temporarily kept in a slice to preserve ordering, but
prior to execution they are applied, forming a giant call-stack, giving
granular control over the execution flow.

* pkg/middleware: adapt to web.Middleware

* pkg/middleware/recovery: use c.Req over req

c.Req gets updated by future handlers, while req stays static.

The current recovery implementation needs this newer information

* pkg/web: correct middleware ordering

* pkg/webtest: adapt middleware

* pkg/web/hack: set w and r onto web.Context

By adopting std middlewares, it may happen they invoke next(w,r) without
putting their modified w,r into the web.Context, leading old-style
handlers to operate on outdated fields.

pkg/web now takes care of this

* pkg/middleware: selectively use future context

* pkg/web: accept closure-style on Use()

* webtest: Middleware testing

adds a utility function to web/webtest to obtain a http.ResponseWriter,
http.Request and http.Handler the same as a middleware that runs would receive

* *: cleanup

* pkg/web: don't wrap Middleware from Router

* pkg/web: require chain to write response

* *: remove temp files

* webtest: don't require chain write

* *: cleanup

pkg/middleware/logger.go

@@ -27,50 +27,52 @@ import (
 	"github.com/grafana/grafana/pkg/web"
 )
 
-func Logger(cfg *setting.Cfg) web.Handler {
-	return func(res http.ResponseWriter, req *http.Request, c *web.Context) {
-		start := time.Now()
+func Logger(cfg *setting.Cfg) web.Middleware {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			start := time.Now()
 
-		rw := res.(web.ResponseWriter)
-		c.Next()
+			rw := web.Rw(w, r)
+			next.ServeHTTP(rw, r)
 
-		timeTaken := time.Since(start) / time.Millisecond
-		duration := time.Since(start).String()
-		ctx := contexthandler.FromContext(c.Req.Context())
-		if ctx != nil && ctx.PerfmonTimer != nil {
-			ctx.PerfmonTimer.Observe(float64(timeTaken))
-		}
-
-		status := rw.Status()
-		if status == 200 || status == 304 {
-			if !cfg.RouterLogging {
-				return
-			}
-		}
-
-		if ctx != nil {
-			logParams := []interface{}{
-				"method", req.Method,
-				"path", req.URL.Path,
-				"status", status,
-				"remote_addr", c.RemoteAddr(),
-				"time_ms", int64(timeTaken),
-				"duration", duration,
-				"size", rw.Size(),
-				"referer", SanitizeURL(ctx, req.Referer()),
+			timeTaken := time.Since(start) / time.Millisecond
+			duration := time.Since(start).String()
+			ctx := contexthandler.FromContext(r.Context())
+			if ctx != nil && ctx.PerfmonTimer != nil {
+				ctx.PerfmonTimer.Observe(float64(timeTaken))
 			}
 
-			traceID := tracing.TraceIDFromContext(ctx.Req.Context(), false)
-			if traceID != "" {
-				logParams = append(logParams, "traceID", traceID)
+			status := rw.Status()
+			if status == 200 || status == 304 {
+				if !cfg.RouterLogging {
+					return
+				}
 			}
 
-			if status >= 500 {
-				ctx.Logger.Error("Request Completed", logParams...)
-			} else {
-				ctx.Logger.Info("Request Completed", logParams...)
+			if ctx != nil {
+				logParams := []interface{}{
+					"method", r.Method,
+					"path", r.URL.Path,
+					"status", status,
+					"remote_addr", ctx.RemoteAddr(),
+					"time_ms", int64(timeTaken),
+					"duration", duration,
+					"size", rw.Size(),
+					"referer", SanitizeURL(ctx, r.Referer()),
+				}
+
+				traceID := tracing.TraceIDFromContext(ctx.Req.Context(), false)
+				if traceID != "" {
+					logParams = append(logParams, "traceID", traceID)
+				}
+
+				if status >= 500 {
+					ctx.Logger.Error("Request Completed", logParams...)
+				} else {
+					ctx.Logger.Info("Request Completed", logParams...)
+				}
 			}
-		}
+		})
 	}
 }
 

pkg/middleware/middleware_test.go

@@ -647,6 +647,9 @@ func middlewareScenario(t *testing.T, desc string, fn scenarioFunc, cbs ...func(
 			sc.context = c
 			if sc.handlerFunc != nil {
 				sc.handlerFunc(sc.context)
+				if !c.Resp.Written() {
+					c.Resp.WriteHeader(http.StatusOK)
+				}
 			} else {
 				t.Log("Returning JSON OK")
 				resp := make(map[string]interface{})

pkg/middleware/recovery.go

@@ -102,69 +102,73 @@ func function(pc uintptr) []byte {
 
 // Recovery returns a middleware that recovers from any panics and writes a 500 if there was one.
 // While Martini is in development mode, Recovery will also output the panic as HTML.
-func Recovery(cfg *setting.Cfg) web.Handler {
-	return func(c *web.Context) {
-		defer func() {
-			if r := recover(); r != nil {
-				var panicLogger log.Logger
-				panicLogger = log.New("recovery")
-				// try to get request logger
-				ctx := contexthandler.FromContext(c.Req.Context())
-				if ctx != nil {
-					panicLogger = ctx.Logger
-				}
+func Recovery(cfg *setting.Cfg) web.Middleware {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+			c := web.FromContext(req.Context())
 
-				if err, ok := r.(error); ok {
-					// http.ErrAbortHandler is suppressed by default in the http package
-					// and used as a signal for aborting requests. Suppresses stacktrace
-					// since it doesn't add any important information.
-					if errors.Is(err, http.ErrAbortHandler) {
-						panicLogger.Error("Request error", "error", err)
+			defer func() {
+				if r := recover(); r != nil {
+					var panicLogger log.Logger
+					panicLogger = log.New("recovery")
+					// try to get request logger
+					ctx := contexthandler.FromContext(c.Req.Context())
+					if ctx != nil {
+						panicLogger = ctx.Logger
+					}
+
+					if err, ok := r.(error); ok {
+						// http.ErrAbortHandler is suppressed by default in the http package
+						// and used as a signal for aborting requests. Suppresses stacktrace
+						// since it doesn't add any important information.
+						if errors.Is(err, http.ErrAbortHandler) {
+							panicLogger.Error("Request error", "error", err)
+							return
+						}
+					}
+
+					stack := stack(3)
+					panicLogger.Error("Request error", "error", r, "stack", string(stack))
+
+					// if response has already been written, skip.
+					if c.Resp.Written() {
 						return
 					}
-				}
 
-				stack := stack(3)
-				panicLogger.Error("Request error", "error", r, "stack", string(stack))
+					data := struct {
+						Title     string
+						AppTitle  string
+						AppSubUrl string
+						Theme     string
+						ErrorMsg  string
+					}{"Server Error", "Grafana", cfg.AppSubURL, cfg.DefaultTheme, ""}
 
-				// if response has already been written, skip.
-				if c.Resp.Written() {
-					return
-				}
+					if setting.Env == setting.Dev {
+						if err, ok := r.(error); ok {
+							data.Title = err.Error()
+						}
 
-				data := struct {
-					Title     string
-					AppTitle  string
-					AppSubUrl string
-					Theme     string
-					ErrorMsg  string
-				}{"Server Error", "Grafana", cfg.AppSubURL, cfg.DefaultTheme, ""}
-
-				if setting.Env == setting.Dev {
-					if err, ok := r.(error); ok {
-						data.Title = err.Error()
+						data.ErrorMsg = string(stack)
 					}
 
-					data.ErrorMsg = string(stack)
-				}
+					if ctx != nil && ctx.IsApiRequest() {
+						resp := make(map[string]interface{})
+						resp["message"] = "Internal Server Error - Check the Grafana server logs for the detailed error message."
 
-				if ctx != nil && ctx.IsApiRequest() {
-					resp := make(map[string]interface{})
-					resp["message"] = "Internal Server Error - Check the Grafana server logs for the detailed error message."
+						if data.ErrorMsg != "" {
+							resp["error"] = fmt.Sprintf("%v - %v", data.Title, data.ErrorMsg)
+						} else {
+							resp["error"] = data.Title
+						}
 
-					if data.ErrorMsg != "" {
-						resp["error"] = fmt.Sprintf("%v - %v", data.Title, data.ErrorMsg)
+						ctx.JSON(500, resp)
 					} else {
-						resp["error"] = data.Title
+						ctx.HTML(500, cfg.ErrTemplateName, data)
 					}
-
-					c.JSON(500, resp)
-				} else {
-					c.HTML(500, cfg.ErrTemplateName, data)
 				}
-			}
-		}()
+			}()
 
-		c.Next()
+			next.ServeHTTP(w, req)
+		})
 	}
 }

pkg/middleware/recovery_test.go

@@ -59,7 +59,7 @@ func recoveryScenario(t *testing.T, desc string, url string, fn scenarioFunc) {
 		require.NoError(t, err)
 
 		sc.m = web.New()
-		sc.m.Use(Recovery(cfg))
+		sc.m.UseMiddleware(Recovery(cfg))
 
 		sc.m.Use(AddDefaultResponseHeaders(cfg))
 		sc.m.UseMiddleware(web.Renderer(viewsPath, "[[", "]]"))

pkg/middleware/request_metrics.go

@@ -46,57 +46,60 @@ func init() {
 }
 
 // RequestMetrics is a middleware handler that instruments the request.
-func RequestMetrics(features featuremgmt.FeatureToggles) web.Handler {
+func RequestMetrics(features featuremgmt.FeatureToggles) web.Middleware {
 	log := log.New("middleware.request-metrics")
 
-	return func(res http.ResponseWriter, req *http.Request, c *web.Context) {
-		rw := res.(web.ResponseWriter)
-		now := time.Now()
-		httpRequestsInFlight.Inc()
-		defer httpRequestsInFlight.Dec()
-		c.Next()
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			rw := web.Rw(w, r)
+			now := time.Now()
+			httpRequestsInFlight.Inc()
+			defer httpRequestsInFlight.Dec()
+			next.ServeHTTP(w, r)
 
-		status := rw.Status()
-		code := sanitizeCode(status)
+			status := rw.Status()
+			code := sanitizeCode(status)
 
-		handler := "unknown"
-		if routeOperation, exists := routeOperationName(c.Req); exists {
-			handler = routeOperation
-		} else {
-			// if grafana does not recognize the handler and returns 404 we should register it as `notfound`
-			if status == http.StatusNotFound {
-				handler = "notfound"
+			handler := "unknown"
+			// TODO: do not depend on web.Context from the future
+			if routeOperation, exists := routeOperationName(web.FromContext(r.Context()).Req); exists {
+				handler = routeOperation
 			} else {
-				// log requests where we could not identify handler so we can register them.
-				if features.IsEnabled(featuremgmt.FlagLogRequestsInstrumentedAsUnknown) {
-					log.Warn("request instrumented as unknown", "path", c.Req.URL.Path, "status_code", status)
+				// if grafana does not recognize the handler and returns 404 we should register it as `notfound`
+				if status == http.StatusNotFound {
+					handler = "notfound"
+				} else {
+					// log requests where we could not identify handler so we can register them.
+					if features.IsEnabled(featuremgmt.FlagLogRequestsInstrumentedAsUnknown) {
+						log.Warn("request instrumented as unknown", "path", r.URL.Path, "status_code", status)
+					}
 				}
 			}
-		}
 
-		// avoiding the sanitize functions for in the new instrumentation
-		// since they dont make much sense. We should remove them later.
-		histogram := httpRequestDurationHistogram.
-			WithLabelValues(handler, code, req.Method)
-		if traceID := tracing.TraceIDFromContext(c.Req.Context(), true); traceID != "" {
-			// Need to type-convert the Observer to an
-			// ExemplarObserver. This will always work for a
-			// HistogramVec.
-			histogram.(prometheus.ExemplarObserver).ObserveWithExemplar(
-				time.Since(now).Seconds(), prometheus.Labels{"traceID": traceID},
-			)
-			return
-		}
-		histogram.Observe(time.Since(now).Seconds())
+			// avoiding the sanitize functions for in the new instrumentation
+			// since they dont make much sense. We should remove them later.
+			histogram := httpRequestDurationHistogram.
+				WithLabelValues(handler, code, r.Method)
+			if traceID := tracing.TraceIDFromContext(r.Context(), true); traceID != "" {
+				// Need to type-convert the Observer to an
+				// ExemplarObserver. This will always work for a
+				// HistogramVec.
+				histogram.(prometheus.ExemplarObserver).ObserveWithExemplar(
+					time.Since(now).Seconds(), prometheus.Labels{"traceID": traceID},
+				)
+				return
+			}
+			histogram.Observe(time.Since(now).Seconds())
 
-		switch {
-		case strings.HasPrefix(req.RequestURI, "/api/datasources/proxy"):
-			countProxyRequests(status)
-		case strings.HasPrefix(req.RequestURI, "/api/"):
-			countApiRequests(status)
-		default:
-			countPageRequests(status)
-		}
+			switch {
+			case strings.HasPrefix(r.RequestURI, "/api/datasources/proxy"):
+				countProxyRequests(status)
+			case strings.HasPrefix(r.RequestURI, "/api/"):
+				countApiRequests(status)
+			default:
+				countPageRequests(status)
+			}
+		})
 	}
 }
 

pkg/middleware/request_tracing.go

@@ -61,37 +61,38 @@ func routeOperationName(req *http.Request) (string, bool) {
 	return "", false
 }
 
-func RequestTracing(tracer tracing.Tracer) web.Handler {
-	return func(res http.ResponseWriter, req *http.Request, c *web.Context) {
-		if strings.HasPrefix(c.Req.URL.Path, "/public/") ||
-			c.Req.URL.Path == "/robots.txt" ||
-			c.Req.URL.Path == "/favicon.ico" {
-			c.Next()
-			return
-		}
+func RequestTracing(tracer tracing.Tracer) web.Middleware {
+	return func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+			if strings.HasPrefix(req.URL.Path, "/public/") || req.URL.Path == "/robots.txt" || req.URL.Path == "/favicon.ico" {
+				next.ServeHTTP(w, req)
+				return
+			}
 
-		rw := res.(web.ResponseWriter)
+			rw := web.Rw(w, req)
 
-		wireContext := otel.GetTextMapPropagator().Extract(req.Context(), propagation.HeaderCarrier(req.Header))
-		ctx, span := tracer.Start(req.Context(), fmt.Sprintf("HTTP %s %s", req.Method, req.URL.Path), trace.WithLinks(trace.LinkFromContext(wireContext)))
+			wireContext := otel.GetTextMapPropagator().Extract(req.Context(), propagation.HeaderCarrier(req.Header))
+			ctx, span := tracer.Start(req.Context(), fmt.Sprintf("HTTP %s %s", req.Method, req.URL.Path), trace.WithLinks(trace.LinkFromContext(wireContext)))
 
-		c.Req = req.WithContext(ctx)
-		c.Next()
+			req = req.WithContext(ctx)
+			next.ServeHTTP(w, req)
 
-		// Only call span.Finish when a route operation name have been set,
-		// meaning that not set the span would not be reported.
-		if routeOperation, exists := routeOperationName(c.Req); exists {
-			defer span.End()
-			span.SetName(fmt.Sprintf("HTTP %s %s", req.Method, routeOperation))
-		}
+			// Only call span.Finish when a route operation name have been set,
+			// meaning that not set the span would not be reported.
+			// TODO: do not depend on web.Context from the future
+			if routeOperation, exists := routeOperationName(web.FromContext(req.Context()).Req); exists {
+				defer span.End()
+				span.SetName(fmt.Sprintf("HTTP %s %s", req.Method, routeOperation))
+			}
 
-		status := rw.Status()
+			status := rw.Status()
 
-		span.SetAttributes("http.status_code", status, attribute.Int("http.status_code", status))
-		span.SetAttributes("http.url", req.RequestURI, attribute.String("http.url", req.RequestURI))
-		span.SetAttributes("http.method", req.Method, attribute.String("http.method", req.Method))
-		if status >= 400 {
-			span.SetStatus(codes.Error, fmt.Sprintf("error with HTTP status code %s", strconv.Itoa(status)))
-		}
+			span.SetAttributes("http.status_code", status, attribute.Int("http.status_code", status))
+			span.SetAttributes("http.url", req.RequestURI, attribute.String("http.url", req.RequestURI))
+			span.SetAttributes("http.method", req.Method, attribute.String("http.method", req.Method))
+			if status >= 400 {
+				span.SetStatus(codes.Error, fmt.Sprintf("error with HTTP status code %s", strconv.Itoa(status)))
+			}
+		})
 	}
 }