Fixes 4432: log request body for server errors (#773)

* Fixes 4432: log request body for server errors

* Fixes 4432: buffered reader, method filter

* Fixes 4432: cleanup

Author: dominikvagner

pkg/middleware/log_server_error_request.go

@@ -0,0 +1,83 @@
+package middleware
+
+import (
+	"bufio"
+	"errors"
+	"io"
+	"net/http"
+
+	ce "github.com/content-services/content-sources-backend/pkg/errors"
+	"github.com/labstack/echo/v4"
+)
+
+const BodyDumpLimit = 1000
+const BodyStoreKey = "body_backup"
+
+func LogServerErrorRequest(next echo.HandlerFunc) echo.HandlerFunc {
+	return func(c echo.Context) (err error) {
+		if c.Get(BodyStoreKey) == nil && isBodiedMethod(c.Request().Method) {
+			storeRequestBody(c)
+		}
+		if err = next(c); err != nil {
+			if containsServerError(err) && isBodiedMethod(c.Request().Method) {
+				logRequestBody(c)
+			}
+			return err
+		}
+		return nil
+	}
+}
+
+func containsServerError(err error) bool {
+	httpError := new(ce.ErrorResponse)
+	if errors.As(err, httpError) {
+		for _, e := range httpError.Errors {
+			if e.Status >= http.StatusInternalServerError {
+				return true
+			}
+		}
+	}
+	return false
+}
+
+func logRequestBody(c echo.Context) {
+	if body := c.Get(BodyStoreKey); body != nil {
+		storedBodyBytes, ok := body.([]byte)
+		if !ok {
+			c.Logger().Error("Error reading request body")
+		}
+		c.Logger().Errorf("Request body: %v", string(storedBodyBytes))
+	}
+}
+
+func storeRequestBody(c echo.Context) {
+	limit := BodyDumpLimit
+	buffered := BufferedReadCloser{bufio.NewReader(c.Request().Body), c.Request().Body}
+
+	bytes, err := buffered.Peek(BodyDumpLimit)
+	if errors.Is(err, io.EOF) {
+		limit = len(bytes)
+		err = nil
+	}
+	if errors.Is(err, bufio.ErrBufferFull) {
+		err = nil
+	}
+	if err != nil {
+		c.Logger().Error("Error reading request body")
+		return
+	}
+
+	c.Set(BodyStoreKey, bytes[:limit])
+	c.Request().Body = buffered
+}
+
+func isBodiedMethod(method string) bool {
+	switch method {
+	case http.MethodGet:
+		return false
+	case http.MethodDelete:
+		return false
+	default:
+		return true
+	}
+}

pkg/middleware/log_server_error_request_test.go

@@ -0,0 +1,119 @@
+package middleware
+
+import (
+	"bytes"
+	"encoding/json"
+	"fmt"
+	"io"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	ce "github.com/content-services/content-sources-backend/pkg/errors"
+	"github.com/labstack/echo/v4"
+	"github.com/stretchr/testify/assert"
+)
+
+const TestBody = `{"limit": 100, "search": "random", "uuids": ["e88efd75-2b29-4b59-8867-bb60435b3742"]}`
+const LargeBody = `{"limit": 100, "search": "Lorem ipsum dolor sit amet, consectetuer adipiscing elit. Integer pellentesque quam vel velit. Vivamus porttitor turpis ac leo. Ut tempus purus at lorem. Nullam justo enim, consectetuer nec, ullamcorper ac, vestibulum in, elit. Nulla pulvinar eleifend sem. Proin mattis lacinia justo. Integer malesuada. Etiam sapien elit, consequat eget, tristique non, venenatis quis, ante. Etiam dui sem, fermentum vitae, sagittis id, malesuada in, quam. Integer lacinia. Proin pede metus, vulputate nec, fermentum fringilla, vehicula vitae, justo. Curabitur bibendum justo non orci. Ut enim ad minima veniam, quis nostrum exercitationem ullam corporis suscipit laboriosam, nisi ut aliquid ex ea commodi consequatur? Etiam sapien elit, consequat eget, tristique non, venenatis quis, ante. Pellentesque habitant morbi tristique senectus et netus et malesuada fames ac turpis egestas. Maecenas sollicitudin. Quisque porta. Nullam sapien sem, ornare ac, nonummy non, lobortis a enim. Pellentesque habitant morbi tristique senectus et netus et malesuada fames ac turpis egestas. Maecenas sollicitudin. Quisque porta. Nullam sapien sem, ornare ac, nonummy non, lobortis a enim.", "uuids": ["e88efd75-2b29-4b59-8867-bb60435b3742"]}`
+
+func TestReadBodyStoreAndRestore(t *testing.T) {
+	e := echo.New()
+	req := httptest.NewRequest(http.MethodPost, "/", bytes.NewBufferString(TestBody))
+	rec := httptest.NewRecorder()
+	c := e.NewContext(req, rec)
+	h := LogServerErrorRequest(func(c echo.Context) error {
+		return c.JSON(http.StatusInternalServerError, map[string]string{
+			"status": fmt.Sprintf("%d", http.StatusInternalServerError),
+			"title":  "testing error",
+		})
+	})
+
+	_ = h(c)
+
+	var reqBody []byte
+	if c.Request().Body != nil {
+		reqBody, _ = io.ReadAll(c.Request().Body)
+	}
+
+	storedBody := c.Get(BodyStoreKey)
+	storedBodyBytes, ok := storedBody.([]byte)
+	if !ok {
+		assert.Fail(t, "Failed type assertion of stored body.")
+	}
+
+	assert.Equal(t, http.StatusInternalServerError, rec.Code)
+	assert.Equal(t, TestBody, string(storedBodyBytes))
+	assert.Equal(t, TestBody, string(reqBody))
+}
+
+func TestLargeBodyCutoff(t *testing.T) {
+	e := echo.New()
+	req := httptest.NewRequest(http.MethodPost, "/", bytes.NewBufferString(LargeBody))
+	rec := httptest.NewRecorder()
+	c := e.NewContext(req, rec)
+	h := LogServerErrorRequest(func(c echo.Context) error {
+		return c.JSON(http.StatusInternalServerError, map[string]string{
+			"status": fmt.Sprintf("%d", http.StatusInternalServerError),
+			"title":  "testing error",
+		})
+	})
+
+	_ = h(c)
+
+	var reqBody []byte
+	if c.Request().Body != nil {
+		reqBody, _ = io.ReadAll(c.Request().Body)
+	}
+
+	storedBody := c.Get(BodyStoreKey)
+	storedBodyBytes, ok := storedBody.([]byte)
+	if !ok {
+		assert.Fail(t, "Failed type assertion of stored body.")
+	}
+
+	assert.Equal(t, http.StatusInternalServerError, rec.Code)
+	assert.Equal(t, LargeBody[:1000], string(storedBodyBytes))
+	assert.Equal(t, LargeBody, string(reqBody))
+}
+
+func TestRequestBodyLogging(t *testing.T) {
+	e := echo.New()
+	req := httptest.NewRequest(http.MethodPost, "/", bytes.NewBufferString(TestBody))
+	rec := httptest.NewRecorder()
+	c := e.NewContext(req, rec)
+	c.Set(BodyStoreKey, []byte(TestBody))
+	buf := new(bytes.Buffer)
+	c.Logger().SetOutput(buf)
+	h := LogServerErrorRequest(func(c echo.Context) error {
+		return ce.NewErrorResponse(http.StatusInternalServerError, "Test Error", "5xx testing error")
+	})
+
+	_ = h(c)
+
+	log := make(map[string]string)
+	_ = json.Unmarshal(buf.Bytes(), &log)
+
+	assert.True(t, bytes.Contains(buf.Bytes(), []byte("\"message\":\"Request body: {\\\"limit\\\": 100, \\\"search\\\": \\\"random\\\", \\\"uuids\\\": [\\\"e88efd75-2b29-4b59-8867-bb60435b3742\\\"]}\"}")))
+	assert.Equal(t, log["message"], fmt.Sprintf("Request body: %s", TestBody))
+	assert.Equal(t, log["level"], "ERROR")
+}
+
+func TestMethodWithoutBody(t *testing.T) {
+	e := echo.New()
+	req := httptest.NewRequest(http.MethodGet, "/", nil)
+	rec := httptest.NewRecorder()
+	c := e.NewContext(req, rec)
+	buf := new(bytes.Buffer)
+	c.Logger().SetOutput(buf)
+	h := LogServerErrorRequest(func(c echo.Context) error {
+		return ce.NewErrorResponse(http.StatusInternalServerError, "Test Error", "5xx testing error")
+	})
+
+	_ = h(c)
+
+	log := make(map[string]string)
+	_ = json.Unmarshal(buf.Bytes(), &log)
+
+	assert.Equal(t, []byte(nil), buf.Bytes())
+}

pkg/middleware/utils.go

@@ -1,6 +1,11 @@
 package middleware
 
-import "github.com/labstack/echo/v4"
+import (
+	"bufio"
+	"io"
+
+	"github.com/labstack/echo/v4"
+)
 
 // See: https://github.com/labstack/echo/pull/1502/files
 // This method exist for v5 echo framework
@@ -13,3 +18,16 @@ func MatchedRoute(ctx echo.Context) string {
 	}
 	return ""
 }
+
+type BufferedReadCloser struct {
+	*bufio.Reader
+	io.ReadCloser
+}
+
+func (rw BufferedReadCloser) Close() error {
+	return rw.ReadCloser.Close()
+}
+
+func (rw BufferedReadCloser) Read(p []byte) (int, error) {
+	return rw.Reader.Read(p)
+}

pkg/router/route.go

@@ -34,6 +34,7 @@ func ConfigureEcho(allRoutes bool) *echo.Echo {
 	}))
 	e.Use(middleware.ExtractStatus) // Must be after lecho
 	e.Use(middleware.EnforceJSONContentType)
+	e.Use(middleware.LogServerErrorRequest)
 
 	// Add routes
 	handler.RegisterPing(e)