Error logging

log/event.go

@@ -77,7 +77,11 @@ func (e *Event) Time(time time.Time) *Event {
 
 // Err adds an "error" field to the log event
 func (e *Event) Err(err error) *Event {
-	e.fields[errorField] = err.Error()
+	if c, ok := err.(Contexter); ok {
+		e.Fields(c.Context())
+	} else {
+		e.fields[errorField] = err.Error()
+	}
 	return e
 }
 

log/log_test.go

@@ -4,7 +4,6 @@ import (
 	"bytes"
 	"github.com/stretchr/testify/require"
 	"heckel.io/ntfy/log"
-	"net/http"
 	"os"
 	"testing"
 	"time"
@@ -23,6 +22,10 @@ func TestLog_TagContextFieldFields(t *testing.T) {
 		UserID: "u_abc",
 		IP:     "1.2.3.4",
 	}
+	err := &fakeError{
+		Code:    123,
+		Message: "some error",
+	}
 	var out bytes.Buffer
 	log.SetOutput(&out)
 	log.SetFormat(log.JSONFormat)
@@ -44,23 +47,39 @@ func TestLog_TagContextFieldFields(t *testing.T) {
 			"stripe_subscription_id": "sub_123",
 		}).
 		Tag("stripe").
-		Err(http.ErrHandlerTimeout).
+		Err(err).
 		Time(time.Unix(456, 0)).
 		Debug("Subscription status %s", "active")
 
 	expected := `{"time":123000,"level":"INFO","message":"hi there phil","field1":"value1","field2":123,"tag":"mytag"}
-{"time":456000,"level":"DEBUG","message":"Subscription status active","error":"http: Handler timeout","stripe_customer_id":"acct_123","stripe_subscription_id":"sub_123","tag":"stripe","user_id":"u_abc","visitor_ip":"1.2.3.4"}
+{"time":456000,"level":"DEBUG","message":"Subscription status active","error":"some error","error_code":123,"stripe_customer_id":"acct_123","stripe_subscription_id":"sub_123","tag":"stripe","user_id":"u_abc","visitor_ip":"1.2.3.4"}
 `
 	require.Equal(t, expected, out.String())
 }
 
