refactor: logging (resolve #169)

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
+}

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())
 

middlewares/sentry.go

@@ -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})
-		}
-	}
-}

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
 		}
 	}

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

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)

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)
 		}

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
 	}
 

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 {

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{

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)
 	}
 }