Improving the request logging (#8)

app.go

@@ -3,6 +3,7 @@ package xecho
 import (
 	"fmt"
 	"net/http"
+	"time"
 
 	"github.com/labstack/echo"
 	"github.com/newrelic/go-agent"
@@ -60,7 +61,7 @@ func Echo(conf Config) *echo.Echo {
 	if conf.UseDefaultHeaders {
 		e.Use(DefaultHeadersMiddleware())
 	}
-	e.Use(RequestLoggerMiddleware())
+	e.Use(RequestLoggerMiddleware(time.Now))
 	e.Use(DebugLoggerMiddleware(conf.IsDebug))
 	e.Use(ErrorHandlerMiddleware(conf.ErrorHandler))
 

context.go

@@ -2,11 +2,12 @@ package xecho
 
 import (
 	"errors"
+	"net/http"
+
 	"github.com/google/uuid"
 	"github.com/labstack/echo"
 	"github.com/newrelic/go-agent"
 	"github.com/sirupsen/logrus"
-	"net/http"
 )
 
 const correlationIDHeaderName = "Correlation-Id"

logging.go

@@ -13,23 +13,6 @@ import (
 	"github.com/sirupsen/logrus"
 )
 
-func RequestLoggerMiddleware() echo.MiddlewareFunc {
-	return func(next echo.HandlerFunc) echo.HandlerFunc {
-		return EchoHandler(func(c *Context) error {
-			lrw := &statefulResponseWriter{w: c.Response().Writer}
-			c.Response().Writer = lrw
-
-			c.Logger()
-
-			c.Logger().Infof("Inbound request on path: '%s'", c.Request().URL.Path)
-			err := next(c)
-			c.Logger().Infof("Response with code: '%d'", lrw.statusCode)
-
-			return err
-		})
-	}
-}
-
 func DebugLoggerMiddleware(isDebug bool) echo.MiddlewareFunc {
 	return func(next echo.HandlerFunc) echo.HandlerFunc {
 		return EchoHandler(func(c *Context) error {
@@ -101,7 +84,7 @@ func appScopeLogger(
 	buildVersion string,
 ) *Logger {
 	entry := logger.WithFields(logrus.Fields{
-		"app":           appName,
+		"application":   appName,
 		"env":           envName,
 		"build_version": buildVersion,
 		"scope":         "app",
@@ -120,23 +103,16 @@ func requestScopeLogger(
 	buildVersion string,
 ) *Logger {
 	ctxLogger := logger.WithFields(logrus.Fields{
-		"app":            appName,
+		"application":    appName,
 		"env":            envName,
 		"build_version":  buildVersion,
 		"scope":          "request",
 		"correlation_id": correlationID,
-		"url":            r.RequestURI,
-		"route":          route,
+		"url":            r.URL.String(),
+		"path":           route,
 		"remote_addr":    r.RemoteAddr,
 		"method":         r.Method,
 		"ip":             ip,
-		"headers": logrus.Fields{
-			"host":              r.Host,
-			"user-agent":        r.UserAgent(),
-			"referer":           r.Referer(),
-			"x-forwarded-for":   r.Header.Get("X-Forwarded-For"),
-			"x-forwarded-proto": r.Header.Get("X-Forwarded-Proto"),
-		},
 	})
 	return &Logger{ctxLogger}
 }

request_logger.go

@@ -0,0 +1,76 @@
+package xecho
+
+import (
+	"math"
+	"net/http"
+	"time"
+
+	"github.com/labstack/echo"
+	"github.com/sirupsen/logrus"
+)
+
+type TimeProvider func() time.Time
+
+func RequestLoggerMiddleware(timeFn TimeProvider) echo.MiddlewareFunc {
+	return func(next echo.HandlerFunc) echo.HandlerFunc {
+		return EchoHandler(func(c *Context) error { return RequestLogger(c, next, timeFn) })
+	}
+}
+
+func RequestLogger(c *Context, next echo.HandlerFunc, time TimeProvider) error {
+	before := time()
+	lrw := &statefulResponseWriter{ResponseWriter: c.Response().Writer}
+	c.Response().Writer = lrw
+	err := next(c)
+	after := time()
+	logger, ok := c.Logger().(*Logger)
+	if !ok {
+		c.Logger().Infof("[%s] %s %d", c.Request().Method, c.Path(), lrw.statusCode)
+		return err
+	}
+	logger.
+		WithFields(createMap(c, after.Sub(before), lrw, err)).
+		Infof("[%s] %s %d", c.Request().Method, c.Path(), lrw.statusCode)
+	return err
+}
+
+func createMap(c echo.Context, timeTaken time.Duration, lrw *statefulResponseWriter, err error) logrus.Fields {
+	r := c.Request()
+	fields := logrus.Fields{
+		"duration_ms": milliseconds(timeTaken),
+		"request":     requestMap(r, c),
+		"response":    responseMap(c.Response(), lrw.statusCode),
+	}
+
+	if err != nil {
+		fields["error"] = err.Error()
+	}
+
+	return fields
+}
+
+func milliseconds(timeTaken time.Duration) int64 {
+	return int64(timeTaken) / 1e6
+}
+
+func responseMap(r *echo.Response, statusCode int) logrus.Fields {
+	return logrus.Fields{
+		"status_code":    statusCode,
+		"content_length": math.Max(float64(r.Size), 0),
+	}
+}
+
+func requestMap(r *http.Request, c echo.Context) logrus.Fields {
+	return logrus.Fields{
+		"method":         r.Method,
+		"host_name":      r.Host,
+		"query_params":   c.QueryParams(),
+		"Content-length": math.Max(float64(r.ContentLength), 0),
+		"headers": logrus.Fields{
+			"user-agent":        r.UserAgent(),
+			"referer":           r.Referer(),
+			"x-forwarded-for":   r.Header.Get("X-Forwarded-For"),
+			"x-forwarded-proto": r.Header.Get("X-Forwarded-Proto"),
+		},
+	}
+}

request_logger_test.go

@@ -0,0 +1,141 @@
+package xecho
+
+import (
+	"bytes"
+	"encoding/json"
+	"net/http"
+	"net/url"
+	"testing"
+	"time"
+
+	"github.com/labstack/echo"
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/assert"
+)
+
+var _ TimeProvider = (&testTimeProvider{}).Next
+
+type testTimeProvider struct {
+	index int
+	calls []time.Time
+}
+
+func (t *testTimeProvider) Next() time.Time {
+	i := t.index
+	t.index++
+	return t.calls[i]
+}
+
+type testContext struct {
+	Context
+	response    *echo.Response
+	queryParams url.Values
+	request     *http.Request
+}
+
+var _ echo.Context = &testContext{}
+
+func (t *testContext) Response() *echo.Response {
+	return t.response
+}
+
+func (t *testContext) Request() *http.Request {
+	return t.request
+}
+
+func (t *testContext) Path() string {
+	return t.request.URL.Path
+}
+
+func (t *testContext) QueryParams() url.Values {
+	return t.queryParams
+}
+
+const urlTo = "https://this.is.a.domain/this/is/the/site?aparam=aValue&aparam2:avalue2"
+
+func TestRequestLogger_LogTest(t *testing.T) {
+	buffer := &bytes.Buffer{}
+	URL, _ := url.Parse(urlTo)
+	writer, _ := NewWriter()
+	context := createTestContext(writer, URL, buffer)
+	now := time.Now()
+	provider := testTimeProvider{calls: []time.Time{now, now.Add(755 * time.Millisecond)}}
+	nextCalled := false
+	nextPtr := &nextCalled
+	var next echo.HandlerFunc = func(context echo.Context) error {
+		*nextPtr = true
+		context.Response().WriteHeader(200)
+		return nil
+	}
+	err := RequestLoggerMiddleware(provider.Next)(next)(context)
+	assert.Nil(t, err)
+	fields := getLogFields(buffer, err, t)
+
+	assert.Equal(t, "[GET] /this/is/the/site 200", fields["msg"])
+	assert.Equal(t, "set_one", fields["correlation_id"])
+	assert.Equal(t, "request", fields["scope"])
+	assert.Equal(t, float64(755), fields["duration_ms"])
+
+	request, ok := fields["request"].(map[string]interface{})
+	assert.True(t, ok)
+	assert.Equal(t, "this.is.a.domain", request["host_name"])
+	assert.Equal(t, "GET", request["method"])
+	//assert.Equal(t, []interface{}{"ONE", "ONE", "TWO"}, request["cookies"])
+
+	response, ok := fields["response"].(map[string]interface{})
+	assert.True(t, ok)
+	assert.Equal(t, float64(200), response["status_code"])
+	assert.Equal(t, float64(150), response["content_length"])
+
+}
+
+func createTestContext(writer *responseWriter, URL *url.URL, buffer *bytes.Buffer) *Context {
+	return &Context{
+		Context: &testContext{
+			queryParams: url.Values{
+				"aparam":  []string{"aValue"},
+				"aparam2": []string{"avalue2"},
+			},
+			response: createResponse(writer),
+			request:  createRequest(URL),
+		},
+		logger: &Logger{Entry: createLogger(buffer).
+			WithField("correlation_id", "set_one").
+			WithField("scope", "request")},
+	}
+}
+
+func createResponse(writer *responseWriter) *echo.Response {
+	return &echo.Response{
+		Writer: writer,
+		Status: 200,
+		Size:   150,
+	}
+}
+
+func createRequest(URL *url.URL) *http.Request {
+	return &http.Request{
+		Method:        "GET",
+		URL:           URL,
+		Header:        http.Header{"Correlation-Id": []string{"set_one"}},
+		ContentLength: 34567,
+		Host:          "this.is.a.domain",
+		RemoteAddr:    "",
+		RequestURI:    urlTo,
+	}
+}
+
+func getLogFields(buffer *bytes.Buffer, err error, t *testing.T) logrus.Fields {
+	fields := logrus.Fields{}
+	logStatement := buffer.Bytes()
+	err = json.Unmarshal(logStatement, &fields)
+	assert.Nil(t, err)
+	return fields
+}
+
+func createLogger(buffer *bytes.Buffer) *logrus.Logger {
+	log := logrus.New()
+	log.Out = buffer
+	log.Formatter = &logrus.JSONFormatter{}
+	return log
+}

stateful_response_writer.go

@@ -3,19 +3,11 @@ package xecho
 import "net/http"
 
 type statefulResponseWriter struct {
-	w          http.ResponseWriter
+	http.ResponseWriter
 	statusCode int
 }
 
-func (lrw *statefulResponseWriter) Header() http.Header {
-	return lrw.w.Header()
-}
-
-func (lrw *statefulResponseWriter) Write(b []byte) (int, error) {
-	return lrw.w.Write(b)
-}
-
 func (lrw *statefulResponseWriter) WriteHeader(code int) {
+	lrw.ResponseWriter.WriteHeader(code)
 	lrw.statusCode = code
-	lrw.w.WriteHeader(code)
 }

stateful_response_writer_test.go

@@ -0,0 +1,65 @@
+package xecho
+
+import (
+	"net/http"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+)
+
+type responseWriter struct {
+	called map[string]int
+	status int
+}
+
+func (r responseWriter) Header() http.Header {
+	r.incCall("Header")
+
+	return http.Header{}
+}
+
+func (r *responseWriter) incCall(methodName string) {
+	if val, ok := r.called[methodName]; ok {
+		r.called[methodName] = val + 1
+	} else {
+		r.called[methodName] = 1
+	}
+}
+
+func (r *responseWriter) Write([]byte) (int, error) {
+	r.incCall("Write")
+	return 0, nil
+}
+
+func (r *responseWriter) WriteHeader(statusCode int) {
+	r.incCall("WriteHeader")
+	r.status = statusCode
+}
+
+func NewWriter() (*responseWriter, *statefulResponseWriter) {
+	response := responseWriter{called: map[string]int{}}
+	writer := statefulResponseWriter{ResponseWriter: &response}
+	return &response, &writer
+}
+
+var _ http.ResponseWriter = &responseWriter{}
+
+func TestStatefulResponseWriter_WriteHeaderTest(t *testing.T) {
+	response, writer := NewWriter()
+	writer.WriteHeader(505)
+	assert.Equal(t, response.called["WriteHeader"], 1)
+	assert.Equal(t, writer.statusCode, 505)
+	assert.Equal(t, response.status, 505)
+}
+
+func TestStatefulResponseWriter_WriteTest(t *testing.T) {
+	response, writer := NewWriter()
+	_, _ = writer.Write([]byte{})
+	assert.Equal(t, response.called["Write"], 1)
+}
+
+func TestStatefulResponseWriter_HeaderTest(t *testing.T) {
+	response, writer := NewWriter()
+	writer.Header()
+	assert.Equal(t, response.called["Header"], 1)
+}