chore(): add timing to logs

ncarlier · Jan 13, 2024 · 04effdc · 04effdc
1 parent 2068275
commit 04effdc
Show file tree

Hide file tree

Showing 5 changed files with 20 additions and 6 deletions.
diff --git a/pkg/db/cleanup-job.go b/pkg/db/cleanup-job.go
@@ -33,6 +33,7 @@ func NewCleanupDatabaseJob(db DB) job.Job {
 func (cdj *CleanupDatabaseJob) Start() {
 	cdj.logger.Debug().Msg("job started")
 	for range cdj.ticker.C {
+		start := time.Now()
 		cdj.logger.Debug().Msg("running job...")
 		nb, err := cdj.db.DeleteReadArticlesOlderThan(maximumArticleRetentionDuration)
 		if err != nil {
@@ -44,7 +45,8 @@ func (cdj *CleanupDatabaseJob) Start() {
 		if nb > 0 {
 			evt = cdj.logger.Info()
 		}
-		evt.Int64("removed_articles", nb).Msg("cleanup done")
+		evt.Int64("removed_articles", nb).Dur("took", time.Since(start)).Msg("cleanup done")
+		start = time.Now()
 		nb, err = cdj.db.DeleteInactiveDevicesOlderThan(maximumDeviceInactivityDuration)
 		if err != nil {
 			cdj.logger.Error().Err(err).Msg("unable to clean old devices from the database")
@@ -55,7 +57,7 @@ func (cdj *CleanupDatabaseJob) Start() {
 		if nb > 0 {
 			evt = cdj.logger.Info()
 		}
-		evt.Int64("removed_devices", nb).Msg("cleanup done")
+		evt.Int64("removed_devices", nb).Dur("took", time.Since(start)).Msg("cleanup done")
 	}
 }
 

diff --git a/pkg/service/articles.go b/pkg/service/articles.go
@@ -3,6 +3,7 @@ package service
 import (
 	"context"
 	"errors"
+	"time"
 
 	"github.com/ncarlier/readflow/pkg/model"
 )
@@ -59,6 +60,7 @@ func (reg *Registry) GetArticle(ctx context.Context, id uint) (*model.Article, e
 
 // MarkAllArticlesAsRead set status to read for all user's articles of a specific status and category
 func (reg *Registry) MarkAllArticlesAsRead(ctx context.Context, status string, categoryID *uint) (int64, error) {
+	start := time.Now()
 	uid := getCurrentUserIDFromContext(ctx)
 
 	nb, err := reg.db.MarkAllArticlesAsReadByUser(uid, status, categoryID)
@@ -70,13 +72,16 @@ func (reg *Registry) MarkAllArticlesAsRead(ctx context.Context, status string, c
 	}
 	reg.logger.Debug().Uint(
 		"uid", uid,
+	).Dur(
+		"took", time.Since(start),
 	).Msg("all articles marked as read")
 
 	return nb, nil
 }
 
 // CleanHistory remove all read articles
 func (reg *Registry) CleanHistory(ctx context.Context) (int64, error) {
+	start := time.Now()
 	uid := getCurrentUserIDFromContext(ctx)
 
 	nb, err := reg.db.DeleteAllReadArticlesByUser(uid)
@@ -88,6 +93,8 @@ func (reg *Registry) CleanHistory(ctx context.Context) (int64, error) {
 	}
 	reg.logger.Debug().Uint(
 		"uid", uid,
+	).Dur(
+		"took", time.Since(start),
 	).Msg("history purged")
 
 	return nb, nil

diff --git a/pkg/service/articles_update.go b/pkg/service/articles_update.go
@@ -16,8 +16,8 @@ const unableToUpdateArticleErrorMsg = "unable to update article"
 
 // UpdateArticle update article
 func (reg *Registry) UpdateArticle(ctx context.Context, form model.ArticleUpdateForm) (*model.Article, error) {
-	uid := getCurrentUserIDFromContext(ctx)
 	start := time.Now()
+	uid := getCurrentUserIDFromContext(ctx)
 
 	logger := reg.logger.With().Uint("uid", uid).Uint("id", form.ID).Logger()
 

diff --git a/pkg/service/devices.go b/pkg/service/devices.go
@@ -6,6 +6,7 @@ import (
 	"errors"
 	"fmt"
 	"strings"
+	"time"
 
 	webpush "github.com/SherClockHolmes/webpush-go"
 
@@ -135,6 +136,7 @@ func (reg *Registry) NotifyDevices(ctx context.Context, payload *model.DeviceNot
 	}
 	counter := 0
 	for _, device := range *devices {
+		start := time.Now()
 		logger = reg.logger.With().Uint("uid", uid).Uint("device", *device.ID).Logger()
 		// Rate limiting
 		if _, _, _, ok, err := reg.notificationRateLimiter.Take(ctx, user.Username); err != nil || !ok {
@@ -162,11 +164,11 @@ func (reg *Registry) NotifyDevices(ctx context.Context, payload *model.DeviceNot
 			continue
 		}
 		if res.StatusCode >= 400 {
-			logger.Info().Err(errors.New(res.Status)).Int("status", res.StatusCode).Msg(errNotification)
+			logger.Info().Err(errors.New(res.Status)).Int("status", res.StatusCode).Dur("took", time.Since(start)).Msg(errNotification)
 			continue
 		}
 		counter++
-		logger.Info().Str("title", payload.Title).Msg("notification sent to user device")
+		logger.Info().Str("title", payload.Title).Dur("took", time.Since(start)).Msg("notification sent to user device")
 	}
 	return counter, nil
 }
diff --git a/pkg/service/users.go b/pkg/service/users.go
@@ -154,6 +154,7 @@ func (reg *Registry) GetUserByHashID(ctx context.Context, hashid string) (*model
 
 // UpdateUser update user account (required admin access)
 func (reg *Registry) UpdateUser(ctx context.Context, form model.UserForm) (*model.User, error) {
+	start := time.Now()
 	uid := getCurrentUserIDFromContext(ctx)
 	if !isAdmin(ctx) {
 		err := errors.New("forbidden")
@@ -201,7 +202,9 @@ func (reg *Registry) UpdateUser(ctx context.Context, form model.UserForm) (*mode
 	}
 	reg.logger.Info().Uint(
 		"uid", *user.ID,
-	).Str("username", user.Username).Msg("user updated")
+	).Str(
+		"username", user.Username,
+	).Dur("took", time.Since(start)).Msg("user updated")
 
 	reg.events.Publish(event.NewEvent(EventUpdateUser, *user))