Prometheus middleware should not call c.Error() as it causes double error logging.

Handle status code properly when next returns an error

Author: aldas

prometheus/prometheus.go

@@ -22,6 +22,7 @@ package prometheus
 
 import (
 	"bytes"
+	"errors"
 	"net/http"
 	"os"
 	"strconv"
@@ -364,7 +365,7 @@ func (p *Prometheus) Use(e *echo.Echo) {
 
 // HandlerFunc defines handler function for middleware
 func (p *Prometheus) HandlerFunc(next echo.HandlerFunc) echo.HandlerFunc {
-	return func(c echo.Context) (err error) {
+	return func(c echo.Context) error {
 		if c.Path() == p.MetricsPath {
 			return next(c)
 		}
@@ -375,18 +376,22 @@ func (p *Prometheus) HandlerFunc(next echo.HandlerFunc) echo.HandlerFunc {
 		start := time.Now()
 		reqSz := computeApproximateRequestSize(c.Request())
 
-		if err = next(c); err != nil {
-			c.Error(err)
-		}
+		err := next(c)
 
-		status := strconv.Itoa(c.Response().Status)
-		url := p.RequestCounterURLLabelMappingFunc(c)
+		status := c.Response().Status
+		if err != nil {
+			var httpError *echo.HTTPError
+			if errors.As(err, &httpError) {
+				status = httpError.Code
+			}
+			if status == 0 || status == http.StatusOK {
+				status = http.StatusInternalServerError
+			}
+		}
 
 		elapsed := float64(time.Since(start)) / float64(time.Second)
-		resSz := float64(c.Response().Size)
-
-		p.reqDur.WithLabelValues(status, c.Request().Method, url).Observe(elapsed)
 
+		url := p.RequestCounterURLLabelMappingFunc(c)
 		if len(p.URLLabelFromContext) > 0 {
 			u := c.Get(p.URLLabelFromContext)
 			if u == nil {
@@ -395,11 +400,15 @@ func (p *Prometheus) HandlerFunc(next echo.HandlerFunc) echo.HandlerFunc {
 			url = u.(string)
 		}
 
-		p.reqCnt.WithLabelValues(status, c.Request().Method, p.RequestCounterHostLabelMappingFunc(c), url).Inc()
-		p.reqSz.WithLabelValues(status, c.Request().Method, url).Observe(float64(reqSz))
-		p.resSz.WithLabelValues(status, c.Request().Method, url).Observe(resSz)
+		statusStr := strconv.Itoa(status)
+		p.reqDur.WithLabelValues(statusStr, c.Request().Method, url).Observe(elapsed)
+		p.reqCnt.WithLabelValues(statusStr, c.Request().Method, p.RequestCounterHostLabelMappingFunc(c), url).Inc()
+		p.reqSz.WithLabelValues(statusStr, c.Request().Method, url).Observe(float64(reqSz))
+
+		resSz := float64(c.Response().Size)
+		p.resSz.WithLabelValues(statusStr, c.Request().Method, url).Observe(resSz)
 
-		return
+		return err
 	}
 }
 

prometheus/prometheus_test.go

@@ -134,3 +134,37 @@ func TestMetricsPushGateway(t *testing.T) {
 	})
 	unregister(p)
 }
+
+func TestMetricsForErrors(t *testing.T) {
+	e := echo.New()
+	p := NewPrometheus("echo", nil)
+	p.Use(e)
+
+	e.GET("/handler_for_ok", func(c echo.Context) error {
+		return c.JSON(http.StatusOK, "OK")
+	})
+	e.GET("/handler_for_nok", func(c echo.Context) error {
+		return c.JSON(http.StatusConflict, "NOK")
+	})
+	e.GET("/handler_for_error", func(c echo.Context) error {
+		return echo.NewHTTPError(http.StatusBadGateway, "BAD")
+	})
+
+	g := gofight.New()
+	g.GET("/handler_for_ok").Run(e, func(r gofight.HTTPResponse, rq gofight.HTTPRequest) { assert.Equal(t, http.StatusOK, r.Code) })
+
+	g.GET("/handler_for_nok").Run(e, func(r gofight.HTTPResponse, rq gofight.HTTPRequest) { assert.Equal(t, http.StatusConflict, r.Code) })
+	g.GET("/handler_for_nok").Run(e, func(r gofight.HTTPResponse, rq gofight.HTTPRequest) { assert.Equal(t, http.StatusConflict, r.Code) })
+
+	g.GET("/handler_for_error").Run(e, func(r gofight.HTTPResponse, rq gofight.HTTPRequest) { assert.Equal(t, http.StatusBadGateway, r.Code) })
+
+	g.GET(p.MetricsPath).Run(e, func(r gofight.HTTPResponse, rq gofight.HTTPRequest) {
+		assert.Equal(t, http.StatusOK, r.Code)
+		body := r.Body.String()
+		assert.Contains(t, body, fmt.Sprintf("%s_requests_total", p.Subsystem))
+		assert.Contains(t, body, `echo_requests_total{code="200",host="",method="GET",url="/handler_for_ok"} 1`)
+		assert.Contains(t, body, `echo_requests_total{code="409",host="",method="GET",url="/handler_for_nok"} 2`)
+		assert.Contains(t, body, `echo_requests_total{code="502",host="",method="GET",url="/handler_for_error"} 1`)
+	})
+	unregister(p)
+}