Add request latency log escalation (#31)

* Add request latency log escalation

This adds the ability to specify a duration and a log level
within the config.  If a given request takes longer than the specified
duration, it will be logged at this new level.

* Update readme for new config options

* Add test

* split test into two

README.md

@@ -116,8 +116,19 @@ func main() {
 	return c.String(http.StatusOK, "Hello, World!")
     })
 }
+
+```
+
+### Escalate log level for slow requests:
+```go
+e.Use(lecho.Middleware(lecho.Config{
+    Logger: logger,
+    RequestLatencyLevel: zerolog.WarnLevel,
+    RequestLatencyLimit: 500 * time.Millisecond,
+}))
 ```
 
+
 ### Nesting under a sub dictionary
 
 ```go

middleware.go

@@ -31,6 +31,10 @@ type (
 		NestKey string
 		// HandleError indicates whether to propagate errors up the middleware chain, so the global error handler can decide appropriate status code.
 		HandleError bool
+		// For long-running requests that take longer than this limit, log at a different level.  Ignored by default
+		RequestLatencyLimit time.Duration
+		// The level to log at if RequestLatencyLimit is exceeded
+		RequestLatencyLevel zerolog.Level
 	}
 
 	// Enricher is a function that can be used to enrich the logger with additional information.
@@ -126,10 +130,12 @@ func Middleware(config Config) echo.MiddlewareFunc {
 			}
 
 			stop := time.Now()
-
+			latency := stop.Sub(start)
 			var mainEvt *zerolog.Event
 			if err != nil {
 				mainEvt = logger.log.Err(err)
+			} else if config.RequestLatencyLimit != 0 && latency > config.RequestLatencyLimit {
+				mainEvt = logger.log.WithLevel(config.RequestLatencyLevel)
 			} else {
 				mainEvt = logger.log.WithLevel(logger.log.GetLevel())
 			}
@@ -148,8 +154,8 @@ func Middleware(config Config) echo.MiddlewareFunc {
 			evt.Str("user_agent", req.UserAgent())
 			evt.Int("status", res.Status)
 			evt.Str("referer", req.Referer())
-			evt.Dur("latency", stop.Sub(start))
-			evt.Str("latency_human", stop.Sub(start).String())
+			evt.Dur("latency", latency)
+			evt.Str("latency_human", latency.String())
 
 			cl := req.Header.Get(echo.HeaderContentLength)
 			if cl == "" {

middleware_test.go

@@ -6,8 +6,10 @@ import (
 	"net/http"
 	"net/http/httptest"
 	"testing"
+	"time"
 
 	"github.com/labstack/echo/v4"
+	"github.com/labstack/gommon/log"
 	"github.com/rs/zerolog"
 	"github.com/stretchr/testify/assert"
 	"github.com/ziflex/lecho/v3"
@@ -97,4 +99,66 @@ func TestMiddleware(t *testing.T) {
 		str := b.String()
 		assert.Contains(t, str, `"test":"test"`)
 	})
+
+	t.Run("should escalate log level for slow requests", func(t *testing.T) {
+		e := echo.New()
+		req := httptest.NewRequest(http.MethodGet, "/", nil)
+		req.Header.Set(echo.HeaderContentType, echo.MIMEApplicationJSON)
+		rec := httptest.NewRecorder()
+		c := e.NewContext(req, rec)
+
+		b := &bytes.Buffer{}
+		l := lecho.New(b)
+		l.SetLevel(log.INFO)
+		m := lecho.Middleware(lecho.Config{
+			Logger:              l,
+			RequestLatencyLimit: 5 * time.Millisecond,
+			RequestLatencyLevel: zerolog.WarnLevel,
+		})
+
+		// Slow request should be logged at the escalated level
+		next := func(c echo.Context) error {
+			time.Sleep(5 * time.Millisecond)
+			return nil
+		}
+		handler := m(next)
+		err := handler(c)
+		assert.NoError(t, err, "should not return error")
+
+		str := b.String()
+		assert.Contains(t, str, `"level":"warn"`)
+		assert.NotContains(t, str, `"level":"info"`)
+	})
+
+	t.Run("shouldn't escalate log level for fast requests", func(t *testing.T) {
+		e := echo.New()
+		req := httptest.NewRequest(http.MethodGet, "/", nil)
+		req.Header.Set(echo.HeaderContentType, echo.MIMEApplicationJSON)
+		rec := httptest.NewRecorder()
+		c := e.NewContext(req, rec)
+
+		b := &bytes.Buffer{}
+		l := lecho.New(b)
+		l.SetLevel(log.INFO)
+		m := lecho.Middleware(lecho.Config{
+			Logger:              l,
+			RequestLatencyLimit: 5 * time.Millisecond,
+			RequestLatencyLevel: zerolog.WarnLevel,
+		})
+
+		// Fast request should be logged at the default level
+		next := func(c echo.Context) error {
+			time.Sleep(1 * time.Millisecond)
+			return nil
+		}
+
+		handler := m(next)
+		err := handler(c)
+
+		assert.NoError(t, err, "should not return error")
+
+		str := b.String()
+		assert.Contains(t, str, `"level":"info"`)
+		assert.NotContains(t, str, `"level":"warn"`)
+	})
 }