Skip to content

Commit

Permalink
Implement structured logging using log/slog package
Browse files Browse the repository at this point in the history
  • Loading branch information
fguillot committed Sep 24, 2023
1 parent 54cb8fa commit af5cfe5
Show file tree
Hide file tree
Showing 16 changed files with 405 additions and 128 deletions.
57 changes: 46 additions & 11 deletions internal/api/middleware.go
Original file line number Diff line number Diff line change
Expand Up @@ -5,11 +5,11 @@ package api // import "miniflux.app/v2/internal/api"

import (
"context"
"log/slog"
"net/http"

"miniflux.app/v2/internal/http/request"
"miniflux.app/v2/internal/http/response/json"
"miniflux.app/v2/internal/logger"
"miniflux.app/v2/internal/storage"
)

Expand Down Expand Up @@ -40,25 +40,37 @@ func (m *middleware) apiKeyAuth(next http.Handler) http.Handler {
token := r.Header.Get("X-Auth-Token")

if token == "" {
logger.Debug("[API][TokenAuth] [ClientIP=%s] No API Key provided, go to the next middleware", clientIP)
slog.Debug("[API] Skipped API token authentication because no API Key has been provided",
slog.String("client_ip", clientIP),
slog.String("user_agent", r.UserAgent()),
)
next.ServeHTTP(w, r)
return
}

user, err := m.store.UserByAPIKey(token)
if err != nil {
logger.Error("[API][TokenAuth] %v", err)
json.ServerError(w, r, err)
return
}

if user == nil {
logger.Error("[API][TokenAuth] [ClientIP=%s] No user found with the given API key", clientIP)
slog.Warn("[API] No user found with the provided API key",
slog.Bool("authentication_failed", true),
slog.String("client_ip", clientIP),
slog.String("user_agent", r.UserAgent()),
)
json.Unauthorized(w, r)
return
}

logger.Info("[API][TokenAuth] [ClientIP=%s] User authenticated: %s", clientIP, user.Username)
slog.Info("[API] User authenticated successfully with the API Token Authentication",
slog.Bool("authentication_successful", true),
slog.String("client_ip", clientIP),
slog.String("user_agent", r.UserAgent()),
slog.String("username", user.Username),
)

m.store.SetLastLogin(user.ID)
m.store.SetAPIKeyUsedTimestamp(user.ID, token)

Expand All @@ -84,37 +96,60 @@ func (m *middleware) basicAuth(next http.Handler) http.Handler {
clientIP := request.ClientIP(r)
username, password, authOK := r.BasicAuth()
if !authOK {
logger.Debug("[API][BasicAuth] [ClientIP=%s] No authentication headers sent", clientIP)
slog.Warn("[API] No Basic HTTP Authentication header sent with the request",
slog.Bool("authentication_failed", true),
slog.String("client_ip", clientIP),
slog.String("user_agent", r.UserAgent()),
)
json.Unauthorized(w, r)
return
}

if username == "" || password == "" {
logger.Error("[API][BasicAuth] [ClientIP=%s] Empty username or password", clientIP)
slog.Warn("[API] Empty username or password provided during Basic HTTP Authentication",
slog.Bool("authentication_failed", true),
slog.String("client_ip", clientIP),
slog.String("user_agent", r.UserAgent()),
)
json.Unauthorized(w, r)
return
}

if err := m.store.CheckPassword(username, password); err != nil {
logger.Error("[API][BasicAuth] [ClientIP=%s] Invalid username or password: %s", clientIP, username)
slog.Warn("[API] Invalid username or password provided during Basic HTTP Authentication",
slog.Bool("authentication_failed", true),
slog.String("client_ip", clientIP),
slog.String("user_agent", r.UserAgent()),
slog.String("username", username),
)
json.Unauthorized(w, r)
return
}

user, err := m.store.UserByUsername(username)
if err != nil {
logger.Error("[API][BasicAuth] %v", err)
json.ServerError(w, r, err)
return
}

if user == nil {
logger.Error("[API][BasicAuth] [ClientIP=%s] User not found: %s", clientIP, username)
slog.Warn("[API] User not found while using Basic HTTP Authentication",
slog.Bool("authentication_failed", true),
slog.String("client_ip", clientIP),
slog.String("user_agent", r.UserAgent()),
slog.String("username", username),
)
json.Unauthorized(w, r)
return
}

logger.Info("[API][BasicAuth] [ClientIP=%s] User authenticated: %s", clientIP, username)
slog.Info("[API] User authenticated successfully with the Basic HTTP Authentication",
slog.Bool("authentication_successful", true),
slog.String("client_ip", clientIP),
slog.String("user_agent", r.UserAgent()),
slog.String("username", username),
)

m.store.SetLastLogin(user.ID)

ctx := r.Context()
Expand Down
19 changes: 13 additions & 6 deletions internal/cli/cleanup_tasks.go
Original file line number Diff line number Diff line change
Expand Up @@ -4,10 +4,10 @@
package cli // import "miniflux.app/v2/internal/cli"

import (
"log/slog"
"time"

"miniflux.app/v2/internal/config"
"miniflux.app/v2/internal/logger"
"miniflux.app/v2/internal/metric"
"miniflux.app/v2/internal/model"
"miniflux.app/v2/internal/storage"
Expand All @@ -16,13 +16,18 @@ import (
func runCleanupTasks(store *storage.Storage) {
nbSessions := store.CleanOldSessions(config.Opts.CleanupRemoveSessionsDays())
nbUserSessions := store.CleanOldUserSessions(config.Opts.CleanupRemoveSessionsDays())
logger.Info("[Sessions] Removed %d application sessions and %d user sessions", nbSessions, nbUserSessions)
slog.Info("Sessions cleanup completed",
slog.Int64("application_sessions_removed", nbSessions),
slog.Int64("user_sessions_removed", nbUserSessions),
)

startTime := time.Now()
if rowsAffected, err := store.ArchiveEntries(model.EntryStatusRead, config.Opts.CleanupArchiveReadDays(), config.Opts.CleanupArchiveBatchSize()); err != nil {
logger.Error("[ArchiveReadEntries] %v", err)
slog.Error("Unable to archive read entries", slog.Any("error", err))
} else {
logger.Info("[ArchiveReadEntries] %d entries changed", rowsAffected)
slog.Info("Archiving read entries completed",
slog.Int64("read_entries_archived", rowsAffected),
)

if config.Opts.HasMetricsCollector() {
metric.ArchiveEntriesDuration.WithLabelValues(model.EntryStatusRead).Observe(time.Since(startTime).Seconds())
Expand All @@ -31,9 +36,11 @@ func runCleanupTasks(store *storage.Storage) {

startTime = time.Now()
if rowsAffected, err := store.ArchiveEntries(model.EntryStatusUnread, config.Opts.CleanupArchiveUnreadDays(), config.Opts.CleanupArchiveBatchSize()); err != nil {
logger.Error("[ArchiveUnreadEntries] %v", err)
slog.Error("Unable to archive unread entries", slog.Any("error", err))
} else {
logger.Info("[ArchiveUnreadEntries] %d entries changed", rowsAffected)
slog.Info("Archiving unread entries completed",
slog.Int64("unread_entries_archived", rowsAffected),
)

if config.Opts.HasMetricsCollector() {
metric.ArchiveEntriesDuration.WithLabelValues(model.EntryStatusUnread).Observe(time.Since(startTime).Seconds())
Expand Down
44 changes: 25 additions & 19 deletions internal/cli/cli.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,11 +6,12 @@ package cli // import "miniflux.app/v2/internal/cli"
import (
"flag"
"fmt"
"log/slog"
"os"

"miniflux.app/v2/internal/config"
"miniflux.app/v2/internal/database"
"miniflux.app/v2/internal/locale"
"miniflux.app/v2/internal/logger"
"miniflux.app/v2/internal/storage"
"miniflux.app/v2/internal/ui/static"
"miniflux.app/v2/internal/version"
Expand Down Expand Up @@ -74,26 +75,26 @@ func Parse() {
if flagConfigFile != "" {
config.Opts, err = cfg.ParseFile(flagConfigFile)
if err != nil {
logger.Fatal("%v", err)
printErrorAndExit(err)
}
}

config.Opts, err = cfg.ParseEnvironmentVariables()
if err != nil {
logger.Fatal("%v", err)
printErrorAndExit(err)
}

if flagConfigDump {
fmt.Print(config.Opts)
return
}

if config.Opts.LogDateTime() {
logger.EnableDateTime()
if flagDebugMode {
config.Opts.SetLogLevel("debug")
}

if flagDebugMode || config.Opts.HasDebugMode() {
logger.EnableDebug()
if err := InitializeDefaultLogger(config.Opts.LogLevel(), os.Stderr, config.Opts.LogFormat(), config.Opts.LogDateTime()); err != nil {
printErrorAndExit(err)
}

if flagHealthCheck != "" {
Expand All @@ -112,25 +113,25 @@ func Parse() {
}

if config.Opts.IsDefaultDatabaseURL() {
logger.Info("The default value for DATABASE_URL is used")
slog.Info("The default value for DATABASE_URL is used")
}

logger.Debug("Loading translations...")
slog.Debug("Loading translations...")
if err := locale.LoadCatalogMessages(); err != nil {
logger.Fatal("Unable to load translations: %v", err)
printErrorAndExit(err)
}

logger.Debug("Loading static assets...")
slog.Debug("Loading static assets...")
if err := static.CalculateBinaryFileChecksums(); err != nil {
logger.Fatal("Unable to calculate binary files checksum: %v", err)
printErrorAndExit(err)
}

if err := static.GenerateStylesheetsBundles(); err != nil {
logger.Fatal("Unable to generate Stylesheet bundles: %v", err)
printErrorAndExit(err)
}

if err := static.GenerateJavascriptBundles(); err != nil {
logger.Fatal("Unable to generate Javascript bundles: %v", err)
printErrorAndExit(err)
}

db, err := database.NewConnectionPool(
Expand All @@ -140,19 +141,19 @@ func Parse() {
config.Opts.DatabaseConnectionLifetime(),
)
if err != nil {
logger.Fatal("Unable to initialize database connection pool: %v", err)
printErrorAndExit(err)
}
defer db.Close()

store := storage.NewStorage(db)

if err := store.Ping(); err != nil {
logger.Fatal("Unable to connect to the database: %v", err)
printErrorAndExit(err)
}

if flagMigrate {
if err := database.Migrate(db); err != nil {
logger.Fatal(`%v`, err)
printErrorAndExit(err)
}
return
}
Expand Down Expand Up @@ -180,12 +181,12 @@ func Parse() {
// Run migrations and start the daemon.
if config.Opts.RunMigrations() {
if err := database.Migrate(db); err != nil {
logger.Fatal(`%v`, err)
printErrorAndExit(err)
}
}

if err := database.IsSchemaUpToDate(db); err != nil {
logger.Fatal(`You must run the SQL migrations, %v`, err)
printErrorAndExit(err)
}

// Create admin user and start the daemon.
Expand All @@ -205,3 +206,8 @@ func Parse() {

startDaemon(store)
}

func printErrorAndExit(err error) {
fmt.Fprintf(os.Stderr, "%v\n", err)
os.Exit(1)
}
6 changes: 4 additions & 2 deletions internal/cli/create_admin.go
Original file line number Diff line number Diff line change
Expand Up @@ -5,10 +5,10 @@ package cli // import "miniflux.app/v2/internal/cli"

import (
"fmt"
"log/slog"
"os"

"miniflux.app/v2/internal/config"
"miniflux.app/v2/internal/logger"
"miniflux.app/v2/internal/model"
"miniflux.app/v2/internal/storage"
"miniflux.app/v2/internal/validator"
Expand All @@ -26,7 +26,9 @@ func createAdmin(store *storage.Storage) {
}

if store.UserExists(userCreationRequest.Username) {
logger.Info(`User %q already exists, skipping creation`, userCreationRequest.Username)
slog.Info("Skipping admin user creation because it already exists",
slog.String("username", userCreationRequest.Username),
)
return
}

Expand Down
22 changes: 11 additions & 11 deletions internal/cli/daemon.go
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@ package cli // import "miniflux.app/v2/internal/cli"

import (
"context"
"log/slog"
"net/http"
"os"
"os/signal"
Expand All @@ -13,15 +14,14 @@ import (

"miniflux.app/v2/internal/config"
httpd "miniflux.app/v2/internal/http/server"
"miniflux.app/v2/internal/logger"
"miniflux.app/v2/internal/metric"
"miniflux.app/v2/internal/storage"
"miniflux.app/v2/internal/systemd"
"miniflux.app/v2/internal/worker"
)

func startDaemon(store *storage.Storage) {
logger.Info("Starting daemon...")
slog.Info("Starting daemon...")

stop := make(chan os.Signal, 1)
signal.Notify(stop, os.Interrupt)
Expand All @@ -44,26 +44,26 @@ func startDaemon(store *storage.Storage) {
}

if systemd.HasNotifySocket() {
logger.Info("Sending readiness notification to Systemd")
slog.Info("Sending readiness notification to Systemd")

if err := systemd.SdNotify(systemd.SdNotifyReady); err != nil {
logger.Error("Unable to send readiness notification to systemd: %v", err)
slog.Error("Unable to send readiness notification to systemd", slog.Any("error", err))
}

if config.Opts.HasWatchdog() && systemd.HasSystemdWatchdog() {
logger.Info("Activating Systemd watchdog")
slog.Info("Activating Systemd watchdog")

go func() {
interval, err := systemd.WatchdogInterval()
if err != nil {
logger.Error("Unable to parse watchdog interval from systemd: %v", err)
slog.Error("Unable to get watchdog interval from systemd", slog.Any("error", err))
return
}

for {

Check failure on line 63 in internal/cli/daemon.go

View workflow job for this annotation

GitHub Actions / Golang Linter

unnecessary leading newline (whitespace)
err := store.Ping()
if err != nil {
logger.Error(`Systemd Watchdog: %v`, err)

if err := store.Ping(); err != nil {
slog.Error("Unable to ping database", slog.Any("error", err))
} else {
systemd.SdNotify(systemd.SdNotifyWatchdog)
}
Expand All @@ -75,13 +75,13 @@ func startDaemon(store *storage.Storage) {
}

<-stop
logger.Info("Shutting down the process...")
slog.Info("Shutting down the process")
ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
defer cancel()

if httpServer != nil {
httpServer.Shutdown(ctx)
}

logger.Info("Process gracefully stopped")
slog.Info("Process gracefully stopped")
}
Loading

0 comments on commit af5cfe5

Please sign in to comment.