From 04effdc2f74a551b7194bdb0e78cd6e13816ffa5 Mon Sep 17 00:00:00 2001 From: Nicolas Carlier Date: Sat, 13 Jan 2024 08:05:23 +0000 Subject: [PATCH] chore(): add timing to logs --- pkg/db/cleanup-job.go | 6 ++++-- pkg/service/articles.go | 7 +++++++ pkg/service/articles_update.go | 2 +- pkg/service/devices.go | 6 ++++-- pkg/service/users.go | 5 ++++- 5 files changed, 20 insertions(+), 6 deletions(-) diff --git a/pkg/db/cleanup-job.go b/pkg/db/cleanup-job.go index e108a4b0d..cb111cbaa 100644 --- 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 index 897658801..7259d59b4 100644 --- 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,6 +72,8 @@ 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 @@ -77,6 +81,7 @@ func (reg *Registry) MarkAllArticlesAsRead(ctx context.Context, status string, c // 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 index 426d0bbd8..f0aebfbfc 100644 --- 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 index 072f63bed..ec8b14b1a 100644 --- 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 index 931d1d64b..6fc8c4483 100644 --- 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))