Skip to content

Commit 3cea500

Browse files
pymqpymq
committed
api: route echo and net/http server logs into awl logger
Echo's internal logs — panic stack traces from the Recover middleware, "response already committed", failures to send an error response — went to gommon's default stdout logger, and net/http server errors to stderr. awl-tray is a GUI process with no console, so all of it vanished; a panic in a handler left no trace anywhere. Adapt the zap logger to the echo.Logger interface and install it, route http.Server.ErrorLog through zap as well (via e.StdLogger — configureServer overwrites Server.ErrorLog with it at startup), and raise the Recover middleware's panic log from the default Print/info to error. The adapter's Fatal logs at error level and panics instead of gommon's os.Exit so a library can't kill the daemon bypassing deferred cleanup.
1 parent ade32aa commit 3cea500

4 files changed

Lines changed: 226 additions & 3 deletions

File tree

‎api/api.go‎

Lines changed: 18 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,8 @@ import (
1515
"github.com/labstack/echo-contrib/echoprometheus"
1616
"github.com/labstack/echo/v4"
1717
"github.com/labstack/echo/v4/middleware"
18+
glog "github.com/labstack/gommon/log"
19+
"go.uber.org/zap"
1820

1921
"github.com/anywherelan/awl/config"
2022
"github.com/anywherelan/awl/p2p"
@@ -95,8 +97,20 @@ func (h *Handler) setupRouter(address string) (*echo.Echo, error) {
9597
e := echo.New()
9698
e.HideBanner = true
9799
e.HidePort = true
100+
// Route echo's internal logs (panic stacks from Recover, response-write
101+
// failures) into the awl logger. StdLogger is the net/http Server.ErrorLog
102+
// ("http: accept error", "http: panic serving"): echo.New built it from
103+
// the default logger's stdout, and configureServer copies it into the
104+
// server at startup, so it must be replaced here, not on e.Server.
105+
e.Logger = newEchoLogger(&h.logger.SugaredLogger)
106+
stdLogger, err := zap.NewStdLogAt(h.logger.Desugar(), zap.ErrorLevel)
107+
if err != nil {
108+
return nil, err
109+
}
110+
e.StdLogger = stdLogger
111+
98112
val := validator.New()
99-
err := val.RegisterValidation("trimmed_str_not_empty", validateTrimmedStringNotEmpty, false)
113+
err = val.RegisterValidation("trimmed_str_not_empty", validateTrimmedStringNotEmpty, false)
100114
if err != nil {
101115
return nil, err
102116
}
@@ -108,7 +122,9 @@ func (h *Handler) setupRouter(address string) (*echo.Echo, error) {
108122
// (basic auth 401s, panics recovered to 500s).
109123
e.Use(errorLogMiddleware(h.logger))
110124
if !h.conf.DevMode() {
111-
e.Use(middleware.Recover())
125+
e.Use(middleware.RecoverWithConfig(middleware.RecoverConfig{
126+
LogLevel: glog.ERROR,
127+
}))
112128
}
113129

114130
if h.conf.HttpBasicAuth.Password != "" {

‎api/logger.go‎

Lines changed: 108 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,108 @@
1+
package api
2+
3+
import (
4+
"fmt"
5+
"io"
6+
7+
"github.com/labstack/echo/v4"
8+
glog "github.com/labstack/gommon/log"
9+
"go.uber.org/zap"
10+
)
11+
12+
// echoLogger adapts our zap-based logger to the echo.Logger interface, so
13+
// echo's internal logs — recovered panic stack traces, "response already
14+
// committed", failures to send an error response — land in awl's log file and
15+
// ring buffer instead of a console.
16+
//
17+
// Echo core only ever calls Print/Warn/Error/Errorf plus the Output/Prefix/
18+
// SetLevel plumbing; the rest of the interface is implemented for
19+
// completeness.
20+
type echoLogger struct {
21+
l *zap.SugaredLogger
22+
}
23+
24+
var _ echo.Logger = (*echoLogger)(nil)
25+
26+
// newEchoLogger wraps l for echo. The caller-skip makes zap report echo's
27+
// call site instead of this adapter.
28+
func newEchoLogger(l *zap.SugaredLogger) *echoLogger {
29+
return &echoLogger{l: l.WithOptions(zap.AddCallerSkip(1))}
30+
}
31+
32+
// Output/Prefix/level plumbing: filtering and destinations are governed by
33+
// the go-log config, not by echo, so the setters are no-ops. Level reports
34+
// DEBUG so echo never suppresses a record before it reaches zap. Output is
35+
// only used by echo for its startup banner colorer (hidden in awl) and the
36+
// initial StdLogger (overridden in setupRouter).
37+
38+
func (e *echoLogger) Output() io.Writer { return io.Discard }
39+
func (e *echoLogger) SetOutput(_ io.Writer) {}
40+
func (e *echoLogger) Prefix() string { return "" }
41+
func (e *echoLogger) SetPrefix(_ string) {}
42+
func (e *echoLogger) Level() glog.Lvl { return glog.DEBUG }
43+
func (e *echoLogger) SetLevel(_ glog.Lvl) {}
44+
func (e *echoLogger) SetHeader(_ string) {}
45+
46+
func (e *echoLogger) Print(i ...any) { e.l.Info(i...) }
47+
func (e *echoLogger) Printf(format string, args ...any) { e.l.Infof(format, args...) }
48+
func (e *echoLogger) Printj(j glog.JSON) { e.l.Infow("", jsonFields(j)...) }
49+
50+
func (e *echoLogger) Debug(i ...any) { e.l.Debug(i...) }
51+
func (e *echoLogger) Debugf(format string, args ...any) { e.l.Debugf(format, args...) }
52+
func (e *echoLogger) Debugj(j glog.JSON) { e.l.Debugw("", jsonFields(j)...) }
53+
54+
func (e *echoLogger) Info(i ...any) { e.l.Info(i...) }
55+
func (e *echoLogger) Infof(format string, args ...any) { e.l.Infof(format, args...) }
56+
func (e *echoLogger) Infoj(j glog.JSON) { e.l.Infow("", jsonFields(j)...) }
57+
58+
func (e *echoLogger) Warn(i ...any) { e.l.Warn(i...) }
59+
func (e *echoLogger) Warnf(format string, args ...any) { e.l.Warnf(format, args...) }
60+
func (e *echoLogger) Warnj(j glog.JSON) { e.l.Warnw("", jsonFields(j)...) }
61+
62+
func (e *echoLogger) Error(i ...any) { e.l.Error(i...) }
63+
func (e *echoLogger) Errorf(format string, args ...any) { e.l.Errorf(format, args...) }
64+
func (e *echoLogger) Errorj(j glog.JSON) { e.l.Errorw("", jsonFields(j)...) }
65+
66+
// Fatal* log at error level and panic instead of gommon's os.Exit: a library
67+
// must not be able to kill the P2P daemon bypassing deferred cleanup, and a
68+
// panic keeps the "does not return" contract while staying catchable by
69+
// Recover.
70+
71+
func (e *echoLogger) Fatal(i ...any) {
72+
e.l.Error(i...)
73+
panic(fmt.Sprint(i...))
74+
}
75+
76+
func (e *echoLogger) Fatalf(format string, args ...any) {
77+
e.l.Errorf(format, args...)
78+
panic(fmt.Sprintf(format, args...))
79+
}
80+
81+
func (e *echoLogger) Fatalj(j glog.JSON) {
82+
e.l.Errorw("", jsonFields(j)...)
83+
panic(fmt.Sprintf("%v", j))
84+
}
85+
86+
func (e *echoLogger) Panic(i ...any) {
87+
e.l.Error(i...)
88+
panic(fmt.Sprint(i...))
89+
}
90+
91+
func (e *echoLogger) Panicf(format string, args ...any) {
92+
e.l.Errorf(format, args...)
93+
panic(fmt.Sprintf(format, args...))
94+
}
95+
96+
func (e *echoLogger) Panicj(j glog.JSON) {
97+
e.l.Errorw("", jsonFields(j)...)
98+
panic(fmt.Sprintf("%v", j))
99+
}
100+
101+
// jsonFields flattens a gommon structured-log map into zap key-value pairs.
102+
func jsonFields(j glog.JSON) []any {
103+
fields := make([]any, 0, len(j)*2)
104+
for k, v := range j {
105+
fields = append(fields, k, v)
106+
}
107+
return fields
108+
}

‎api/logger_test.go‎

Lines changed: 99 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,99 @@
1+
package api
2+
3+
import (
4+
"net/http"
5+
"net/http/httptest"
6+
"testing"
7+
8+
"github.com/labstack/echo/v4"
9+
"github.com/labstack/echo/v4/middleware"
10+
glog "github.com/labstack/gommon/log"
11+
"github.com/stretchr/testify/require"
12+
"go.uber.org/zap"
13+
"go.uber.org/zap/zapcore"
14+
"go.uber.org/zap/zaptest/observer"
15+
)
16+
17+
func newObservedEchoLogger() (*echoLogger, *observer.ObservedLogs) {
18+
core, logs := observer.New(zapcore.DebugLevel)
19+
return newEchoLogger(zap.New(core).Sugar()), logs
20+
}
21+
22+
func TestEchoLoggerLevels(t *testing.T) {
23+
logger, logs := newObservedEchoLogger()
24+
25+
logger.Debugf("debug %s", "msg")
26+
logger.Infof("info %s", "msg")
27+
logger.Warnf("warn %s", "msg")
28+
logger.Errorf("error %s", "msg")
29+
// gommon's level-less Print maps to info.
30+
logger.Print("print msg")
31+
32+
entries := logs.All()
33+
require.Len(t, entries, 5)
34+
require.Equal(t, zapcore.DebugLevel, entries[0].Level)
35+
require.Equal(t, "debug msg", entries[0].Message)
36+
require.Equal(t, zapcore.InfoLevel, entries[1].Level)
37+
require.Equal(t, zapcore.WarnLevel, entries[2].Level)
38+
require.Equal(t, zapcore.ErrorLevel, entries[3].Level)
39+
require.Equal(t, zapcore.InfoLevel, entries[4].Level)
40+
}
41+
42+
func TestEchoLoggerJSONFields(t *testing.T) {
43+
logger, logs := newObservedEchoLogger()
44+
45+
logger.Errorj(glog.JSON{"file": "app.go", "line": 42})
46+
47+
entries := logs.All()
48+
require.Len(t, entries, 1)
49+
require.Equal(t, zapcore.ErrorLevel, entries[0].Level)
50+
fields := entries[0].ContextMap()
51+
require.Equal(t, "app.go", fields["file"])
52+
require.EqualValues(t, 42, fields["line"])
53+
}
54+
55+
// Fatal must not os.Exit like gommon does — a library must not be able to
56+
// kill the daemon. It logs at error level and panics instead.
57+
func TestEchoLoggerFatalPanics(t *testing.T) {
58+
logger, logs := newObservedEchoLogger()
59+
60+
require.PanicsWithValue(t, "fatal problem", func() {
61+
logger.Fatalf("fatal %s", "problem")
62+
})
63+
require.PanicsWithValue(t, "panic problem", func() {
64+
logger.Panicf("panic %s", "problem")
65+
})
66+
67+
entries := logs.All()
68+
require.Len(t, entries, 2)
69+
require.Equal(t, zapcore.ErrorLevel, entries[0].Level)
70+
require.Equal(t, "fatal problem", entries[0].Message)
71+
require.Equal(t, zapcore.ErrorLevel, entries[1].Level)
72+
}
73+
74+
// The original motivation for the adapter: a panic inside a handler must
75+
// leave a stack trace in awl's logs, not on a console the process may not
76+
// have.
77+
func TestEchoLoggerPanicStackReachesZap(t *testing.T) {
78+
logger, logs := newObservedEchoLogger()
79+
80+
e := echo.New()
81+
e.Logger = logger
82+
e.Use(middleware.RecoverWithConfig(middleware.RecoverConfig{
83+
LogLevel: glog.ERROR,
84+
}))
85+
e.GET("/boom", func(c echo.Context) error {
86+
panic("kaboom")
87+
})
88+
89+
req := httptest.NewRequest(http.MethodGet, "/boom", nil)
90+
rec := httptest.NewRecorder()
91+
e.ServeHTTP(rec, req)
92+
require.Equal(t, http.StatusInternalServerError, rec.Code)
93+
94+
entries := logs.FilterLevelExact(zapcore.ErrorLevel).All()
95+
require.Len(t, entries, 1)
96+
require.Contains(t, entries[0].Message, "PANIC RECOVER")
97+
require.Contains(t, entries[0].Message, "kaboom")
98+
require.Contains(t, entries[0].Message, "goroutine")
99+
}

‎go.mod‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@ require (
1919
github.com/ipfs/go-log/v2 v2.9.1
2020
github.com/labstack/echo-contrib v0.50.1
2121
github.com/labstack/echo/v4 v4.15.4
22+
github.com/labstack/gommon v0.5.0
2223
github.com/libp2p/go-libp2p v0.48.0
2324
github.com/libp2p/go-libp2p-kad-dht v0.39.2
2425
github.com/libp2p/go-libp2p-kbucket v0.8.0
@@ -80,7 +81,6 @@ require (
8081
github.com/josharian/native v1.1.1-0.20230202152459-5c7d0dd6ab86 // indirect
8182
github.com/klauspost/cpuid/v2 v2.3.0 // indirect
8283
github.com/koron/go-ssdp v0.0.6 // indirect
83-
github.com/labstack/gommon v0.5.0 // indirect
8484
github.com/leodido/go-urn v1.4.0 // indirect
8585
github.com/libp2p/go-buffer-pool v0.1.0 // indirect
8686
github.com/libp2p/go-cidranger v1.1.0 // indirect

0 commit comments

Comments
 (0)