+type fakeError struct {
+	Code    int
+	Message string
+}
+
+func (e fakeError) Error() string {
+	return e.Message
+}
+
+func (e fakeError) Context() log.Context {
+	return log.Context{
+		"error":      e.Message,
+		"error_code": e.Code,
+	}
+}
+
 type fakeVisitor struct {
 	UserID string
 	IP     string
 }
 
 func (v *fakeVisitor) Context() log.Context {
-	return map[string]any{
+	return log.Context{
 		"user_id":    v.UserID,
 		"visitor_ip": v.IP,
 	}

server/errors.go

@@ -3,6 +3,7 @@ package server
 import (
 	"encoding/json"
 	"fmt"
+	"heckel.io/ntfy/log"
 	"net/http"
 )
 
@@ -23,6 +24,14 @@ func (e errHTTP) JSON() string {
 	return string(b)
 }
 
+func (e errHTTP) Context() log.Context {
+	return log.Context{
+		"error":       e.Message,
+		"error_code":  e.Code,
+		"http_status": e.HTTPCode,
+	}
+}
+
 func wrapErrHTTP(err *errHTTP, message string, args ...any) *errHTTP {
 	return &errHTTP{
 		Code:     err.Code,

server/log.go

@@ -3,6 +3,7 @@ package server
 import (
 	"fmt"
 	"github.com/emersion/go-smtp"
+	"github.com/gorilla/websocket"
 	"golang.org/x/time/rate"
 	"heckel.io/ntfy/log"
 	"heckel.io/ntfy/util"
@@ -13,7 +14,7 @@ import (
 
 // logr creates a new log event with HTTP request fields
 func logr(r *http.Request) *log.Event {
-	return log.Fields(httpFields(r))
+	return log.Fields(httpContext(r))
 }
 
 // logr creates a new log event with visitor fields
@@ -23,7 +24,7 @@ func logv(v *visitor) *log.Event {
 
 // logr creates a new log event with HTTP request and visitor fields
 func logvr(v *visitor, r *http.Request) *log.Event {
-	return logv(v).Fields(httpFields(r))
+	return logv(v).Fields(httpContext(r))
 }
 
 // logvrm creates a new log event with HTTP request, visitor fields and message fields
@@ -46,17 +47,30 @@ func logem(state *smtp.ConnectionState) *log.Event {
 		})
 }
 
-func httpFields(r *http.Request) map[string]any {
+func httpContext(r *http.Request) log.Context {
 	requestURI := r.RequestURI
 	if requestURI == "" {
 		requestURI = r.URL.Path
 	}
-	return map[string]any{
+	return log.Context{
 		"http_method": r.Method,
 		"http_path":   requestURI,
 	}
 }
 
+func websocketErrorContext(err error) log.Context {
+	if c, ok := err.(*websocket.CloseError); ok {
+		return log.Context{
+			"error":      c.Error(),
+			"error_code": c.Code,
+			"error_type": "websocket.CloseError",
+		}
+	}
+	return log.Context{
+		"error": err.Error(),
+	}
+}
+
 func requestLimiterFields(limiter *rate.Limiter) map[string]any {
 	return map[string]any{
 		"visitor_request_limiter_limit":  limiter.Limit(),

server/server.go

@@ -334,9 +334,9 @@ func (s *Server) handle(w http.ResponseWriter, r *http.Request) {
 		if websocket.IsWebSocketUpgrade(r) {
 			isNormalError := strings.Contains(err.Error(), "i/o timeout")
 			if isNormalError {
-				logvr(v, r).Tag(tagWebsocket).Err(err).Debug("WebSocket error (this error is okay, it happens a lot): %s", err.Error())
+				logvr(v, r).Tag(tagWebsocket).Err(err).Fields(websocketErrorContext(err)).Debug("WebSocket error (this error is okay, it happens a lot): %s", err.Error())
 			} else {
-				logvr(v, r).Tag(tagWebsocket).Err(err).Info("WebSocket error: %s", err.Error())
+				logvr(v, r).Tag(tagWebsocket).Err(err).Fields(websocketErrorContext(err)).Info("WebSocket error: %s", err.Error())
 			}
 			return // Do not attempt to write to upgraded connection
 		}
@@ -351,19 +351,11 @@ func (s *Server) handle(w http.ResponseWriter, r *http.Request) {
 		isNormalError := httpErr.HTTPCode == http.StatusNotFound || httpErr.HTTPCode == http.StatusBadRequest
 		if isNormalError {
 			logvr(v, r).
-				Fields(log.Context{
+				Err(httpErr).
-					"error_code":  httpErr.Code,
-					"http_status": httpErr.HTTPCode,
-				}).
-				Err(err).
 				Debug("Connection closed with HTTP %d (ntfy error %d): %s", httpErr.HTTPCode, httpErr.Code, err.Error())
 		} else {
 			logvr(v, r).
-				Fields(log.Context{
+				Err(httpErr).
-					"error_code":  httpErr.Code,
-					"http_status": httpErr.HTTPCode,
-				}).
-				Err(err).
 				Info("Connection closed with HTTP %d (ntfy error %d): %s", httpErr.HTTPCode, httpErr.Code, err.Error())
 		}
 		w.Header().Set("Content-Type", "application/json")
@@ -1161,7 +1153,7 @@ func (s *Server) handleSubscribeWS(w http.ResponseWriter, r *http.Request, v *vi
 	}
 	err = g.Wait()
 	if err != nil && websocket.IsCloseError(err, websocket.CloseNormalClosure, websocket.CloseGoingAway, websocket.CloseAbnormalClosure) {
-		logvr(v, r).Tag(tagWebsocket).Err(err).Trace("WebSocket connection closed")
+		logvr(v, r).Tag(tagWebsocket).Err(err).Fields(websocketErrorContext(err)).Trace("WebSocket connection closed")
 		return nil // Normal closures are not errors; note: "1006 (abnormal closure)" is treated as normal, because people disconnect a lot
 	}
 	return err