From dca736752e022b8084ba6bdffa8a5f703234751f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ferdinand=20M=C3=BCtsch?= Date: Fri, 16 Apr 2021 15:59:39 +0200 Subject: [PATCH] refactor: logging (resolve #169) --- config/sentry.go | 111 +++++++++++++++++++++++++++++++---- main.go | 3 +- middlewares/sentry.go | 30 ---------- routes/api/heartbeat.go | 5 +- routes/api/metrics.go | 2 + routes/login.go | 4 +- routes/settings.go | 6 +- services/aggregation.go | 10 ++-- services/imports/wakatime.go | 8 +-- services/misc.go | 4 +- utils/http.go | 4 +- 11 files changed, 122 insertions(+), 65 deletions(-) delete mode 100644 middlewares/sentry.go diff --git a/config/sentry.go b/config/sentry.go index 7644ac2..8340f3b 100644 --- a/config/sentry.go +++ b/config/sentry.go @@ -4,22 +4,100 @@ import ( "github.com/emvi/logbuch" "github.com/getsentry/sentry-go" "github.com/muety/wakapi/models" + "io" "net/http" "os" "strings" ) -type SentryErrorWriter struct{} +// How to: Logging +// Use logbuch.[Debug|Info|Warn|Error|Fatal]() by default +// Use config.Log().[Debug|Info|Warn|Error|Fatal]() when wanting the log to appear in Sentry as well -// TODO: extend sentry error logging to include context and stacktrace -// see https://github.com/muety/wakapi/issues/169 -func (s *SentryErrorWriter) Write(p []byte) (n int, err error) { - sentry.CaptureMessage(string(p)) - return os.Stderr.Write(p) +type capturingWriter struct { + Writer io.Writer + Message string } -func init() { - logbuch.SetOutput(os.Stdout, &SentryErrorWriter{}) +func (c *capturingWriter) Clear() { + c.Message = "" +} + +func (c *capturingWriter) Write(p []byte) (n int, err error) { + c.Message = string(p) + return c.Writer.Write(p) +} + +// SentryWrapperLogger is a wrapper around a logbuch.Logger that forwards events to Sentry in addition and optionally allows to attach a request context +type SentryWrapperLogger struct { + *logbuch.Logger + req *http.Request + outWriter *capturingWriter + errWriter *capturingWriter +} + +func Log() *SentryWrapperLogger { + ow, ew := &capturingWriter{Writer: os.Stdout}, &capturingWriter{Writer: os.Stderr} + return &SentryWrapperLogger{ + Logger: logbuch.NewLogger(ow, ew), + outWriter: ow, + errWriter: ew, + } +} + +func (l *SentryWrapperLogger) Request(req *http.Request) *SentryWrapperLogger { + l.req = req + return l +} + +func (l *SentryWrapperLogger) Debug(msg string, params ...interface{}) { + l.outWriter.Clear() + l.Logger.Debug(msg, params...) + l.log(l.errWriter.Message, sentry.LevelDebug) +} + +func (l *SentryWrapperLogger) Info(msg string, params ...interface{}) { + l.outWriter.Clear() + l.Logger.Info(msg, params...) + l.log(l.errWriter.Message, sentry.LevelInfo) +} + +func (l *SentryWrapperLogger) Warn(msg string, params ...interface{}) { + l.outWriter.Clear() + l.Logger.Warn(msg, params...) + l.log(l.errWriter.Message, sentry.LevelWarning) +} + +func (l *SentryWrapperLogger) Error(msg string, params ...interface{}) { + l.errWriter.Clear() + l.Logger.Error(msg, params...) + l.log(l.errWriter.Message, sentry.LevelError) +} + +func (l *SentryWrapperLogger) Fatal(msg string, params ...interface{}) { + l.errWriter.Clear() + l.Logger.Fatal(msg, params...) + l.log(l.errWriter.Message, sentry.LevelFatal) +} + +func (l *SentryWrapperLogger) log(msg string, level sentry.Level) { + event := sentry.NewEvent() + event.Level = level + event.Message = msg + + if l.req != nil { + if h := l.req.Context().Value(sentry.HubContextKey); h != nil { + hub := h.(*sentry.Hub) + hub.Scope().SetRequest(l.req) + if u := getPrincipal(l.req); u != nil { + hub.Scope().SetUser(sentry.User{ID: u.ID}) + } + hub.CaptureEvent(event) + return + } + } + + sentry.CaptureEvent(event) } func initSentry(config sentryConfig, debug bool) { @@ -43,13 +121,10 @@ func initSentry(config sentryConfig, debug bool) { return sentry.UniformTracesSampler(config.SampleRate).Sample(ctx) }), BeforeSend: func(event *sentry.Event, hint *sentry.EventHint) *sentry.Event { - type principalGetter interface { - GetPrincipal() *models.User - } if hint.Context != nil { if req, ok := hint.Context.Value(sentry.RequestContextKey).(*http.Request); ok { - if p := req.Context().Value("principal"); p != nil { - event.User.ID = p.(principalGetter).GetPrincipal().ID + if u := getPrincipal(req); u != nil { + event.User.ID = u.ID } } } @@ -59,3 +134,13 @@ func initSentry(config sentryConfig, debug bool) { logbuch.Fatal("failed to initialized sentry – %v", err) } } + +func getPrincipal(r *http.Request) *models.User { + type principalGetter interface { + GetPrincipal() *models.User + } + if p := r.Context().Value("principal"); p != nil { + return p.(principalGetter).GetPrincipal() + } + return nil +} diff --git a/main.go b/main.go index 8212ab0..bd1dba5 100644 --- a/main.go +++ b/main.go @@ -2,6 +2,7 @@ package main import ( "embed" + sentryhttp "github.com/getsentry/sentry-go/http" "io/fs" "log" "net/http" @@ -183,7 +184,7 @@ func main() { router.Use(middlewares.NewLoggingMiddleware(logbuch.Info, []string{"/assets"})) router.Use(handlers.RecoveryHandler()) if config.Sentry.Dsn != "" { - router.Use(middlewares.NewSentryMiddleware()) + router.Use(sentryhttp.New(sentryhttp.Options{Repanic: true}).Handle) } rootRouter.Use(middlewares.NewSecurityMiddleware()) diff --git a/middlewares/sentry.go b/middlewares/sentry.go deleted file mode 100644 index 41b78c7..0000000 --- a/middlewares/sentry.go +++ /dev/null @@ -1,30 +0,0 @@ -package middlewares - -import ( - "context" - "github.com/getsentry/sentry-go" - sentryhttp "github.com/getsentry/sentry-go/http" - "net/http" -) - -type SentryMiddleware struct { - handler http.Handler -} - -func NewSentryMiddleware() func(http.Handler) http.Handler { - return func(h http.Handler) http.Handler { - return sentryhttp.New(sentryhttp.Options{ - Repanic: true, - }).Handle(&SentryMiddleware{handler: h}) - } -} - -func (h *SentryMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request) { - ctx := context.WithValue(r.Context(), "-", "-") - h.handler.ServeHTTP(w, r.WithContext(ctx)) - if hub := sentry.GetHubFromContext(ctx); hub != nil { - if user := GetPrincipal(r); user != nil { - hub.Scope().SetUser(sentry.User{ID: user.ID}) - } - } -} diff --git a/routes/api/heartbeat.go b/routes/api/heartbeat.go index b51efc3..40206b9 100644 --- a/routes/api/heartbeat.go +++ b/routes/api/heartbeat.go @@ -2,7 +2,6 @@ package api import ( "encoding/json" - "github.com/emvi/logbuch" "github.com/gorilla/mux" conf "github.com/muety/wakapi/config" "github.com/muety/wakapi/middlewares" @@ -83,7 +82,7 @@ func (h *HeartbeatApiHandler) Post(w http.ResponseWriter, r *http.Request) { if err := h.heartbeatSrvc.InsertBatch(heartbeats); err != nil { w.WriteHeader(http.StatusInternalServerError) w.Write([]byte(conf.ErrInternalServerError)) - logbuch.Error("failed to batch-insert heartbeats – %v", err) + conf.Log().Request(r).Error("failed to batch-insert heartbeats – %v", err) return } @@ -92,7 +91,7 @@ func (h *HeartbeatApiHandler) Post(w http.ResponseWriter, r *http.Request) { if _, err := h.userSrvc.Update(user); err != nil { w.WriteHeader(http.StatusInternalServerError) w.Write([]byte(conf.ErrInternalServerError)) - logbuch.Error("failed to update user – %v", err) + conf.Log().Request(r).Error("failed to update user – %v", err) return } } diff --git a/routes/api/metrics.go b/routes/api/metrics.go index d18fefa..f2479af 100644 --- a/routes/api/metrics.go +++ b/routes/api/metrics.go @@ -78,6 +78,7 @@ func (h *MetricsHandler) Get(w http.ResponseWriter, r *http.Request) { var metrics mm.Metrics if userMetrics, err := h.getUserMetrics(reqUser); err != nil { + conf.Log().Request(r).Error("%v", err) w.WriteHeader(http.StatusInternalServerError) w.Write([]byte(conf.ErrInternalServerError)) return @@ -89,6 +90,7 @@ func (h *MetricsHandler) Get(w http.ResponseWriter, r *http.Request) { if reqUser.IsAdmin { if adminMetrics, err := h.getAdminMetrics(reqUser); err != nil { + conf.Log().Request(r).Error("%v", err) w.WriteHeader(http.StatusInternalServerError) w.Write([]byte(conf.ErrInternalServerError)) return diff --git a/routes/login.go b/routes/login.go index b5c2900..d0b62b8 100644 --- a/routes/login.go +++ b/routes/login.go @@ -284,14 +284,14 @@ func (h *LoginHandler) PostResetPassword(w http.ResponseWriter, r *http.Request) go func(user *models.User) { link := fmt.Sprintf("%s/set-password?token=%s", h.config.Server.GetPublicUrl(), user.ResetToken) if err := h.mailSrvc.SendPasswordReset(user, link); err != nil { - logbuch.Error("failed to send password reset mail to %s – %v", user.ID, err) + conf.Log().Request(r).Error("failed to send password reset mail to %s – %v", user.ID, err) } else { logbuch.Info("sent password reset mail to %s", user.ID) } }(u) } } else { - logbuch.Warn("password reset requested for unregistered address '%s'", resetRequest.Email) + conf.Log().Request(r).Warn("password reset requested for unregistered address '%s'", resetRequest.Email) } http.Redirect(w, r, fmt.Sprintf("%s/?success=%s", h.config.Server.BasePath, "an e-mail was sent to you in case your e-mail address was registered"), http.StatusFound) diff --git a/routes/settings.go b/routes/settings.go index 8297f65..b8e5d6e 100644 --- a/routes/settings.go +++ b/routes/settings.go @@ -450,7 +450,7 @@ func (h *SettingsHandler) actionImportWaktime(w http.ResponseWriter, r *http.Req if user.Email != "" { if err := h.mailSrvc.SendImportNotification(user, time.Now().Sub(start), int(countAfter-countBefore)); err != nil { - logbuch.Error("failed to send import notification mail to %s – %v", user.ID, err) + conf.Log().Request(r).Error("failed to send import notification mail to %s – %v", user.ID, err) } else { logbuch.Info("sent import notification mail to %s", user.ID) } @@ -472,7 +472,7 @@ func (h *SettingsHandler) actionRegenerateSummaries(w http.ResponseWriter, r *ht go func(user *models.User) { if err := h.regenerateSummaries(user); err != nil { - logbuch.Error("failed to regenerate summaries for user '%s' – %v", user.ID, err) + conf.Log().Request(r).Error("failed to regenerate summaries for user '%s' – %v", user.ID, err) } }(middlewares.GetPrincipal(r)) @@ -489,7 +489,7 @@ func (h *SettingsHandler) actionDeleteUser(w http.ResponseWriter, r *http.Reques logbuch.Info("deleting user '%s' shortly", user.ID) time.Sleep(5 * time.Minute) if err := h.userSrvc.Delete(user); err != nil { - logbuch.Error("failed to delete user '%s' – %v", user.ID, err) + conf.Log().Request(r).Error("failed to delete user '%s' – %v", user.ID, err) } else { logbuch.Info("successfully deleted user '%s'", user.ID) } diff --git a/services/aggregation.go b/services/aggregation.go index 7eba357..32f0122 100644 --- a/services/aggregation.go +++ b/services/aggregation.go @@ -73,7 +73,7 @@ func (srv *AggregationService) Run(userIds map[string]bool) error { func (srv *AggregationService) summaryWorker(jobs <-chan *AggregationJob, summaries chan<- *models.Summary) { for job := range jobs { if summary, err := srv.summaryService.Summarize(job.From, job.To, &models.User{ID: job.UserID}); err != nil { - logbuch.Error("failed to generate summary (%v, %v, %s) – %v", job.From, job.To, job.UserID, err) + config.Log().Error("failed to generate summary (%v, %v, %s) – %v", job.From, job.To, job.UserID, err) } else { logbuch.Info("successfully generated summary (%v, %v, %s)", job.From, job.To, job.UserID) summaries <- summary @@ -84,7 +84,7 @@ func (srv *AggregationService) summaryWorker(jobs <-chan *AggregationJob, summar func (srv *AggregationService) persistWorker(summaries <-chan *models.Summary) { for summary := range summaries { if err := srv.summaryService.Insert(summary); err != nil { - logbuch.Error("failed to save summary (%v, %v, %s) – %v", summary.UserID, summary.FromTime, summary.ToTime, err) + config.Log().Error("failed to save summary (%v, %v, %s) – %v", summary.UserID, summary.FromTime, summary.ToTime, err) } } } @@ -94,7 +94,7 @@ func (srv *AggregationService) trigger(jobs chan<- *AggregationJob, userIds map[ var users []*models.User if allUsers, err := srv.userService.GetAll(); err != nil { - logbuch.Error(err.Error()) + config.Log().Error(err.Error()) return err } else if userIds != nil && len(userIds) > 0 { users = make([]*models.User, 0) @@ -110,14 +110,14 @@ func (srv *AggregationService) trigger(jobs chan<- *AggregationJob, userIds map[ // Get a map from user ids to the time of their latest summary or nil if none exists yet lastUserSummaryTimes, err := srv.summaryService.GetLatestByUser() if err != nil { - logbuch.Error(err.Error()) + config.Log().Error(err.Error()) return err } // Get a map from user ids to the time of their earliest heartbeats or nil if none exists yet firstUserHeartbeatTimes, err := srv.heartbeatService.GetFirstByUsers() if err != nil { - logbuch.Error(err.Error()) + config.Log().Error(err.Error()) return err } diff --git a/services/imports/wakatime.go b/services/imports/wakatime.go index 17ff3a5..fa54b0c 100644 --- a/services/imports/wakatime.go +++ b/services/imports/wakatime.go @@ -42,7 +42,7 @@ func (w *WakatimeHeartbeatImporter) Import(user *models.User, minFrom time.Time, go func(user *models.User, out chan *models.Heartbeat) { startDate, endDate, err := w.fetchRange() if err != nil { - logbuch.Error("failed to fetch date range while importing wakatime heartbeats for user '%s' – %v", user.ID, err) + config.Log().Error("failed to fetch date range while importing wakatime heartbeats for user '%s' – %v", user.ID, err) return } @@ -55,13 +55,13 @@ func (w *WakatimeHeartbeatImporter) Import(user *models.User, minFrom time.Time, userAgents, err := w.fetchUserAgents() if err != nil { - logbuch.Error("failed to fetch user agents while importing wakatime heartbeats for user '%s' – %v", user.ID, err) + config.Log().Error("failed to fetch user agents while importing wakatime heartbeats for user '%s' – %v", user.ID, err) return } machinesNames, err := w.fetchMachineNames() if err != nil { - logbuch.Error("failed to fetch machine names while importing wakatime heartbeats for user '%s' – %v", user.ID, err) + config.Log().Error("failed to fetch machine names while importing wakatime heartbeats for user '%s' – %v", user.ID, err) return } @@ -84,7 +84,7 @@ func (w *WakatimeHeartbeatImporter) Import(user *models.User, minFrom time.Time, d := day.Format(config.SimpleDateFormat) heartbeats, err := w.fetchHeartbeats(d) if err != nil { - logbuch.Error("failed to fetch heartbeats for day '%s' and user '%s' – &v", d, user.ID, err) + config.Log().Error("failed to fetch heartbeats for day '%s' and user '%s' – &v", d, user.ID, err) } for _, h := range heartbeats { diff --git a/services/misc.go b/services/misc.go index f646016..f128f47 100644 --- a/services/misc.go +++ b/services/misc.go @@ -42,7 +42,7 @@ type CountTotalTimeResult struct { func (srv *MiscService) ScheduleCountTotalTime() { // Run once initially if err := srv.runCountTotalTime(); err != nil { - logbuch.Error("failed to run CountTotalTimeJob: %v", err) + logbuch.Fatal("failed to run CountTotalTimeJob: %v", err) } s := gocron.NewScheduler(time.Local) @@ -80,7 +80,7 @@ func (srv *MiscService) runCountTotalTime() error { func (srv *MiscService) countTotalTimeWorker(jobs <-chan *CountTotalTimeJob, results chan<- *CountTotalTimeResult) { for job := range jobs { if result, err := srv.summaryService.Aliased(time.Time{}, time.Now(), &models.User{ID: job.UserID}, srv.summaryService.Retrieve, false); err != nil { - logbuch.Error("failed to count total for user %s: %v", job.UserID, err) + config.Log().Error("failed to count total for user %s: %v", job.UserID, err) } else { logbuch.Info("successfully counted total for user %s", job.UserID) results <- &CountTotalTimeResult{ diff --git a/utils/http.go b/utils/http.go index 8cfe040..8197fb9 100644 --- a/utils/http.go +++ b/utils/http.go @@ -2,7 +2,7 @@ package utils import ( "encoding/json" - "github.com/emvi/logbuch" + "github.com/muety/wakapi/config" "net/http" ) @@ -10,6 +10,6 @@ func RespondJSON(w http.ResponseWriter, status int, object interface{}) { w.Header().Set("Content-Type", "application/json") w.WriteHeader(status) if err := json.NewEncoder(w).Encode(object); err != nil { - logbuch.Error("error while writing json response: %v", err) + config.Log().Error("error while writing json response: %v", err) } }