diff --git a/core/echo_errors.go b/core/echo_errors.go index 4848ab207..6eb8a25f7 100644 --- a/core/echo_errors.go +++ b/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) } } } diff --git a/core/echo_errors_test.go b/core/echo_errors_test.go index baedee9b1..b50e12291 100644 --- a/core/echo_errors_test.go +++ b/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")