Correct the logs to use the format key:value

muety · Aug 20, 2024 · b5bb3da · b5bb3da
1 parent 118e511
commit b5bb3da
Show file tree

Hide file tree

Showing 30 changed files with 5,340 additions and 1,339 deletions.
diff --git a/config/jobqueue.go b/config/jobqueue.go
@@ -42,7 +42,7 @@ func InitQueue(name string, workers int) error {
 	if _, ok := jobQueues[name]; ok {
 		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].Start()
 	return nil

diff --git a/coverage/coverage.out b/coverage/coverage.out
diff --git a/main.go b/main.go
@@ -143,7 +143,7 @@ func main() {
 	slog.Info("starting with database", "dialect", config.Db.Dialect)
 	db, err = gorm.Open(config.Db.GetDialector(), &gorm.Config{Logger: gormLogger}, conf.GetWakapiDBOpts(&config.Db))
 	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")
 	}
 
@@ -152,7 +152,7 @@ func main() {
 	}
 	sqlDb, err := db.DB()
 	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")
 	}
 	sqlDb.SetMaxIdleConns(int(config.Db.MaxConn))
@@ -452,4 +452,5 @@ func initLogger() {
 	}
 	l := slog.New(handler)
 	slog.SetDefault(l)
+	slog.Info("logger initialized", "env", config.Env)
 }
