Global/wakapi
1
0
Fork 0
mirror of https://github.com/muety/wakapi.git synced 2025-12-06 22:36:34 -08:00
Code Issues Packages Projects Releases Wiki Activity

Correct the logs to use the format key:value

Browse Source
This commit is contained in:
finn
2024-08-20 08:45:43 +07:00
parent 118e51139a
commit b5bb3da9b6
30 changed files with 4800 additions and 799 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
config/jobqueue.go
View File

@@ -42,7 +42,7 @@ func InitQueue(name string, workers int) error {
if _, ok := jobQueues[name]; ok { if _, ok := jobQueues[name]; ok {
return fmt.Errorf("queue '%s' already existing", name) return fmt.Errorf("queue '%s' already existing", name)
} }
slog.Info("creating job queue '%s' (%d workers)", name, workers) slog.Info("creating job queue", "name", name, "workers", workers)
jobQueues[name] = artifex.NewDispatcher(workers, 4096) jobQueues[name] = artifex.NewDispatcher(workers, 4096)
jobQueues[name].Start() jobQueues[name].Start()
return nil return nil

5434
coverage/coverage.out
View File

File diff suppressed because it is too large Load Diff

5
main.go
View File

@@ -143,7 +143,7 @@ func main() {
slog.Info("starting with database", "dialect", config.Db.Dialect) slog.Info("starting with database", "dialect", config.Db.Dialect)
db, err = gorm.Open(config.Db.GetDialector(), &gorm.Config{Logger: gormLogger}, conf.GetWakapiDBOpts(&config.Db)) db, err = gorm.Open(config.Db.GetDialector(), &gorm.Config{Logger: gormLogger}, conf.GetWakapiDBOpts(&config.Db))
if err != nil { if err != nil {
slog.Error("could not connect to database", "error", err.Error()) slog.Error("could not connect to database", "error", err)
log.Fatal("could not open database") log.Fatal("could not open database")
} }
@@ -152,7 +152,7 @@ func main() {
} }
sqlDb, err := db.DB() sqlDb, err := db.DB()
if err != nil { if err != nil {
slog.Error("could not connect to database", "error", err.Error()) slog.Error("could not connect to database", "error", err)
log.Fatal("could not connect to database") log.Fatal("could not connect to database")
} }
sqlDb.SetMaxIdleConns(int(config.Db.MaxConn)) sqlDb.SetMaxIdleConns(int(config.Db.MaxConn))
@@ -452,4 +452,5 @@ func initLogger() {
} }
l := slog.New(handler) l := slog.New(handler)
slog.SetDefault(l) slog.SetDefault(l)
slog.Info("logger initialized", "env", config.Env)
} }

12
middlewares/custom/wakatime.go
View File

