Merge pull request #259 from anywherelan/fix/win-gateway-winnat-errors

Improve error reporting: WinNAT diagnostics, API error logging, echo logs

Author: pymq

README.md

@@ -327,6 +327,7 @@ The privacy exposure — your IP appearing as the source of another device's tra
 - **A "what's my IP" site still shows your own IP after enabling.** Check the gateway status (the **VPN Gateway** card, or `awl cli gateway status`): if it's not connected, awl can't reach the exit node, so nothing is being tunnelled.
 - **A site works over IPv6 but not through the gateway.** Expected — IPv6 isn't tunnelled (see the note above). Dual-stack hosts fall back to IPv4 automatically; anything IPv6-only won't work while the gateway is on.
 - **Turning on *Serve as VPN Gateway* fails on Windows.** Windows effectively allows one NAT instance per host, and it may already be taken by Docker (Windows containers), WSL2 or Internet Connection Sharing — the error message lists the current holders. Free it up, or share this device over SOCKS5 instead: the SOCKS5 exit node doesn't need NAT.
+- **Turning on *Serve as VPN Gateway* on Windows fails with "WinNAT is not available" (HRESULT 0x80041010).** awl's exit-node NAT is built on Windows' own WinNAT, and on this installation the `MSFT_NetNat` WMI class doesn't exist. Windows **Home** editions don't ship WinNAT at all — there is no way to enable it there. On Pro/Enterprise/Server it can also be missing when neither Hyper-V nor RAS components are enabled (turning on the Hyper-V feature registers it) or when the WMI repository is corrupted. If you can't get WinNAT on your machine, share this device over SOCKS5 instead — the SOCKS5 exit node doesn't need it.
 - **No IPv6 connectivity after awl crashed (Linux).** If awl is killed (not shut down) with the gateway client on, its IPv6 block stays behind. It is removed automatically on the next awl start (and stop).
 - **Devices are reachable only via relay from a Windows machine with multiple network interfaces.** awl on Windows pins its peer-to-peer traffic to the interface that holds the default route, so peers reachable only through a secondary network card may fall back to relayed connections.
 

api/api.go

