From 2dd2eba704888e49336280732e5fa1a445cc8f12 Mon Sep 17 00:00:00 2001 From: Augustin Husson Date: Thu, 5 Nov 2026 14:17:18 +0100 Subject: [PATCH 1/6] [BREAKINGCHANGE] echo: upgrade to echo v5 echo v4 only receives bug fixes until 2026-12-31 and security fixes until 2027-12-31. The public API of the package keeps the same Builder methods and flags, but exposes the echo v5 types. - The server is started with echo.StartConfig, which gracefully shuts it down when the context is canceled. The timeouts are set in BeforeServeFunc, as echo v5 sets a default ReadTimeout of 30s. - The panics are logged with their stack trace by a central error handler and counted as 500 by the logger and the metrics, which now run before Recover. - The logger and the metrics middlewares return the error instead of handling it, and resolve the status with echo.ResolveResponseStatus. - The address listened, the errors of the http.Server and the graceful shutdown timeout are logged with logrus. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Augustin Husson --- echo/builder_test.go | 4 +- echo/error_handler_test.go | 188 ++++++++++++++++++++++++++ echo/logging_test.go | 163 +++++++++++++++++++++++ echo/metrics.go | 2 +- echo/middleware/logger.go | 17 +-- echo/middleware/logger_test.go | 6 +- echo/middleware/metrics.go | 32 ++--- echo/server.go | 232 ++++++++++++++++++++------------- echo/server_test.go | 2 +- echo/timeout_test.go | 11 +- go.mod | 10 +- go.sum | 16 +-- 12 files changed, 531 insertions(+), 152 deletions(-) create mode 100644 echo/error_handler_test.go create mode 100644 echo/logging_test.go diff --git a/echo/builder_test.go b/echo/builder_test.go index 8f02d87..8c2d445 100644 --- a/echo/builder_test.go +++ b/echo/builder_test.go @@ -18,7 +18,7 @@ import ( "net/http/httptest" "testing" - "github.com/labstack/echo/v4" + "github.com/labstack/echo/v5" "github.com/prometheus/client_golang/prometheus" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -27,7 +27,7 @@ import ( type helloRegister struct{} func (h *helloRegister) RegisterRoute(e *echo.Echo) { - e.GET("/hello", func(c echo.Context) error { + e.GET("/hello", func(c *echo.Context) error { return c.NoContent(http.StatusOK) }) } diff --git a/echo/error_handler_test.go b/echo/error_handler_test.go new file mode 100644 index 0000000..11043eb --- /dev/null +++ b/echo/error_handler_test.go @@ -0,0 +1,188 @@ +// Copyright The Perses Authors +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package echo + +import ( + "errors" + "net/http" + "net/http/httptest" + "strconv" + "testing" + + echoLib "github.com/labstack/echo/v5" + "github.com/prometheus/client_golang/prometheus" + "github.com/sirupsen/logrus" + logrustest "github.com/sirupsen/logrus/hooks/test" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// newLogHook captures the logs of the standard logrus logger until the end of the test. +func newLogHook(t *testing.T) *logrustest.Hook { + t.Helper() + origHooks := logrus.StandardLogger().ReplaceHooks(make(logrus.LevelHooks)) + t.Cleanup(func() { + logrus.StandardLogger().ReplaceHooks(origHooks) + }) + return logrustest.NewLocal(logrus.StandardLogger()) +} + +// findLogEntry returns the first entry captured by the hook with the given message. +func findLogEntry(hook *logrustest.Hook, message string) *logrus.Entry { + for _, entry := range hook.AllEntries() { + if entry.Message == message { + return entry + } + } + return nil +} + +// counterValue returns the value of the counter with the given name and labels, or 0 if it doesn't exist. +func counterValue(t *testing.T, registry *prometheus.Registry, name string, labels map[string]string) float64 { + t.Helper() + families, err := registry.Gather() + require.NoError(t, err) + for _, family := range families { + if family.GetName() != name { + continue + } + for _, metric := range family.GetMetric() { + matched := 0 + for _, label := range metric.GetLabel() { + if value, ok := labels[label.GetName()]; ok && value == label.GetValue() { + matched++ + } + } + if matched == len(labels) { + return metric.GetCounter().GetValue() + } + } + } + return 0 +} + +type errorRegister struct{} + +func (r *errorRegister) RegisterRoute(e *echoLib.Echo) { + e.GET("/panic", func(_ *echoLib.Context) error { + panic("boom") + }) + e.GET("/unexpected", func(_ *echoLib.Context) error { + return errors.New("unexpected failure") + }) + e.GET("/unauthorized", func(_ *echoLib.Context) error { + return echoLib.NewHTTPError(http.StatusUnauthorized, "missing token") + }) + e.GET("/bad-gateway", func(_ *echoLib.Context) error { + return echoLib.NewHTTPError(http.StatusBadGateway, "datasource unreachable") + }) +} + +func TestServer_ErrorHandling(t *testing.T) { + tests := []struct { + name string + path string + route string + expectedCode int + expectedBody string + expectedError string + }{ + { + name: "panic", + path: "/panic", + route: "/panic", + expectedCode: http.StatusInternalServerError, + expectedBody: `{"message":"Internal Server Error"}`, + expectedError: "panic recovered while handling the request", + }, + { + name: "unexpected error", + path: "/unexpected", + route: "/unexpected", + expectedCode: http.StatusInternalServerError, + expectedBody: `{"message":"Internal Server Error"}`, + expectedError: "unexpected error while handling the request", + }, + { + name: "HTTP error", + path: "/unauthorized", + route: "/unauthorized", + expectedCode: http.StatusUnauthorized, + expectedBody: `{"message":"missing token"}`, + }, + { + name: "HTTP error with a 5xx status", + path: "/bad-gateway", + route: "/bad-gateway", + expectedCode: http.StatusBadGateway, + expectedBody: `{"message":"datasource unreachable"}`, + }, + { + name: "route not found", + path: "/does-not-exist", + expectedCode: http.StatusNotFound, + expectedBody: `{"message":"Not Found"}`, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + hook := newLogHook(t) + registry := prometheus.NewRegistry() + handler, err := NewBuilder(). + APIRegistration(&errorRegister{}). + MetricNamespace("test"). + PrometheusRegisterer(registry). + BuildHandler() + require.NoError(t, err) + + rec := httptest.NewRecorder() + handler.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, tt.path, nil)) + + assert.Equal(t, tt.expectedCode, rec.Code) + assert.JSONEq(t, tt.expectedBody, rec.Body.String()) + + // The access log and the metrics report the status of the response sent. + var accessLog *logrus.Entry + for _, entry := range hook.AllEntries() { + if entry.Data["uri"] == tt.path && entry.Data["status"] != nil { + accessLog = entry + } + } + require.NotNil(t, accessLog) + assert.Equal(t, tt.expectedCode, accessLog.Data["status"]) + labels := map[string]string{"code": strconv.Itoa(tt.expectedCode), "method": http.MethodGet} + if tt.route != "" { + labels["handler"] = tt.route + } + assert.Equal(t, float64(1), counterValue(t, registry, "test_http_requests_total", labels)) + + // Only the errors that don't carry an HTTP status are logged as errors. + errorEntry := findLogEntry(hook, tt.expectedError) + if tt.expectedError == "" { + for _, entry := range hook.AllEntries() { + assert.NotEqual(t, logrus.ErrorLevel, entry.Level, entry.Message) + } + return + } + require.NotNil(t, errorEntry) + assert.Equal(t, logrus.ErrorLevel, errorEntry.Level) + assert.Equal(t, http.MethodGet, errorEntry.Data["method"]) + assert.Equal(t, tt.path, errorEntry.Data["uri"]) + if tt.name == "panic" { + assert.EqualError(t, errorEntry.Data[logrus.ErrorKey].(error), "boom") + assert.Contains(t, errorEntry.Data["stack"], "goroutine") + } + }) + } +} diff --git a/echo/logging_test.go b/echo/logging_test.go new file mode 100644 index 0000000..76cfe96 --- /dev/null +++ b/echo/logging_test.go @@ -0,0 +1,163 @@ +// Copyright The Perses Authors +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package echo + +import ( + "context" + "net/http" + "strings" + "testing" + "time" + + echoLib "github.com/labstack/echo/v5" + "github.com/sirupsen/logrus" + logrustest "github.com/sirupsen/logrus/hooks/test" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestServer_ConfigureHTTPServer(t *testing.T) { + hook := newLogHook(t) + s, err := NewBuilder(). + APIRegistration(&mockRegister{}). + OverrideDefaultMiddleware(true). + build() + require.NoError(t, err) + + // echo creates the http.Server with a ReadTimeout of 30s, which must not be kept, as there is no read timeout by default. + httpServer := &http.Server{ReadTimeout: 30 * time.Second} + s.configureHTTPServer(httpServer) + assert.Equal(t, defaultReadHeaderTimeout, httpServer.ReadHeaderTimeout) + assert.Equal(t, time.Duration(0), httpServer.ReadTimeout) + assert.Equal(t, time.Duration(0), httpServer.WriteTimeout) + assert.Equal(t, defaultIdleTimeout, httpServer.IdleTimeout) + + // The errors of the server are logged with logrus. + require.NotNil(t, httpServer.ErrorLog) + httpServer.ErrorLog.Printf("http: TLS handshake error from %s: EOF", "127.0.0.1:1234") + entry := hook.LastEntry() + require.NotNil(t, entry) + assert.Equal(t, logrus.ErrorLevel, entry.Level) + assert.Equal(t, "http: TLS handshake error from 127.0.0.1:1234: EOF", entry.Message) +} + +// startServer starts the server built by the builder on a random port and returns its address, read from the logs. +// The server is stopped at the end of the test. +func startServer(t *testing.T, hook *logrustest.Hook, builder *Builder) string { + t.Helper() + builder.ListenAddress("127.0.0.1:0") + task, err := builder.Build() + require.NoError(t, err) + require.NoError(t, task.Initialize()) + + ctx, cancel := context.WithCancel(context.Background()) + done := make(chan struct{}) + go func() { + defer close(done) + _ = task.Execute(ctx, cancel) + }() + t.Cleanup(func() { + cancel() + <-done + require.NoError(t, task.Finalize()) + }) + return waitForListenAddress(t, hook) +} + +// waitForListenAddress waits for the server to log the address it listens on, and returns it. +func waitForListenAddress(t *testing.T, hook *logrustest.Hook) string { + t.Helper() + var address string + require.Eventually(t, func() bool { + for _, entry := range hook.AllEntries() { + if after, ok := strings.CutPrefix(entry.Message, "http server started on "); ok { + address = after + return true + } + } + return false + }, 5*time.Second, 10*time.Millisecond) + return address +} + +func TestServer_LogsTheListenAddress(t *testing.T) { + hook := newLogHook(t) + address := startServer(t, hook, NewBuilder().APIRegistration(&mockRegister{}).OverrideDefaultMiddleware(true)) + assert.True(t, strings.HasPrefix(address, "127.0.0.1:")) + assert.NotEqual(t, "127.0.0.1:0", address) +} + +func TestServer_HidesTheListenAddress(t *testing.T) { + origHidePort := hidePort + hidePort = true + t.Cleanup(func() { + hidePort = origHidePort + }) + hook := newLogHook(t) + s, err := NewBuilder().APIRegistration(&mockRegister{}).OverrideDefaultMiddleware(true).build() + require.NoError(t, err) + s.logListenerAddr(nil) + assert.Empty(t, hook.AllEntries()) +} + +type blockingRegister struct { + started chan struct{} + release chan struct{} +} + +func (r *blockingRegister) RegisterRoute(e *echoLib.Echo) { + e.GET("/block", func(c *echoLib.Context) error { + close(r.started) + <-r.release + return c.NoContent(http.StatusOK) + }) +} + +func TestServer_LogsTheShutdownTimeout(t *testing.T) { + hook := newLogHook(t) + api := &blockingRegister{started: make(chan struct{}), release: make(chan struct{})} + builder := NewBuilder().APIRegistration(api).OverrideDefaultMiddleware(true) + builder.ListenAddress("127.0.0.1:0") + task, err := builder.Build() + require.NoError(t, err) + task.(*server).shutdownTimeout = 50 * time.Millisecond + require.NoError(t, task.Initialize()) + + ctx, cancel := context.WithCancel(context.Background()) + done := make(chan struct{}) + go func() { + defer close(done) + _ = task.Execute(ctx, cancel) + }() + address := waitForListenAddress(t, hook) + + // A request is still running when the server is stopped, so the graceful shutdown reaches its timeout. + requestDone := make(chan struct{}) + go func() { + defer close(requestDone) + resp, reqErr := http.Get("http://" + address + "/block") + if reqErr == nil { + _ = resp.Body.Close() + } + }() + <-api.started + cancel() + <-done + close(api.release) + <-requestDone + + entry := findLogEntry(hook, "the http server did not shut down gracefully before the timeout") + require.NotNil(t, entry) + assert.Equal(t, logrus.ErrorLevel, entry.Level) +} diff --git a/echo/metrics.go b/echo/metrics.go index 5fe5bd3..25d51bd 100644 --- a/echo/metrics.go +++ b/echo/metrics.go @@ -16,7 +16,7 @@ package echo import ( "flag" - "github.com/labstack/echo/v4" + "github.com/labstack/echo/v5" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/promhttp" ) diff --git a/echo/middleware/logger.go b/echo/middleware/logger.go index 863e525..51e1d61 100644 --- a/echo/middleware/logger.go +++ b/echo/middleware/logger.go @@ -14,8 +14,8 @@ package middleware import ( - "github.com/labstack/echo/v4" - "github.com/labstack/echo/v4/middleware" + "github.com/labstack/echo/v5" + "github.com/labstack/echo/v5/middleware" "github.com/perses/common/slices" "github.com/sirupsen/logrus" ) @@ -49,7 +49,7 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc { config.BlackListEndpoint = defaultLoggerConfig.BlackListEndpoint } return func(next echo.HandlerFunc) echo.HandlerFunc { - return func(c echo.Context) error { + return func(c *echo.Context) error { if config.Skipper(c) { return next(c) } @@ -58,19 +58,20 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc { // and the escaped path cannot contain control characters. path := c.Request().URL.EscapedPath() route := c.Path() - if err := next(c); err != nil { - c.Error(err) - } + // The error is not handled here, it is returned to be handled by the central error handler of echo. + // The status logged is the one of the response that will be sent, resolved from this error. + err := next(c) + _, status := echo.ResolveResponseStatus(c.Response(), err) entry := logrus.WithField("method", c.Request().Method). WithField("uri", path). - WithField("status", c.Response().Status) + WithField("status", status) if slices.InvertSubContains(config.BlackListEndpoint, route) { entry.Debug() } else { entry.Info() } - return nil + return err } } } diff --git a/echo/middleware/logger_test.go b/echo/middleware/logger_test.go index eebd29a..c9c77f3 100644 --- a/echo/middleware/logger_test.go +++ b/echo/middleware/logger_test.go @@ -19,7 +19,7 @@ import ( "net/http/httptest" "testing" - "github.com/labstack/echo/v4" + "github.com/labstack/echo/v5" "github.com/sirupsen/logrus" logrusTest "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" @@ -42,14 +42,14 @@ func TestLogger(t *testing.T) { e := echo.New() e.Use(Logger()) - handler := func(c echo.Context) error { + handler := func(c *echo.Context) error { return c.NoContent(http.StatusOK) } e.GET("/api/v1/users", handler) e.GET("/api/v1/projects/:project", handler) e.GET("/metrics", handler) // Like a reverse proxy, this handler modifies the path of the request. - e.GET("/proxy/*", func(c echo.Context) error { + e.GET("/proxy/*", func(c *echo.Context) error { c.Request().URL.Path = "/rewritten" return c.NoContent(http.StatusOK) }) diff --git a/echo/middleware/metrics.go b/echo/middleware/metrics.go index 4e09a32..68050db 100644 --- a/echo/middleware/metrics.go +++ b/echo/middleware/metrics.go @@ -19,7 +19,7 @@ import ( "strconv" "time" - "github.com/labstack/echo/v4" + "github.com/labstack/echo/v5" "github.com/prometheus/client_golang/prometheus" "github.com/sirupsen/logrus" ) @@ -66,13 +66,12 @@ func (m *Metrics) Describe(ch chan<- *prometheus.Desc) { // ProcessHTTPRequest is an echo middleware. It will intercept all responses. // It will increase the metrics that count the number of HTTP request and calculate the time took to respond. +// The error returned by the next handler is returned as is, to be handled by the central error handler of echo. +// The status code counted is the one of the response that will be sent, resolved from this error. func (m *Metrics) ProcessHTTPRequest(next echo.HandlerFunc) echo.HandlerFunc { - return func(ctx echo.Context) error { + return func(ctx *echo.Context) error { start := time.Now() - if err := next(ctx); err != nil { - // Note: if this method is called, the code won't go further. - ctx.Error(err) - } + err := next(ctx) elapsedTime := time.Since(start).Seconds() method := ctx.Request().Method if method != http.MethodPost && @@ -88,21 +87,22 @@ func (m *Metrics) ProcessHTTPRequest(next echo.HandlerFunc) echo.HandlerFunc { method = "not_standard" } - status := strconv.Itoa(ctx.Response().Status) - counter, err := m.totalHTTPRequest.GetMetricWith(prometheus.Labels{labelCode: status, labelHandler: ctx.Path(), labelMethod: method}) - if err != nil { - logrus.WithError(err).Error("unable to get the counter metrics in the api monitoring") + _, code := echo.ResolveResponseStatus(ctx.Response(), err) + status := strconv.Itoa(code) + counter, metricErr := m.totalHTTPRequest.GetMetricWith(prometheus.Labels{labelCode: status, labelHandler: ctx.Path(), labelMethod: method}) + if metricErr != nil { + logrus.WithError(metricErr).Error("unable to get the counter metrics in the api monitoring") // maybe not a really smart choice, but for the moment let's not impact the business if the monitoring somehow failed (which will unlikely happen) - return nil + return err } counter.Inc() - sum, err := m.durationHTTPRequest.GetMetricWith(prometheus.Labels{labelHandler: ctx.Path(), labelMethod: method}) - if err != nil { - logrus.WithError(err).Error("unable to get the summary metrics in the api monitoring") + sum, metricErr := m.durationHTTPRequest.GetMetricWith(prometheus.Labels{labelHandler: ctx.Path(), labelMethod: method}) + if metricErr != nil { + logrus.WithError(metricErr).Error("unable to get the summary metrics in the api monitoring") // maybe not a really smart choice, but for the moment let's not impact the business if the monitoring somehow failed (which will unlikely happen) - return nil + return err } sum.Observe(elapsedTime) - return nil + return err } } diff --git a/echo/server.go b/echo/server.go index 6a0500c..6d17c56 100644 --- a/echo/server.go +++ b/echo/server.go @@ -58,14 +58,16 @@ import ( "errors" "flag" "fmt" + "log" + "net" "net/http" "net/http/pprof" "slices" "strings" "time" - "github.com/labstack/echo/v4" - "github.com/labstack/echo/v4/middleware" + "github.com/labstack/echo/v5" + "github.com/labstack/echo/v5/middleware" "github.com/perses/common/async" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/collectors/version" @@ -332,19 +334,9 @@ func (b *Builder) build() (*server, error) { if b.gzipSkipper == nil { b.gzipSkipper = middleware.DefaultSkipper } - defaultMiddleware := []echo.MiddlewareFunc{ - // Activate recover middleware to recover from panics anywhere in the chain. - // It prints stack trace and handles the control to the centralized HTTPErrorHandler. - // More information here: https://echo.labstack.com/middleware/recover - middleware.Recover(), - persesMiddleware.Logger(), - middleware.GzipWithConfig( - middleware.GzipConfig{ - Skipper: b.gzipSkipper, - Level: 5, - }, - ), - } + // The logger and the metrics are executed first, so they see the result of every request. + // It includes the panics, as the middleware Recover turns them into errors returned to the previous middlewares. + defaultMiddleware := []echo.MiddlewareFunc{persesMiddleware.Logger()} if b.promRegisterer == nil { b.promRegisterer = prometheus.DefaultRegisterer } @@ -354,8 +346,19 @@ func (b *Builder) build() (*server, error) { return nil, err } defaultMiddleware = append(defaultMiddleware, metricMiddleware.ProcessHTTPRequest) - } + defaultMiddleware = append(defaultMiddleware, + // Recover from the panics anywhere in the rest of the chain. + // The panic is returned as an error (with the stack trace) that is logged by the central error handler. + // More information here: https://echo.labstack.com/docs/middleware/recover + middleware.Recover(), + middleware.GzipWithConfig( + middleware.GzipConfig{ + Skipper: b.gzipSkipper, + Level: 5, + }, + ), + ) mdws = append(defaultMiddleware, mdws...) } @@ -382,9 +385,7 @@ func (b *Builder) build() (*server, error) { logrus.Warn("--web.tls-min-version, --web.tls-max-version and --web.tls-cipher-suites have no effect because HTTPS is not enabled (--web.tls-cert-file and --web.tls-key-file are not set)") } - e := echo.New() - e.HideBanner = true - e.HidePort = hidePort + e := echo.NewWithConfig(echo.Config{HTTPErrorHandler: handleError}) readHeaderTimeout := b.readHeaderTimeout if readHeaderTimeout == 0 { readHeaderTimeout = defaultReadHeaderTimeout @@ -393,25 +394,23 @@ func (b *Builder) build() (*server, error) { readHeaderTimeout = min(b.readTimeout, defaultReadHeaderTimeout) } } - for _, httpServer := range []*http.Server{e.Server, e.TLSServer} { - httpServer.ReadHeaderTimeout = readHeaderTimeout - httpServer.ReadTimeout = b.readTimeout - httpServer.WriteTimeout = b.writeTimeout - httpServer.IdleTimeout = cmp.Or(b.idleTimeout, defaultIdleTimeout) - } return &server{ - addr: b.addr, - apis: b.apis, - e: e, - cert: cert, - key: key, - tlsMinVersion: parsedMinVersion, - tlsMaxVersion: parsedMaxVersion, - tlsCipherSuites: parsedCipherSuites, - mdws: mdws, - preMDWs: b.preMDWs, - shutdownTimeout: 30 * time.Second, - activatePprof: b.activatePprof, + addr: b.addr, + apis: b.apis, + e: e, + cert: cert, + key: key, + tlsMinVersion: parsedMinVersion, + tlsMaxVersion: parsedMaxVersion, + tlsCipherSuites: parsedCipherSuites, + mdws: mdws, + preMDWs: b.preMDWs, + shutdownTimeout: 30 * time.Second, + activatePprof: b.activatePprof, + readHeaderTimeout: readHeaderTimeout, + readTimeout: b.readTimeout, + writeTimeout: b.writeTimeout, + idleTimeout: cmp.Or(b.idleTimeout, defaultIdleTimeout), }, nil } @@ -441,18 +440,22 @@ func (b *Builder) registerMetrics() (*persesMiddleware.Metrics, error) { type server struct { async.Task - addr string - apis []Register - e *echo.Echo - cert string - key string - tlsMinVersion uint16 - tlsMaxVersion uint16 - tlsCipherSuites []uint16 - mdws []echo.MiddlewareFunc - preMDWs []echo.MiddlewareFunc - shutdownTimeout time.Duration - activatePprof bool + addr string + apis []Register + e *echo.Echo + cert string + key string + tlsMinVersion uint16 + tlsMaxVersion uint16 + tlsCipherSuites []uint16 + mdws []echo.MiddlewareFunc + preMDWs []echo.MiddlewareFunc + shutdownTimeout time.Duration + activatePprof bool + readHeaderTimeout time.Duration + readTimeout time.Duration + writeTimeout time.Duration + idleTimeout time.Duration } func (s *server) String() string { @@ -478,42 +481,99 @@ func (s *server) Initialize() error { } func (s *server) Execute(ctx context.Context, cancelFunc context.CancelFunc) error { - // start server - // The channel is buffered, so the go routine is not blocked when the server is stopped after the end of this method. - serverErr := make(chan error, 1) - go func() { - var err error - if s.cert != "" && s.key != "" { - err = s.startTLS() - } else { - err = s.e.Start(s.addr) + startConfig := echo.StartConfig{ + Address: s.addr, + HideBanner: true, + // echo logs the address with its own logger, so it is logged with logrus by logListenerAddr instead. + HidePort: true, + ListenerAddrFunc: s.logListenerAddr, + GracefulTimeout: s.shutdownTimeout, + OnShutdownError: func(err error) { + logrus.WithError(err).Error("the http server did not shut down gracefully before the timeout") + }, + BeforeServeFunc: func(httpServer *http.Server) error { + s.configureHTTPServer(httpServer) + return nil + }, + } + if s.cert != "" && s.key != "" { + tlsConfig, err := s.tlsConfig() + if err != nil { + cancelFunc() + return fmt.Errorf("http server stopped unexpectedly: %w", err) } - logrus.Debug("go routine running the http server has been stopped.") - serverErr <- err - }() - // Wait for the end of the task or cancellation - select { - case err := <-serverErr: - // Server ended unexpectedly (for example, the address is already in use, or the TLS certificate cannot be loaded) + startConfig.TLSConfig = tlsConfig + } + // Start blocks until the context is canceled, then it gracefully shuts down the server. + // It returns before if the server cannot start or stops unexpectedly (for example, when the address is already in use). + err := startConfig.Start(ctx, s.e) + logrus.Debug("http server has been stopped") + if ctx.Err() == nil { // In our ecosystem, as we are producing each time an HTTP API, if the HTTP api stopped, we want to stop the whole application. // That's why we are calling the parent cancelFunc cancelFunc() - if err != nil && !errors.Is(err, http.ErrServerClosed) { - return fmt.Errorf("http server stopped unexpectedly: %w", err) - } - case <-ctx.Done(): - // Cancellation requested by the parent context. The server is stopped by the method Finalize. - logrus.Debug("server cancellation requested") + } + if err != nil { + return fmt.Errorf("http server stopped unexpectedly: %w", err) } return nil } -// startTLS starts the HTTPS server. -// echo.StartTLS is not used because it replaces the TLS configuration, and it loads the certificate only once. -func (s *server) startTLS() error { +func (s *server) logListenerAddr(addr net.Addr) { + if hidePort { + return + } + scheme := "http" + if s.cert != "" { + scheme = "https" + } + logrus.Infof("%s server started on %s", scheme, addr) +} + +// configureHTTPServer sets the timeouts and the error logger of the http.Server created by echo. +// Every timeout is set, even when it is zero, as echo sets a default ReadTimeout. +func (s *server) configureHTTPServer(httpServer *http.Server) { + httpServer.ReadHeaderTimeout = s.readHeaderTimeout + httpServer.ReadTimeout = s.readTimeout + httpServer.WriteTimeout = s.writeTimeout + httpServer.IdleTimeout = s.idleTimeout + // The errors of the server (like the TLS handshake errors) are logged with logrus instead of the logger of echo. + httpServer.ErrorLog = log.New(logrusErrorWriter{}, "", 0) +} + +// logrusErrorWriter logs with logrus, as an error, every line written by a log.Logger. +type logrusErrorWriter struct{} + +func (logrusErrorWriter) Write(p []byte) (int, error) { + logrus.Error(strings.TrimSuffix(string(p), "\n")) + return len(p), nil +} + +var defaultHTTPErrorHandler = echo.DefaultHTTPErrorHandler(false) + +// handleError is the central error handler of the server, called with the error returned by the middleware chain. +// The errors that don't carry an HTTP status (like a panic recovered by the middleware Recover or an unexpected error) are logged, +// as nothing turned them into a response. Then, like the default echo handler, it writes the error as a JSON response +// without exposing the internal errors. +func handleError(c *echo.Context, err error) { + if echo.StatusCode(err) == 0 { + entry := logrus.WithField("method", c.Request().Method).WithField("uri", c.Request().URL.EscapedPath()) + var panicErr *middleware.PanicStackError + if errors.As(err, &panicErr) { + entry.WithError(panicErr.Err).WithField("stack", string(panicErr.Stack)).Error("panic recovered while handling the request") + } else { + entry.WithError(err).Error("unexpected error while handling the request") + } + } + defaultHTTPErrorHandler(c, err) +} + +// tlsConfig builds the TLS configuration of the HTTPS server. +// The certificate is provided by a reloader, so a rotated certificate is used without restarting the server. +func (s *server) tlsConfig() (*tls.Config, error) { reloader, err := newCertificateReloader(s.cert, s.key) if err != nil { - return err + return nil, err } tlsConfig := &tls.Config{ MinVersion: s.tlsMinVersion, @@ -521,21 +581,17 @@ func (s *server) startTLS() error { CipherSuites: s.tlsCipherSuites, GetCertificate: reloader.GetCertificate, } - switch { - case s.e.DisableHTTP2: - case !isHTTP2Compatible(s.tlsMinVersion, s.tlsCipherSuites): - logrus.Warn("HTTP/2 is disabled because --web.tls-cipher-suites contains neither TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 nor TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, required by HTTP/2") - default: + if isHTTP2Compatible(s.tlsMinVersion, s.tlsCipherSuites) { tlsConfig.NextProtos = []string{"h2"} + } else { + logrus.Warn("HTTP/2 is disabled because --web.tls-cipher-suites contains neither TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 nor TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, required by HTTP/2") } - s.e.TLSServer.Addr = s.addr - s.e.TLSServer.TLSConfig = tlsConfig - return s.e.StartServer(s.e.TLSServer) + return tlsConfig, nil } // isHTTP2Compatible tells if HTTP/2 can be offered with the given TLS settings. // HTTP/2 requires one of these cipher suites when TLS 1.2 is allowed (RFC 7540, section 9.2.2), -// otherwise net/http refuses to start the server. +// otherwise the connections of the clients negotiating HTTP/2 with another cipher suite are rejected. func isHTTP2Compatible(minVersion uint16, cipherSuites []uint16) bool { if len(cipherSuites) == 0 || minVersion >= tls.VersionTLS13 { return true @@ -547,13 +603,7 @@ func isHTTP2Compatible(minVersion uint16, cipherSuites []uint16) bool { } func (s *server) Finalize() error { - logrus.Debug("try to shutdown the http server") - shutdownCtx, shutdownCancelFunc := context.WithTimeout(context.Background(), s.shutdownTimeout) - // call shutdownCancelFunc to release the resources in case the task ended before the timeout - defer shutdownCancelFunc() - if err := s.e.Shutdown(shutdownCtx); err != nil { - return fmt.Errorf("server shutdown not properly: %w", err) - } + // The server is gracefully stopped by Execute once the context is canceled. return nil } diff --git a/echo/server_test.go b/echo/server_test.go index 3818399..577f2a7 100644 --- a/echo/server_test.go +++ b/echo/server_test.go @@ -21,7 +21,7 @@ import ( "testing" "time" - echoLib "github.com/labstack/echo/v4" + echoLib "github.com/labstack/echo/v5" "github.com/prometheus/client_golang/prometheus" "github.com/sirupsen/logrus" logrustest "github.com/sirupsen/logrus/hooks/test" diff --git a/echo/timeout_test.go b/echo/timeout_test.go index b0a65cc..a6f57d9 100644 --- a/echo/timeout_test.go +++ b/echo/timeout_test.go @@ -17,7 +17,6 @@ import ( "context" "io" "net" - "net/http" "testing" "time" @@ -133,12 +132,10 @@ func TestBuild_HTTPServerTimeouts(t *testing.T) { tt.configure(builder) s, err := builder.build() require.NoError(t, err) - for _, httpServer := range []*http.Server{s.e.Server, s.e.TLSServer} { - assert.Equal(t, tt.expectedReadHeaderTimeout, httpServer.ReadHeaderTimeout) - assert.Equal(t, tt.expectedReadTimeout, httpServer.ReadTimeout) - assert.Equal(t, tt.expectedWriteTimeout, httpServer.WriteTimeout) - assert.Equal(t, tt.expectedIdleTimeout, httpServer.IdleTimeout) - } + assert.Equal(t, tt.expectedReadHeaderTimeout, s.readHeaderTimeout) + assert.Equal(t, tt.expectedReadTimeout, s.readTimeout) + assert.Equal(t, tt.expectedWriteTimeout, s.writeTimeout) + assert.Equal(t, tt.expectedIdleTimeout, s.idleTimeout) }) } } diff --git a/go.mod b/go.mod index 748c70f..146ea53 100644 --- a/go.mod +++ b/go.mod @@ -5,7 +5,7 @@ go 1.27.1 require ( github.com/flc1125/go-cron/v4 v4.14.0 github.com/fsnotify/fsnotify v1.10.1 - github.com/labstack/echo/v4 v4.16.2 + github.com/labstack/echo/v5 v5.4.4 github.com/nexucis/lamenv v0.5.2 github.com/prometheus/client_golang v1.25.0 github.com/prometheus/common v0.72.1 @@ -23,23 +23,15 @@ require ( github.com/go-logr/stdr v1.2.2 // indirect github.com/google/uuid v1.6.0 // indirect github.com/kr/text v0.2.0 // indirect - github.com/labstack/gommon v0.5.0 // indirect - github.com/mattn/go-colorable v0.1.15 // indirect - github.com/mattn/go-isatty v0.0.22 // indirect github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect github.com/prometheus/client_model v0.6.3 // indirect github.com/prometheus/procfs v0.22.0 // indirect - github.com/valyala/bytebufferpool v1.0.0 // indirect - github.com/valyala/fasttemplate v1.2.2 // indirect go.opentelemetry.io/auto/sdk v1.2.1 // indirect go.opentelemetry.io/otel/log v1.47.0 // indirect go.opentelemetry.io/otel/metric v1.47.0 // indirect go.opentelemetry.io/otel/trace v1.47.0 // indirect go.yaml.in/yaml/v3 v3.0.5 // indirect - golang.org/x/crypto v0.58.0 // indirect - golang.org/x/net v0.61.0 // indirect golang.org/x/sys v0.49.0 // indirect - golang.org/x/text v0.43.0 // indirect golang.org/x/time v0.15.0 // indirect google.golang.org/protobuf v1.36.12 // indirect ) diff --git a/go.sum b/go.sum index aaab321..3f23857 100644 --- a/go.sum +++ b/go.sum @@ -24,14 +24,8 @@ github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0SNc= github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw= -github.com/labstack/echo/v4 v4.16.2 h1:WFPVqfogOZGH4dTr1UCIB1sqjFIQ/k7vIk5ByL6oWjY= -github.com/labstack/echo/v4 v4.16.2/go.mod h1:V/EQaTVHYJH92QhbQe7kFQ4mjgcjxLQQUQtAN87zZdw= -github.com/labstack/gommon v0.5.0 h1:6VSQ2NOzsnEJ5W6+84E0RbcaDDmgB6NIAzWCczTEe6c= -github.com/labstack/gommon v0.5.0/go.mod h1:Rzlg7HHy1maLfzBYGg9NZcVuz1sA68HHhLjhcEllYE0= -github.com/mattn/go-colorable v0.1.15 h1:+u9SLTRGnXv73cEsnsmoZBom+dMU88B2M0aDcWy0/jY= -github.com/mattn/go-colorable v0.1.15/go.mod h1:6LmQG8QLFO4G5z1gPvYEzlUgJ2wF+stgPZH1UqBm1s8= -github.com/mattn/go-isatty v0.0.22 h1:j8l17JJ9i6VGPUFUYoTUKPSgKe/83EYU2zBC7YNKMw4= -github.com/mattn/go-isatty v0.0.22/go.mod h1:ZXfXG4SQHsB/w3ZeOYbR0PrPwLy+n6xiMrJlRFqopa4= +github.com/labstack/echo/v5 v5.4.4 h1:Nag9Mee0M9sOcKjProYuDNiw60QisysgfbIgz5US5Cw= +github.com/labstack/echo/v5 v5.4.4/go.mod h1:4iEGNQiPPZnkfYpNR/L6fINd3NLiGWUD5+eBotFALas= github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 h1:C3w9PqII01/Oq1c1nUAm88MOHcQC9l5mIlSMApZMrHA= github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822/go.mod h1:+n7T8mK8HuQTcFwEeznm/DIxMOiR9yIdICNftLE1DvQ= github.com/nexucis/lamenv v0.5.2 h1:tK/u3XGhCq9qIoVNcXsK9LZb8fKopm0A5weqSRvHd7M= @@ -50,10 +44,6 @@ github.com/sirupsen/logrus v1.10.2 h1:G2SED73/qrAu6YwbdxOD6peLkCBI3z7L+ykJFTXJBB github.com/sirupsen/logrus v1.10.2/go.mod h1:SLEg8TqYulVKKfIGHldVp2K2aYz2DKSVBq4g/H5bR7Q= github.com/stretchr/testify v1.12.1 h1:EuwCh5fleGS7H32xRwO3wRGT7DxrDhLAT6FF8MpWDWE= github.com/stretchr/testify v1.12.1/go.mod h1:MDEgiDPPsNp5cuIrHPPCyornHKgEVbtFUmoNlxoYthg= -github.com/valyala/bytebufferpool v1.0.0 h1:GqA5TC/0021Y/b9FG4Oi9Mr3q7XYx6KllzawFIhcdPw= -github.com/valyala/bytebufferpool v1.0.0/go.mod h1:6bBcMArwyJ5K/AmCkWv1jt77kVWyCJ6HpOuEn7z0Csc= -github.com/valyala/fasttemplate v1.2.2 h1:lxLXG0uE3Qnshl9QyaK6XJxMXlQZELvChBOCmQD0Loo= -github.com/valyala/fasttemplate v1.2.2/go.mod h1:KHLXt3tVN2HBp8eijSv/kGJopbvo7S+qRAEEKiv+SiQ= go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= go.opentelemetry.io/auto/sdk v1.2.1/go.mod h1:KRTj+aOaElaLi+wW1kO/DZRXwkF4C5xPbEe3ZiIhN7Y= go.opentelemetry.io/otel v1.47.0 h1:j7ALJ/zgkS7Z6aeJW09p8VC9804bC+PpeTfCD4XPnOM= @@ -74,8 +64,6 @@ go.yaml.in/yaml/v2 v2.4.4 h1:tuyd0P+2Ont/d6e2rl3be67goVK4R6deVxCUX5vyPaQ= go.yaml.in/yaml/v2 v2.4.4/go.mod h1:gMZqIpDtDqOfM0uNfy0SkpRhvUryYH0Z6wdMYcacYXQ= go.yaml.in/yaml/v3 v3.0.5 h1:N6y/pJk8buWs9NY5ERU2HSMfm+IuD/OtfdAnq6kESPw= go.yaml.in/yaml/v3 v3.0.5/go.mod h1:HVTZu1O7/Vkt2N+BFy8Zza+lnLsABggaTM2ZpNIGuKg= -golang.org/x/crypto v0.58.0 h1:COkYLr4k7nDI4r6QtMML2AfzeIswWHAJthLS6K/M/54= -golang.org/x/crypto v0.58.0/go.mod h1:Xh+kl5A+M0gMiWDytH2Hhr5Z7WbNCpv/eB/EFgfSk+w= golang.org/x/net v0.61.0 h1:RR+6j/BTBCrggOLugxa+66R8FvoN6MHlzDlZIbN9YFw= golang.org/x/net v0.61.0/go.mod h1:WgDCOTH8iwtB66T4/GfI94AHo/hhdb7Hah9NDseQfiI= golang.org/x/sys v0.49.0 h1:XbzkgYJHdqh/8m2Uu0W/dQv8nktxx4BFHp1M0gROTXA= From 44d46106ebac6d5122dff7ddbc0726508aea3b7d Mon Sep 17 00:00:00 2001 From: Augustin Husson Date: Thu, 5 Nov 2026 16:01:20 +0100 Subject: [PATCH 2/6] echo: report the graceful shutdown timeout and log the panics carrying an HTTP status Address the review of the upgrade to echo v5: - echo v5 only gives the error of the graceful shutdown (like a timeout) to StartConfig.OnShutdownError. It is now returned by Finalize, like before the upgrade, so the task reports the failure instead of a successful shutdown. - The value of a recovered panic can carry an HTTP status (like panic(echo.NewHTTPError(...))), as PanicStackError unwraps it. The panics are now checked first, so they are always logged with their stack trace. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Augustin Husson --- echo/error_handler_test.go | 20 ++++++++++++++++++-- echo/logging_test.go | 20 +++++++++++++++----- echo/server.go | 30 ++++++++++++++++++------------ 3 files changed, 51 insertions(+), 19 deletions(-) diff --git a/echo/error_handler_test.go b/echo/error_handler_test.go index 11043eb..70dcda8 100644 --- a/echo/error_handler_test.go +++ b/echo/error_handler_test.go @@ -78,6 +78,9 @@ func (r *errorRegister) RegisterRoute(e *echoLib.Echo) { e.GET("/panic", func(_ *echoLib.Context) error { panic("boom") }) + e.GET("/panic-http-error", func(_ *echoLib.Context) error { + panic(echoLib.NewHTTPError(http.StatusServiceUnavailable, "maintenance")) + }) e.GET("/unexpected", func(_ *echoLib.Context) error { return errors.New("unexpected failure") }) @@ -97,6 +100,8 @@ func TestServer_ErrorHandling(t *testing.T) { expectedCode int expectedBody string expectedError string + // expectedPanic is the error of the panic logged with its stack trace. + expectedPanic string }{ { name: "panic", @@ -105,6 +110,17 @@ func TestServer_ErrorHandling(t *testing.T) { expectedCode: http.StatusInternalServerError, expectedBody: `{"message":"Internal Server Error"}`, expectedError: "panic recovered while handling the request", + expectedPanic: "boom", + }, + { + // The value of the panic carries an HTTP status, it must be logged as a panic anyway. + name: "panic with an HTTP error", + path: "/panic-http-error", + route: "/panic-http-error", + expectedCode: http.StatusServiceUnavailable, + expectedBody: `{"message":"maintenance"}`, + expectedError: "panic recovered while handling the request", + expectedPanic: echoLib.NewHTTPError(http.StatusServiceUnavailable, "maintenance").Error(), }, { name: "unexpected error", @@ -179,8 +195,8 @@ func TestServer_ErrorHandling(t *testing.T) { assert.Equal(t, logrus.ErrorLevel, errorEntry.Level) assert.Equal(t, http.MethodGet, errorEntry.Data["method"]) assert.Equal(t, tt.path, errorEntry.Data["uri"]) - if tt.name == "panic" { - assert.EqualError(t, errorEntry.Data[logrus.ErrorKey].(error), "boom") + if tt.expectedPanic != "" { + assert.EqualError(t, errorEntry.Data[logrus.ErrorKey].(error), tt.expectedPanic) assert.Contains(t, errorEntry.Data["stack"], "goroutine") } }) diff --git a/echo/logging_test.go b/echo/logging_test.go index 76cfe96..e64ef92 100644 --- a/echo/logging_test.go +++ b/echo/logging_test.go @@ -124,7 +124,7 @@ func (r *blockingRegister) RegisterRoute(e *echoLib.Echo) { }) } -func TestServer_LogsTheShutdownTimeout(t *testing.T) { +func TestServer_FinalizeReturnsTheShutdownTimeout(t *testing.T) { hook := newLogHook(t) api := &blockingRegister{started: make(chan struct{}), release: make(chan struct{})} builder := NewBuilder().APIRegistration(api).OverrideDefaultMiddleware(true) @@ -136,9 +136,10 @@ func TestServer_LogsTheShutdownTimeout(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) done := make(chan struct{}) + var executeErr error go func() { defer close(done) - _ = task.Execute(ctx, cancel) + executeErr = task.Execute(ctx, cancel) }() address := waitForListenAddress(t, hook) @@ -157,7 +158,16 @@ func TestServer_LogsTheShutdownTimeout(t *testing.T) { close(api.release) <-requestDone - entry := findLogEntry(hook, "the http server did not shut down gracefully before the timeout") - require.NotNil(t, entry) - assert.Equal(t, logrus.ErrorLevel, entry.Level) + // The server stopped as requested, but its shutdown failed: the task must report it, like before echo v5. + assert.NoError(t, executeErr) + err = task.Finalize() + assert.ErrorIs(t, err, context.DeadlineExceeded) + assert.ErrorContains(t, err, "server shutdown not properly") +} + +func TestServer_FinalizeWithoutShutdownError(t *testing.T) { + hook := newLogHook(t) + address := startServer(t, hook, NewBuilder().APIRegistration(&mockRegister{}).OverrideDefaultMiddleware(true)) + assert.NotEmpty(t, address) + // startServer stops the server and checks Finalize returns no error at the end of the test. } diff --git a/echo/server.go b/echo/server.go index 6d17c56..c02bbe2 100644 --- a/echo/server.go +++ b/echo/server.go @@ -456,6 +456,8 @@ type server struct { readTimeout time.Duration writeTimeout time.Duration idleTimeout time.Duration + // shutdownErr is the error of the graceful shutdown done by Execute (like a timeout), returned by Finalize. + shutdownErr error } func (s *server) String() string { @@ -488,8 +490,10 @@ func (s *server) Execute(ctx context.Context, cancelFunc context.CancelFunc) err HidePort: true, ListenerAddrFunc: s.logListenerAddr, GracefulTimeout: s.shutdownTimeout, + // echo logs this error and returns nil. It is returned by Finalize instead, so the task reports the failure. + // It is called before Start returns, so before Finalize is called. OnShutdownError: func(err error) { - logrus.WithError(err).Error("the http server did not shut down gracefully before the timeout") + s.shutdownErr = err }, BeforeServeFunc: func(httpServer *http.Server) error { s.configureHTTPServer(httpServer) @@ -552,18 +556,17 @@ func (logrusErrorWriter) Write(p []byte) (int, error) { var defaultHTTPErrorHandler = echo.DefaultHTTPErrorHandler(false) // handleError is the central error handler of the server, called with the error returned by the middleware chain. -// The errors that don't carry an HTTP status (like a panic recovered by the middleware Recover or an unexpected error) are logged, -// as nothing turned them into a response. Then, like the default echo handler, it writes the error as a JSON response -// without exposing the internal errors. +// The panics recovered by the middleware Recover and the errors that don't carry an HTTP status (unexpected errors) +// are logged, as nothing turned them into a response. Then, like the default echo handler, it writes the error as a JSON +// response without exposing the internal errors. func handleError(c *echo.Context, err error) { - if echo.StatusCode(err) == 0 { - entry := logrus.WithField("method", c.Request().Method).WithField("uri", c.Request().URL.EscapedPath()) - var panicErr *middleware.PanicStackError - if errors.As(err, &panicErr) { - entry.WithError(panicErr.Err).WithField("stack", string(panicErr.Stack)).Error("panic recovered while handling the request") - } else { - entry.WithError(err).Error("unexpected error while handling the request") - } + entry := logrus.WithField("method", c.Request().Method).WithField("uri", c.Request().URL.EscapedPath()) + // A panic is checked first: its value can carry an HTTP status (like panic(echo.NewHTTPError(...))). + var panicErr *middleware.PanicStackError + if errors.As(err, &panicErr) { + entry.WithError(panicErr.Err).WithField("stack", string(panicErr.Stack)).Error("panic recovered while handling the request") + } else if echo.StatusCode(err) == 0 { + entry.WithError(err).Error("unexpected error while handling the request") } defaultHTTPErrorHandler(c, err) } @@ -604,6 +607,9 @@ func isHTTP2Compatible(minVersion uint16, cipherSuites []uint16) bool { func (s *server) Finalize() error { // The server is gracefully stopped by Execute once the context is canceled. + if s.shutdownErr != nil { + return fmt.Errorf("server shutdown not properly: %w", s.shutdownErr) + } return nil } From 2344031865ccf7eb6b38979cbcafcd5376e79a13 Mon Sep 17 00:00:00 2001 From: Augustin Husson Date: Thu, 5 Nov 2026 16:29:07 +0100 Subject: [PATCH 3/6] echo: log the errors with the path logged by the access logger The central error handler read the path of the request after the handlers, which can rewrite it (like a reverse proxy). The error log and the access log of the same request could then show different paths. The Logger middleware now saves the path it logs in the echo context, and the error handler uses it (middleware.RequestPath), or the current path when the logger didn't handle the request. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Augustin Husson --- echo/error_handler_test.go | 27 ++++++++++++++++++++ echo/middleware/logger.go | 15 ++++++++++++ echo/middleware/logger_test.go | 45 ++++++++++++++++++++++++++++++++++ echo/server.go | 3 ++- 4 files changed, 89 insertions(+), 1 deletion(-) diff --git a/echo/error_handler_test.go b/echo/error_handler_test.go index 70dcda8..45cc07c 100644 --- a/echo/error_handler_test.go +++ b/echo/error_handler_test.go @@ -81,6 +81,15 @@ func (r *errorRegister) RegisterRoute(e *echoLib.Echo) { e.GET("/panic-http-error", func(_ *echoLib.Context) error { panic(echoLib.NewHTTPError(http.StatusServiceUnavailable, "maintenance")) }) + // Like a reverse proxy, these handlers modify the path of the request before failing. + e.GET("/rewrite-then-panic", func(c *echoLib.Context) error { + c.Request().URL.Path = "/rewritten" + panic("boom") + }) + e.GET("/rewrite-then-fail", func(c *echoLib.Context) error { + c.Request().URL.Path = "/rewritten" + return errors.New("unexpected failure") + }) e.GET("/unexpected", func(_ *echoLib.Context) error { return errors.New("unexpected failure") }) @@ -122,6 +131,24 @@ func TestServer_ErrorHandling(t *testing.T) { expectedError: "panic recovered while handling the request", expectedPanic: echoLib.NewHTTPError(http.StatusServiceUnavailable, "maintenance").Error(), }, + { + // The error log and the access log use the path requested by the client. + name: "panic after the path is rewritten", + path: "/rewrite-then-panic", + route: "/rewrite-then-panic", + expectedCode: http.StatusInternalServerError, + expectedBody: `{"message":"Internal Server Error"}`, + expectedError: "panic recovered while handling the request", + expectedPanic: "boom", + }, + { + name: "unexpected error after the path is rewritten", + path: "/rewrite-then-fail", + route: "/rewrite-then-fail", + expectedCode: http.StatusInternalServerError, + expectedBody: `{"message":"Internal Server Error"}`, + expectedError: "unexpected error while handling the request", + }, { name: "unexpected error", path: "/unexpected", diff --git a/echo/middleware/logger.go b/echo/middleware/logger.go index 51e1d61..ce8279a 100644 --- a/echo/middleware/logger.go +++ b/echo/middleware/logger.go @@ -57,6 +57,8 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc { // Only the escaped path is logged: the query string can contain sensitive data (tokens, OAuth codes, etc.), // and the escaped path cannot contain control characters. path := c.Request().URL.EscapedPath() + // The path is saved, so the other logs about this request (like the one of the central error handler) use the same. + c.Set(contextKeyRequestPath, path) route := c.Path() // The error is not handled here, it is returned to be handled by the central error handler of echo. // The status logged is the one of the response that will be sent, resolved from this error. @@ -75,3 +77,16 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc { } } } + +// contextKeyRequestPath is the key of the echo context in which the Logger middleware saves the escaped path of the request. +const contextKeyRequestPath = "github.com/perses/common/echo/middleware.requestPath" + +// RequestPath returns the escaped path of the request as logged by the Logger middleware, before the next handlers +// possibly rewrote it (like a reverse proxy). Like that, every log about the same request uses the same path. +// It returns the current escaped path of the request when the Logger middleware didn't handle it. +func RequestPath(c *echo.Context) string { + if path, ok := c.Get(contextKeyRequestPath).(string); ok { + return path + } + return c.Request().URL.EscapedPath() +} diff --git a/echo/middleware/logger_test.go b/echo/middleware/logger_test.go index c9c77f3..c366246 100644 --- a/echo/middleware/logger_test.go +++ b/echo/middleware/logger_test.go @@ -125,3 +125,48 @@ func TestLogger(t *testing.T) { }) } } + +func TestRequestPath(t *testing.T) { + tests := []struct { + name string + middleware []echo.MiddlewareFunc + expectedPath string + }{ + { + name: "the path logged by the logger is returned, even if the handler modifies it", + middleware: []echo.MiddlewareFunc{LoggerWithConfig(LoggerConfig{})}, + expectedPath: "/proxy/api%2Fv1", + }, + { + name: "the current path is returned when the logger doesn't handle the request", + middleware: []echo.MiddlewareFunc{LoggerWithConfig(LoggerConfig{Skipper: func(*echo.Context) bool { return true }})}, + expectedPath: "/rewritten", + }, + { + name: "the current path is returned without the logger", + expectedPath: "/rewritten", + }, + } + origOutput := logrus.StandardLogger().Out + logrus.SetOutput(io.Discard) + t.Cleanup(func() { + logrus.SetOutput(origOutput) + }) + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + var path string + e := echo.New() + e.Use(tt.middleware...) + // Like a reverse proxy, this handler modifies the path of the request. + e.GET("/proxy/*", func(c *echo.Context) error { + c.Request().URL.Path = "/rewritten" + path = RequestPath(c) + return c.NoContent(http.StatusOK) + }) + rec := httptest.NewRecorder() + e.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/proxy/api%2Fv1", nil)) + require.Equal(t, http.StatusOK, rec.Code) + assert.Equal(t, tt.expectedPath, path) + }) + } +} diff --git a/echo/server.go b/echo/server.go index c02bbe2..d682302 100644 --- a/echo/server.go +++ b/echo/server.go @@ -560,7 +560,8 @@ var defaultHTTPErrorHandler = echo.DefaultHTTPErrorHandler(false) // are logged, as nothing turned them into a response. Then, like the default echo handler, it writes the error as a JSON // response without exposing the internal errors. func handleError(c *echo.Context, err error) { - entry := logrus.WithField("method", c.Request().Method).WithField("uri", c.Request().URL.EscapedPath()) + // The path logged by the access logger is used, as the handlers can rewrite the path of the request. + entry := logrus.WithField("method", c.Request().Method).WithField("uri", persesMiddleware.RequestPath(c)) // A panic is checked first: its value can carry an HTTP status (like panic(echo.NewHTTPError(...))). var panicErr *middleware.PanicStackError if errors.As(err, &panicErr) { From c8a96c5453f117f2f3dfd53ff8efff27a74a18f0 Mon Sep 17 00:00:00 2001 From: Augustin Husson Date: Mon, 9 Nov 2026 10:53:24 +0100 Subject: [PATCH 4/6] echo: log the echo logs with logrus and expose the IP and scheme extractors Address the review of the upgrade to echo v5: - echo v5 logs with log/slog (JSON on stdout by default). A slog handler writing with logrus is given to echo, so all its logs (like "response already written to client") have the same format, level and output as the other logs. - Builder.IPExtractor and Builder.SchemeExtractor configure how echo.Context.RealIP and echo.Context.Scheme trust the forwarding headers, as echo v5 changed their defaults. - An unexpected error is logged as a warning once the response is sent, and at the debug level when the client went away (the request is canceled). - The TLS handshake errors of the http.Server are caused by the clients, so they are logged as warnings. - Only the stack of the goroutine that panicked is logged: getting the stacks of all the goroutines stops the world. - Document the Logger middleware and the --web.hide-port flag, and harden the new tests (bounded waits, error of Execute checked, t.Context()). Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Augustin Husson --- echo/builder_test.go | 53 +++++++++++ echo/error_handler_test.go | 97 +++++++++++++++---- echo/logging.go | 118 +++++++++++++++++++++++ echo/logging_test.go | 187 ++++++++++++++++++++++++++++++++----- echo/middleware/logger.go | 5 + echo/middleware/metrics.go | 1 + echo/server.go | 73 +++++++++++---- 7 files changed, 479 insertions(+), 55 deletions(-) create mode 100644 echo/logging.go diff --git a/echo/builder_test.go b/echo/builder_test.go index 8c2d445..891cd89 100644 --- a/echo/builder_test.go +++ b/echo/builder_test.go @@ -14,6 +14,7 @@ package echo import ( + "net" "net/http" "net/http/httptest" "testing" @@ -90,3 +91,55 @@ func TestBuilder_MetricsRegistrationError(t *testing.T) { Build() assert.Error(t, err) } + +type clientRegister struct{} + +func (r *clientRegister) RegisterRoute(e *echo.Echo) { + e.GET("/client", func(c *echo.Context) error { + return c.String(http.StatusOK, c.Scheme()+" "+c.RealIP()) + }) +} + +func TestBuilder_IPAndSchemeExtractors(t *testing.T) { + _, proxyNetwork, err := net.ParseCIDR("203.0.113.0/24") + require.NoError(t, err) + tests := []struct { + name string + configure func(b *Builder) + // expected is the scheme and the IP address of the client, as seen by the handler. + expected string + }{ + { + // The forwarding headers can be spoofed by any client, so they are not trusted from a public address by default. + name: "default", + configure: func(*Builder) {}, + expected: "http 203.0.113.10", + }, + { + name: "trusted proxy", + configure: func(b *Builder) { + b.IPExtractor(echo.ExtractIPFromXFFHeader(echo.TrustIPRange(proxyNetwork))). + SchemeExtractor(echo.ExtractSchemeFromHeaders(echo.TrustIPRange(proxyNetwork))) + }, + expected: "https 198.51.100.7", + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + builder := NewBuilder().APIRegistration(&clientRegister{}).OverrideDefaultMiddleware(true) + tt.configure(builder) + handler, err := builder.BuildHandler() + require.NoError(t, err) + + // The request comes from a proxy with a public address (like a cloud load balancer). + req := httptest.NewRequest(http.MethodGet, "/client", nil) + req.RemoteAddr = "203.0.113.10:1234" + req.Header.Set(echo.HeaderXForwardedFor, "198.51.100.7") + req.Header.Set(echo.HeaderXForwardedProto, "https") + rec := httptest.NewRecorder() + handler.ServeHTTP(rec, req) + require.Equal(t, http.StatusOK, rec.Code) + assert.Equal(t, tt.expected, rec.Body.String()) + }) + } +} diff --git a/echo/error_handler_test.go b/echo/error_handler_test.go index 45cc07c..08c6861 100644 --- a/echo/error_handler_test.go +++ b/echo/error_handler_test.go @@ -14,9 +14,12 @@ package echo import ( + "context" "errors" + "io" "net/http" "net/http/httptest" + "regexp" "strconv" "testing" @@ -28,14 +31,22 @@ import ( "github.com/stretchr/testify/require" ) -// newLogHook captures the logs of the standard logrus logger until the end of the test. +// newLogHook captures the logs of the standard logrus logger, at every level, until the end of the test. +// The logs are not written to the output during the test. func newLogHook(t *testing.T) *logrustest.Hook { t.Helper() - origHooks := logrus.StandardLogger().ReplaceHooks(make(logrus.LevelHooks)) + logger := logrus.StandardLogger() + origHooks := logger.ReplaceHooks(make(logrus.LevelHooks)) + origLevel := logger.GetLevel() + origOutput := logger.Out + logger.SetLevel(logrus.TraceLevel) + logger.SetOutput(io.Discard) t.Cleanup(func() { - logrus.StandardLogger().ReplaceHooks(origHooks) + logger.ReplaceHooks(origHooks) + logger.SetLevel(origLevel) + logger.SetOutput(origOutput) }) - return logrustest.NewLocal(logrus.StandardLogger()) + return logrustest.NewLocal(logger) } // findLogEntry returns the first entry captured by the hook with the given message. @@ -93,6 +104,16 @@ func (r *errorRegister) RegisterRoute(e *echoLib.Echo) { e.GET("/unexpected", func(_ *echoLib.Context) error { return errors.New("unexpected failure") }) + e.GET("/fail-after-response", func(c *echoLib.Context) error { + if err := c.JSON(http.StatusOK, map[string]string{"message": "partial"}); err != nil { + return err + } + return errors.New("unexpected failure") + }) + // Like a handler calling a datasource, the error is caused by the cancellation of the request when the client went away. + e.GET("/canceled", func(c *echoLib.Context) error { + return c.Request().Context().Err() + }) e.GET("/unauthorized", func(_ *echoLib.Context) error { return echoLib.NewHTTPError(http.StatusUnauthorized, "missing token") }) @@ -101,14 +122,21 @@ func (r *errorRegister) RegisterRoute(e *echoLib.Echo) { }) } +// goroutineHeader matches the first line of the stack of a goroutine (like "goroutine 7 [running]:"). +var goroutineHeader = regexp.MustCompile(`(?m)^goroutine \d+ \[`) + func TestServer_ErrorHandling(t *testing.T) { tests := []struct { - name string - path string - route string - expectedCode int - expectedBody string + name string + path string + route string + // canceled cancels the request before it is handled, like when the client went away. + canceled bool + expectedCode int + expectedBody string + // expectedError is the message of the error logged (if any) with the level expectedLevel. expectedError string + expectedLevel logrus.Level // expectedPanic is the error of the panic logged with its stack trace. expectedPanic string }{ @@ -119,6 +147,7 @@ func TestServer_ErrorHandling(t *testing.T) { expectedCode: http.StatusInternalServerError, expectedBody: `{"message":"Internal Server Error"}`, expectedError: "panic recovered while handling the request", + expectedLevel: logrus.ErrorLevel, expectedPanic: "boom", }, { @@ -129,6 +158,7 @@ func TestServer_ErrorHandling(t *testing.T) { expectedCode: http.StatusServiceUnavailable, expectedBody: `{"message":"maintenance"}`, expectedError: "panic recovered while handling the request", + expectedLevel: logrus.ErrorLevel, expectedPanic: echoLib.NewHTTPError(http.StatusServiceUnavailable, "maintenance").Error(), }, { @@ -139,6 +169,7 @@ func TestServer_ErrorHandling(t *testing.T) { expectedCode: http.StatusInternalServerError, expectedBody: `{"message":"Internal Server Error"}`, expectedError: "panic recovered while handling the request", + expectedLevel: logrus.ErrorLevel, expectedPanic: "boom", }, { @@ -148,6 +179,7 @@ func TestServer_ErrorHandling(t *testing.T) { expectedCode: http.StatusInternalServerError, expectedBody: `{"message":"Internal Server Error"}`, expectedError: "unexpected error while handling the request", + expectedLevel: logrus.ErrorLevel, }, { name: "unexpected error", @@ -156,6 +188,28 @@ func TestServer_ErrorHandling(t *testing.T) { expectedCode: http.StatusInternalServerError, expectedBody: `{"message":"Internal Server Error"}`, expectedError: "unexpected error while handling the request", + expectedLevel: logrus.ErrorLevel, + }, + { + // The client already received the status of the response, which the error cannot change. + name: "unexpected error after the response is sent", + path: "/fail-after-response", + route: "/fail-after-response", + expectedCode: http.StatusOK, + expectedBody: `{"message":"partial"}`, + expectedError: "unexpected error while handling the request", + expectedLevel: logrus.WarnLevel, + }, + { + // The error is caused by the client that went away. + name: "unexpected error after the client went away", + path: "/canceled", + route: "/canceled", + canceled: true, + expectedCode: http.StatusInternalServerError, + expectedBody: `{"message":"Internal Server Error"}`, + expectedError: "unexpected error while handling the request", + expectedLevel: logrus.DebugLevel, }, { name: "HTTP error", @@ -189,8 +243,14 @@ func TestServer_ErrorHandling(t *testing.T) { BuildHandler() require.NoError(t, err) + req := httptest.NewRequest(http.MethodGet, tt.path, nil) + if tt.canceled { + ctx, cancel := context.WithCancel(t.Context()) + cancel() + req = req.WithContext(ctx) + } rec := httptest.NewRecorder() - handler.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, tt.path, nil)) + handler.ServeHTTP(rec, req) assert.Equal(t, tt.expectedCode, rec.Code) assert.JSONEq(t, tt.expectedBody, rec.Body.String()) @@ -210,21 +270,26 @@ func TestServer_ErrorHandling(t *testing.T) { } assert.Equal(t, float64(1), counterValue(t, registry, "test_http_requests_total", labels)) - // Only the errors that don't carry an HTTP status are logged as errors. - errorEntry := findLogEntry(hook, tt.expectedError) + // Only the errors that don't carry an HTTP status are logged. if tt.expectedError == "" { for _, entry := range hook.AllEntries() { - assert.NotEqual(t, logrus.ErrorLevel, entry.Level, entry.Message) + assert.NotContains(t, []logrus.Level{logrus.WarnLevel, logrus.ErrorLevel}, entry.Level, entry.Message) } return } + errorEntry := findLogEntry(hook, tt.expectedError) require.NotNil(t, errorEntry) - assert.Equal(t, logrus.ErrorLevel, errorEntry.Level) + assert.Equal(t, tt.expectedLevel, errorEntry.Level) assert.Equal(t, http.MethodGet, errorEntry.Data["method"]) assert.Equal(t, tt.path, errorEntry.Data["uri"]) if tt.expectedPanic != "" { - assert.EqualError(t, errorEntry.Data[logrus.ErrorKey].(error), tt.expectedPanic) - assert.Contains(t, errorEntry.Data["stack"], "goroutine") + loggedErr, ok := errorEntry.Data[logrus.ErrorKey].(error) + require.True(t, ok, "the value of the panic must be logged as an error") + assert.EqualError(t, loggedErr, tt.expectedPanic) + // Only the stack of the goroutine that panicked is logged. + stack, ok := errorEntry.Data["stack"].(string) + require.True(t, ok, "the stack must be logged") + assert.Len(t, goroutineHeader.FindAllString(stack, -1), 1, stack) } }) } diff --git a/echo/logging.go b/echo/logging.go new file mode 100644 index 0000000..a14edba --- /dev/null +++ b/echo/logging.go @@ -0,0 +1,118 @@ +// Copyright The Perses Authors +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package echo + +import ( + "context" + "log/slog" + "maps" + "strings" + + "github.com/sirupsen/logrus" +) + +// logrusHandler is a slog.Handler writing the records with the standard logger of logrus. +// echo v5 logs with log/slog, so this handler is given to echo to have its logs with the same format, level and output as the other logs. +// The attributes are written as logrus fields. The keys of the attributes in a group are prefixed by the name of the group (like "group.key"). +type logrusHandler struct { + // fields are the attributes added by WithAttrs. + fields logrus.Fields + // groupPrefix prefixes the keys of the next attributes. It is built from the groups added by WithGroup. + groupPrefix string +} + +func (h logrusHandler) Enabled(_ context.Context, level slog.Level) bool { + return logrus.IsLevelEnabled(logrusLevel(level)) +} + +func (h logrusHandler) Handle(ctx context.Context, record slog.Record) error { + fields := make(logrus.Fields, len(h.fields)+record.NumAttrs()) + maps.Copy(fields, h.fields) + record.Attrs(func(attr slog.Attr) bool { + addField(fields, h.groupPrefix, attr) + return true + }) + // logrus uses the current time when the time of the record is zero. + logrus.WithContext(ctx).WithTime(record.Time).WithFields(fields).Log(logrusLevel(record.Level), record.Message) + return nil +} + +func (h logrusHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + fields := make(logrus.Fields, len(h.fields)+len(attrs)) + maps.Copy(fields, h.fields) + for _, attr := range attrs { + addField(fields, h.groupPrefix, attr) + } + return logrusHandler{fields: fields, groupPrefix: h.groupPrefix} +} + +func (h logrusHandler) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + return logrusHandler{fields: h.fields, groupPrefix: h.groupPrefix + name + "."} +} + +// addField adds the attribute to the fields. The attributes of a group are added one by one, prefixed by the name of the group. +func addField(fields logrus.Fields, prefix string, attr slog.Attr) { + attr.Value = attr.Value.Resolve() + if attr.Value.Kind() == slog.KindGroup { + // Like the handlers of slog, the attributes of a group without key are inlined. + if attr.Key != "" { + prefix += attr.Key + "." + } + for _, groupAttr := range attr.Value.Group() { + addField(fields, prefix, groupAttr) + } + return + } + // An attribute without key (like the empty attributes, ignored by the handlers of slog) cannot be a logrus field. + if attr.Key == "" { + return + } + fields[prefix+attr.Key] = attr.Value.Any() +} + +// logrusLevel converts a slog level to the closest logrus level. +// The levels Fatal and Panic are never returned, as logrus would exit or panic after logging. +func logrusLevel(level slog.Level) logrus.Level { + switch { + case level >= slog.LevelError: + return logrus.ErrorLevel + case level >= slog.LevelWarn: + return logrus.WarnLevel + case level >= slog.LevelInfo: + return logrus.InfoLevel + case level >= slog.LevelDebug: + return logrus.DebugLevel + default: + return logrus.TraceLevel + } +} + +// httpServerErrorWriter writes with logrus every line logged by the http.Server. +// The TLS handshake errors are caused by the clients (like a load balancer only checking that the port is open, or a client +// not supporting the TLS versions or cipher suites configured), so they are logged as warnings. +// The other errors (like a panic not recovered by a middleware) are logged as errors. +type httpServerErrorWriter struct{} + +func (httpServerErrorWriter) Write(p []byte) (int, error) { + message := strings.TrimSuffix(string(p), "\n") + level := logrus.ErrorLevel + if strings.HasPrefix(message, "http: TLS handshake error") { + level = logrus.WarnLevel + } + logrus.StandardLogger().Log(level, message) + return len(p), nil +} diff --git a/echo/logging_test.go b/echo/logging_test.go index e64ef92..c6a5f29 100644 --- a/echo/logging_test.go +++ b/echo/logging_test.go @@ -15,7 +15,10 @@ package echo import ( "context" + "errors" + "log/slog" "net/http" + "net/http/httptest" "strings" "testing" "time" @@ -43,13 +46,33 @@ func TestServer_ConfigureHTTPServer(t *testing.T) { assert.Equal(t, time.Duration(0), httpServer.WriteTimeout) assert.Equal(t, defaultIdleTimeout, httpServer.IdleTimeout) - // The errors of the server are logged with logrus. + // The errors of the server are logged with logrus. The TLS handshake errors are caused by the clients, so they are warnings. require.NotNil(t, httpServer.ErrorLog) - httpServer.ErrorLog.Printf("http: TLS handshake error from %s: EOF", "127.0.0.1:1234") - entry := hook.LastEntry() - require.NotNil(t, entry) - assert.Equal(t, logrus.ErrorLevel, entry.Level) - assert.Equal(t, "http: TLS handshake error from 127.0.0.1:1234: EOF", entry.Message) + tests := []struct { + name string + line string + expectedLevel logrus.Level + }{ + { + name: "TLS handshake error", + line: "http: TLS handshake error from 127.0.0.1:1234: EOF", + expectedLevel: logrus.WarnLevel, + }, + { + name: "panic not recovered by a middleware", + line: "http: panic serving 127.0.0.1:1234: boom", + expectedLevel: logrus.ErrorLevel, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + httpServer.ErrorLog.Print(tt.line) + entry := hook.LastEntry() + require.NotNil(t, entry) + assert.Equal(t, tt.expectedLevel, entry.Level) + assert.Equal(t, tt.line, entry.Message) + }) + } } // startServer starts the server built by the builder on a random port and returns its address, read from the logs. @@ -61,16 +84,18 @@ func startServer(t *testing.T, hook *logrustest.Hook, builder *Builder) string { require.NoError(t, err) require.NoError(t, task.Initialize()) - ctx, cancel := context.WithCancel(context.Background()) + ctx, cancel := context.WithCancel(t.Context()) done := make(chan struct{}) + var executeErr error go func() { defer close(done) - _ = task.Execute(ctx, cancel) + executeErr = task.Execute(ctx, cancel) }() t.Cleanup(func() { cancel() <-done - require.NoError(t, task.Finalize()) + assert.NoError(t, executeErr) + assert.NoError(t, task.Finalize()) }) return waitForListenAddress(t, hook) } @@ -129,38 +154,47 @@ func TestServer_FinalizeReturnsTheShutdownTimeout(t *testing.T) { api := &blockingRegister{started: make(chan struct{}), release: make(chan struct{})} builder := NewBuilder().APIRegistration(api).OverrideDefaultMiddleware(true) builder.ListenAddress("127.0.0.1:0") - task, err := builder.Build() + s, err := builder.build() require.NoError(t, err) - task.(*server).shutdownTimeout = 50 * time.Millisecond - require.NoError(t, task.Initialize()) + s.shutdownTimeout = 50 * time.Millisecond + require.NoError(t, s.Initialize()) - ctx, cancel := context.WithCancel(context.Background()) + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() done := make(chan struct{}) var executeErr error go func() { defer close(done) - executeErr = task.Execute(ctx, cancel) + executeErr = s.Execute(ctx, cancel) }() address := waitForListenAddress(t, hook) // A request is still running when the server is stopped, so the graceful shutdown reaches its timeout. - requestDone := make(chan struct{}) + requestErr := make(chan error, 1) go func() { - defer close(requestDone) - resp, reqErr := http.Get("http://" + address + "/block") + client := &http.Client{Timeout: 5 * time.Second} + resp, reqErr := client.Get("http://" + address + "/block") if reqErr == nil { - _ = resp.Body.Close() + reqErr = resp.Body.Close() } + requestErr <- reqErr }() - <-api.started + select { + case <-api.started: + case reqErr := <-requestErr: + t.Fatalf("the request ended before reaching the handler: %v", reqErr) + case <-time.After(5 * time.Second): + t.Fatal("the request didn't reach the handler") + } cancel() <-done close(api.release) - <-requestDone + // The shutdown timeout doesn't interrupt the request still running: it ends normally once released. + assert.NoError(t, <-requestErr) // The server stopped as requested, but its shutdown failed: the task must report it, like before echo v5. assert.NoError(t, executeErr) - err = task.Finalize() + err = s.Finalize() assert.ErrorIs(t, err, context.DeadlineExceeded) assert.ErrorContains(t, err, "server shutdown not properly") } @@ -171,3 +205,114 @@ func TestServer_FinalizeWithoutShutdownError(t *testing.T) { assert.NotEmpty(t, address) // startServer stops the server and checks Finalize returns no error at the end of the test. } + +func TestLogrusHandler(t *testing.T) { + testErr := errors.New("boom") + tests := []struct { + name string + log func(logger *slog.Logger) + expectedLevel logrus.Level + expectedFields logrus.Fields + }{ + { + name: "debug", + log: func(logger *slog.Logger) { logger.Debug("message") }, + expectedLevel: logrus.DebugLevel, + expectedFields: logrus.Fields{}, + }, + { + name: "info with attributes", + log: func(logger *slog.Logger) { logger.Info("message", "address", "127.0.0.1:8080", "count", 2) }, + expectedLevel: logrus.InfoLevel, + expectedFields: logrus.Fields{"address": "127.0.0.1:8080", "count": int64(2)}, + }, + { + name: "warning", + log: func(logger *slog.Logger) { logger.Warn("message") }, + expectedLevel: logrus.WarnLevel, + expectedFields: logrus.Fields{}, + }, + { + name: "error with the error as attribute", + log: func(logger *slog.Logger) { logger.Error("message", "error", testErr) }, + expectedLevel: logrus.ErrorLevel, + expectedFields: logrus.Fields{logrus.ErrorKey: testErr}, + }, + { + // logrus would exit or panic with the levels above error. + name: "level above error", + log: func(logger *slog.Logger) { logger.Log(context.Background(), slog.LevelError+4, "message") }, + expectedLevel: logrus.ErrorLevel, + expectedFields: logrus.Fields{}, + }, + { + name: "attributes and groups added to the logger", + log: func(logger *slog.Logger) { + logger.With("component", "echo").WithGroup("request").With("method", http.MethodGet). + Info("message", "status", http.StatusOK, slog.Group("user", "name", "admin")) + }, + expectedLevel: logrus.InfoLevel, + expectedFields: logrus.Fields{ + "component": "echo", + "request.method": http.MethodGet, + "request.status": int64(http.StatusOK), + "request.user.name": "admin", + }, + }, + { + name: "empty attributes are ignored, and the attributes of a group without key are inlined", + log: func(logger *slog.Logger) { + logger.WithGroup("").Info("message", slog.Attr{}, slog.Group("", "inlined", true), slog.Group("empty")) + }, + expectedLevel: logrus.InfoLevel, + expectedFields: logrus.Fields{"inlined": true}, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + hook := newLogHook(t) + tt.log(slog.New(logrusHandler{})) + require.Len(t, hook.AllEntries(), 1) + entry := hook.LastEntry() + assert.Equal(t, "message", entry.Message) + assert.Equal(t, tt.expectedLevel, entry.Level) + assert.Equal(t, tt.expectedFields, entry.Data) + }) + } +} + +func TestLogrusHandler_Enabled(t *testing.T) { + hook := newLogHook(t) + logrus.SetLevel(logrus.WarnLevel) + logger := slog.New(logrusHandler{}) + assert.False(t, logger.Enabled(context.Background(), slog.LevelInfo)) + assert.True(t, logger.Enabled(context.Background(), slog.LevelWarn)) + logger.Info("message") + assert.Empty(t, hook.AllEntries()) +} + +type doubleWriteRegister struct{} + +func (r *doubleWriteRegister) RegisterRoute(e *echoLib.Echo) { + e.GET("/double-write", func(c *echoLib.Context) error { + if err := c.NoContent(http.StatusOK); err != nil { + return err + } + return c.NoContent(http.StatusAccepted) + }) +} + +func TestServer_EchoLogsWithLogrus(t *testing.T) { + hook := newLogHook(t) + handler, err := NewBuilder().APIRegistration(&doubleWriteRegister{}).OverrideDefaultMiddleware(true).BuildHandler() + require.NoError(t, err) + + rec := httptest.NewRecorder() + handler.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/double-write", nil)) + assert.Equal(t, http.StatusOK, rec.Code) + + // echo logs with log/slog that the response was already written: the log is written with logrus. + entry := findLogEntry(hook, "echo: response already written to client") + require.NotNil(t, entry) + assert.Equal(t, logrus.ErrorLevel, entry.Level) +} diff --git a/echo/middleware/logger.go b/echo/middleware/logger.go index ce8279a..cecc141 100644 --- a/echo/middleware/logger.go +++ b/echo/middleware/logger.go @@ -37,10 +37,15 @@ var defaultLoggerConfig = LoggerConfig{ }, } +// Logger returns a middleware that logs every request (its method, escaped path and status) with logrus, once it is handled. +// It must be executed before the middleware Recover, so the panics are logged too. +// The error returned by the next handler is not handled here: it is returned, to be handled once by the central error handler of echo. +// The status logged is the one of the response that the error handler will send. func Logger() echo.MiddlewareFunc { return LoggerWithConfig(defaultLoggerConfig) } +// LoggerWithConfig returns a Logger middleware (see Logger) with the given configuration. func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc { if config.Skipper == nil { config.Skipper = defaultLoggerConfig.Skipper diff --git a/echo/middleware/metrics.go b/echo/middleware/metrics.go index 68050db..aef6e68 100644 --- a/echo/middleware/metrics.go +++ b/echo/middleware/metrics.go @@ -66,6 +66,7 @@ func (m *Metrics) Describe(ch chan<- *prometheus.Desc) { // ProcessHTTPRequest is an echo middleware. It will intercept all responses. // It will increase the metrics that count the number of HTTP request and calculate the time took to respond. +// It must be executed before the middleware Recover, so the panics are counted too. // The error returned by the next handler is returned as is, to be handled by the central error handler of echo. // The status code counted is the one of the response that will be sent, resolved from this error. func (m *Metrics) ProcessHTTPRequest(next echo.HandlerFunc) echo.HandlerFunc { diff --git a/echo/server.go b/echo/server.go index d682302..666833d 100644 --- a/echo/server.go +++ b/echo/server.go @@ -59,6 +59,7 @@ import ( "flag" "fmt" "log" + "log/slog" "net" "net/http" "net/http/pprof" @@ -88,7 +89,7 @@ const ( var ( // http address listened addr string - // hide port when printing the server status on stdout + // hide the address listened when logging that the server started hidePort bool // https cert for server cert string @@ -104,7 +105,7 @@ var ( func InitFlag() { flag.StringVar(&addr, "web.listen-address", defaultAddr, "The address to listen on for HTTP requests, web interface and telemetry.") - flag.BoolVar(&hidePort, "web.hide-port", false, "If true, it won't be print on stdout the port listened to receive the HTTP request") + flag.BoolVar(&hidePort, "web.hide-port", false, "If true, the address listened to receive the HTTP requests is not logged when the server starts") flag.StringVar(&cert, "web.tls-cert-file", "", "The path to the cert to use for the HTTPS server. It is reloaded when the file changes.") flag.StringVar(&key, "web.tls-key-file", "", "The path to the key to use for the HTTPS server. It is reloaded when the file changes.") flag.StringVar(&tlsMinVersion, "web.tls-min-version", "", "Minimum TLS version (e.g., \"1.2\", \"1.3\")") @@ -194,6 +195,8 @@ type Builder struct { readTimeout time.Duration writeTimeout time.Duration idleTimeout time.Duration + ipExtractor echo.IPExtractor + schemeExtractor echo.SchemeExtractor } func NewBuilder() *Builder { @@ -294,6 +297,28 @@ func (b *Builder) IdleTimeout(timeout time.Duration) *Builder { return b } +// IPExtractor sets how echo.Context.RealIP gets the IP address of the client. +// By default, the address of the direct peer (http.Request.RemoteAddr) is used, as the headers X-Forwarded-For and X-Real-IP +// can be spoofed by any client. When the server is behind proxies, use an extractor that only trusts the headers set by them, +// for example: +// +// builder.IPExtractor(echo.ExtractIPFromXFFHeader(echo.TrustIPRange(proxyNetwork))) +func (b *Builder) IPExtractor(extractor echo.IPExtractor) *Builder { + b.ipExtractor = extractor + return b +} + +// SchemeExtractor sets how echo.Context.Scheme gets the scheme (http or https) used by the client. +// By default, the headers like X-Forwarded-Proto are only trusted when the request comes from a loopback, link-local or +// private network address. When the server is behind a proxy with another address (like a CDN or a cloud load balancer), +// use an extractor that trusts it, for example: +// +// builder.SchemeExtractor(echo.ExtractSchemeFromHeaders(echo.TrustIPRange(proxyNetwork))) +func (b *Builder) SchemeExtractor(extractor echo.SchemeExtractor) *Builder { + b.schemeExtractor = extractor + return b +} + func (b *Builder) Build() (async.Task, error) { return b.build() } @@ -350,8 +375,9 @@ func (b *Builder) build() (*server, error) { defaultMiddleware = append(defaultMiddleware, // Recover from the panics anywhere in the rest of the chain. // The panic is returned as an error (with the stack trace) that is logged by the central error handler. + // Only the stack of the goroutine that panicked is kept: getting the stacks of all the goroutines stops the world. // More information here: https://echo.labstack.com/docs/middleware/recover - middleware.Recover(), + middleware.RecoverWithConfig(middleware.RecoverConfig{DisableStackAll: true}), middleware.GzipWithConfig( middleware.GzipConfig{ Skipper: b.gzipSkipper, @@ -385,7 +411,13 @@ func (b *Builder) build() (*server, error) { logrus.Warn("--web.tls-min-version, --web.tls-max-version and --web.tls-cipher-suites have no effect because HTTPS is not enabled (--web.tls-cert-file and --web.tls-key-file are not set)") } - e := echo.NewWithConfig(echo.Config{HTTPErrorHandler: handleError}) + e := echo.NewWithConfig(echo.Config{ + // echo logs with log/slog: its logs are written with logrus, like the other logs. + Logger: slog.New(logrusHandler{}), + HTTPErrorHandler: handleError, + IPExtractor: b.ipExtractor, + SchemeExtractor: b.schemeExtractor, + }) readHeaderTimeout := b.readHeaderTimeout if readHeaderTimeout == 0 { readHeaderTimeout = defaultReadHeaderTimeout @@ -486,7 +518,7 @@ func (s *server) Execute(ctx context.Context, cancelFunc context.CancelFunc) err startConfig := echo.StartConfig{ Address: s.addr, HideBanner: true, - // echo logs the address with its own logger, so it is logged with logrus by logListenerAddr instead. + // The address is logged by logListenerAddr instead of echo, to tell if the server uses HTTPS (like echo v4). HidePort: true, ListenerAddrFunc: s.logListenerAddr, GracefulTimeout: s.shutdownTimeout, @@ -541,16 +573,8 @@ func (s *server) configureHTTPServer(httpServer *http.Server) { httpServer.ReadTimeout = s.readTimeout httpServer.WriteTimeout = s.writeTimeout httpServer.IdleTimeout = s.idleTimeout - // The errors of the server (like the TLS handshake errors) are logged with logrus instead of the logger of echo. - httpServer.ErrorLog = log.New(logrusErrorWriter{}, "", 0) -} - -// logrusErrorWriter logs with logrus, as an error, every line written by a log.Logger. -type logrusErrorWriter struct{} - -func (logrusErrorWriter) Write(p []byte) (int, error) { - logrus.Error(strings.TrimSuffix(string(p), "\n")) - return len(p), nil + // echo logs every error of the server as an error, but the TLS handshake errors are caused by the clients. + httpServer.ErrorLog = log.New(httpServerErrorWriter{}, "", 0) } var defaultHTTPErrorHandler = echo.DefaultHTTPErrorHandler(false) @@ -563,15 +587,28 @@ func handleError(c *echo.Context, err error) { // The path logged by the access logger is used, as the handlers can rewrite the path of the request. entry := logrus.WithField("method", c.Request().Method).WithField("uri", persesMiddleware.RequestPath(c)) // A panic is checked first: its value can carry an HTTP status (like panic(echo.NewHTTPError(...))). - var panicErr *middleware.PanicStackError - if errors.As(err, &panicErr) { + if panicErr, ok := errors.AsType[*middleware.PanicStackError](err); ok { entry.WithError(panicErr.Err).WithField("stack", string(panicErr.Stack)).Error("panic recovered while handling the request") } else if echo.StatusCode(err) == 0 { - entry.WithError(err).Error("unexpected error while handling the request") + entry.WithError(err).Log(unexpectedErrorLevel(c), "unexpected error while handling the request") } defaultHTTPErrorHandler(c, err) } +// unexpectedErrorLevel returns the level of the log of an unexpected error. +// The error is less severe when the client went away, or when the response is already sent. +func unexpectedErrorLevel(c *echo.Context) logrus.Level { + if errors.Is(c.Request().Context().Err(), context.Canceled) { + // The request is canceled when the client closes the connection, so the error is likely caused by this cancellation. + return logrus.DebugLevel + } + if response, _ := echo.UnwrapResponse(c.Response()); response != nil && response.Committed { + // The client already received the status of the response, which the error cannot change anymore. + return logrus.WarnLevel + } + return logrus.ErrorLevel +} + // tlsConfig builds the TLS configuration of the HTTPS server. // The certificate is provided by a reloader, so a rotated certificate is used without restarting the server. func (s *server) tlsConfig() (*tls.Config, error) { From c06b06579f3f7ad4b8efc260fc4d77e81eb217ec Mon Sep 17 00:00:00 2001 From: Augustin Husson Date: Mon, 9 Nov 2026 11:34:12 +0100 Subject: [PATCH 5/6] echo: log the client errors of the http.Server as warnings and report the slog caller Address the second review of the upgrade to echo v5: - Most errors logged by the http.Server are caused by the clients (like the HTTP/2 protocol errors), so any client can trigger them. They are now logged as warnings, and only the defects of the server (like a panic not recovered by a middleware) as errors. - With --log.method-trace, the logs of echo report the code calling slog as caller, instead of the slog handler. - The comment of isHTTP2Compatible and its warning explain why HTTP/2 is only offered with one of the cipher suites required by RFC 7540: net/http doesn't check it when the TLS configuration is on the listener. - --web.hide-port is tested with a running server. - The central error handler moves to error_handler.go, and the log of the listen address to logging.go, so each test file matches its source file. - Fix the reason why the levels Fatal and Panic of logrus are not used. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Augustin Husson --- echo/error_handler.go | 57 ++++++++ echo/logging.go | 52 +++++-- echo/logging_test.go | 315 ++++++++++++++++++------------------------ echo/server.go | 55 +------- echo/server_test.go | 142 +++++++++++++++++++ 5 files changed, 387 insertions(+), 234 deletions(-) create mode 100644 echo/error_handler.go diff --git a/echo/error_handler.go b/echo/error_handler.go new file mode 100644 index 0000000..39d3473 --- /dev/null +++ b/echo/error_handler.go @@ -0,0 +1,57 @@ +// Copyright The Perses Authors +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package echo + +import ( + "context" + "errors" + + "github.com/labstack/echo/v5" + "github.com/labstack/echo/v5/middleware" + "github.com/sirupsen/logrus" + + persesMiddleware "github.com/perses/common/echo/middleware" +) + +var defaultHTTPErrorHandler = echo.DefaultHTTPErrorHandler(false) + +// handleError is the central error handler of the server, called with the error returned by the middleware chain. +// The panics recovered by the middleware Recover and the errors that don't carry an HTTP status (unexpected errors) +// are logged, as nothing turned them into a response. Then, like the default echo handler, it writes the error as a JSON +// response without exposing the internal errors. +func handleError(c *echo.Context, err error) { + // The path logged by the access logger is used, as the handlers can rewrite the path of the request. + entry := logrus.WithField("method", c.Request().Method).WithField("uri", persesMiddleware.RequestPath(c)) + // A panic is checked first: its value can carry an HTTP status (like panic(echo.NewHTTPError(...))). + if panicErr, ok := errors.AsType[*middleware.PanicStackError](err); ok { + entry.WithError(panicErr.Err).WithField("stack", string(panicErr.Stack)).Error("panic recovered while handling the request") + } else if echo.StatusCode(err) == 0 { + entry.WithError(err).Log(unexpectedErrorLevel(c), "unexpected error while handling the request") + } + defaultHTTPErrorHandler(c, err) +} + +// unexpectedErrorLevel returns the level of the log of an unexpected error. +// The error is less severe when the client went away, or when the response is already sent. +func unexpectedErrorLevel(c *echo.Context) logrus.Level { + if errors.Is(c.Request().Context().Err(), context.Canceled) { + // The request is canceled when the client closes the connection, so the error is likely caused by this cancellation. + return logrus.DebugLevel + } + if response, _ := echo.UnwrapResponse(c.Response()); response != nil && response.Committed { + // The client already received the status of the response, which the error cannot change anymore. + return logrus.WarnLevel + } + return logrus.ErrorLevel +} diff --git a/echo/logging.go b/echo/logging.go index a14edba..6630f0f 100644 --- a/echo/logging.go +++ b/echo/logging.go @@ -17,6 +17,9 @@ import ( "context" "log/slog" "maps" + "net" + "runtime" + "slices" "strings" "github.com/sirupsen/logrus" @@ -44,7 +47,14 @@ func (h logrusHandler) Handle(ctx context.Context, record slog.Record) error { return true }) // logrus uses the current time when the time of the record is zero. - logrus.WithContext(ctx).WithTime(record.Time).WithFields(fields).Log(logrusLevel(record.Level), record.Message) + entry := logrus.WithContext(ctx).WithTime(record.Time).WithFields(fields) + // When logrus reports the caller, it would report this method, so the caller of slog is given instead. + // It is only set in this case, as logrus writes the caller as soon as it is set. + if record.PC != 0 && logrus.StandardLogger().ReportCaller { + frame, _ := runtime.CallersFrames([]uintptr{record.PC}).Next() + entry.Caller = &frame + } + entry.Log(logrusLevel(record.Level), record.Message) return nil } @@ -85,7 +95,7 @@ func addField(fields logrus.Fields, prefix string, attr slog.Attr) { } // logrusLevel converts a slog level to the closest logrus level. -// The levels Fatal and Panic are never returned, as logrus would exit or panic after logging. +// slog has no level above Error, so the levels Fatal and Panic of logrus (for the errors stopping the process) are never returned. func logrusLevel(level slog.Level) logrus.Level { switch { case level >= slog.LevelError: @@ -102,17 +112,43 @@ func logrusLevel(level slog.Level) logrus.Level { } // httpServerErrorWriter writes with logrus every line logged by the http.Server. -// The TLS handshake errors are caused by the clients (like a load balancer only checking that the port is open, or a client -// not supporting the TLS versions or cipher suites configured), so they are logged as warnings. -// The other errors (like a panic not recovered by a middleware) are logged as errors. +// Most of these errors are caused by the clients (like the TLS handshake errors, or the HTTP/2 protocol errors), so they are +// logged as warnings, as any client can trigger them. Only the defects of the server (see httpServerDefects) are logged as errors. type httpServerErrorWriter struct{} +// httpServerDefects are the beginnings of the errors logged by the http.Server (net/http and its HTTP/2 server) +// that are caused by the server itself: a handler, or the system. +var httpServerDefects = []string{ + "http: panic serving", + "http2: panic serving", + "http: superfluous response.WriteHeader call", + // response.Write and response.WriteHeader on a hijacked connection. + "http: response.Write", + "http: invalid Content-Length", + "http: WriteHeader called with both Transfer-Encoding", + "ignoring invalid trailer", + "http: Accept error", + "http: error reading directory", +} + func (httpServerErrorWriter) Write(p []byte) (int, error) { message := strings.TrimSuffix(string(p), "\n") - level := logrus.ErrorLevel - if strings.HasPrefix(message, "http: TLS handshake error") { - level = logrus.WarnLevel + level := logrus.WarnLevel + if slices.ContainsFunc(httpServerDefects, func(prefix string) bool { return strings.HasPrefix(message, prefix) }) { + level = logrus.ErrorLevel } logrus.StandardLogger().Log(level, message) return len(p), nil } + +// logListenerAddr logs the address listened by the server, unless it is hidden with the flag --web.hide-port. +func (s *server) logListenerAddr(addr net.Addr) { + if hidePort { + return + } + scheme := "http" + if s.cert != "" { + scheme = "https" + } + logrus.Infof("%s server started on %s", scheme, addr) +} diff --git a/echo/logging_test.go b/echo/logging_test.go index c6a5f29..da6c627 100644 --- a/echo/logging_test.go +++ b/echo/logging_test.go @@ -16,196 +16,23 @@ package echo import ( "context" "errors" + "fmt" + "log" "log/slog" + "net" "net/http" "net/http/httptest" + "slices" "strings" "testing" "time" echoLib "github.com/labstack/echo/v5" "github.com/sirupsen/logrus" - logrustest "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) -func TestServer_ConfigureHTTPServer(t *testing.T) { - hook := newLogHook(t) - s, err := NewBuilder(). - APIRegistration(&mockRegister{}). - OverrideDefaultMiddleware(true). - build() - require.NoError(t, err) - - // echo creates the http.Server with a ReadTimeout of 30s, which must not be kept, as there is no read timeout by default. - httpServer := &http.Server{ReadTimeout: 30 * time.Second} - s.configureHTTPServer(httpServer) - assert.Equal(t, defaultReadHeaderTimeout, httpServer.ReadHeaderTimeout) - assert.Equal(t, time.Duration(0), httpServer.ReadTimeout) - assert.Equal(t, time.Duration(0), httpServer.WriteTimeout) - assert.Equal(t, defaultIdleTimeout, httpServer.IdleTimeout) - - // The errors of the server are logged with logrus. The TLS handshake errors are caused by the clients, so they are warnings. - require.NotNil(t, httpServer.ErrorLog) - tests := []struct { - name string - line string - expectedLevel logrus.Level - }{ - { - name: "TLS handshake error", - line: "http: TLS handshake error from 127.0.0.1:1234: EOF", - expectedLevel: logrus.WarnLevel, - }, - { - name: "panic not recovered by a middleware", - line: "http: panic serving 127.0.0.1:1234: boom", - expectedLevel: logrus.ErrorLevel, - }, - } - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - httpServer.ErrorLog.Print(tt.line) - entry := hook.LastEntry() - require.NotNil(t, entry) - assert.Equal(t, tt.expectedLevel, entry.Level) - assert.Equal(t, tt.line, entry.Message) - }) - } -} - -// startServer starts the server built by the builder on a random port and returns its address, read from the logs. -// The server is stopped at the end of the test. -func startServer(t *testing.T, hook *logrustest.Hook, builder *Builder) string { - t.Helper() - builder.ListenAddress("127.0.0.1:0") - task, err := builder.Build() - require.NoError(t, err) - require.NoError(t, task.Initialize()) - - ctx, cancel := context.WithCancel(t.Context()) - done := make(chan struct{}) - var executeErr error - go func() { - defer close(done) - executeErr = task.Execute(ctx, cancel) - }() - t.Cleanup(func() { - cancel() - <-done - assert.NoError(t, executeErr) - assert.NoError(t, task.Finalize()) - }) - return waitForListenAddress(t, hook) -} - -// waitForListenAddress waits for the server to log the address it listens on, and returns it. -func waitForListenAddress(t *testing.T, hook *logrustest.Hook) string { - t.Helper() - var address string - require.Eventually(t, func() bool { - for _, entry := range hook.AllEntries() { - if after, ok := strings.CutPrefix(entry.Message, "http server started on "); ok { - address = after - return true - } - } - return false - }, 5*time.Second, 10*time.Millisecond) - return address -} - -func TestServer_LogsTheListenAddress(t *testing.T) { - hook := newLogHook(t) - address := startServer(t, hook, NewBuilder().APIRegistration(&mockRegister{}).OverrideDefaultMiddleware(true)) - assert.True(t, strings.HasPrefix(address, "127.0.0.1:")) - assert.NotEqual(t, "127.0.0.1:0", address) -} - -func TestServer_HidesTheListenAddress(t *testing.T) { - origHidePort := hidePort - hidePort = true - t.Cleanup(func() { - hidePort = origHidePort - }) - hook := newLogHook(t) - s, err := NewBuilder().APIRegistration(&mockRegister{}).OverrideDefaultMiddleware(true).build() - require.NoError(t, err) - s.logListenerAddr(nil) - assert.Empty(t, hook.AllEntries()) -} - -type blockingRegister struct { - started chan struct{} - release chan struct{} -} - -func (r *blockingRegister) RegisterRoute(e *echoLib.Echo) { - e.GET("/block", func(c *echoLib.Context) error { - close(r.started) - <-r.release - return c.NoContent(http.StatusOK) - }) -} - -func TestServer_FinalizeReturnsTheShutdownTimeout(t *testing.T) { - hook := newLogHook(t) - api := &blockingRegister{started: make(chan struct{}), release: make(chan struct{})} - builder := NewBuilder().APIRegistration(api).OverrideDefaultMiddleware(true) - builder.ListenAddress("127.0.0.1:0") - s, err := builder.build() - require.NoError(t, err) - s.shutdownTimeout = 50 * time.Millisecond - require.NoError(t, s.Initialize()) - - ctx, cancel := context.WithCancel(t.Context()) - defer cancel() - done := make(chan struct{}) - var executeErr error - go func() { - defer close(done) - executeErr = s.Execute(ctx, cancel) - }() - address := waitForListenAddress(t, hook) - - // A request is still running when the server is stopped, so the graceful shutdown reaches its timeout. - requestErr := make(chan error, 1) - go func() { - client := &http.Client{Timeout: 5 * time.Second} - resp, reqErr := client.Get("http://" + address + "/block") - if reqErr == nil { - reqErr = resp.Body.Close() - } - requestErr <- reqErr - }() - select { - case <-api.started: - case reqErr := <-requestErr: - t.Fatalf("the request ended before reaching the handler: %v", reqErr) - case <-time.After(5 * time.Second): - t.Fatal("the request didn't reach the handler") - } - cancel() - <-done - close(api.release) - // The shutdown timeout doesn't interrupt the request still running: it ends normally once released. - assert.NoError(t, <-requestErr) - - // The server stopped as requested, but its shutdown failed: the task must report it, like before echo v5. - assert.NoError(t, executeErr) - err = s.Finalize() - assert.ErrorIs(t, err, context.DeadlineExceeded) - assert.ErrorContains(t, err, "server shutdown not properly") -} - -func TestServer_FinalizeWithoutShutdownError(t *testing.T) { - hook := newLogHook(t) - address := startServer(t, hook, NewBuilder().APIRegistration(&mockRegister{}).OverrideDefaultMiddleware(true)) - assert.NotEmpty(t, address) - // startServer stops the server and checks Finalize returns no error at the end of the test. -} - func TestLogrusHandler(t *testing.T) { testErr := errors.New("boom") tests := []struct { @@ -239,7 +66,7 @@ func TestLogrusHandler(t *testing.T) { expectedFields: logrus.Fields{logrus.ErrorKey: testErr}, }, { - // logrus would exit or panic with the levels above error. + // slog has no level above error: the levels above it are logged as errors. name: "level above error", log: func(logger *slog.Logger) { logger.Log(context.Background(), slog.LevelError+4, "message") }, expectedLevel: logrus.ErrorLevel, @@ -291,6 +118,28 @@ func TestLogrusHandler_Enabled(t *testing.T) { assert.Empty(t, hook.AllEntries()) } +func TestLogrusHandler_Caller(t *testing.T) { + hook := newLogHook(t) + logger := slog.New(logrusHandler{}) + + // The caller is not set when logrus doesn't report it, as logrus writes it as soon as it is set. + logger.Info("message") + entry := hook.LastEntry() + require.NotNil(t, entry) + assert.Nil(t, entry.Caller) + + // When logrus reports the caller, it is the code calling slog, not the handler. + origReportCaller := logrus.StandardLogger().ReportCaller + logrus.SetReportCaller(true) + t.Cleanup(func() { + logrus.SetReportCaller(origReportCaller) + }) + logger.Info("message") + entry = hook.LastEntry() + require.NotNil(t, entry.Caller) + assert.Equal(t, "github.com/perses/common/echo.TestLogrusHandler_Caller", entry.Caller.Function) +} + type doubleWriteRegister struct{} func (r *doubleWriteRegister) RegisterRoute(e *echoLib.Echo) { @@ -316,3 +165,113 @@ func TestServer_EchoLogsWithLogrus(t *testing.T) { require.NotNil(t, entry) assert.Equal(t, logrus.ErrorLevel, entry.Level) } + +func TestHTTPServerErrorWriter(t *testing.T) { + tests := []struct { + name string + line string + expectedLevel logrus.Level + }{ + { + name: "TLS handshake error", + line: "http: TLS handshake error from 127.0.0.1:1234: EOF", + expectedLevel: logrus.WarnLevel, + }, + { + name: "HTTP/2 preface sent by the client", + line: `http2: server: error reading preface from client 127.0.0.1:1234: bogus greeting "GET / HTTP/1.1"`, + expectedLevel: logrus.WarnLevel, + }, + { + name: "HTTP/2 protocol error of the client", + line: "http2: server connection error from 127.0.0.1:1234: connection error: PROTOCOL_ERROR", + expectedLevel: logrus.WarnLevel, + }, + { + name: "panic not recovered by a middleware", + line: "http: panic serving 127.0.0.1:1234: boom\ngoroutine 7 [running]:", + expectedLevel: logrus.ErrorLevel, + }, + { + name: "HTTP/2 panic not recovered by a middleware", + line: "http2: panic serving 127.0.0.1:1234: boom\ngoroutine 7 [running]:", + expectedLevel: logrus.ErrorLevel, + }, + { + name: "handler writing the header twice", + line: "http: superfluous response.WriteHeader call from main.handler (main.go:12)", + expectedLevel: logrus.ErrorLevel, + }, + { + name: "connections not accepted", + line: "http: Accept error: accept tcp 127.0.0.1:8080: accept: too many open files; retrying in 5ms", + expectedLevel: logrus.ErrorLevel, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + hook := newLogHook(t) + log.New(httpServerErrorWriter{}, "", 0).Print(tt.line) + entry := hook.LastEntry() + require.NotNil(t, entry) + assert.Equal(t, tt.expectedLevel, entry.Level) + assert.Equal(t, tt.line, entry.Message) + }) + } +} + +func TestServer_LogListenerAddr(t *testing.T) { + tests := []struct { + name string + hidePort bool + expectedLogged bool + }{ + { + name: "the address is logged", + expectedLogged: true, + }, + { + name: "the address is hidden with --web.hide-port", + hidePort: true, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + origHidePort := hidePort + hidePort = tt.hidePort + t.Cleanup(func() { + hidePort = origHidePort + }) + hook := newLogHook(t) + address := freeAddress(t) + builder := NewBuilder().APIRegistration(&helloRegister{}).OverrideDefaultMiddleware(true) + builder.ListenAddress(address) + runServer(t, builder) + + // Once the server answers, it has logged that it started (or not). + client := &http.Client{Timeout: time.Second} + require.Eventually(t, func() bool { + resp, err := client.Get("http://" + address + "/hello") + if err != nil { + return false + } + _ = resp.Body.Close() + return resp.StatusCode == http.StatusOK + }, 5*time.Second, 10*time.Millisecond) + logged := slices.ContainsFunc(hook.AllEntries(), func(entry *logrus.Entry) bool { + return strings.Contains(fmt.Sprint(entry.Message, entry.Data), address) + }) + assert.Equal(t, tt.expectedLogged, logged) + }) + } +} + +// freeAddress returns a local address with a port that is free when the function returns. +func freeAddress(t *testing.T) string { + t.Helper() + listener, err := net.Listen("tcp", "127.0.0.1:0") + require.NoError(t, err) + address := listener.Addr().String() + require.NoError(t, listener.Close()) + return address +} diff --git a/echo/server.go b/echo/server.go index 666833d..8cee3c2 100644 --- a/echo/server.go +++ b/echo/server.go @@ -60,7 +60,6 @@ import ( "fmt" "log" "log/slog" - "net" "net/http" "net/http/pprof" "slices" @@ -555,17 +554,6 @@ func (s *server) Execute(ctx context.Context, cancelFunc context.CancelFunc) err return nil } -func (s *server) logListenerAddr(addr net.Addr) { - if hidePort { - return - } - scheme := "http" - if s.cert != "" { - scheme = "https" - } - logrus.Infof("%s server started on %s", scheme, addr) -} - // configureHTTPServer sets the timeouts and the error logger of the http.Server created by echo. // Every timeout is set, even when it is zero, as echo sets a default ReadTimeout. func (s *server) configureHTTPServer(httpServer *http.Server) { @@ -573,42 +561,10 @@ func (s *server) configureHTTPServer(httpServer *http.Server) { httpServer.ReadTimeout = s.readTimeout httpServer.WriteTimeout = s.writeTimeout httpServer.IdleTimeout = s.idleTimeout - // echo logs every error of the server as an error, but the TLS handshake errors are caused by the clients. + // echo logs every error of the server as an error, but most of them are caused by the clients (see httpServerErrorWriter). httpServer.ErrorLog = log.New(httpServerErrorWriter{}, "", 0) } -var defaultHTTPErrorHandler = echo.DefaultHTTPErrorHandler(false) - -// handleError is the central error handler of the server, called with the error returned by the middleware chain. -// The panics recovered by the middleware Recover and the errors that don't carry an HTTP status (unexpected errors) -// are logged, as nothing turned them into a response. Then, like the default echo handler, it writes the error as a JSON -// response without exposing the internal errors. -func handleError(c *echo.Context, err error) { - // The path logged by the access logger is used, as the handlers can rewrite the path of the request. - entry := logrus.WithField("method", c.Request().Method).WithField("uri", persesMiddleware.RequestPath(c)) - // A panic is checked first: its value can carry an HTTP status (like panic(echo.NewHTTPError(...))). - if panicErr, ok := errors.AsType[*middleware.PanicStackError](err); ok { - entry.WithError(panicErr.Err).WithField("stack", string(panicErr.Stack)).Error("panic recovered while handling the request") - } else if echo.StatusCode(err) == 0 { - entry.WithError(err).Log(unexpectedErrorLevel(c), "unexpected error while handling the request") - } - defaultHTTPErrorHandler(c, err) -} - -// unexpectedErrorLevel returns the level of the log of an unexpected error. -// The error is less severe when the client went away, or when the response is already sent. -func unexpectedErrorLevel(c *echo.Context) logrus.Level { - if errors.Is(c.Request().Context().Err(), context.Canceled) { - // The request is canceled when the client closes the connection, so the error is likely caused by this cancellation. - return logrus.DebugLevel - } - if response, _ := echo.UnwrapResponse(c.Response()); response != nil && response.Committed { - // The client already received the status of the response, which the error cannot change anymore. - return logrus.WarnLevel - } - return logrus.ErrorLevel -} - // tlsConfig builds the TLS configuration of the HTTPS server. // The certificate is provided by a reloader, so a rotated certificate is used without restarting the server. func (s *server) tlsConfig() (*tls.Config, error) { @@ -625,14 +581,17 @@ func (s *server) tlsConfig() (*tls.Config, error) { if isHTTP2Compatible(s.tlsMinVersion, s.tlsCipherSuites) { tlsConfig.NextProtos = []string{"h2"} } else { - logrus.Warn("HTTP/2 is disabled because --web.tls-cipher-suites contains neither TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 nor TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, required by HTTP/2") + logrus.Warn("HTTP/2 is disabled because --web.tls-cipher-suites contains neither TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 nor TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, one of which HTTP/2 requires with TLS 1.2 (RFC 7540, section 9.2.2)") } return tlsConfig, nil } // isHTTP2Compatible tells if HTTP/2 can be offered with the given TLS settings. -// HTTP/2 requires one of these cipher suites when TLS 1.2 is allowed (RFC 7540, section 9.2.2), -// otherwise the connections of the clients negotiating HTTP/2 with another cipher suite are rejected. +// With TLS 1.2, HTTP/2 deployments must support TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (RFC 7540, section 9.2.2), so every +// HTTP/2 client can negotiate a cipher suite allowed by HTTP/2 (the connections using a cipher suite forbidden by +// RFC 7540, appendix A, are rejected). net/http checks it only when the TLS configuration is set on the http.Server, +// not on the listener like here. So, like net/http, HTTP/2 is only offered when TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 +// or TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 is configured. func isHTTP2Compatible(minVersion uint16, cipherSuites []uint16) bool { if len(cipherSuites) == 0 || minVersion >= tls.VersionTLS13 { return true diff --git a/echo/server_test.go b/echo/server_test.go index 577f2a7..83b44c3 100644 --- a/echo/server_test.go +++ b/echo/server_test.go @@ -17,6 +17,7 @@ import ( "context" "crypto/tls" "net" + "net/http" "strings" "testing" "time" @@ -407,6 +408,30 @@ func TestBuild_TLSFlagValues(t *testing.T) { assert.Equal(t, "/path/key.pem", s.key) } +func TestServer_ConfigureHTTPServer(t *testing.T) { + hook := newLogHook(t) + s, err := NewBuilder(). + APIRegistration(&mockRegister{}). + OverrideDefaultMiddleware(true). + build() + require.NoError(t, err) + + // echo creates the http.Server with a ReadTimeout of 30s, which must not be kept, as there is no read timeout by default. + httpServer := &http.Server{ReadTimeout: 30 * time.Second} + s.configureHTTPServer(httpServer) + assert.Equal(t, defaultReadHeaderTimeout, httpServer.ReadHeaderTimeout) + assert.Equal(t, time.Duration(0), httpServer.ReadTimeout) + assert.Equal(t, time.Duration(0), httpServer.WriteTimeout) + assert.Equal(t, defaultIdleTimeout, httpServer.IdleTimeout) + + // The errors of the server are logged with logrus (their levels are tested by TestHTTPServerErrorWriter). + require.NotNil(t, httpServer.ErrorLog) + httpServer.ErrorLog.Print("http: TLS handshake error from 127.0.0.1:1234: EOF") + entry := hook.LastEntry() + require.NotNil(t, entry) + assert.Equal(t, "http: TLS handshake error from 127.0.0.1:1234: EOF", entry.Message) +} + func TestIsHTTP2Compatible(t *testing.T) { tests := []struct { name string @@ -660,3 +685,120 @@ func TestBuild_PartialTLSConfigurationDoesNotModifyTheBuilder(t *testing.T) { _, err = builder.Build() require.NoError(t, err) } + +// runServer runs the server built by the builder until the end of the test, when it is stopped and finalized. +func runServer(t *testing.T, builder *Builder) { + t.Helper() + task, err := builder.Build() + require.NoError(t, err) + require.NoError(t, task.Initialize()) + + ctx, cancel := context.WithCancel(t.Context()) + done := make(chan struct{}) + var executeErr error + go func() { + defer close(done) + executeErr = task.Execute(ctx, cancel) + }() + t.Cleanup(func() { + cancel() + <-done + assert.NoError(t, executeErr) + assert.NoError(t, task.Finalize()) + }) +} + +// startServer runs the server built by the builder on a random port until the end of the test, and returns its address, +// read from the logs. +func startServer(t *testing.T, hook *logrustest.Hook, builder *Builder) string { + t.Helper() + builder.ListenAddress("127.0.0.1:0") + runServer(t, builder) + return waitForListenAddress(t, hook) +} + +// waitForListenAddress waits for the server to log the address it listens on, and returns it. +func waitForListenAddress(t *testing.T, hook *logrustest.Hook) string { + t.Helper() + var address string + require.Eventually(t, func() bool { + for _, entry := range hook.AllEntries() { + if after, ok := strings.CutPrefix(entry.Message, "http server started on "); ok { + address = after + return true + } + } + return false + }, 5*time.Second, 10*time.Millisecond) + return address +} + +type blockingRegister struct { + started chan struct{} + release chan struct{} +} + +func (r *blockingRegister) RegisterRoute(e *echoLib.Echo) { + e.GET("/block", func(c *echoLib.Context) error { + close(r.started) + <-r.release + return c.NoContent(http.StatusOK) + }) +} + +func TestServer_FinalizeReturnsTheShutdownTimeout(t *testing.T) { + hook := newLogHook(t) + api := &blockingRegister{started: make(chan struct{}), release: make(chan struct{})} + builder := NewBuilder().APIRegistration(api).OverrideDefaultMiddleware(true) + builder.ListenAddress("127.0.0.1:0") + s, err := builder.build() + require.NoError(t, err) + s.shutdownTimeout = 50 * time.Millisecond + require.NoError(t, s.Initialize()) + + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + done := make(chan struct{}) + var executeErr error + go func() { + defer close(done) + executeErr = s.Execute(ctx, cancel) + }() + address := waitForListenAddress(t, hook) + + // A request is still running when the server is stopped, so the graceful shutdown reaches its timeout. + requestErr := make(chan error, 1) + go func() { + client := &http.Client{Timeout: 5 * time.Second} + resp, reqErr := client.Get("http://" + address + "/block") + if reqErr == nil { + reqErr = resp.Body.Close() + } + requestErr <- reqErr + }() + select { + case <-api.started: + case reqErr := <-requestErr: + t.Fatalf("the request ended before reaching the handler: %v", reqErr) + case <-time.After(5 * time.Second): + t.Fatal("the request didn't reach the handler") + } + cancel() + <-done + close(api.release) + // The shutdown timeout doesn't interrupt the request still running: it ends normally once released. + assert.NoError(t, <-requestErr) + + // The server stopped as requested, but its shutdown failed: the task must report it, like before echo v5. + assert.NoError(t, executeErr) + err = s.Finalize() + assert.ErrorIs(t, err, context.DeadlineExceeded) + assert.ErrorContains(t, err, "server shutdown not properly") +} + +func TestServer_FinalizeWithoutShutdownError(t *testing.T) { + hook := newLogHook(t) + address := startServer(t, hook, NewBuilder().APIRegistration(&mockRegister{}).OverrideDefaultMiddleware(true)) + assert.NotEmpty(t, address) + // startServer stops the server and checks Finalize returns no error at the end of the test. +} From 013b92476cdcb86846df45bca376d6cc1a67bd14 Mon Sep 17 00:00:00 2001 From: Augustin Husson Date: Mon, 9 Nov 2026 12:19:39 +0100 Subject: [PATCH 6/6] echo: log the unexpected errors at the debug level only when the client went away Address the third review of the upgrade to echo v5: - A middleware can replace the context of the request and cancel it (like echo's ContextTimeout), so every unexpected error was logged at the debug level. The context of the request is now saved as received by the server, before any middleware, and an error is logged at the debug level only when it is a cancellation and this context is canceled (the client went away). - The access log, the metrics and the error log use the method of the request as received, like the path, even if a handler rewrites it (like a proxy). middleware.RequestMethod returns it, next to middleware.RequestPath. - logrus has no way to read if it reports the caller without racing with SetReportCaller, so this setting is read once, when the server is built. - With --log.method-trace, the errors of the http.Server report the code of net/http that logged them as caller, instead of the writer. - The slog handler builds the logrus entry directly (12 allocations per log instead of 18), and the error handler builds its entry only when it logs. - The Logger middleware test checks the status and the method logged. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Augustin Husson --- echo/error_handler.go | 44 +++++++++++++++---- echo/error_handler_test.go | 69 ++++++++++++++++++++++++++++-- echo/logging.go | 60 ++++++++++++++++++++++---- echo/logging_test.go | 53 +++++++++++++++++++---- echo/middleware/logger.go | 40 +++++++++++++----- echo/middleware/logger_test.go | 77 ++++++++++++++++++++++++++-------- echo/middleware/metrics.go | 3 +- echo/server.go | 6 ++- 8 files changed, 294 insertions(+), 58 deletions(-) diff --git a/echo/error_handler.go b/echo/error_handler.go index 39d3473..96c9b76 100644 --- a/echo/error_handler.go +++ b/echo/error_handler.go @@ -26,27 +26,55 @@ import ( var defaultHTTPErrorHandler = echo.DefaultHTTPErrorHandler(false) +// contextKeyRequestContext is the key of the echo context in which saveRequestContext saves the context of the request. +const contextKeyRequestContext = "github.com/perses/common/echo.requestContext" + +// saveRequestContext is a middleware, executed before every other one, that saves the context of the request as received +// by the server. The middlewares and the handlers can replace the context of the request (like the middleware ContextTimeout, +// which cancels its own context once the request is handled), so only this one tells if the client went away. +func saveRequestContext(next echo.HandlerFunc) echo.HandlerFunc { + return func(c *echo.Context) error { + c.Set(contextKeyRequestContext, c.Request().Context()) + return next(c) + } +} + +// requestContext returns the context of the request as received by the server (see saveRequestContext). +func requestContext(c *echo.Context) context.Context { + if ctx, ok := c.Get(contextKeyRequestContext).(context.Context); ok { + return ctx + } + return c.Request().Context() +} + // handleError is the central error handler of the server, called with the error returned by the middleware chain. // The panics recovered by the middleware Recover and the errors that don't carry an HTTP status (unexpected errors) // are logged, as nothing turned them into a response. Then, like the default echo handler, it writes the error as a JSON // response without exposing the internal errors. func handleError(c *echo.Context, err error) { - // The path logged by the access logger is used, as the handlers can rewrite the path of the request. - entry := logrus.WithField("method", c.Request().Method).WithField("uri", persesMiddleware.RequestPath(c)) // A panic is checked first: its value can carry an HTTP status (like panic(echo.NewHTTPError(...))). if panicErr, ok := errors.AsType[*middleware.PanicStackError](err); ok { - entry.WithError(panicErr.Err).WithField("stack", string(panicErr.Stack)).Error("panic recovered while handling the request") + requestLogEntry(c).WithError(panicErr.Err).WithField("stack", string(panicErr.Stack)).Error("panic recovered while handling the request") } else if echo.StatusCode(err) == 0 { - entry.WithError(err).Log(unexpectedErrorLevel(c), "unexpected error while handling the request") + requestLogEntry(c).WithError(err).Log(unexpectedErrorLevel(c, err), "unexpected error while handling the request") } defaultHTTPErrorHandler(c, err) } +// requestLogEntry returns a log entry describing the request like the access log: with the method and the escaped path +// of the request as received, as the handlers can rewrite them (see persesMiddleware.RequestMethod and RequestPath). +func requestLogEntry(c *echo.Context) *logrus.Entry { + return logrus.WithFields(logrus.Fields{ + "method": persesMiddleware.RequestMethod(c), + "uri": persesMiddleware.RequestPath(c), + }) +} + // unexpectedErrorLevel returns the level of the log of an unexpected error. -// The error is less severe when the client went away, or when the response is already sent. -func unexpectedErrorLevel(c *echo.Context) logrus.Level { - if errors.Is(c.Request().Context().Err(), context.Canceled) { - // The request is canceled when the client closes the connection, so the error is likely caused by this cancellation. +// The error is less severe when it is caused by the client that went away, or when the response is already sent. +func unexpectedErrorLevel(c *echo.Context, err error) logrus.Level { + if errors.Is(err, context.Canceled) && requestContext(c).Err() != nil { + // The request is canceled when the client closes the connection, and the error is caused by this cancellation. return logrus.DebugLevel } if response, _ := echo.UnwrapResponse(c.Response()); response != nil && response.Committed { diff --git a/echo/error_handler_test.go b/echo/error_handler_test.go index 08c6861..3534d03 100644 --- a/echo/error_handler_test.go +++ b/echo/error_handler_test.go @@ -22,8 +22,10 @@ import ( "regexp" "strconv" "testing" + "time" echoLib "github.com/labstack/echo/v5" + "github.com/labstack/echo/v5/middleware" "github.com/prometheus/client_golang/prometheus" "github.com/sirupsen/logrus" logrustest "github.com/sirupsen/logrus/hooks/test" @@ -101,6 +103,10 @@ func (r *errorRegister) RegisterRoute(e *echoLib.Echo) { c.Request().URL.Path = "/rewritten" return errors.New("unexpected failure") }) + e.GET("/rewrite-method-then-fail", func(c *echoLib.Context) error { + c.Request().Method = http.MethodPost + return errors.New("unexpected failure") + }) e.GET("/unexpected", func(_ *echoLib.Context) error { return errors.New("unexpected failure") }) @@ -114,6 +120,13 @@ func (r *errorRegister) RegisterRoute(e *echoLib.Echo) { e.GET("/canceled", func(c *echoLib.Context) error { return c.Request().Context().Err() }) + // Like a handler aborting its own work, the handler cancels the context of the request, while the client is still there. + e.GET("/canceled-by-the-server", func(c *echoLib.Context) error { + ctx, cancel := context.WithCancel(c.Request().Context()) + c.SetRequest(c.Request().WithContext(ctx)) + cancel() + return ctx.Err() + }) e.GET("/unauthorized", func(_ *echoLib.Context) error { return echoLib.NewHTTPError(http.StatusUnauthorized, "missing token") }) @@ -131,7 +144,9 @@ func TestServer_ErrorHandling(t *testing.T) { path string route string // canceled cancels the request before it is handled, like when the client went away. - canceled bool + canceled bool + // middlewares are added after the default ones. + middlewares []echoLib.MiddlewareFunc expectedCode int expectedBody string // expectedError is the message of the error logged (if any) with the level expectedLevel. @@ -181,6 +196,16 @@ func TestServer_ErrorHandling(t *testing.T) { expectedError: "unexpected error while handling the request", expectedLevel: logrus.ErrorLevel, }, + { + // Like a proxy, the handler rewrites the method: the logs and the metrics use the method received. + name: "unexpected error after the method is rewritten", + path: "/rewrite-method-then-fail", + route: "/rewrite-method-then-fail", + expectedCode: http.StatusInternalServerError, + expectedBody: `{"message":"Internal Server Error"}`, + expectedError: "unexpected error while handling the request", + expectedLevel: logrus.ErrorLevel, + }, { name: "unexpected error", path: "/unexpected", @@ -190,6 +215,38 @@ func TestServer_ErrorHandling(t *testing.T) { expectedError: "unexpected error while handling the request", expectedLevel: logrus.ErrorLevel, }, + { + // The middleware ContextTimeout cancels its own context once the request is handled: the client didn't go away. + name: "unexpected error with a middleware canceling its context", + path: "/unexpected", + route: "/unexpected", + middlewares: []echoLib.MiddlewareFunc{middleware.ContextTimeout(time.Minute)}, + expectedCode: http.StatusInternalServerError, + expectedBody: `{"message":"Internal Server Error"}`, + expectedError: "unexpected error while handling the request", + expectedLevel: logrus.ErrorLevel, + }, + { + // The error is caused by a cancellation, but the client didn't go away: the server canceled its own context. + name: "cancellation by the server", + path: "/canceled-by-the-server", + route: "/canceled-by-the-server", + expectedCode: http.StatusInternalServerError, + expectedBody: `{"message":"Internal Server Error"}`, + expectedError: "unexpected error while handling the request", + expectedLevel: logrus.ErrorLevel, + }, + { + // The client went away, but the error is not caused by the cancellation of the request. + name: "unexpected error not caused by the client that went away", + path: "/unexpected", + route: "/unexpected", + canceled: true, + expectedCode: http.StatusInternalServerError, + expectedBody: `{"message":"Internal Server Error"}`, + expectedError: "unexpected error while handling the request", + expectedLevel: logrus.ErrorLevel, + }, { // The client already received the status of the response, which the error cannot change. name: "unexpected error after the response is sent", @@ -236,11 +293,14 @@ func TestServer_ErrorHandling(t *testing.T) { t.Run(tt.name, func(t *testing.T) { hook := newLogHook(t) registry := prometheus.NewRegistry() - handler, err := NewBuilder(). + builder := NewBuilder(). APIRegistration(&errorRegister{}). MetricNamespace("test"). - PrometheusRegisterer(registry). - BuildHandler() + PrometheusRegisterer(registry) + for _, mdw := range tt.middlewares { + builder.Middleware(mdw) + } + handler, err := builder.BuildHandler() require.NoError(t, err) req := httptest.NewRequest(http.MethodGet, tt.path, nil) @@ -264,6 +324,7 @@ func TestServer_ErrorHandling(t *testing.T) { } require.NotNil(t, accessLog) assert.Equal(t, tt.expectedCode, accessLog.Data["status"]) + assert.Equal(t, http.MethodGet, accessLog.Data["method"]) labels := map[string]string{"code": strconv.Itoa(tt.expectedCode), "method": http.MethodGet} if tt.route != "" { labels["handler"] = tt.route diff --git a/echo/logging.go b/echo/logging.go index 6630f0f..d8bdb16 100644 --- a/echo/logging.go +++ b/echo/logging.go @@ -33,6 +33,15 @@ type logrusHandler struct { fields logrus.Fields // groupPrefix prefixes the keys of the next attributes. It is built from the groups added by WithGroup. groupPrefix string + // reportCaller tells if logrus reports the caller (see newLogrusHandler). + reportCaller bool +} + +// newLogrusHandler returns a logrusHandler for the current configuration of logrus. +// logrus has no way to read if it reports the caller without racing with SetReportCaller, so this setting is read once, +// here: logrus must be configured before (like app.Runner does). +func newLogrusHandler() logrusHandler { + return logrusHandler{reportCaller: logrus.StandardLogger().ReportCaller} } func (h logrusHandler) Enabled(_ context.Context, level slog.Level) bool { @@ -46,11 +55,12 @@ func (h logrusHandler) Handle(ctx context.Context, record slog.Record) error { addField(fields, h.groupPrefix, attr) return true }) + // The entry is built directly, as WithContext, WithTime and WithFields would copy it each time. // logrus uses the current time when the time of the record is zero. - entry := logrus.WithContext(ctx).WithTime(record.Time).WithFields(fields) + entry := &logrus.Entry{Logger: logrus.StandardLogger(), Data: fields, Time: record.Time, Context: ctx} // When logrus reports the caller, it would report this method, so the caller of slog is given instead. // It is only set in this case, as logrus writes the caller as soon as it is set. - if record.PC != 0 && logrus.StandardLogger().ReportCaller { + if h.reportCaller && record.PC != 0 { frame, _ := runtime.CallersFrames([]uintptr{record.PC}).Next() entry.Caller = &frame } @@ -64,14 +74,17 @@ func (h logrusHandler) WithAttrs(attrs []slog.Attr) slog.Handler { for _, attr := range attrs { addField(fields, h.groupPrefix, attr) } - return logrusHandler{fields: fields, groupPrefix: h.groupPrefix} + // h is a copy: the receiver is not modified, and the other settings are kept. + h.fields = fields + return h } func (h logrusHandler) WithGroup(name string) slog.Handler { if name == "" { return h } - return logrusHandler{fields: h.fields, groupPrefix: h.groupPrefix + name + "."} + h.groupPrefix += name + "." + return h } // addField adds the attribute to the fields. The attributes of a group are added one by one, prefixed by the name of the group. @@ -114,7 +127,15 @@ func logrusLevel(level slog.Level) logrus.Level { // httpServerErrorWriter writes with logrus every line logged by the http.Server. // Most of these errors are caused by the clients (like the TLS handshake errors, or the HTTP/2 protocol errors), so they are // logged as warnings, as any client can trigger them. Only the defects of the server (see httpServerDefects) are logged as errors. -type httpServerErrorWriter struct{} +type httpServerErrorWriter struct { + // reportCaller tells if logrus reports the caller (see newLogrusHandler). + reportCaller bool +} + +// newHTTPServerErrorWriter returns an httpServerErrorWriter for the current configuration of logrus (see newLogrusHandler). +func newHTTPServerErrorWriter() httpServerErrorWriter { + return httpServerErrorWriter{reportCaller: logrus.StandardLogger().ReportCaller} +} // httpServerDefects are the beginnings of the errors logged by the http.Server (net/http and its HTTP/2 server) // that are caused by the server itself: a handler, or the system. @@ -131,16 +152,41 @@ var httpServerDefects = []string{ "http: error reading directory", } -func (httpServerErrorWriter) Write(p []byte) (int, error) { +func (w httpServerErrorWriter) Write(p []byte) (int, error) { message := strings.TrimSuffix(string(p), "\n") level := logrus.WarnLevel if slices.ContainsFunc(httpServerDefects, func(prefix string) bool { return strings.HasPrefix(message, prefix) }) { level = logrus.ErrorLevel } - logrus.StandardLogger().Log(level, message) + entry := logrus.NewEntry(logrus.StandardLogger()) + // When logrus reports the caller, it would report this method, so the code of net/http that logged is given instead. + if w.reportCaller { + entry.Caller = httpServerLogCaller() + } + entry.Log(level, message) return len(p), nil } +// httpServerLogCaller returns the code that logged with the error logger of the http.Server. +// It skips this writer, the package log, and the logging functions of net/http (like Server.logf, used by the code logging). +func httpServerLogCaller() *runtime.Frame { + var pcs [16]uintptr + // runtime.Callers, httpServerLogCaller and httpServerErrorWriter.Write are skipped. + frames := runtime.CallersFrames(pcs[:runtime.Callers(3, pcs[:])]) + for { + frame, more := frames.Next() + isLogging := strings.HasPrefix(frame.Function, "log.") || + (strings.HasPrefix(frame.Function, "net/http") && strings.HasSuffix(frame.Function, "logf")) + if frame.Function != "" && !isLogging { + return &frame + } + if !more { + // logrus reports its own caller when none is given. + return nil + } + } +} + // logListenerAddr logs the address listened by the server, unless it is hidden with the flag --web.hide-port. func (s *server) logListenerAddr(addr net.Addr) { if hidePort { diff --git a/echo/logging_test.go b/echo/logging_test.go index da6c627..471edc4 100644 --- a/echo/logging_test.go +++ b/echo/logging_test.go @@ -120,24 +120,28 @@ func TestLogrusHandler_Enabled(t *testing.T) { func TestLogrusHandler_Caller(t *testing.T) { hook := newLogHook(t) - logger := slog.New(logrusHandler{}) - // The caller is not set when logrus doesn't report it, as logrus writes it as soon as it is set. - logger.Info("message") + slog.New(newLogrusHandler()).Info("message") entry := hook.LastEntry() require.NotNil(t, entry) assert.Nil(t, entry.Caller) // When logrus reports the caller, it is the code calling slog, not the handler. + setReportCaller(t, true) + slog.New(newLogrusHandler()).With("key", "value").WithGroup("group").Info("message") + entry = hook.LastEntry() + require.NotNil(t, entry.Caller) + assert.Equal(t, "github.com/perses/common/echo.TestLogrusHandler_Caller", entry.Caller.Function) +} + +// setReportCaller sets if logrus reports the caller until the end of the test. +func setReportCaller(t *testing.T, reportCaller bool) { + t.Helper() origReportCaller := logrus.StandardLogger().ReportCaller - logrus.SetReportCaller(true) + logrus.SetReportCaller(reportCaller) t.Cleanup(func() { logrus.SetReportCaller(origReportCaller) }) - logger.Info("message") - entry = hook.LastEntry() - require.NotNil(t, entry.Caller) - assert.Equal(t, "github.com/perses/common/echo.TestLogrusHandler_Caller", entry.Caller.Function) } type doubleWriteRegister struct{} @@ -220,6 +224,39 @@ func TestHTTPServerErrorWriter(t *testing.T) { } } +func TestHTTPServerErrorWriter_Caller(t *testing.T) { + hook := newLogHook(t) + // The caller is not set when logrus doesn't report it, as logrus writes it as soon as it is set. + log.New(newHTTPServerErrorWriter(), "", 0).Print("http: TLS handshake error from 127.0.0.1:1234: EOF") + entry := hook.LastEntry() + require.NotNil(t, entry) + assert.Nil(t, entry.Caller) + + // When logrus reports the caller, it is the code of net/http that logged the error, not the writer or the package log. + setReportCaller(t, true) + server := httptest.NewUnstartedServer(http.NotFoundHandler()) + server.Config.ErrorLog = log.New(newHTTPServerErrorWriter(), "", 0) + server.StartTLS() + t.Cleanup(server.Close) + hook.Reset() + // A client sending HTTP to the HTTPS server makes it log a TLS handshake error. + conn, err := net.Dial("tcp", server.Listener.Addr().String()) + require.NoError(t, err) + t.Cleanup(func() { + _ = conn.Close() + }) + _, err = conn.Write([]byte("GET / HTTP/1.1\r\nHost: localhost\r\n\r\n")) + require.NoError(t, err) + require.Eventually(t, func() bool { + return hook.LastEntry() != nil + }, 5*time.Second, 10*time.Millisecond) + entry = hook.LastEntry() + assert.Equal(t, logrus.WarnLevel, entry.Level) + assert.Contains(t, entry.Message, "http: TLS handshake error") + require.NotNil(t, entry.Caller) + assert.Equal(t, "net/http.(*conn).serve", entry.Caller.Function) +} + func TestServer_LogListenerAddr(t *testing.T) { tests := []struct { name string diff --git a/echo/middleware/logger.go b/echo/middleware/logger.go index cecc141..2543498 100644 --- a/echo/middleware/logger.go +++ b/echo/middleware/logger.go @@ -58,20 +58,22 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc { if config.Skipper(c) { return next(c) } - // The request is described before calling the next handler, as it can modify it (like a reverse proxy rewriting the path). + // The request is described before calling the next handler, as it can modify it (like a reverse proxy rewriting the path or the method). // Only the escaped path is logged: the query string can contain sensitive data (tokens, OAuth codes, etc.), // and the escaped path cannot contain control characters. - path := c.Request().URL.EscapedPath() - // The path is saved, so the other logs about this request (like the one of the central error handler) use the same. - c.Set(contextKeyRequestPath, path) + request := loggedRequest{method: c.Request().Method, path: c.Request().URL.EscapedPath()} + // The request is saved, so the other logs about it (like the one of the central error handler) describe it the same way. + c.Set(contextKeyLoggedRequest, request) route := c.Path() // The error is not handled here, it is returned to be handled by the central error handler of echo. // The status logged is the one of the response that will be sent, resolved from this error. err := next(c) _, status := echo.ResolveResponseStatus(c.Response(), err) - entry := logrus.WithField("method", c.Request().Method). - WithField("uri", path). - WithField("status", status) + entry := logrus.WithFields(logrus.Fields{ + "method": request.method, + "uri": request.path, + "status": status, + }) if slices.InvertSubContains(config.BlackListEndpoint, route) { entry.Debug() @@ -83,15 +85,31 @@ func LoggerWithConfig(config LoggerConfig) echo.MiddlewareFunc { } } -// contextKeyRequestPath is the key of the echo context in which the Logger middleware saves the escaped path of the request. -const contextKeyRequestPath = "github.com/perses/common/echo/middleware.requestPath" +// loggedRequest describes the request as logged by the Logger middleware. +type loggedRequest struct { + method string + path string +} + +// contextKeyLoggedRequest is the key of the echo context in which the Logger middleware saves the request it logs. +const contextKeyLoggedRequest = "github.com/perses/common/echo/middleware.loggedRequest" + +// RequestMethod returns the method of the request as logged by the Logger middleware, before the next handlers +// possibly rewrote it (like a reverse proxy). Like that, every log about the same request uses the same method. +// It returns the current method of the request when the Logger middleware didn't handle it. +func RequestMethod(c *echo.Context) string { + if request, ok := c.Get(contextKeyLoggedRequest).(loggedRequest); ok { + return request.method + } + return c.Request().Method +} // RequestPath returns the escaped path of the request as logged by the Logger middleware, before the next handlers // possibly rewrote it (like a reverse proxy). Like that, every log about the same request uses the same path. // It returns the current escaped path of the request when the Logger middleware didn't handle it. func RequestPath(c *echo.Context) string { - if path, ok := c.Get(contextKeyRequestPath).(string); ok { - return path + if request, ok := c.Get(contextKeyLoggedRequest).(loggedRequest); ok { + return request.path } return c.Request().URL.EscapedPath() } diff --git a/echo/middleware/logger_test.go b/echo/middleware/logger_test.go index c366246..51eaaca 100644 --- a/echo/middleware/logger_test.go +++ b/echo/middleware/logger_test.go @@ -14,12 +14,14 @@ package middleware import ( + "errors" "io" "net/http" "net/http/httptest" "testing" "github.com/labstack/echo/v5" + echoMiddleware "github.com/labstack/echo/v5/middleware" "github.com/sirupsen/logrus" logrusTest "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" @@ -41,18 +43,29 @@ func TestLogger(t *testing.T) { hook := logrusTest.NewLocal(logger) e := echo.New() - e.Use(Logger()) + // Like the default middlewares, the logger is executed before the middleware Recover, so it logs the panics too. + e.Use(Logger(), echoMiddleware.Recover()) handler := func(c *echo.Context) error { return c.NoContent(http.StatusOK) } e.GET("/api/v1/users", handler) e.GET("/api/v1/projects/:project", handler) e.GET("/metrics", handler) - // Like a reverse proxy, this handler modifies the path of the request. + // Like a reverse proxy, this handler modifies the path and the method of the request. e.GET("/proxy/*", func(c *echo.Context) error { c.Request().URL.Path = "/rewritten" + c.Request().Method = http.MethodPost return c.NoContent(http.StatusOK) }) + e.GET("/error", func(*echo.Context) error { + return errors.New("unexpected failure") + }) + e.GET("/forbidden", func(*echo.Context) error { + return echo.ErrForbidden + }) + e.GET("/panic", func(*echo.Context) error { + panic("boom") + }) tests := []struct { name string @@ -97,12 +110,33 @@ func TestLogger(t *testing.T) { expectedURI: "/metrics-hidden", }, { - name: "the path requested by the client is logged, even if the handler modifies it", + name: "the path and the method requested by the client are logged, even if the handler modifies them", target: "/proxy/api/v1/query", expectedStatus: http.StatusOK, expectedLevel: logrus.InfoLevel, expectedURI: "/proxy/api/v1/query", }, + { + name: "the status of an unexpected error is the one sent by the error handler", + target: "/error", + expectedStatus: http.StatusInternalServerError, + expectedLevel: logrus.InfoLevel, + expectedURI: "/error", + }, + { + name: "the status of an HTTP error is the one carried by the error", + target: "/forbidden", + expectedStatus: http.StatusForbidden, + expectedLevel: logrus.InfoLevel, + expectedURI: "/forbidden", + }, + { + name: "a panic is logged", + target: "/panic", + expectedStatus: http.StatusInternalServerError, + expectedLevel: logrus.InfoLevel, + expectedURI: "/panic", + }, { name: "the control characters are escaped", target: "/api/v1/projects/a%0Ab", @@ -122,29 +156,35 @@ func TestLogger(t *testing.T) { require.NotNil(t, entry) assert.Equal(t, tt.expectedLevel, entry.Level) assert.Equal(t, tt.expectedURI, entry.Data["uri"]) + assert.Equal(t, http.MethodGet, entry.Data["method"]) + assert.Equal(t, tt.expectedStatus, entry.Data["status"]) }) } } -func TestRequestPath(t *testing.T) { +func TestRequestMethodAndPath(t *testing.T) { tests := []struct { - name string - middleware []echo.MiddlewareFunc - expectedPath string + name string + middleware []echo.MiddlewareFunc + expectedMethod string + expectedPath string }{ { - name: "the path logged by the logger is returned, even if the handler modifies it", - middleware: []echo.MiddlewareFunc{LoggerWithConfig(LoggerConfig{})}, - expectedPath: "/proxy/api%2Fv1", + name: "the method and the path logged by the logger are returned, even if the handler modifies them", + middleware: []echo.MiddlewareFunc{LoggerWithConfig(LoggerConfig{})}, + expectedMethod: http.MethodGet, + expectedPath: "/proxy/api%2Fv1", }, { - name: "the current path is returned when the logger doesn't handle the request", - middleware: []echo.MiddlewareFunc{LoggerWithConfig(LoggerConfig{Skipper: func(*echo.Context) bool { return true }})}, - expectedPath: "/rewritten", + name: "the current method and path are returned when the logger doesn't handle the request", + middleware: []echo.MiddlewareFunc{LoggerWithConfig(LoggerConfig{Skipper: func(*echo.Context) bool { return true }})}, + expectedMethod: http.MethodPost, + expectedPath: "/rewritten", }, { - name: "the current path is returned without the logger", - expectedPath: "/rewritten", + name: "the current method and path are returned without the logger", + expectedMethod: http.MethodPost, + expectedPath: "/rewritten", }, } origOutput := logrus.StandardLogger().Out @@ -154,18 +194,21 @@ func TestRequestPath(t *testing.T) { }) for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - var path string + var method, path string e := echo.New() e.Use(tt.middleware...) - // Like a reverse proxy, this handler modifies the path of the request. + // Like a reverse proxy, this handler modifies the path and the method of the request. e.GET("/proxy/*", func(c *echo.Context) error { c.Request().URL.Path = "/rewritten" + c.Request().Method = http.MethodPost + method = RequestMethod(c) path = RequestPath(c) return c.NoContent(http.StatusOK) }) rec := httptest.NewRecorder() e.ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/proxy/api%2Fv1", nil)) require.Equal(t, http.StatusOK, rec.Code) + assert.Equal(t, tt.expectedMethod, method) assert.Equal(t, tt.expectedPath, path) }) } diff --git a/echo/middleware/metrics.go b/echo/middleware/metrics.go index aef6e68..7fd66b6 100644 --- a/echo/middleware/metrics.go +++ b/echo/middleware/metrics.go @@ -72,9 +72,10 @@ func (m *Metrics) Describe(ch chan<- *prometheus.Desc) { func (m *Metrics) ProcessHTTPRequest(next echo.HandlerFunc) echo.HandlerFunc { return func(ctx *echo.Context) error { start := time.Now() + // The method is read before calling the next handler, as it can modify it (like a reverse proxy). + method := ctx.Request().Method err := next(ctx) elapsedTime := time.Since(start).Seconds() - method := ctx.Request().Method if method != http.MethodPost && method != http.MethodGet && method != http.MethodHead && diff --git a/echo/server.go b/echo/server.go index 8cee3c2..5281d0c 100644 --- a/echo/server.go +++ b/echo/server.go @@ -412,7 +412,7 @@ func (b *Builder) build() (*server, error) { e := echo.NewWithConfig(echo.Config{ // echo logs with log/slog: its logs are written with logrus, like the other logs. - Logger: slog.New(logrusHandler{}), + Logger: slog.New(newLogrusHandler()), HTTPErrorHandler: handleError, IPExtractor: b.ipExtractor, SchemeExtractor: b.schemeExtractor, @@ -496,6 +496,8 @@ func (s *server) String() string { } func (s *server) Initialize() error { + // The context of the request is saved before any middleware can replace it (see saveRequestContext). + s.e.Pre(saveRequestContext) // init global middleware // Remove trailing slash middleware a trailing slash from the request URI s.e.Pre(middleware.RemoveTrailingSlash()) @@ -562,7 +564,7 @@ func (s *server) configureHTTPServer(httpServer *http.Server) { httpServer.WriteTimeout = s.writeTimeout httpServer.IdleTimeout = s.idleTimeout // echo logs every error of the server as an error, but most of them are caused by the clients (see httpServerErrorWriter). - httpServer.ErrorLog = log.New(httpServerErrorWriter{}, "", 0) + httpServer.ErrorLog = log.New(newHTTPServerErrorWriter(), "", 0) } // tlsConfig builds the TLS configuration of the HTTPS server.