@@ -62,7 +62,7 @@ func (m *WakatimeRelayMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Reque
err := m.filterByCache(r) err := m.filterByCache(r)
if err != nil { if err != nil {
slog.Warn("%v", err) slog.Warn("filter cache error", "error", err)
return return
} }
@@ -104,7 +104,7 @@ func (m *WakatimeRelayMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Reque
func (m *WakatimeRelayMiddleware) send(method, url string, body io.Reader, headers http.Header, forUser *models.User) { func (m *WakatimeRelayMiddleware) send(method, url string, body io.Reader, headers http.Header, forUser *models.User) {
request, err := http.NewRequest(method, url, body) request, err := http.NewRequest(method, url, body)
if err != nil { if err != nil {
slog.Warn("error constructing relayed request - %v", err) slog.Warn("error constructing relayed request", "error", err)
return return
} }
@@ -116,12 +116,12 @@ func (m *WakatimeRelayMiddleware) send(method, url string, body io.Reader, heade
response, err := m.httpClient.Do(request) response, err := m.httpClient.Do(request)
if err != nil { if err != nil {
slog.Warn("error executing relayed request - %v", err) slog.Warn("error executing relayed request", "error", err)
return return
} }
if response.StatusCode < 200 || response.StatusCode >= 300 { if response.StatusCode < 200 || response.StatusCode >= 300 {
slog.Warn("failed to relay request for user %s, got status %d", forUser.ID, response.StatusCode) slog.Warn("failed to relay request for user", "userID", forUser.ID, "statusCode", response.StatusCode)
// TODO: use leaky bucket instead of expiring cache? // TODO: use leaky bucket instead of expiring cache?
if _, found := m.failureCache.Get(forUser.ID); !found { if _, found := m.failureCache.Get(forUser.ID); !found {
@@ -133,7 +133,7 @@ func (m *WakatimeRelayMiddleware) send(method, url string, body io.Reader, heade
Fields: map[string]interface{}{config.FieldUser: forUser, config.FieldPayload: n}, Fields: map[string]interface{}{config.FieldUser: forUser, config.FieldPayload: n},
}) })
} else if n%10 == 0 { } else if n%10 == 0 {
slog.Warn("%d / %d failed wakatime heartbeat relaying attempts for user %s within last 24 hours", n, maxFailuresPerDay, forUser.ID) slog.Warn("failed wakatime heartbeat relaying attempts for user", "failedCount", n, "maxFailures", maxFailuresPerDay, "userID", forUser.ID)
} }
} }
} }
@@ -182,7 +182,7 @@ func (m *WakatimeRelayMiddleware) filterByCache(r *http.Request) error {
if len(newData) != len(heartbeats) { if len(newData) != len(heartbeats) {
user := middlewares.GetPrincipal(r) user := middlewares.GetPrincipal(r)
slog.Warn("only relaying %d of %d heartbeats for user %s", len(newData), len(heartbeats), user.ID) slog.Warn("only relaying partial heartbeats for user", "relayedCount", len(newData), "totalCount", len(heartbeats), "userID", user.ID)
} }
buf := bytes.Buffer{} buf := bytes.Buffer{}

4
migrations/20201103_rename_language_mappings_table.go
View File

@@ -16,12 +16,12 @@ func init() {
oldIndexName, newIndexName := "idx_customrule_user", "idx_language_mapping_user" oldIndexName, newIndexName := "idx_customrule_user", "idx_language_mapping_user"
if migrator.HasTable(oldTableName) { if migrator.HasTable(oldTableName) {
slog.Info("renaming '%s' table to '%s'", oldTableName, newTableName) slog.Info("renaming table", "oldName", oldTableName, "newName", newTableName)
if err := migrator.RenameTable(oldTableName, &models.LanguageMapping{}); err != nil { if err := migrator.RenameTable(oldTableName, &models.LanguageMapping{}); err != nil {
return err return err
} }
slog.Info("renaming '%s' index to '%s'", oldIndexName, newIndexName) slog.Info("renaming index", "oldName", oldIndexName, "newName", newIndexName)
return migrator.RenameIndex(&models.LanguageMapping{}, oldIndexName, newIndexName) return migrator.RenameIndex(&models.LanguageMapping{}, oldIndexName, newIndexName)
} }
return nil return nil

2
migrations/20201106_migration_cascade_constraints.go
View File

@@ -51,7 +51,7 @@ func init() {
for name, table := range constraints { for name, table := range constraints {
if migrator.HasConstraint(table, name) { if migrator.HasConstraint(table, name) {
slog.Info("dropping constraint '%s'", name) slog.Info("dropping constraint", "name", name)
if err := migrator.DropConstraint(table, name); err != nil { if err := migrator.DropConstraint(table, name); err != nil {
return err return err
} }

2
migrations/20210202_fix_cascade_for_alias_user_constraint.go
View File

@@ -31,7 +31,7 @@ func init() {
} }
if migrator.HasConstraint(&models.Alias{}, "fk_aliases_user") { if migrator.HasConstraint(&models.Alias{}, "fk_aliases_user") {
slog.Info("dropping constraint 'fk_aliases_user'") slog.Info("dropping constraint", "name", "fk_aliases_user")
if err := migrator.DropConstraint(&models.Alias{}, "fk_aliases_user"); err != nil { if err := migrator.DropConstraint(&models.Alias{}, "fk_aliases_user"); err != nil {
return err return err
} }

4
migrations/20210206_drop_badges_column_add_sharing_flags.go
View File

@@ -38,14 +38,14 @@ func init() {
} }
if cfg.Db.Dialect == config.SQLDialectSqlite { if cfg.Db.Dialect == config.SQLDialectSqlite {
slog.Info("not attempting to drop column 'badges_enabled' on sqlite") slog.Info("not attempting to drop column on sqlite", "column", "badges_enabled")
return nil return nil
} }
if err := migrator.DropColumn(&models.User{}, "badges_enabled"); err != nil { if err := migrator.DropColumn(&models.User{}, "badges_enabled"); err != nil {
return err return err
} }
slog.Info("dropped column 'badges_enabled' after substituting it by sharing indicators") slog.Info("dropped column after substituting it by sharing indicators", "column", "badges_enabled")
return nil return nil
}, },

2
migrations/20210411_drop_migrations_table.go
View File

@@ -12,7 +12,7 @@ func init() {
name: name, name: name,
f: func(db *gorm.DB, cfg *config.Config) error { f: func(db *gorm.DB, cfg *config.Config) error {
if err := db.Migrator().DropTable("gorp_migrations"); err == nil { if err := db.Migrator().DropTable("gorp_migrations"); err == nil {
slog.Info("dropped table 'gorp_migrations'") slog.Info("dropped table", "table", "gorp_migrations")
} }
return nil return nil
}, },

2
migrations/20211215_migrate_id_to_bigint.go
View File

@@ -40,7 +40,7 @@ func init() {
} else { } else {
// sqlite doesn't allow for changing column type easily // sqlite doesn't allow for changing column type easily
// https://stackoverflow.com/a/2083562/3112139 // https://stackoverflow.com/a/2083562/3112139
slog.Warn("unable to migrate id columns to bigint on %s", cfg.Db.Dialect) slog.Warn("unable to migrate id columns to bigint", "dialect", cfg.Db.Dialect)
} }
setHasRun(name, db) setHasRun(name, db)

2
migrations/20220317_align_num_heartbeats.go
View File

@@ -45,7 +45,7 @@ func init() {
return err return err
} }
slog.Info("corrected heartbeats counter of %d summaries", result.RowsAffected) slog.Info("corrected heartbeats counter of summaries", "count", result.RowsAffected)
setHasRun(name, db) setHasRun(name, db)
return nil return nil

6
migrations/202203191_drop_diagnostics_user.go
View File

@@ -19,14 +19,14 @@ func init() {
migrator := db.Migrator() migrator := db.Migrator()
if migrator.HasColumn(&models.Diagnostics{}, "user_id") { if migrator.HasColumn(&models.Diagnostics{}, "user_id") {
slog.Info("running migration '%s'", name) slog.Info("running migration", "name", name)
if err := migrator.DropConstraint(&models.Diagnostics{}, "fk_diagnostics_user"); err != nil { if err := migrator.DropConstraint(&models.Diagnostics{}, "fk_diagnostics_user"); err != nil {
slog.Warn("failed to drop 'fk_diagnostics_user' constraint (%v)", err) slog.Warn("failed to drop constraint", "constraint", "fk_diagnostics_user", "error", err)
} }
if err := migrator.DropColumn(&models.Diagnostics{}, "user_id"); err != nil { if err := migrator.DropColumn(&models.Diagnostics{}, "user_id"); err != nil {
slog.Warn("failed to drop user_id column of diagnostics (%v)", err) slog.Warn("failed to drop column", "table", "diagnostics", "column", "user_id", "error", err)
} }
} }

4
migrations/20220403_drop_user_project_idx.go
View File

@@ -25,9 +25,9 @@ func init() {
} }
if cfg.Db.IsSQLite() && db.Migrator().HasIndex(&models.Heartbeat{}, idxName) { if cfg.Db.IsSQLite() && db.Migrator().HasIndex(&models.Heartbeat{}, idxName) {
slog.Info("running migration '%s'", name) slog.Info("running migration", "name", name)
if err := db.Migrator().DropIndex(&models.Heartbeat{}, idxName); err != nil { if err := db.Migrator().DropIndex(&models.Heartbeat{}, idxName); err != nil {
slog.Warn("failed to drop %s", idxName) slog.Warn("failed to drop index", "indexName", idxName)
} }
} }

4
migrations/20221016_drop_rank_column.go
View File

@@ -19,10 +19,10 @@ func init() {
migrator := db.Migrator() migrator := db.Migrator()
if migrator.HasTable(&models.LeaderboardItem{}) && migrator.HasColumn(&models.LeaderboardItem{}, "rank") { if migrator.HasTable(&models.LeaderboardItem{}) && migrator.HasColumn(&models.LeaderboardItem{}, "rank") {
slog.Info("running migration '%s'", name) slog.Info("running migration", "name", name)
if err := migrator.DropColumn(&models.LeaderboardItem{}, "rank"); err != nil { if err := migrator.DropColumn(&models.LeaderboardItem{}, "rank"); err != nil {
slog.Warn("failed to drop 'rank' column (%v)", err) slog.Warn("failed to drop column", "column", "rank", "error", err)
} }
} }

2
migrations/20230219_add_astro_language.go
View File

@@ -15,7 +15,7 @@ func init() {
return nil return nil
} }
slog.Info("running migration '%s'", name) slog.Info("running migration", "name", name)
if err := db.Exec("UPDATE heartbeats SET language = 'Astro' where language = '' and entity like '%.astro'").Error; err != nil { if err := db.Exec("UPDATE heartbeats SET language = 'Astro' where language = '' and entity like '%.astro'").Error; err != nil {
return err return err

2
migrations/20230219_add_subscription_renewal.go
View File

@@ -19,7 +19,7 @@ func init() {
migrator := db.Migrator() migrator := db.Migrator()
if migrator.HasColumn(&models.User{}, "subscription_renewal") { if migrator.HasColumn(&models.User{}, "subscription_renewal") {
slog.Info("running migration '%s'", name) slog.Info("running migration", "name", name)
if err := db.Exec("UPDATE users SET subscription_renewal = subscribed_until WHERE subscribed_until is not null").Error; err != nil { if err := db.Exec("UPDATE users SET subscription_renewal = subscribed_until WHERE subscribed_until is not null").Error; err != nil {
return err return err

4
migrations/migrations.go
View File

@@ -87,7 +87,7 @@ func RunPreMigrations(db *gorm.DB, cfg *config.Config) {
sort.Sort(preMigrations) sort.Sort(preMigrations)
for _, m := range preMigrations { for _, m := range preMigrations {
slog.Info("potentially running migration '%s'", m.name) slog.Info("potentially running migration", "name", m.name)
if err := m.f(db, cfg); err != nil { if err := m.f(db, cfg); err != nil {
log.Fatalf("migration '%s' failed - %v", m.name, err) log.Fatalf("migration '%s' failed - %v", m.name, err)
} }
@@ -98,7 +98,7 @@ func RunPostMigrations(db *gorm.DB, cfg *config.Config) {
sort.Sort(postMigrations) sort.Sort(postMigrations)
for _, m := range postMigrations { for _, m := range postMigrations {
slog.Info("potentially running migration '%s'", m.name) slog.Info("potentially running migration", "name", m.name)
if err := m.f(db, cfg); err != nil { if err := m.f(db, cfg); err != nil {
log.Fatalf("migration '%s' failed - %v", m.name, err) log.Fatalf("migration '%s' failed - %v", m.name, err)
} }

12
routes/api/metrics.go
View File

@@ -349,7 +349,7 @@ func (h *MetricsHandler) getUserMetrics(user *models.User) (*mm.Metrics, error)
// Database metrics // Database metrics
dbSize, err := h.metricsRepo.GetDatabaseSize() dbSize, err := h.metricsRepo.GetDatabaseSize()
if err != nil { if err != nil {
slog.Warn("failed to get database size (%v)", err) slog.Warn("failed to get database size", "error", err)
} }
metrics = append(metrics, &mm.GaugeMetric{ metrics = append(metrics, &mm.GaugeMetric{
@@ -383,7 +383,7 @@ func (h *MetricsHandler) getAdminMetrics(user *models.User) (*mm.Metrics, error)
var metrics mm.Metrics var metrics mm.Metrics
t0 := time.Now() t0 := time.Now()
slog.Debug("[metrics] start admin metrics calculation") slog.Debug("start admin metrics calculation")
if !user.IsAdmin { if !user.IsAdmin {
return nil, errors.New("unauthorized") return nil, errors.New("unauthorized")
@@ -398,14 +398,14 @@ func (h *MetricsHandler) getAdminMetrics(user *models.User) (*mm.Metrics, error)
totalUsers, _ := h.userSrvc.Count() totalUsers, _ := h.userSrvc.Count()
totalHeartbeats, _ := h.heartbeatSrvc.Count(true) totalHeartbeats, _ := h.heartbeatSrvc.Count(true)
slog.Debug("[metrics] finished counting users and heartbeats after %v", time.Now().Sub(t0)) slog.Debug("finished counting users and heartbeats", "duration", time.Since(t0))
activeUsers, err := h.userSrvc.GetActive(false) activeUsers, err := h.userSrvc.GetActive(false)
if err != nil { if err != nil {
conf.Log().Error("failed to retrieve active users for metric - %v", err) conf.Log().Error("failed to retrieve active users for metric - %v", err)
return nil, err return nil, err
} }
slog.Debug("[metrics] finished getting active users after %v", time.Now().Sub(t0)) slog.Debug("finished getting active users", "duration", time.Since(t0))
metrics = append(metrics, &mm.GaugeMetric{ metrics = append(metrics, &mm.GaugeMetric{
Name: MetricsPrefix + "_admin_seconds_total", Name: MetricsPrefix + "_admin_seconds_total",
@@ -451,7 +451,7 @@ func (h *MetricsHandler) getAdminMetrics(user *models.User) (*mm.Metrics, error)
Labels: []mm.Label{{Key: "user", Value: uc.User}}, Labels: []mm.Label{{Key: "user", Value: uc.User}},
}) })
} }
slog.Debug("[metrics] finished counting heartbeats by user after %v", time.Now().Sub(t0)) slog.Debug("finished counting heartbeats by user", "duration", time.Since(t0))
// Get per-user total activity // Get per-user total activity
@@ -480,7 +480,7 @@ func (h *MetricsHandler) getAdminMetrics(user *models.User) (*mm.Metrics, error)
} }
wp.StopAndWait() wp.StopAndWait()
slog.Debug("[metrics] finished retrieving total activity time by user after %v", time.Now().Sub(t0)) slog.Debug("finished retrieving total activity time by user", "duration", time.Since(t0))
return &metrics, nil return &metrics, nil
} }

2
routes/login.go
View File

@@ -341,7 +341,7 @@ func (h *LoginHandler) PostResetPassword(w http.ResponseWriter, r *http.Request)
if err := h.mailSrvc.SendPasswordReset(user, link); err != nil { if err := h.mailSrvc.SendPasswordReset(user, link); err != nil {
conf.Log().Request(r).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 { } else {
slog.Info("sent password reset mail to %s", user.ID) slog.Info("sent password reset mail", "userID", user.ID)
} }
}(u) }(u)
} }

20
routes/settings.go
View File

@@ -118,7 +118,7 @@ func (h *SettingsHandler) PostIndex(w http.ResponseWriter, r *http.Request) {
actionFunc := h.dispatchAction(action) actionFunc := h.dispatchAction(action)
if actionFunc == nil { if actionFunc == nil {
slog.Warn("failed to dispatch action '%s'", action) slog.Warn("failed to dispatch action", "action", action)
w.WriteHeader(http.StatusBadRequest) w.WriteHeader(http.StatusBadRequest)
templates[conf.SettingsTemplate].Execute(w, h.buildViewModel(r, w, nil).WithError("unknown action requests")) templates[conf.SettingsTemplate].Execute(w, h.buildViewModel(r, w, nil).WithError("unknown action requests"))
return return
@@ -637,7 +637,7 @@ func (h *SettingsHandler) actionImportWakatime(w http.ResponseWriter, r *http.Re
insert := func(batch []*models.Heartbeat) { insert := func(batch []*models.Heartbeat) {
if err := h.heartbeatSrvc.InsertBatch(batch); err != nil { if err := h.heartbeatSrvc.InsertBatch(batch); err != nil {
slog.Warn("failed to insert imported heartbeat, already existing? - %v", err) slog.Warn("failed to insert imported heartbeat, already existing?", "error", err)
} }
} }
@@ -655,7 +655,7 @@ func (h *SettingsHandler) actionImportWakatime(w http.ResponseWriter, r *http.Re
} }
countAfter, _ := h.heartbeatSrvc.CountByUser(user) countAfter, _ := h.heartbeatSrvc.CountByUser(user)
slog.Info("downloaded %d heartbeats for user '%s' (%d actually imported)", count, user.ID, countAfter-countBefore) slog.Info("downloaded heartbeats for user", "count", count, "userID", user.ID, "importedCount", countAfter-countBefore)
h.regenerateSummaries(user) h.regenerateSummaries(user)
@@ -670,7 +670,7 @@ func (h *SettingsHandler) actionImportWakatime(w http.ResponseWriter, r *http.Re
if err := h.mailSrvc.SendImportNotification(user, time.Now().Sub(start), int(countAfter-countBefore)); err != nil { if err := h.mailSrvc.SendImportNotification(user, time.Now().Sub(start), int(countAfter-countBefore)); err != nil {
conf.Log().Request(r).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 { } else {
slog.Info("sent import notification mail to %s", user.ID) slog.Info("sent import notification mail", "userID", user.ID)
} }
} }
}(user) }(user)
@@ -711,15 +711,15 @@ func (h *SettingsHandler) actionClearData(w http.ResponseWriter, r *http.Request
} }
user := middlewares.GetPrincipal(r) user := middlewares.GetPrincipal(r)
slog.Info("user '%s' requested to delete all data", user.ID) slog.Info("user requested to delete all data", "userID", user.ID)
go func(user *models.User) { go func(user *models.User) {
slog.Info("deleting summaries for user '%s'", user.ID) slog.Info("deleting summaries for user", "userID", user.ID)
if err := h.summarySrvc.DeleteByUser(user.ID); err != nil { if err := h.summarySrvc.DeleteByUser(user.ID); err != nil {
conf.Log().Request(r).Error("failed to clear summaries: %v", err) conf.Log().Request(r).Error("failed to clear summaries: %v", err)
} }
slog.Info("deleting heartbeats for user '%s'", user.ID) slog.Info("deleting heartbeats for user", "userID", user.ID)
if err := h.heartbeatSrvc.DeleteByUser(user); err != nil { if err := h.heartbeatSrvc.DeleteByUser(user); err != nil {
conf.Log().Request(r).Error("failed to clear heartbeats: %v", err) conf.Log().Request(r).Error("failed to clear heartbeats: %v", err)
} }
@@ -735,12 +735,12 @@ func (h *SettingsHandler) actionDeleteUser(w http.ResponseWriter, r *http.Reques
user := middlewares.GetPrincipal(r) user := middlewares.GetPrincipal(r)
go func(user *models.User) { go func(user *models.User) {
slog.Info("deleting user '%s' shortly", user.ID) slog.Info("deleting user shortly", "userID", user.ID)
time.Sleep(5 * time.Minute) time.Sleep(5 * time.Minute)
if err := h.userSrvc.Delete(user); err != nil { if err := h.userSrvc.Delete(user); err != nil {
conf.Log().Request(r).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 { } else {
slog.Info("successfully deleted user '%s'", user.ID) slog.Info("successfully deleted user", "userID", user.ID)
} }
}(user) }(user)
@@ -806,7 +806,7 @@ func (h *SettingsHandler) validateWakatimeKey(apiKey string, baseUrl string) boo
} }
func (h *SettingsHandler) regenerateSummaries(user *models.User) error { func (h *SettingsHandler) regenerateSummaries(user *models.User) error {
slog.Info("clearing summaries for user '%s'", user.ID) slog.Info("clearing summaries for user", "userID", user.ID)
if err := h.summarySrvc.DeleteByUser(user.ID); err != nil { if err := h.summarySrvc.DeleteByUser(user.ID); err != nil {
conf.Log().Error("failed to clear summaries: %v", err) conf.Log().Error("failed to clear summaries: %v", err)
return err return err

26
routes/subscription.go
View File

@@ -59,11 +59,11 @@ func NewSubscriptionHandler(
price, err := stripePrice.Get(config.Subscriptions.StandardPriceId, nil) price, err := stripePrice.Get(config.Subscriptions.StandardPriceId, nil)
if err != nil { if err != nil {
log.Fatal("failed to fetch stripe plan details: %v", err) log.Fatalf("failed to fetch stripe plan details: %v", err)
} }
config.Subscriptions.StandardPrice = strings.TrimSpace(fmt.Sprintf("%2.f €", price.UnitAmountDecimal/100.0)) // TODO: respect actual currency config.Subscriptions.StandardPrice = strings.TrimSpace(fmt.Sprintf("%2.f €", price.UnitAmountDecimal/100.0)) // TODO: respect actual currency
slog.Info("enabling subscriptions with stripe payment for %s / month", config.Subscriptions.StandardPrice) slog.Info("enabling subscriptions with stripe payment", "price", config.Subscriptions.StandardPrice)
} }
handler := &SubscriptionHandler{ handler := &SubscriptionHandler{
@@ -82,9 +82,9 @@ func NewSubscriptionHandler(
continue continue
} }
slog.Info("cancelling subscription for user '%s' (email '%s', stripe customer '%s') upon account deletion", user.ID, user.Email, user.StripeCustomerId) slog.Info("cancelling subscription for user upon account deletion", "userID", user.ID, "email", user.Email, "stripeCustomerID", user.StripeCustomerId)
if err := handler.cancelUserSubscription(user); err == nil { if err := handler.cancelUserSubscription(user); err == nil {
slog.Info("successfully cancelled subscription for user '%s' (email '%s', stripe customer '%s')", user.ID, user.Email, user.StripeCustomerId) slog.Info("successfully cancelled subscription for user", "userID", user.ID, "email", user.Email, "stripeCustomerID", user.StripeCustomerId)
} else { } else {
conf.Log().Error("failed to cancel subscription for user '%s' (email '%s', stripe customer '%s') - %v", user.ID, user.Email, user.StripeCustomerId, err) conf.Log().Error("failed to cancel subscription for user '%s' (email '%s', stripe customer '%s') - %v", user.ID, user.Email, user.StripeCustomerId, err)
} }
@@ -223,7 +223,7 @@ func (h *SubscriptionHandler) PostWebhook(w http.ResponseWriter, r *http.Request
if err != nil { if err != nil {
return // status code already written return // status code already written
} }
slog.Info("received stripe subscription event of type '%s' for subscription '%s' (customer '%s').", event.Type, subscription.ID, subscription.Customer.ID) slog.Info("received stripe subscription event", "eventType", event.Type, "subscriptionID", subscription.ID, "customerID", subscription.Customer.ID)
// first, try to get user by associated customer id (requires checkout.session.completed event to have been processed before) // first, try to get user by associated customer id (requires checkout.session.completed event to have been processed before)
user, err := h.userSrvc.GetUserByStripeCustomerId(subscription.Customer.ID) user, err := h.userSrvc.GetUserByStripeCustomerId(subscription.Customer.ID)
@@ -259,7 +259,7 @@ func (h *SubscriptionHandler) PostWebhook(w http.ResponseWriter, r *http.Request
if err != nil { if err != nil {
return // status code already written return // status code already written
} }
slog.Info("received stripe checkout session event of type '%s' for session '%s' (customer '%s' with email '%s').", event.Type, checkoutSession.ID, checkoutSession.Customer.ID, checkoutSession.CustomerEmail) slog.Info("received stripe checkout session event", "eventType", event.Type, "sessionID", checkoutSession.ID, "customerID", checkoutSession.Customer.ID, "customerEmail", checkoutSession.CustomerEmail)
user, err := h.userSrvc.GetUserById(checkoutSession.ClientReferenceID) user, err := h.userSrvc.GetUserById(checkoutSession.ClientReferenceID)
if err != nil { if err != nil {
@@ -272,14 +272,14 @@ func (h *SubscriptionHandler) PostWebhook(w http.ResponseWriter, r *http.Request
if _, err := h.userSrvc.Update(user); err != nil { if _, err := h.userSrvc.Update(user); err != nil {
conf.Log().Request(r).Error("failed to update stripe customer id (%s) for user '%s', %v", checkoutSession.Customer.ID, user.ID, err) conf.Log().Request(r).Error("failed to update stripe customer id (%s) for user '%s', %v", checkoutSession.Customer.ID, user.ID, err)
} else { } else {
slog.Info("associated user '%s' with stripe customer '%s'", user.ID, checkoutSession.Customer.ID) slog.Info("associated user with stripe customer", "userID", user.ID, "stripeCustomerID", checkoutSession.Customer.ID)
} }
} else if user.StripeCustomerId != checkoutSession.Customer.ID { } else if user.StripeCustomerId != checkoutSession.Customer.ID {
conf.Log().Request(r).Error("invalid state: tried to associate user '%s' with stripe customer '%s', but '%s' already assigned", user.ID, checkoutSession.Customer.ID, user.StripeCustomerId) conf.Log().Request(r).Error("invalid state: tried to associate user '%s' with stripe customer '%s', but '%s' already assigned", user.ID, checkoutSession.Customer.ID, user.StripeCustomerId)
} }
default: default:
slog.Warn("got stripe event '%s' with no handler defined", event.Type) slog.Warn("got stripe event with no handler defined", "eventType", event.Type)
} }
w.WriteHeader(http.StatusOK) w.WriteHeader(http.StatusOK)
@@ -305,19 +305,19 @@ func (h *SubscriptionHandler) handleSubscriptionEvent(subscription *stripe.Subsc
hasSubscribed = true hasSubscribed = true
user.SubscribedUntil = &until user.SubscribedUntil = &until
user.SubscriptionRenewal = &until user.SubscriptionRenewal = &until
slog.Info("user %s got active subscription %s until %v", user.ID, subscription.ID, user.SubscribedUntil) slog.Info("user got active subscription", "userID", user.ID, "subscriptionID", subscription.ID, "subscribedUntil", user.SubscribedUntil)
} }
if cancelAt := time.Unix(subscription.CancelAt, 0); !cancelAt.IsZero() && cancelAt.After(time.Now()) { if cancelAt := time.Unix(subscription.CancelAt, 0); !cancelAt.IsZero() && cancelAt.After(time.Now()) {
user.SubscriptionRenewal = nil user.SubscriptionRenewal = nil
slog.Info("user %s chose to cancel subscription %s by %v", user.ID, subscription.ID, cancelAt) slog.Info("user chose to cancel subscription", "userID", user.ID, "subscriptionID", subscription.ID, "cancelAt", cancelAt)
} }
case "canceled", "unpaid", "incomplete_expired": case "canceled", "unpaid", "incomplete_expired":
user.SubscribedUntil = nil user.SubscribedUntil = nil
user.SubscriptionRenewal = nil user.SubscriptionRenewal = nil
slog.Info("user %s's subscription %s got canceled, because of status update to '%s'", user.ID, subscription.ID, subscription.Status) slog.Info("user's subscription got canceled due to status update", "userID", user.ID, "subscriptionID", subscription.ID, "status", subscription.Status)
default: default:
slog.Info("got subscription (%s) status update to '%s' for user '%s'", subscription.ID, subscription.Status, user.ID) slog.Info("got subscription status update", "subscriptionID", subscription.ID, "status", subscription.Status, "userID", user.ID)
return nil return nil
} }
@@ -399,6 +399,6 @@ func (h *SubscriptionHandler) findCurrentStripeSubscription(customerId string) (
func (h *SubscriptionHandler) clearSubscriptionNotificationStatus(userId string) { func (h *SubscriptionHandler) clearSubscriptionNotificationStatus(userId string) {
key := fmt.Sprintf("%s_%s", conf.KeySubscriptionNotificationSent, userId) key := fmt.Sprintf("%s_%s", conf.KeySubscriptionNotificationSent, userId)
if err := h.keyValueSrvc.DeleteString(key); err != nil { if err := h.keyValueSrvc.DeleteString(key); err != nil {
slog.Warn("failed to delete '%s', %v", key, err) slog.Warn("failed to delete", "key", key, "error", err)
} }
} }

2
services/aggregation.go
View File

@@ -140,7 +140,7 @@ func (srv *AggregationService) process(job AggregationJob) {
if summary, err := srv.summaryService.Summarize(job.From, job.To, job.User, nil); err != nil { if summary, err := srv.summaryService.Summarize(job.From, job.To, job.User, nil); err != nil {
config.Log().Error("failed to generate summary (%v, %v, %s) - %v", job.From, job.To, job.User.ID, err) config.Log().Error("failed to generate summary (%v, %v, %s) - %v", job.From, job.To, job.User.ID, err)
} else { } else {
slog.Info("successfully generated summary (%v, %v, %s)", job.From, job.To, job.User.ID) slog.Info("successfully generated summary", "from", job.From, "to", job.To, "userID", job.User.ID)
if err := srv.summaryService.Insert(summary); err != nil { if err := srv.summaryService.Insert(summary); err != nil {
config.Log().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)
} }

14
services/housekeeping.go
View File

@@ -37,9 +37,9 @@ func (s *HousekeepingService) Schedule() {
} }
func (s *HousekeepingService) CleanUserDataBefore(user *models.User, before time.Time) error { func (s *HousekeepingService) CleanUserDataBefore(user *models.User, before time.Time) error {
slog.Warn("cleaning up user data for '%s' older than %v", user.ID, before) slog.Warn("cleaning up user data older than", "userID", user.ID, "date", before)
if s.config.App.DataCleanupDryRun { if s.config.App.DataCleanupDryRun {
slog.Info("skipping actual data deletion for '%v', because this is just a dry run", user.ID) slog.Info("skipping actual data deletion for dry run", "userID", user.ID)
return nil return nil
} }
@@ -49,7 +49,7 @@ func (s *HousekeepingService) CleanUserDataBefore(user *models.User, before time
} }
// clear old summaries // clear old summaries
slog.Info("clearing summaries for user '%s' older than %v", user.ID, before) slog.Info("clearing summaries for user older than", "userID", user.ID, "date", before)
if err := s.summarySrvc.DeleteByUserBefore(user.ID, before); err != nil { if err := s.summarySrvc.DeleteByUserBefore(user.ID, before); err != nil {
return err return err
} }
@@ -58,7 +58,7 @@ func (s *HousekeepingService) CleanUserDataBefore(user *models.User, before time
} }
func (s *HousekeepingService) CleanInactiveUsers(before time.Time) error { func (s *HousekeepingService) CleanInactiveUsers(before time.Time) error {
slog.Info("cleaning up users inactive since %v", before) slog.Info("cleaning up users inactive since", "date", before)
users, err := s.userSrvc.GetAll() users, err := s.userSrvc.GetAll()
if err != nil { if err != nil {
return err return err
@@ -70,20 +70,20 @@ func (s *HousekeepingService) CleanInactiveUsers(before time.Time) error {
continue continue
} }
slog.Warn("deleting user '%s', because inactive and not having data", u.ID) slog.Warn("deleting user due to inactivity and no data", "userID", u.ID)
if err := s.userSrvc.Delete(u); err != nil { if err := s.userSrvc.Delete(u); err != nil {
config.Log().Error("failed to delete user '%s'", u.ID) config.Log().Error("failed to delete user '%s'", u.ID)
} else { } else {
i++ i++
} }
} }
slog.Info("deleted %d (of %d total) users due to inactivity", i, len(users)) slog.Info("deleted users due to inactivity", "deletedCount", i, "totalCount", len(users))
return nil return nil
} }
func (s *HousekeepingService) WarmUserProjectStatsCache(user *models.User) error { func (s *HousekeepingService) WarmUserProjectStatsCache(user *models.User) error {
slog.Info("pre-warming project stats cache for '%s'", user.ID) slog.Info("pre-warming project stats cache for user", "userID", user.ID)
if _, err := s.heartbeatSrvc.GetUserProjectStats(user, time.Time{}, utils.BeginOfToday(time.Local), nil, true); err != nil { if _, err := s.heartbeatSrvc.GetUserProjectStats(user, time.Time{}, utils.BeginOfToday(time.Local), nil, true); err != nil {
config.Log().Error("failed to pre-warm project stats cache for '%s', %v", user.ID, err) config.Log().Error("failed to pre-warm project stats cache for '%s', %v", user.ID, err)
} }

2
services/imports/wakatime_heartbeats.go
View File

@@ -117,7 +117,7 @@ func (w *WakatimeHeartbeatsImporter) Import(user *models.User, minFrom time.Time
} }
if minDataAge := user.MinDataAge(); minFrom.Before(minDataAge) { if minDataAge := user.MinDataAge(); minFrom.Before(minDataAge) {
slog.Info("wakatime data import for user capped", "userID", user.ID, "capped to", fmt.Sprintf("[%v, %v]", minDataAge, maxTo)) slog.Info("wakatime data import for user capped", "userID", user.ID, "cappedTo", fmt.Sprintf("[%v, %v]", minDataAge, maxTo))
} }
slog.Info("scheduling wakatime import for user", "userID", user.ID, "interval", fmt.Sprintf("[%v, %v]", minFrom, maxTo)) slog.Info("scheduling wakatime import for user", "userID", user.ID, "interval", fmt.Sprintf("[%v, %v]", minFrom, maxTo))

6
services/leaderboard.go
View File

@@ -61,10 +61,10 @@ func NewLeaderboardService(leaderboardRepo repositories.ILeaderboardRepository,
} }
if user.PublicLeaderboard && !exists { if user.PublicLeaderboard && !exists {
slog.Info("generating leaderboard for '%s' after settings update", user.ID) slog.Info("generating leaderboard after settings update", "userID", user.ID)
srv.ComputeLeaderboard([]*models.User{user}, srv.defaultScope, []uint8{models.SummaryLanguage}) srv.ComputeLeaderboard([]*models.User{user}, srv.defaultScope, []uint8{models.SummaryLanguage})
} else if !user.PublicLeaderboard && exists { } else if !user.PublicLeaderboard && exists {
slog.Info("clearing leaderboard for '%s' after settings update", user.ID) slog.Info("clearing leaderboard after settings update", "userID", user.ID)
if err := srv.repository.DeleteByUser(user.ID); err != nil { if err := srv.repository.DeleteByUser(user.ID); err != nil {
config.Log().Error("failed to clear leaderboard for user '%s' - %v", user.ID, err) config.Log().Error("failed to clear leaderboard for user '%s' - %v", user.ID, err)
} }
@@ -100,7 +100,7 @@ func (srv *LeaderboardService) Schedule() {
} }
func (srv *LeaderboardService) ComputeLeaderboard(users []*models.User, interval *models.IntervalKey, by []uint8) error { func (srv *LeaderboardService) ComputeLeaderboard(users []*models.User, interval *models.IntervalKey, by []uint8) error {
slog.Info("generating leaderboard (%s) for %d users (%d aggregations)", (*interval)[0], len(users), len(by)) slog.Info("generating leaderboard", "interval", (*interval)[0], "userCount", len(users), "aggregationCount", len(by))
for _, user := range users { for _, user := range users {
if err := srv.repository.DeleteByUserAndInterval(user.ID, interval); err != nil { if err := srv.repository.DeleteByUserAndInterval(user.ID, interval); err != nil {

2
services/mail/noop.go
View File

@@ -8,6 +8,6 @@ import (
type NoopSendingService struct{} type NoopSendingService struct{}
func (n *NoopSendingService) Send(mail *models.Mail) error { func (n *NoopSendingService) Send(mail *models.Mail) error {
slog.Info("noop mail service doing nothing instead of sending password reset mail to [%v]", mail.To.Strings()) slog.Info("noop mail service doing nothing instead of sending password reset mail", "to", mail.To.Strings())
return nil return nil
} }

2
services/misc.go
View File

@@ -250,7 +250,7 @@ func (srv *MiscService) countUserTotalTime(userId string) time.Duration {
func (srv *MiscService) sendSubscriptionNotificationScheduled(user *models.User, hasExpired bool) { func (srv *MiscService) sendSubscriptionNotificationScheduled(user *models.User, hasExpired bool) {
u := *user u := *user
srv.queueMails.Dispatch(func() { srv.queueMails.Dispatch(func() {
slog.Info("sending subscription expiry notification mail to %s (expired: %v)", u.ID, hasExpired) slog.Info("sending subscription expiry notification mail", "userID", u.ID, "expired", hasExpired)
defer time.Sleep(10 * time.Second) defer time.Sleep(10 * time.Second)
if err := srv.mailService.SendSubscriptionNotification(&u, hasExpired); err != nil { if err := srv.mailService.SendSubscriptionNotification(&u, hasExpired); err != nil {

10
services/report.go
View File

@@ -58,7 +58,7 @@ func (srv *ReportService) Schedule() {
// make the job take at least reportDelay seconds // make the job take at least reportDelay seconds
if diff := reportDelay - time.Now().Sub(t0); diff > 0 { if diff := reportDelay - time.Now().Sub(t0); diff > 0 {
slog.Debug("waiting for %v before sending next report", diff) slog.Debug("waiting before sending next report", "duration", diff)
time.Sleep(diff) time.Sleep(diff)
} }
}); err != nil { }); err != nil {
@@ -80,7 +80,7 @@ func (srv *ReportService) Schedule() {
}) })
// schedule jobs, throttled by one job per x seconds // schedule jobs, throttled by one job per x seconds
slog.Info("scheduling report generation for %d users", len(users)) slog.Info("scheduling report generation", "userCount", len(users))
for _, u := range users { for _, u := range users {
scheduleUserReport(u) scheduleUserReport(u)
} }
@@ -93,11 +93,11 @@ func (srv *ReportService) Schedule() {
func (srv *ReportService) SendReport(user *models.User, duration time.Duration) error { func (srv *ReportService) SendReport(user *models.User, duration time.Duration) error {
if user.Email == "" { if user.Email == "" {
slog.Warn("not generating report for '%s' as no e-mail address is set") slog.Warn("not generating report as no e-mail address is set", "userID", user.ID)
return nil return nil
} }
slog.Info("generating report for '%s'", user.ID) slog.Info("generating report for user", "userID", user.ID)
end := time.Now().In(user.TZ()) end := time.Now().In(user.TZ())
start := time.Now().Add(-1 * duration) start := time.Now().Add(-1 * duration)
@@ -137,6 +137,6 @@ func (srv *ReportService) SendReport(user *models.User, duration time.Duration)
return err return err
} }
slog.Info("sent report to user '%s'", user.ID) slog.Info("sent report to user", "userID", user.ID)
return nil return nil
} }

4
services/summary.go
View File

@@ -335,13 +335,13 @@ func (srv *SummaryService) mergeSummaries(summaries []*models.Summary) (*models.
for i, s := range summaries { for i, s := range summaries {
hash := s.FromTime.T() hash := s.FromTime.T()
if _, found := processed[hash]; found { if _, found := processed[hash]; found {
slog.Warn("summary from %v to %v (user '%s') was attempted to be processed more often than once", s.FromTime, s.ToTime, s.UserID) slog.Warn("summary was attempted to be processed more often than once", "fromTime", s.FromTime, "toTime", s.ToTime, "userID", s.UserID)
continue continue
} }
if i > 0 { if i > 0 {
if prev := summaries[i-1]; s.FromTime.T().Before(prev.ToTime.T()) { if prev := summaries[i-1]; s.FromTime.T().Before(prev.ToTime.T()) {
slog.Warn("got overlapping summaries (ids %d, %d) for user '%s' from %v (current.from) to %v (previous.to)", prev.ID, s.ID, s.UserID, s.FromTime, prev.ToTime) slog.Warn("got overlapping summaries for user", "prevID", prev.ID, "currentID", s.ID, "userID", s.UserID, "fromTime", s.FromTime, "prevToTime", prev.ToTime)
} }
} }

4
services/user.go
View File

@@ -39,7 +39,7 @@ func NewUserService(mailService IMailService, userRepo repositories.IUserReposit
user := m.Fields[config.FieldUser].(*models.User) user := m.Fields[config.FieldUser].(*models.User)
n := m.Fields[config.FieldPayload].(int) n := m.Fields[config.FieldPayload].(int)
slog.Warn("resetting wakatime api key for user %s, because of too many failures (%d)", user.ID, n) slog.Warn("resetting wakatime api key for user due to too many failures", "userID", user.ID, "failureCount", n)
if _, err := srv.SetWakatimeApiCredentials(user, "", ""); err != nil { if _, err := srv.SetWakatimeApiCredentials(user, "", ""); err != nil {
config.Log().Error("failed to set wakatime api key for user %s", user.ID) config.Log().Error("failed to set wakatime api key for user %s", user.ID)
@@ -49,7 +49,7 @@ func NewUserService(mailService IMailService, userRepo repositories.IUserReposit
if err := mailService.SendWakatimeFailureNotification(user, n); err != nil { if err := mailService.SendWakatimeFailureNotification(user, n); err != nil {
config.Log().Error("failed to send wakatime failure notification mail to user %s", user.ID) config.Log().Error("failed to send wakatime failure notification mail to user %s", user.ID)
} else { } else {
slog.Info("sent wakatime connection failure mail to %s", user.ID) slog.Info("sent wakatime connection failure mail", "userID", user.ID)
} }
} }
} }