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
fguillot committed Sep 25, 2023
1 parent 54cb8fa commit b5347e1
Show file tree
Hide file tree
Showing 77 changed files with 1,874 additions and 892 deletions.
57 changes: 46 additions & 11 deletions internal/api/middleware.go
View file
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
3 changes: 1 addition & 2 deletions internal/cli/ask_credentials.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,8 +16,7 @@ func askCredentials() (string, string) {
fd := int(os.Stdin.Fd())

if !term.IsTerminal(fd) {
fmt.Fprintf(os.Stderr, "This is not a terminal, exiting.\n")
os.Exit(1)
printErrorAndExit(fmt.Errorf("this is not a terminal, exiting"))
}

fmt.Print("Enter Username: ")
Expand Down
19 changes: 13 additions & 6 deletions internal/cli/cleanup_tasks.go
View file
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
58 changes: 39 additions & 19 deletions internal/cli/cli.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,11 +6,13 @@ package cli // import "miniflux.app/v2/internal/cli"
import (
"flag"
"fmt"
"io"
"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 +76,41 @@ 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()
logFile := config.Opts.LogFile()
var logFileHandler io.Writer
switch logFile {
case "stdout":
logFileHandler = os.Stdout
case "stderr":
logFileHandler = os.Stderr
default:
logFileHandler, err = os.OpenFile(logFile, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0600)
if err != nil {
printErrorAndExit(fmt.Errorf("unable to open log file: %v", err))
}
defer logFileHandler.(*os.File).Close()
}

if err := InitializeDefaultLogger(config.Opts.LogLevel(), logFileHandler, config.Opts.LogFormat(), config.Opts.LogDateTime()); err != nil {
printErrorAndExit(err)
}

if flagHealthCheck != "" {
Expand All @@ -112,25 +129,23 @@ 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...")
if err := locale.LoadCatalogMessages(); err != nil {
logger.Fatal("Unable to load translations: %v", err)
printErrorAndExit(fmt.Errorf("unable to load translations: %v", err))
}

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

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

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

db, err := database.NewConnectionPool(
Expand All @@ -140,19 +155,19 @@ func Parse() {
config.Opts.DatabaseConnectionLifetime(),
)
if err != nil {
logger.Fatal("Unable to initialize database connection pool: %v", err)
printErrorAndExit(fmt.Errorf("unable to connect to database: %v", 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 +195,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 +220,8 @@ func Parse() {

startDaemon(store)
}

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

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

"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,17 +24,17 @@ 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
}

if validationErr := validator.ValidateUserCreationWithPassword(store, userCreationRequest); validationErr != nil {
fmt.Fprintf(os.Stderr, "%s\n", validationErr)
os.Exit(1)
printErrorAndExit(validationErr.Error())
}

if _, err := store.CreateUser(userCreationRequest); err != nil {
fmt.Fprintf(os.Stderr, "%v\n", err)
os.Exit(1)
printErrorAndExit(err)
}
}
Loading

0 comments on commit b5347e1

Please sign in to comment.