Make HTTPErrorHandler idempotent on committed responses

core/echo_errors.go

@@ -50,6 +50,15 @@ const unmappedStatusCode = 0
 // CreateHTTPErrorHandler returns an Echo HTTPErrorHandler that logs the error with extra fields and returns it as an HTTP response.
 func CreateHTTPErrorHandler() echo.HTTPErrorHandler {
 	return func(err error, ctx echo.Context) {
+		// Echo can invoke the error handler twice for the same request: middleware
+		// like BodyDump calls c.Error(err) on its way out and still returns the err,
+		// causing echo's server loop to invoke the error handler a second time.
+		// Skip the second invocation — the response has already been written and
+		// the error logged by the first invocation. echo.DefaultHTTPErrorHandler
+		// behaves the same way.
+		if ctx.Response().Committed {
+			return
+		}
 		// HTTPErrors occur e.g. when a parameter bind fails. We map this to a httpStatusCodeError so its status code
 		// and message get directly mapped to a problem.
 		if echoErr, ok := err.(*echo.HTTPError); ok {
@@ -76,19 +85,12 @@ func CreateHTTPErrorHandler() echo.HTTPErrorHandler {
 		} else {
 			logMsg.Warn(title)
 		}
-		if !ctx.Response().Committed {
-			errorWriter, _ := ctx.Get(ErrorWriterContextKey).(ErrorWriter)
-			if errorWriter == nil {
-				errorWriter = &problemErrorWriter{}
-			}
-			writeError := errorWriter.Write(ctx, statusCode, title, err)
-			if writeError != nil {
-				logger.Error(err)
-			}
-		} else {
-			logger.
-				WithError(err).
-				Warn("Unable to send error back to client, response already committed")
+		errorWriter, _ := ctx.Get(ErrorWriterContextKey).(ErrorWriter)
+		if errorWriter == nil {
+			errorWriter = &problemErrorWriter{}
+		}
+		if writeError := errorWriter.Write(ctx, statusCode, title, err); writeError != nil {
+			logger.Error(err)
 		}
 	}
 }

core/echo_errors_test.go

@@ -21,6 +21,9 @@ package core
 import (
 	"errors"
 	"github.com/labstack/echo/v4"
+	"github.com/labstack/echo/v4/middleware"
+	"github.com/sirupsen/logrus"
+	logrustest "github.com/sirupsen/logrus/hooks/test"
 	"github.com/stretchr/testify/assert"
 	"io"
 	"net/http"
@@ -89,6 +92,47 @@ func TestHttpErrorHandler(t *testing.T) {
 	})
 }
 
+func TestHttpErrorHandler_idempotent_with_BodyDump(t *testing.T) {
+	// Echo's BodyDump middleware (and any other middleware that calls c.Error
+	// on the way out and still returns the error) causes echo to invoke the
+	// HTTPErrorHandler twice for the same request: once via c.Error and once
+	// via the err returned to echo's server loop. The second invocation must
+	// be a no-op so it does not log "response already committed" warnings.
+	logger, hook := logrustest.NewNullLogger()
+	logger.SetLevel(logrus.DebugLevel)
+	prevLogger := logrus.StandardLogger()
+	logrus.SetOutput(io.Discard)
+	prevHooks := prevLogger.Hooks
+	prevLogger.Hooks = make(logrus.LevelHooks)
+	prevLogger.AddHook(hook)
+	t.Cleanup(func() {
+		prevLogger.Hooks = prevHooks
+		logrus.SetOutput(prevLogger.Out)
+	})
+
+	es := echo.New()
+	es.HTTPErrorHandler = CreateHTTPErrorHandler()
+	es.Use(middleware.BodyDump(func(c echo.Context, _, _ []byte) {}))
+	es.Add(http.MethodGet, "/", func(c echo.Context) error {
+		c.Set(OperationIDContextKey, "test")
+		return errors.New("upstream failed")
+	})
+	server := httptest.NewServer(es)
+	t.Cleanup(server.Close)
+
+	resp, err := http.Get(server.URL + "/")
+	assert.NoError(t, err)
+	assert.Equal(t, http.StatusInternalServerError, resp.StatusCode)
+	body, _ := io.ReadAll(resp.Body)
+	assert.Contains(t, string(body), "upstream failed",
+		"the error must be written to the response exactly once")
+
+	for _, entry := range hook.AllEntries() {
+		assert.NotContains(t, entry.Message, "response already committed",
+			"HTTPErrorHandler must be idempotent when invoked on a committed response")
+	}
+}
+
 func Test_NotFoundError(t *testing.T) {
 	err := NotFoundError("failed: %s", "oops").(httpStatusCodeError)
 	assert.EqualError(t, err, "failed: oops")