diff --git a/middlewares/custom/wakatime.go b/middlewares/custom/wakatime.go
@@ -62,7 +62,7 @@ func (m *WakatimeRelayMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Reque
 
 	err := m.filterByCache(r)
 	if err != nil {
-		slog.Warn("%v", err)
+		slog.Warn("filter cache error", "error", err)
 		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) {
 	request, err := http.NewRequest(method, url, body)
 	if err != nil {
-		slog.Warn("error constructing relayed request - %v", err)
+		slog.Warn("error constructing relayed request", "error", err)
 		return
 	}
 
@@ -116,12 +116,12 @@ func (m *WakatimeRelayMiddleware) send(method, url string, body io.Reader, heade
 
 	response, err := m.httpClient.Do(request)
 	if err != nil {
-		slog.Warn("error executing relayed request - %v", err)
+		slog.Warn("error executing relayed request", "error", err)
 		return
 	}
 
 	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?
 		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},
 			})
 		} 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) {
 		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{}

diff --git a/migrations/20201103_rename_language_mappings_table.go b/migrations/20201103_rename_language_mappings_table.go
@@ -16,12 +16,12 @@ func init() {
 			oldIndexName, newIndexName := "idx_customrule_user", "idx_language_mapping_user"
 
 			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 {
 					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 nil

diff --git a/migrations/20201106_migration_cascade_constraints.go b/migrations/20201106_migration_cascade_constraints.go
@@ -51,7 +51,7 @@ func init() {
 
 			for name, table := range constraints {
 				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 {
 						return err
 					}

diff --git a/migrations/20210202_fix_cascade_for_alias_user_constraint.go b/migrations/20210202_fix_cascade_for_alias_user_constraint.go
@@ -31,7 +31,7 @@ func init() {
 			}
 
 			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 {
 					return err
 				}

diff --git a/migrations/20210206_drop_badges_column_add_sharing_flags.go b/migrations/20210206_drop_badges_column_add_sharing_flags.go
@@ -38,14 +38,14 @@ func init() {
 			}
 
 			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
 			}
 
 			if err := migrator.DropColumn(&models.User{}, "badges_enabled"); err != nil {
 				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
 		},

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

diff --git a/migrations/20211215_migrate_id_to_bigint.go b/migrations/20211215_migrate_id_to_bigint.go
@@ -40,7 +40,7 @@ func init() {
 			} else {
 				// sqlite doesn't allow for changing column type easily
 				// 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)

diff --git a/migrations/20220317_align_num_heartbeats.go b/migrations/20220317_align_num_heartbeats.go
@@ -45,7 +45,7 @@ func init() {
 				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)
 			return nil

diff --git a/migrations/202203191_drop_diagnostics_user.go b/migrations/202203191_drop_diagnostics_user.go
@@ -19,14 +19,14 @@ func init() {
 			migrator := db.Migrator()
 
 			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 {
-					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 {
-					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)
 				}
 			}
 

diff --git a/migrations/20220403_drop_user_project_idx.go b/migrations/20220403_drop_user_project_idx.go
@@ -25,9 +25,9 @@ func init() {
 			}
 
 			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 {
-					slog.Warn("failed to drop %s", idxName)
+					slog.Warn("failed to drop index", "indexName", idxName)
 				}
 			}
 

diff --git a/migrations/20221016_drop_rank_column.go b/migrations/20221016_drop_rank_column.go
@@ -19,10 +19,10 @@ func init() {
 			migrator := db.Migrator()
 
 			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 {
-					slog.Warn("failed to drop 'rank' column (%v)", err)
+					slog.Warn("failed to drop column", "column", "rank", "error", err)
 				}
 			}
 

diff --git a/migrations/20230219_add_astro_language.go b/migrations/20230219_add_astro_language.go
@@ -15,7 +15,7 @@ func init() {
 				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 {
 				return err

diff --git a/migrations/20230219_add_subscription_renewal.go b/migrations/20230219_add_subscription_renewal.go
@@ -19,7 +19,7 @@ func init() {
 			migrator := db.Migrator()
 
 			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 {
 					return err

diff --git a/migrations/migrations.go b/migrations/migrations.go
@@ -87,7 +87,7 @@ func RunPreMigrations(db *gorm.DB, cfg *config.Config) {
 	sort.Sort(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 {
 			log.Fatalf("migration '%s' failed - %v", m.name, err)
 		}
@@ -98,7 +98,7 @@ func RunPostMigrations(db *gorm.DB, cfg *config.Config) {
 	sort.Sort(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 {
 			log.Fatalf("migration '%s' failed - %v", m.name, err)
 		}

diff --git a/routes/api/metrics.go b/routes/api/metrics.go
@@ -349,7 +349,7 @@ func (h *MetricsHandler) getUserMetrics(user *models.User) (*mm.Metrics, error)
 	// Database metrics
 	dbSize, err := h.metricsRepo.GetDatabaseSize()
 	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{
@@ -383,7 +383,7 @@ func (h *MetricsHandler) getAdminMetrics(user *models.User) (*mm.Metrics, error)
 	var metrics mm.Metrics
 
 	t0 := time.Now()
-	slog.Debug("[metrics] start admin metrics calculation")
+	slog.Debug("start admin metrics calculation")
 
 	if !user.IsAdmin {
 		return nil, errors.New("unauthorized")
@@ -398,14 +398,14 @@ func (h *MetricsHandler) getAdminMetrics(user *models.User) (*mm.Metrics, error)
 
 	totalUsers, _ := h.userSrvc.Count()
 	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)
 	if err != nil {
 		conf.Log().Error("failed to retrieve active users for metric - %v", 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{
 		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}},
 		})
 	}
-	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
 
@@ -480,7 +480,7 @@ func (h *MetricsHandler) getAdminMetrics(user *models.User) (*mm.Metrics, error)
 	}
 
 	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
 }
diff --git a/routes/login.go b/routes/login.go
@@ -341,7 +341,7 @@ func (h *LoginHandler) PostResetPassword(w http.ResponseWriter, r *http.Request)
 				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)
 				} else {
-					slog.Info("sent password reset mail to %s", user.ID)
+					slog.Info("sent password reset mail", "userID", user.ID)
 				}
 			}(u)
 		}

diff --git a/routes/settings.go b/routes/settings.go
@@ -118,7 +118,7 @@ func (h *SettingsHandler) PostIndex(w http.ResponseWriter, r *http.Request) {
 
 	actionFunc := h.dispatchAction(action)
 	if actionFunc == nil {
-		slog.Warn("failed to dispatch action '%s'", action)
+		slog.Warn("failed to dispatch action", "action", action)
 		w.WriteHeader(http.StatusBadRequest)
 		templates[conf.SettingsTemplate].Execute(w, h.buildViewModel(r, w, nil).WithError("unknown action requests"))
 		return
@@ -637,7 +637,7 @@ func (h *SettingsHandler) actionImportWakatime(w http.ResponseWriter, r *http.Re
 
 		insert := func(batch []*models.Heartbeat) {
 			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)
-		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)
 
@@ -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 {
 				conf.Log().Request(r).Error("failed to send import notification mail to %s - %v", user.ID, err)
 			} else {
-				slog.Info("sent import notification mail to %s", user.ID)
+				slog.Info("sent import notification mail", "userID", user.ID)
 			}
 		}
 	}(user)
@@ -711,15 +711,15 @@ func (h *SettingsHandler) actionClearData(w http.ResponseWriter, r *http.Request
 	}
 
 	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) {
-		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 {
 			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 {
 			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)
 	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)
 		if err := h.userSrvc.Delete(user); err != nil {
 			conf.Log().Request(r).Error("failed to delete user '%s' - %v", user.ID, err)
 		} else {
-			slog.Info("successfully deleted user '%s'", user.ID)
+			slog.Info("successfully deleted user", "userID", user.ID)
 		}
 	}(user)
 
@@ -806,7 +806,7 @@ func (h *SettingsHandler) validateWakatimeKey(apiKey string, baseUrl string) boo
 }
 
 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 {
 		conf.Log().Error("failed to clear summaries: %v", err)
 		return err