From 9b54f63eb1748e2f825508beb4388ae30a470326 Mon Sep 17 00:00:00 2001 From: binwiederhier Date: Mon, 6 Feb 2023 16:01:32 -0500 Subject: [PATCH] Error logging --- log/event.go | 6 +++++- log/log_test.go | 27 +++++++++++++++++++++++---- server/errors.go | 9 +++++++++ server/log.go | 22 ++++++++++++++++++---- server/server.go | 18 +++++------------- 5 files changed, 60 insertions(+), 22 deletions(-) diff --git a/log/event.go b/log/event.go index fb02fd0c..31795501 100644 --- a/log/event.go +++ b/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 } diff --git a/log/log_test.go b/log/log_test.go index 4d912f09..c1045fda 100644 --- a/log/log_test.go +++ b/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, } diff --git a/server/errors.go b/server/errors.go index 1a0b28e5..654ea15f 100644 --- a/server/errors.go +++ b/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, diff --git a/server/log.go b/server/log.go index 85ab8b51..0a96ac6e 100644 --- a/server/log.go +++ b/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(), diff --git a/server/server.go b/server/server.go index 33aab7fc..3a5b5ffb 100644 --- a/server/server.go +++ b/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{ - "error_code": httpErr.Code, - "http_status": httpErr.HTTPCode, - }). - Err(err). + Err(httpErr). Debug("Connection closed with HTTP %d (ntfy error %d): %s", httpErr.HTTPCode, httpErr.Code, err.Error()) } else { logvr(v, r). - Fields(log.Context{ - "error_code": httpErr.Code, - "http_status": httpErr.HTTPCode, - }). - Err(err). + Err(httpErr). 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