@@ -15,6 +15,8 @@ import (
 	"github.com/labstack/echo-contrib/echoprometheus"
 	"github.com/labstack/echo/v4"
 	"github.com/labstack/echo/v4/middleware"
+	glog "github.com/labstack/gommon/log"
+	"go.uber.org/zap"
 
 	"github.com/anywherelan/awl/config"
 	"github.com/anywherelan/awl/p2p"
@@ -95,17 +97,34 @@ func (h *Handler) setupRouter(address string) (*echo.Echo, error) {
 	e := echo.New()
 	e.HideBanner = true
 	e.HidePort = true
+	// Route echo's internal logs (panic stacks from Recover, response-write
+	// failures) into the awl logger. StdLogger is the net/http Server.ErrorLog
+	// ("http: accept error", "http: panic serving"): echo.New built it from
+	// the default logger's stdout, and configureServer copies it into the
+	// server at startup, so it must be replaced here, not on e.Server.
+	e.Logger = newEchoLogger(&h.logger.SugaredLogger)
+	stdLogger, err := zap.NewStdLogAt(h.logger.Desugar(), zap.ErrorLevel)
+	if err != nil {
+		return nil, err
+	}
+	e.StdLogger = stdLogger
+
 	val := validator.New()
-	err := val.RegisterValidation("trimmed_str_not_empty", validateTrimmedStringNotEmpty, false)
+	err = val.RegisterValidation("trimmed_str_not_empty", validateTrimmedStringNotEmpty, false)
 	if err != nil {
 		return nil, err
 	}
 
 	e.Validator = &customValidator{validator: val}
 
 	// Middleware
+	// First/outermost, so it also sees errors from the middleware below
+	// (basic auth 401s, panics recovered to 500s).
+	e.Use(errorLogMiddleware(h.logger))
 	if !h.conf.DevMode() {
-		e.Use(middleware.Recover())
+		e.Use(middleware.RecoverWithConfig(middleware.RecoverConfig{
+			LogLevel: glog.ERROR,
+		}))
 	}
 
 	if h.conf.HttpBasicAuth.Password != "" {

api/logger.go

@@ -0,0 +1,108 @@
+package api
+
+import (
+	"fmt"
+	"io"
+
+	"github.com/labstack/echo/v4"
+	glog "github.com/labstack/gommon/log"
+	"go.uber.org/zap"
+)
+
+// echoLogger adapts our zap-based logger to the echo.Logger interface, so
+// echo's internal logs — recovered panic stack traces, "response already
+// committed", failures to send an error response — land in awl's log file and
+// ring buffer instead of a console.
+//
+// Echo core only ever calls Print/Warn/Error/Errorf plus the Output/Prefix/
+// SetLevel plumbing; the rest of the interface is implemented for
+// completeness.
+type echoLogger struct {
+	l *zap.SugaredLogger
+}
+
+var _ echo.Logger = (*echoLogger)(nil)
+
+// newEchoLogger wraps l for echo. The caller-skip makes zap report echo's
+// call site instead of this adapter.
+func newEchoLogger(l *zap.SugaredLogger) *echoLogger {
+	return &echoLogger{l: l.WithOptions(zap.AddCallerSkip(1))}
+}
+
+// Output/Prefix/level plumbing: filtering and destinations are governed by
+// the go-log config, not by echo, so the setters are no-ops. Level reports
+// DEBUG so echo never suppresses a record before it reaches zap. Output is
+// only used by echo for its startup banner colorer (hidden in awl) and the
+// initial StdLogger (overridden in setupRouter).
+
+func (e *echoLogger) Output() io.Writer     { return io.Discard }
+func (e *echoLogger) SetOutput(_ io.Writer) {}
+func (e *echoLogger) Prefix() string        { return "" }
+func (e *echoLogger) SetPrefix(_ string)    {}
+func (e *echoLogger) Level() glog.Lvl       { return glog.DEBUG }
+func (e *echoLogger) SetLevel(_ glog.Lvl)   {}
+func (e *echoLogger) SetHeader(_ string)    {}
+
+func (e *echoLogger) Print(i ...any)                    { e.l.Info(i...) }
+func (e *echoLogger) Printf(format string, args ...any) { e.l.Infof(format, args...) }
+func (e *echoLogger) Printj(j glog.JSON)                { e.l.Infow("", jsonFields(j)...) }
+
+func (e *echoLogger) Debug(i ...any)                    { e.l.Debug(i...) }
+func (e *echoLogger) Debugf(format string, args ...any) { e.l.Debugf(format, args...) }
+func (e *echoLogger) Debugj(j glog.JSON)                { e.l.Debugw("", jsonFields(j)...) }
+
+func (e *echoLogger) Info(i ...any)                    { e.l.Info(i...) }
+func (e *echoLogger) Infof(format string, args ...any) { e.l.Infof(format, args...) }
+func (e *echoLogger) Infoj(j glog.JSON)                { e.l.Infow("", jsonFields(j)...) }
+
+func (e *echoLogger) Warn(i ...any)                    { e.l.Warn(i...) }
+func (e *echoLogger) Warnf(format string, args ...any) { e.l.Warnf(format, args...) }
+func (e *echoLogger) Warnj(j glog.JSON)                { e.l.Warnw("", jsonFields(j)...) }
+
+func (e *echoLogger) Error(i ...any)                    { e.l.Error(i...) }
+func (e *echoLogger) Errorf(format string, args ...any) { e.l.Errorf(format, args...) }
+func (e *echoLogger) Errorj(j glog.JSON)                { e.l.Errorw("", jsonFields(j)...) }
+
+// Fatal* log at error level and panic instead of gommon's os.Exit: a library
+// must not be able to kill the P2P daemon bypassing deferred cleanup, and a
+// panic keeps the "does not return" contract while staying catchable by
+// Recover.
+
+func (e *echoLogger) Fatal(i ...any) {
+	e.l.Error(i...)
+	panic(fmt.Sprint(i...))
+}
+
+func (e *echoLogger) Fatalf(format string, args ...any) {
+	e.l.Errorf(format, args...)
+	panic(fmt.Sprintf(format, args...))
+}
+
+func (e *echoLogger) Fatalj(j glog.JSON) {
+	e.l.Errorw("", jsonFields(j)...)
+	panic(fmt.Sprintf("%v", j))
+}
+
+func (e *echoLogger) Panic(i ...any) {
+	e.l.Error(i...)
+	panic(fmt.Sprint(i...))
+}
+
+func (e *echoLogger) Panicf(format string, args ...any) {
+	e.l.Errorf(format, args...)
+	panic(fmt.Sprintf(format, args...))
+}
+
+func (e *echoLogger) Panicj(j glog.JSON) {
+	e.l.Errorw("", jsonFields(j)...)
+	panic(fmt.Sprintf("%v", j))
+}
+
+// jsonFields flattens a gommon structured-log map into zap key-value pairs.
+func jsonFields(j glog.JSON) []any {
+	fields := make([]any, 0, len(j)*2)
+	for k, v := range j {
+		fields = append(fields, k, v)
+	}
+	return fields
+}

api/logger_test.go

@@ -0,0 +1,99 @@
+package api
+
+import (
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/labstack/echo/v4"
+	"github.com/labstack/echo/v4/middleware"
+	glog "github.com/labstack/gommon/log"
+	"github.com/stretchr/testify/require"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap/zaptest/observer"
+)
+
+func newObservedEchoLogger() (*echoLogger, *observer.ObservedLogs) {
+	core, logs := observer.New(zapcore.DebugLevel)
+	return newEchoLogger(zap.New(core).Sugar()), logs
+}
+
+func TestEchoLoggerLevels(t *testing.T) {
+	logger, logs := newObservedEchoLogger()
+
+	logger.Debugf("debug %s", "msg")
+	logger.Infof("info %s", "msg")
+	logger.Warnf("warn %s", "msg")
+	logger.Errorf("error %s", "msg")
+	// gommon's level-less Print maps to info.
+	logger.Print("print msg")
+
+	entries := logs.All()
+	require.Len(t, entries, 5)
+	require.Equal(t, zapcore.DebugLevel, entries[0].Level)
+	require.Equal(t, "debug msg", entries[0].Message)
+	require.Equal(t, zapcore.InfoLevel, entries[1].Level)
+	require.Equal(t, zapcore.WarnLevel, entries[2].Level)
+	require.Equal(t, zapcore.ErrorLevel, entries[3].Level)
+	require.Equal(t, zapcore.InfoLevel, entries[4].Level)
+}
+
+func TestEchoLoggerJSONFields(t *testing.T) {
+	logger, logs := newObservedEchoLogger()
+
+	logger.Errorj(glog.JSON{"file": "app.go", "line": 42})
+
+	entries := logs.All()
+	require.Len(t, entries, 1)
+	require.Equal(t, zapcore.ErrorLevel, entries[0].Level)
+	fields := entries[0].ContextMap()
+	require.Equal(t, "app.go", fields["file"])
+	require.EqualValues(t, 42, fields["line"])
+}
+
+// Fatal must not os.Exit like gommon does — a library must not be able to
+// kill the daemon. It logs at error level and panics instead.
+func TestEchoLoggerFatalPanics(t *testing.T) {
+	logger, logs := newObservedEchoLogger()
+
+	require.PanicsWithValue(t, "fatal problem", func() {
+		logger.Fatalf("fatal %s", "problem")
+	})
+	require.PanicsWithValue(t, "panic problem", func() {
+		logger.Panicf("panic %s", "problem")
+	})
+
+	entries := logs.All()
+	require.Len(t, entries, 2)
+	require.Equal(t, zapcore.ErrorLevel, entries[0].Level)
+	require.Equal(t, "fatal problem", entries[0].Message)
+	require.Equal(t, zapcore.ErrorLevel, entries[1].Level)
+}
+
+// The original motivation for the adapter: a panic inside a handler must
+// leave a stack trace in awl's logs, not on a console the process may not
+// have.
+func TestEchoLoggerPanicStackReachesZap(t *testing.T) {
+	logger, logs := newObservedEchoLogger()
+
+	e := echo.New()
+	e.Logger = logger
+	e.Use(middleware.RecoverWithConfig(middleware.RecoverConfig{
+		LogLevel: glog.ERROR,
+	}))
+	e.GET("/boom", func(c echo.Context) error {
+		panic("kaboom")
+	})
+
+	req := httptest.NewRequest(http.MethodGet, "/boom", nil)
+	rec := httptest.NewRecorder()
+	e.ServeHTTP(rec, req)
+	require.Equal(t, http.StatusInternalServerError, rec.Code)
+
+	entries := logs.FilterLevelExact(zapcore.ErrorLevel).All()
+	require.Len(t, entries, 1)
+	require.Contains(t, entries[0].Message, "PANIC RECOVER")
+	require.Contains(t, entries[0].Message, "kaboom")
+	require.Contains(t, entries[0].Message, "goroutine")
+}

api/middleware.go

@@ -0,0 +1,124 @@
+package api
+
+import (
+	"bytes"
+	"errors"
+	"net/http"
+	"strings"
+
+	"github.com/ipfs/go-log/v2"
+	"github.com/labstack/echo/v4"
+)
+
+// errorBodyLogLimit caps how much of an error response body is captured for
+// logging. Error bodies are small JSON objects; the cap only guards against a
+// pathological handler.
+const errorBodyLogLimit = 4 * 1024
+
+// errorLogMiddleware logs every error response, which would otherwise exist
+// only in the UI banner that showed it: handlers write errors directly with
+// c.JSON(4xx/5xx, ...), so from echo's point of view they are successful
+// responses and no framework hook sees them. Must be registered first (as the
+// outermost middleware) — errors from inner middleware (basic auth 401s,
+// panics recovered to 500s) are only visible to middleware outside of them.
+//
+// 5xx are logged everywhere as errors; 4xx as warnings and only under the API
+// prefix — outside it they are browser noise (static file misses, the basic
+// auth 401 every browser session starts with).
+func errorLogMiddleware(logger *log.ZapEventLogger) echo.MiddlewareFunc {
+	return errorLogMiddlewareLogf(func(status int, format string, args ...any) {
+		if status >= http.StatusInternalServerError {
+			logger.Errorf(format, args...)
+		} else {
+			logger.Warnf(format, args...)
+		}
+	})
+}
+
+// errorLogMiddlewareLogf is errorLogMiddleware with the log destination
+// injected, so tests can assert on emitted records.
+func errorLogMiddlewareLogf(logf func(status int, format string, args ...any)) echo.MiddlewareFunc {
+	return func(next echo.HandlerFunc) echo.HandlerFunc {
+		return func(c echo.Context) error {
+			w := &errorCaptureWriter{ResponseWriter: c.Response().Writer}
+			c.Response().Writer = w
+
+			err := next(c)
+			req := c.Request()
+
+			// An error heading to echo's HTTPErrorHandler: it is rendered
+			// after this middleware returns, so the capture below never sees
+			// its body — log the error value itself. If the response is
+			// already committed, the write went through the capture writer
+			// and the branch below reports it instead.
+			if err != nil && !c.Response().Committed {
+				status := http.StatusInternalServerError
+				if httpErr, ok := errors.AsType[*echo.HTTPError](err); ok {
+					status = httpErr.Code
+				}
+				if shouldLogErrorResponse(status, req.URL.Path) {
+					logf(status, "%s %s: %d: %v", req.Method, req.URL.Path, status, err)
+				}
+				return err
+			}
+
+			if w.status >= 400 && shouldLogErrorResponse(w.status, req.URL.Path) {
+				body := bytes.TrimSpace(w.body.Bytes())
+				truncated := ""
+				if w.truncated {
+					truncated = " (body truncated)"
+				}
+				logf(w.status, "%s %s: %d: %s%s", req.Method, req.URL.Path, w.status, body, truncated)
+			}
+			return err
+		}
+	}
+}
+
+func shouldLogErrorResponse(status int, path string) bool {
+	return status >= http.StatusInternalServerError || strings.HasPrefix(path, V0Prefix)
+}
+
+// errorCaptureWriter passes everything through to the underlying
+// ResponseWriter and additionally keeps a copy of the body — but only once
+// the status is known to be an error, so success responses (log dumps,
+// metrics scrapes, pprof profiles) are never buffered.
+type errorCaptureWriter struct {
+	http.ResponseWriter
+	status    int
+	body      bytes.Buffer
+	truncated bool
+}
+
+func (w *errorCaptureWriter) WriteHeader(status int) {
+	w.status = status
+	w.ResponseWriter.WriteHeader(status)
+}
+
+func (w *errorCaptureWriter) Write(b []byte) (int, error) {
+	if w.status >= 400 {
+		free := errorBodyLogLimit - w.body.Len()
+		if len(b) <= free {
+			w.body.Write(b)
+		} else {
+			w.body.Write(b[:free])
+			w.truncated = true
+		}
+	}
+	return w.ResponseWriter.Write(b)
+}
+
+// Flush keeps streaming endpoints (pprof profiles) working: echo's
+// Response.Flush type-asserts the underlying writer to http.Flusher and would
+// panic on a wrapper without it.
+func (w *errorCaptureWriter) Flush() {
+	if f, ok := w.ResponseWriter.(http.Flusher); ok {
+		f.Flush()
+	}
+}
+
+// Unwrap lets http.ResponseController reach the underlying writer's optional
+// interfaces.
+func (w *errorCaptureWriter) Unwrap() http.ResponseWriter {
+	return w.ResponseWriter
+}