diff options
77 files changed, 1869 insertions, 893 deletions
diff --git a/internal/api/middleware.go b/internal/api/middleware.go index 73c96f5e..eeadc3a0 100644 --- a/internal/api/middleware.go +++ b/internal/api/middleware.go @@ -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" ) @@ -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) @@ -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() diff --git a/internal/cli/ask_credentials.go b/internal/cli/ask_credentials.go index b8329274..1c1e2c12 100644 --- a/internal/cli/ask_credentials.go +++ b/internal/cli/ask_credentials.go @@ -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: ") diff --git a/internal/cli/cleanup_tasks.go b/internal/cli/cleanup_tasks.go index f7e791e7..adeb280b 100644 --- a/internal/cli/cleanup_tasks.go +++ b/internal/cli/cleanup_tasks.go @@ -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" @@ -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()) @@ -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()) diff --git a/internal/cli/cli.go b/internal/cli/cli.go index 61fe226f..f74ea5aa 100644 --- a/internal/cli/cli.go +++ b/internal/cli/cli.go @@ -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" @@ -74,13 +76,13 @@ 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 { @@ -88,12 +90,27 @@ func Parse() { 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 != "" { @@ -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( @@ -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 } @@ -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. @@ -205,3 +220,8 @@ func Parse() { startDaemon(store) } + +func printErrorAndExit(err error) { + fmt.Fprintf(os.Stderr, "%v\n", err) + os.Exit(1) +} diff --git a/internal/cli/create_admin.go b/internal/cli/create_admin.go index dd79bb80..d45073f3 100644 --- a/internal/cli/create_admin.go +++ b/internal/cli/create_admin.go @@ -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" @@ -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) } } diff --git a/internal/cli/daemon.go b/internal/cli/daemon.go index 378c4219..3f58f560 100644 --- a/internal/cli/daemon.go +++ b/internal/cli/daemon.go @@ -5,6 +5,7 @@ package cli // import "miniflux.app/v2/internal/cli" import ( "context" + "log/slog" "net/http" "os" "os/signal" @@ -13,7 +14,6 @@ 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" @@ -21,7 +21,7 @@ import ( ) func startDaemon(store *storage.Storage) { - logger.Info("Starting daemon...") + slog.Debug("Starting daemon...") stop := make(chan os.Signal, 1) signal.Notify(stop, os.Interrupt) @@ -44,26 +44,25 @@ func startDaemon(store *storage.Storage) { } if systemd.HasNotifySocket() { - logger.Info("Sending readiness notification to Systemd") + slog.Debug("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.Debug("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 { - 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) } @@ -75,7 +74,7 @@ func startDaemon(store *storage.Storage) { } <-stop - logger.Info("Shutting down the process...") + slog.Debug("Shutting down the process") ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() @@ -83,5 +82,5 @@ func startDaemon(store *storage.Storage) { httpServer.Shutdown(ctx) } - logger.Info("Process gracefully stopped") + slog.Debug("Process gracefully stopped") } diff --git a/internal/cli/flush_sessions.go b/internal/cli/flush_sessions.go index bbf5c21c..7358c2db 100644 --- a/internal/cli/flush_sessions.go +++ b/internal/cli/flush_sessions.go @@ -5,7 +5,6 @@ package cli // import "miniflux.app/v2/internal/cli" import ( "fmt" - "os" "miniflux.app/v2/internal/storage" ) @@ -13,7 +12,6 @@ import ( func flushSessions(store *storage.Storage) { fmt.Println("Flushing all sessions (disconnect users)") if err := store.FlushAllSessions(); err != nil { - fmt.Fprintf(os.Stderr, "%v\n", err) - os.Exit(1) + printErrorAndExit(err) } } diff --git a/internal/cli/health_check.go b/internal/cli/health_check.go index 14b2c569..bea886e1 100644 --- a/internal/cli/health_check.go +++ b/internal/cli/health_check.go @@ -4,11 +4,12 @@ package cli // import "miniflux.app/v2/internal/cli" import ( + "fmt" + "log/slog" "net/http" "time" "miniflux.app/v2/internal/config" - "miniflux.app/v2/internal/logger" ) func doHealthCheck(healthCheckEndpoint string) { @@ -16,18 +17,18 @@ func doHealthCheck(healthCheckEndpoint string) { healthCheckEndpoint = "http://" + config.Opts.ListenAddr() + config.Opts.BasePath() + "/healthcheck" } - logger.Debug(`Executing health check on %s`, healthCheckEndpoint) + slog.Debug("Executing health check request", slog.String("endpoint", healthCheckEndpoint)) client := &http.Client{Timeout: 3 * time.Second} resp, err := client.Get(healthCheckEndpoint) if err != nil { - logger.Fatal(`Health check failure: %v`, err) + printErrorAndExit(fmt.Errorf(`health check failure: %v`, err)) } defer resp.Body.Close() if resp.StatusCode != 200 { - logger.Fatal(`Health check failed with status code %d`, resp.StatusCode) + printErrorAndExit(fmt.Errorf(`health check failed with status code %d`, resp.StatusCode)) } - logger.Debug(`Health check is OK`) + slog.Debug(`Health check is passing`) } diff --git a/internal/cli/logger.go b/internal/cli/logger.go new file mode 100644 index 00000000..4c4f08d3 --- /dev/null +++ b/internal/cli/logger.go @@ -0,0 +1,46 @@ +// SPDX-FileCopyrightText: Copyright The Miniflux Authors. All rights reserved. +// SPDX-License-Identifier: Apache-2.0 + +package cli // import "miniflux.app/v2/internal/cli" + +import ( + "io" + "log/slog" +) + +func InitializeDefaultLogger(logLevel string, logFile io.Writer, logFormat string, logTime bool) error { + var programLogLevel = new(slog.LevelVar) + switch logLevel { + case "debug": + programLogLevel.Set(slog.LevelDebug) + case "info": + programLogLevel.Set(slog.LevelInfo) + case "warning": + programLogLevel.Set(slog.LevelWarn) + case "error": + programLogLevel.Set(slog.LevelError) + } + + logHandlerOptions := &slog.HandlerOptions{Level: programLogLevel} + if !logTime { + logHandlerOptions.ReplaceAttr = func(groups []string, a slog.Attr) slog.Attr { + if a.Key == slog.TimeKey { + return slog.Attr{} + } + + return a + } + } + + var logger *slog.Logger + switch logFormat { + case "json": + logger = slog.New(slog.NewJSONHandler(logFile, logHandlerOptions)) + default: + logger = slog.New(slog.NewTextHandler(logFile, logHandlerOptions)) + } + + slog.SetDefault(logger) + + return nil +} diff --git a/internal/cli/refresh_feeds.go b/internal/cli/refresh_feeds.go index 0e90a6cf..d5b1edd3 100644 --- a/internal/cli/refresh_feeds.go +++ b/internal/cli/refresh_feeds.go @@ -4,11 +4,11 @@ package cli // import "miniflux.app/v2/internal/cli" import ( + "log/slog" "sync" "time" "miniflux.app/v2/internal/config" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" feedHandler "miniflux.app/v2/internal/reader/handler" "miniflux.app/v2/internal/storage" @@ -20,22 +20,39 @@ func refreshFeeds(store *storage.Storage) { startTime := time.Now() jobs, err := store.NewBatch(config.Opts.BatchSize()) if err != nil { - logger.Error("[Cronjob] %v", err) + slog.Error("Unable to fetch jobs from database", slog.Any("error", err)) } nbJobs := len(jobs) - logger.Info("[Cronjob]] Created %d jobs from a batch size of %d", nbJobs, config.Opts.BatchSize()) + + slog.Info("Created a batch of feeds", + slog.Int("nb_jobs", nbJobs), + slog.Int("batch_size", config.Opts.BatchSize()), + ) + var jobQueue = make(chan model.Job, nbJobs) - logger.Info("[Cronjob] Starting a pool of %d workers", config.Opts.WorkerPoolSize()) + slog.Info("Starting a pool of workers", + slog.Int("nb_workers", config.Opts.WorkerPoolSize()), + ) + for i := 0; i < config.Opts.WorkerPoolSize(); i++ { wg.Add(1) go func(workerID int) { defer wg.Done() for job := range jobQueue { - logger.Info("[Cronjob] Refreshing feed #%d for user #%d in worker #%d", job.FeedID, job.UserID, workerID) + slog.Info("Refreshing feed", + slog.Int64("feed_id", job.FeedID), + slog.Int64("user_id", job.UserID), + slog.Int("worker_id", workerID), + ) + if err := feedHandler.RefreshFeed(store, job.UserID, job.FeedID, false); err != nil { - logger.Error("[Cronjob] Refreshing the feed #%d returned this error: %v", job.FeedID, err) + slog.Error("Unable to refresh feed", + slog.Int64("feed_id", job.FeedID), + slog.Int64("user_id", job.UserID), + slog.Any("error", err), + ) } } }(i) @@ -47,5 +64,9 @@ func refreshFeeds(store *storage.Storage) { close(jobQueue) wg.Wait() - logger.Info("[Cronjob] Refreshed %d feed(s) in %s", nbJobs, time.Since(startTime)) + + slog.Info("Refreshed a batch of feeds", + slog.Int("nb_feeds", nbJobs), + slog.String("duration", time.Since(startTime).String()), + ) } diff --git a/internal/cli/reset_password.go b/internal/cli/reset_password.go index a4241ebb..6ea5b744 100644 --- a/internal/cli/reset_password.go +++ b/internal/cli/reset_password.go @@ -5,7 +5,6 @@ package cli // import "miniflux.app/v2/internal/cli" import ( "fmt" - "os" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/storage" @@ -16,27 +15,23 @@ func resetPassword(store *storage.Storage) { username, password := askCredentials() user, err := store.UserByUsername(username) if err != nil { - fmt.Fprintf(os.Stderr, "%v\n", err) - os.Exit(1) + printErrorAndExit(err) } if user == nil { - fmt.Fprintf(os.Stderr, "User not found!\n") - os.Exit(1) + printErrorAndExit(fmt.Errorf("user not found")) } userModificationRequest := &model.UserModificationRequest{ Password: &password, } if validationErr := validator.ValidateUserModification(store, user.ID, userModificationRequest); validationErr != nil { - fmt.Fprintf(os.Stderr, "%s\n", validationErr) - os.Exit(1) + printErrorAndExit(validationErr.Error()) } user.Password = password if err := store.UpdateUser(user); err != nil { - fmt.Fprintf(os.Stderr, "%v\n", err) - os.Exit(1) + printErrorAndExit(err) } fmt.Println("Password changed!") diff --git a/internal/cli/scheduler.go b/internal/cli/scheduler.go index ae9dbb11..6bde37c0 100644 --- a/internal/cli/scheduler.go +++ b/internal/cli/scheduler.go @@ -4,16 +4,16 @@ 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/storage" "miniflux.app/v2/internal/worker" ) func runScheduler(store *storage.Storage, pool *worker.Pool) { - logger.Info(`Starting background scheduler...`) + slog.Debug(`Starting background scheduler...`) go feedScheduler( store, @@ -31,10 +31,12 @@ func runScheduler(store *storage.Storage, pool *worker.Pool) { func feedScheduler(store *storage.Storage, pool *worker.Pool, frequency, batchSize int) { for range time.Tick(time.Duration(frequency) * time.Minute) { jobs, err := store.NewBatch(batchSize) - logger.Info("[Scheduler:Feed] Pushing %d jobs to the queue", len(jobs)) if err != nil { - logger.Error("[Scheduler:Feed] %v", err) + slog.Error("Unable to fetch jobs from database", slog.Any("error", err)) } else { + slog.Info("Created a batch of feeds", + slog.Int("nb_jobs", len(jobs)), + ) pool.Push(jobs) } } diff --git a/internal/config/config_test.go b/internal/config/config_test.go index 18bfe4ce..7734a4fc 100644 --- a/internal/config/config_test.go +++ b/internal/config/config_test.go @@ -8,6 +8,181 @@ import ( "testing" ) +func TestLogFileDefaultValue(t *testing.T) { + os.Clearenv() + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + + if opts.LogFile() != defaultLogFile { + t.Fatalf(`Unexpected log file value, got %q`, opts.LogFile()) + } +} + +func TestLogFileWithCustomFilename(t *testing.T) { + os.Clearenv() + os.Setenv("LOG_FILE", "foobar.log") + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + if opts.LogFile() != "foobar.log" { + t.Fatalf(`Unexpected log file value, got %q`, opts.LogFile()) + } +} + +func TestLogFileWithEmptyValue(t *testing.T) { + os.Clearenv() + os.Setenv("LOG_FILE", "") + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + + if opts.LogFile() != defaultLogFile { + t.Fatalf(`Unexpected log file value, got %q`, opts.LogFile()) + } +} + +func TestLogLevelDefaultValue(t *testing.T) { + os.Clearenv() + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + + if opts.LogLevel() != defaultLogLevel { + t.Fatalf(`Unexpected log level value, got %q`, opts.LogLevel()) + } +} + +func TestLogLevelWithCustomValue(t *testing.T) { + os.Clearenv() + os.Setenv("LOG_LEVEL", "warning") + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + + if opts.LogLevel() != "warning" { + t.Fatalf(`Unexpected log level value, got %q`, opts.LogLevel()) + } +} + +func TestLogLevelWithInvalidValue(t *testing.T) { + os.Clearenv() + os.Setenv("LOG_LEVEL", "invalid") + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + + if opts.LogLevel() != defaultLogLevel { + t.Fatalf(`Unexpected log level value, got %q`, opts.LogLevel()) + } +} + +func TestLogDateTimeDefaultValue(t *testing.T) { + os.Clearenv() + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + + if opts.LogDateTime() != defaultLogDateTime { + t.Fatalf(`Unexpected log date time value, got %v`, opts.LogDateTime()) + } +} + +func TestLogDateTimeWithCustomValue(t *testing.T) { + os.Clearenv() + os.Setenv("LOG_DATETIME", "false") + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + + if opts.LogDateTime() != false { + t.Fatalf(`Unexpected log date time value, got %v`, opts.LogDateTime()) + } +} + +func TestLogDateTimeWithInvalidValue(t *testing.T) { + os.Clearenv() + os.Setenv("LOG_DATETIME", "invalid") + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + + if opts.LogDateTime() != defaultLogDateTime { + t.Fatalf(`Unexpected log date time value, got %v`, opts.LogDateTime()) + } +} + +func TestLogFormatDefaultValue(t *testing.T) { + os.Clearenv() + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + + if opts.LogFormat() != defaultLogFormat { + t.Fatalf(`Unexpected log format value, got %q`, opts.LogFormat()) + } +} + +func TestLogFormatWithCustomValue(t *testing.T) { + os.Clearenv() + os.Setenv("LOG_FORMAT", "json") + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + + if opts.LogFormat() != "json" { + t.Fatalf(`Unexpected log format value, got %q`, opts.LogFormat()) + } +} + +func TestLogFormatWithInvalidValue(t *testing.T) { + os.Clearenv() + os.Setenv("LOG_FORMAT", "invalid") + + parser := NewParser() + opts, err := parser.ParseEnvironmentVariables() + if err != nil { + t.Fatalf(`Parsing failure: %v`, err) + } + + if opts.LogFormat() != defaultLogFormat { + t.Fatalf(`Unexpected log format value, got %q`, opts.LogFormat()) + } +} + func TestDebugModeOn(t *testing.T) { os.Clearenv() os.Setenv("DEBUG", "1") @@ -18,8 +193,8 @@ func TestDebugModeOn(t *testing.T) { t.Fatalf(`Parsing failure: %v`, err) } - if !opts.HasDebugMode() { - t.Fatalf(`Unexpected debug mode value, got "%v"`, opts.HasDebugMode()) + if opts.LogLevel() != "debug" { + t.Fatalf(`Unexpected debug mode value, got %q`, opts.LogLevel()) } } @@ -32,8 +207,8 @@ func TestDebugModeOff(t *testing.T) { t.Fatalf(`Parsing failure: %v`, err) } - if opts.HasDebugMode() { - t.Fatalf(`Unexpected debug mode value, got "%v"`, opts.HasDebugMode()) + if opts.LogLevel() != "info" { + t.Fatalf(`Unexpected debug mode value, got %q`, opts.LogLevel()) } } @@ -1544,8 +1719,8 @@ Invalid text t.Errorf(`Parsing failure: %v`, err) } - if opts.HasDebugMode() != true { - t.Errorf(`Unexpected debug mode value, got "%v"`, opts.HasDebugMode()) + if opts.LogLevel() != "debug" { + t.Errorf(`Unexpected debug mode value, got %q`, opts.LogLevel()) } expected := ">#1234" diff --git a/internal/config/options.go b/internal/config/options.go index 16d16cbd..11a4ac2c 100644 --- a/internal/config/options.go +++ b/internal/config/options.go @@ -15,7 +15,10 @@ import ( const ( defaultHTTPS = false + defaultLogFile = "stderr" defaultLogDateTime = false + defaultLogFormat = "text" + defaultLogLevel = "info" defaultHSTS = true defaultHTTPService = true defaultSchedulerService = true @@ -91,11 +94,13 @@ type Option struct { // Options contains configuration options. type Options struct { HTTPS bool + logFile string logDateTime bool + logFormat string + logLevel string hsts bool httpService bool schedulerService bool - debug bool serverTimingHeader bool baseURL string rootURL string @@ -165,11 +170,13 @@ func NewOptions() *Options { return &Options{ HTTPS: defaultHTTPS, + logFile: defaultLogFile, logDateTime: defaultLogDateTime, + logFormat: defaultLogFormat, + logLevel: defaultLogLevel, hsts: defaultHSTS, httpService: defaultHTTPService, schedulerService: defaultSchedulerService, - debug: defaultDebug, serverTimingHeader: defaultTiming, baseURL: defaultBaseURL, rootURL: defaultRootURL, @@ -231,11 +238,30 @@ func NewOptions() *Options { } } +func (o *Options) LogFile() string { + return o.logFile +} + // LogDateTime returns true if the date/time should be displayed in log messages. func (o *Options) LogDateTime() bool { return o.logDateTime } +// LogFormat returns the log format. +func (o *Options) LogFormat() string { + return o.logFormat +} + +// LogLevel returns the log level. +func (o *Options) LogLevel() string { + return o.logLevel +} + +// SetLogLevel sets the log level. +func (o *Options) SetLogLevel(level string) { + o.logLevel = level +} + // HasMaintenanceMode returns true if maintenance mode is enabled. func (o *Options) HasMaintenanceMode() bool { return o.maintenanceMode @@ -246,11 +272,6 @@ func (o *Options) MaintenanceMessage() string { return o.maintenanceMessage } -// HasDebugMode returns true if debug mode is enabled. -func (o *Options) HasDebugMode() bool { - return o.debug -} - // HasServerTimingHeader returns true if server-timing headers enabled. func (o *Options) HasServerTimingHeader() bool { return o.serverTimingHeader @@ -593,7 +614,6 @@ func (o *Options) SortedOptions(redactSecret bool) []*Option { "DATABASE_MAX_CONNS": o.databaseMaxConns, "DATABASE_MIN_CONNS": o.databaseMinConns, "DATABASE_URL": redactSecretValue(o.databaseURL, redactSecret), - "DEBUG": o.debug, "DISABLE_HSTS": !o.hsts, "DISABLE_HTTP_SERVICE": !o.httpService, "DISABLE_SCHEDULER_SERVICE": !o.schedulerService, @@ -609,7 +629,10 @@ func (o *Options) SortedOptions(redactSecret bool) []*Option { "INVIDIOUS_INSTANCE": o.invidiousInstance, "KEY_FILE": o.certKeyFile, "LISTEN_ADDR": o.listenAddr, + "LOG_FILE": o.logFile, "LOG_DATE_TIME": o.logDateTime, + "LOG_FORMAT": o.logFormat, + "LOG_LEVEL": o.logLevel, "MAINTENANCE_MESSAGE": o.maintenanceMessage, "MAINTENANCE_MODE": o.maintenanceMode, "METRICS_ALLOWED_NETWORKS": strings.Join(o.metricsAllowedNetworks, ","), diff --git a/internal/config/parser.go b/internal/config/parser.go index d0d19af3..f354e5b5 100644 --- a/internal/config/parser.go +++ b/internal/config/parser.go @@ -10,7 +10,7 @@ import ( "errors" "fmt" "io" - url_parser "net/url" + "net/url" "os" "strconv" "strings" @@ -72,10 +72,25 @@ func (p *Parser) parseLines(lines []string) (err error) { value := strings.TrimSpace(fields[1]) switch key { + case "LOG_FILE": + p.opts.logFile = parseString(value, defaultLogFile) case "LOG_DATE_TIME": p.opts.logDateTime = parseBool(value, defaultLogDateTime) + case "LOG_LEVEL": + parsedValue := parseString(value, defaultLogLevel) + if parsedValue == "debug" || parsedValue == "info" || parsedValue == "warning" || parsedValue == "error" { + p.opts.logLevel = parsedValue + } + case "LOG_FORMAT": + parsedValue := parseString(value, defaultLogFormat) + if parsedValue == "json" || parsedValue == "text" { + p.opts.logFormat = parsedValue + } case "DEBUG": - p.opts.debug = parseBool(value, defaultDebug) + parsedValue := parseBool(value, defaultDebug) + if parsedValue { + p.opts.logLevel = "debug" + } case "SERVER_TIMING_HEADER": p.opts.serverTimingHeader = parseBool(value, defaultTiming) case "BASE_URL": @@ -247,19 +262,19 @@ func parseBaseURL(value string) (string, string, string, error) { value = value[:len(value)-1] } - url, err := url_parser.Parse(value) + parsedURL, err := url.Parse(value) if err != nil { return "", "", "", fmt.Errorf("config: invalid BASE_URL: %w", err) } - scheme := strings.ToLower(url.Scheme) + scheme := strings.ToLower(parsedURL.Scheme) if scheme != "https" && scheme != "http" { return "", "", "", errors.New("config: invalid BASE_URL: scheme must be http or https") } - basePath := url.Path - url.Path = "" - return value, url.String(), basePath, nil + basePath := parsedURL.Path + parsedURL.Path = "" + return value, parsedURL.String(), basePath, nil } func parseBool(value string, fallback bool) bool { diff --git a/internal/database/database.go b/internal/database/database.go index 59eddc4c..e5a2f3a5 100644 --- a/internal/database/database.go +++ b/internal/database/database.go @@ -6,6 +6,7 @@ package database // import "miniflux.app/v2/internal/database" import ( "database/sql" "fmt" + "log/slog" "time" // Postgresql driver import @@ -31,12 +32,13 @@ func Migrate(db *sql.DB) error { var currentVersion int db.QueryRow(`SELECT version FROM schema_version`).Scan(¤tVersion) - fmt.Println("-> Current schema version:", currentVersion) - fmt.Println("-> Latest schema version:", schemaVersion) + slog.Debug("Running database migrations", + slog.Int("current_version", currentVersion), + slog.Int("latest_version", schemaVersion), + ) for version := currentVersion; version < schemaVersion; version++ { newVersion := version + 1 - fmt.Println("* Migrating to version:", newVersion) tx, err := db.Begin() if err != nil { diff --git a/internal/fever/handler.go b/internal/fever/handler.go index 5060beac..90a0d5f2 100644 --- a/internal/fever/handler.go +++ b/internal/fever/handler.go @@ -4,6 +4,7 @@ package fever // import "miniflux.app/v2/internal/fever" import ( + "log/slog" "net/http" "strconv" "strings" @@ -12,7 +13,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/json" "miniflux.app/v2/internal/integration" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/proxy" "miniflux.app/v2/internal/storage" @@ -80,7 +80,9 @@ is_spark equal to 1. */ func (h *handler) handleGroups(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) - logger.Debug("[Fever] Fetching groups for user #%d", userID) + slog.Debug("[Fever] Fetching groups", + slog.Int64("user_id", userID), + ) categories, err := h.store.Categories(userID) if err != nil { @@ -130,7 +132,9 @@ For the “Sparks” super group the items should be limited to feeds with an is */ func (h *handler) handleFeeds(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) - logger.Debug("[Fever] Fetching feeds for userID=%d", userID) + slog.Debug("[Fever] Fetching feeds", + slog.Int64("user_id", userID), + ) feeds, err := h.store.Feeds(userID) if err != nil { @@ -183,7 +187,9 @@ A PHP/HTML example: */ func (h *handler) handleFavicons(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) - logger.Debug("[Fever] Fetching favicons for user #%d", userID) + slog.Debug("[Fever] Fetching favicons", + slog.Int64("user_id", userID), + ) icons, err := h.store.Icons(userID) if err != nil { @@ -247,16 +253,24 @@ func (h *handler) handleItems(w http.ResponseWriter, r *http.Request) { case request.HasQueryParam(r, "since_id"): sinceID := request.QueryInt64Param(r, "since_id", 0) if sinceID > 0 { - logger.Debug("[Fever] Fetching items since #%d for user #%d", sinceID, userID) + slog.Debug("[Fever] Fetching items since a given date", + slog.Int64("user_id", userID), + slog.Int64("since_id", sinceID), + ) builder.AfterEntryID(sinceID) } case request.HasQueryParam(r, "max_id"): maxID := request.QueryInt64Param(r, "max_id", 0) if maxID == 0 { - logger.Debug("[Fever] Fetching most recent items for user #%d", userID) + slog.Debug("[Fever] Fetching most recent items", + slog.Int64("user_id", userID), + ) builder.WithSorting("id", "DESC") } else if maxID > 0 { - logger.Debug("[Fever] Fetching items before #%d for user #%d", maxID, userID) + slog.Debug("[Fever] Fetching items before a given item ID", + slog.Int64("user_id", userID), + slog.Int64("max_id", maxID), + ) builder.BeforeEntryID(maxID) builder.WithSorting("id", "DESC") } @@ -274,7 +288,9 @@ func (h *handler) handleItems(w http.ResponseWriter, r *http.Request) { builder.WithEntryIDs(itemIDs) } default: - logger.Debug("[Fever] Fetching oldest items for user #%d", userID) + slog.Debug("[Fever] Fetching oldest items", + slog.Int64("user_id", userID), + ) } entries, err := builder.GetEntries() @@ -330,7 +346,9 @@ A request with the unread_item_ids argument will return one additional member: */ func (h *handler) handleUnreadItems(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) - logger.Debug("[Fever] Fetching unread items for user #%d", userID) + slog.Debug("[Fever] Fetching unread items", + slog.Int64("user_id", userID), + ) builder := h.store.NewEntryQueryBuilder(userID) builder.WithStatus(model.EntryStatusUnread) @@ -361,7 +379,9 @@ with the remote Fever installation. */ func (h *handler) handleSavedItems(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) - logger.Debug("[Fever] Fetching saved items for user #%d", userID) + slog.Debug("[Fever] Fetching saved items", + slog.Int64("user_id", userID), + ) builder := h.store.NewEntryQueryBuilder(userID) builder.WithStarred(true) @@ -389,7 +409,9 @@ id=? where ? is replaced with the id of the item to modify */ func (h *handler) handleWriteItems(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) - logger.Debug("[Fever] Receiving mark=item call for user #%d", userID) + slog.Debug("[Fever] Receiving mark=item call", + slog.Int64("user_id", userID), + ) entryID := request.FormInt64Value(r, "id") if entryID <= 0 { @@ -407,20 +429,32 @@ func (h *handler) handleWriteItems(w http.ResponseWriter, r *http.Request) { } if entry == nil { - logger.Debug("[Fever] Marking entry #%d but not found, ignored", entryID) + slog.Debug("[Fever] Entry not found", + slog.Int64("user_id", userID), + slog.Int64("entry_id", entryID), + ) json.OK(w, r, newBaseResponse()) return } switch r.FormValue("as") { case "read": - logger.Debug("[Fever] Mark entry #%d as read for user #%d", entryID, userID) + slog.Debug("[Fever] Mark entry as read", + slog.Int64("user_id", userID), + slog.Int64("entry_id", entryID), + ) h.store.SetEntriesStatus(userID, []int64{entryID}, model.EntryStatusRead) case "unread": - logger.Debug("[Fever] Mark entry #%d as unread for user #%d", entryID, userID) + slog.Debug("[Fever] Mark entry as unread", + slog.Int64("user_id", userID), + slog.Int64("entry_id", entryID), + ) h.store.SetEntriesStatus(userID, []int64{entryID}, model.EntryStatusUnread) case "saved": - logger.Debug("[Fever] Mark entry #%d as saved for user #%d", entryID, userID) + slog.Debug("[Fever] Mark entry as saved", + slog.Int64("user_id", userID), + slog.Int64("entry_id", entryID), + ) if err := h.store.ToggleBookmark(userID, entryID); err != nil { json.ServerError(w, r, err) return @@ -436,7 +470,10 @@ func (h *handler) handleWriteItems(w http.ResponseWriter, r *http.Request) { integration.SendEntry(entry, settings) }() case "unsaved": - logger.Debug("[Fever] Mark entry #%d as unsaved for user #%d", entryID, userID) + slog.Debug("[Fever] Mark entry as unsaved", + slog.Int64("user_id", userID), + slog.Int64("entry_id", entryID), + ) if err := h.store.ToggleBookmark(userID, entryID); err != nil { json.ServerError(w, r, err) return @@ -457,7 +494,11 @@ func (h *handler) handleWriteFeeds(w http.ResponseWriter, r *http.Request) { feedID := request.FormInt64Value(r, "id") before := time.Unix(request.FormInt64Value(r, "before"), 0) - logger.Debug("[Fever] Mark feed #%d as read for user #%d before %v", feedID, userID, before) + slog.Debug("[Fever] Mark feed as read before a given date", + slog.Int64("user_id", userID), + slog.Int64("feed_id", feedID), + slog.Time("before_ts", before), + ) if feedID <= 0 { return @@ -465,7 +506,12 @@ func (h *handler) handleWriteFeeds(w http.ResponseWriter, r *http.Request) { go func() { if err := h.store.MarkFeedAsRead(userID, feedID, before); err != nil { - logger.Error("[Fever] MarkFeedAsRead failed: %v", err) + slog.Error("[Fever] Unable to mark feed as read", + slog.Int64("user_id", userID), + slog.Int64("feed_id", feedID), + slog.Time("before_ts", before), + slog.Any("error", err), + ) } }() @@ -483,7 +529,11 @@ func (h *handler) handleWriteGroups(w http.ResponseWriter, r *http.Request) { groupID := request.FormInt64Value(r, "id") before := time.Unix(request.FormInt64Value(r, "before"), 0) - logger.Debug("[Fever] Mark group #%d as read for user #%d before %v", groupID, userID, before) + slog.Debug("[Fever] Mark group as read before a given date", + slog.Int64("user_id", userID), + slog.Int64("group_id", groupID), + slog.Time("before_ts", before), + ) if groupID < 0 { return @@ -499,7 +549,12 @@ func (h *handler) handleWriteGroups(w http.ResponseWriter, r *http.Request) { } if err != nil { - logger.Error("[Fever] MarkCategoryAsRead failed: %v", err) + slog.Error("[Fever] Unable to mark group as read", + slog.Int64("user_id", userID), + slog.Int64("group_id", groupID), + slog.Time("before_ts", before), + slog.Any("error", err), + ) } }() diff --git a/internal/fever/middleware.go b/internal/fever/middleware.go index 96d06f3e..dfa6c0a1 100644 --- a/internal/fever/middleware.go +++ b/internal/fever/middleware.go @@ -5,11 +5,11 @@ package fever // import "miniflux.app/v2/internal/fever" 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" ) @@ -26,25 +26,45 @@ func (m *middleware) serve(next http.Handler) http.Handler { clientIP := request.ClientIP(r) apiKey := r.FormValue("api_key") if apiKey == "" { - logger.Info("[Fever] [ClientIP=%s] No API key provided", clientIP) + slog.Warn("[Fever] No API key provided", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) json.OK(w, r, newAuthFailureResponse()) return } user, err := m.store.UserByFeverToken(apiKey) if err != nil { - logger.Error("[Fever] %v", err) + slog.Error("[Fever] Unable to fetch user by API key", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Any("error", err), + ) json.OK(w, r, newAuthFailureResponse()) return } if user == nil { - logger.Info("[Fever] [ClientIP=%s] No user found with this API key", clientIP) + slog.Warn("[Fever] No user found with the API key provided", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) json.OK(w, r, newAuthFailureResponse()) return } - logger.Info("[Fever] [ClientIP=%s] User #%d is authenticated with user agent %q", clientIP, user.ID, r.UserAgent()) + slog.Info("[Fever] User authenticated successfully", + slog.Bool("authentication_successful", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", user.ID), + slog.String("username", user.Username), + ) + m.store.SetLastLogin(user.ID) ctx := r.Context() diff --git a/internal/googlereader/handler.go b/internal/googlereader/handler.go index d3c0dfce..3c88d55f 100644 --- a/internal/googlereader/handler.go +++ b/internal/googlereader/handler.go @@ -6,19 +6,18 @@ package googlereader // import "miniflux.app/v2/internal/googlereader" import ( "errors" "fmt" + "log/slog" "net/http" - "net/http/httputil" "strconv" "strings" "time" - "github.com/gorilla/mux" "miniflux.app/v2/internal/config" "miniflux.app/v2/internal/http/request" + "miniflux.app/v2/internal/http/response" "miniflux.app/v2/internal/http/response/json" "miniflux.app/v2/internal/http/route" "miniflux.app/v2/internal/integration" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/proxy" mff "miniflux.app/v2/internal/reader/handler" @@ -26,6 +25,8 @@ import ( "miniflux.app/v2/internal/storage" "miniflux.app/v2/internal/urllib" "miniflux.app/v2/internal/validator" + + "github.com/gorilla/mux" ) type handler struct { @@ -201,24 +202,25 @@ func (r RequestModifiers) String() string { // Serve handles Google Reader API calls. func Serve(router *mux.Router, store *storage.Storage) { handler := &handler{store, router} + router.HandleFunc("/accounts/ClientLogin", handler.clientLoginHandler).Methods(http.MethodPost).Name("ClientLogin") + middleware := newMiddleware(store) - router.HandleFunc("/accounts/ClientLogin", middleware.clientLogin).Methods(http.MethodPost).Name("ClientLogin") sr := router.PathPrefix("/reader/api/0").Subrouter() sr.Use(middleware.handleCORS) sr.Use(middleware.apiKeyAuth) sr.Methods(http.MethodOptions) - sr.HandleFunc("/token", middleware.token).Methods(http.MethodGet).Name("Token") - sr.HandleFunc("/edit-tag", handler.editTag).Methods(http.MethodPost).Name("EditTag") - sr.HandleFunc("/rename-tag", handler.renameTag).Methods(http.MethodPost).Name("Rename Tag") - sr.HandleFunc("/disable-tag", handler.disableTag).Methods(http.MethodPost).Name("Disable Tag") - sr.HandleFunc("/tag/list", handler.tagList).Methods(http.MethodGet).Name("TagList") - sr.HandleFunc("/user-info", handler.userInfo).Methods(http.MethodGet).Name("UserInfo") - sr.HandleFunc("/subscription/list", handler.subscriptionList).Methods(http.MethodGet).Name("SubscriptonList") - sr.HandleFunc("/subscription/edit", handler.editSubscription).Methods(http.MethodPost).Name("SubscriptionEdit") - sr.HandleFunc("/subscription/quickadd", handler.quickAdd).Methods(http.MethodPost).Name("QuickAdd") - sr.HandleFunc("/stream/items/ids", handler.streamItemIDs).Methods(http.MethodGet).Name("StreamItemIDs") - sr.HandleFunc("/stream/items/contents", handler.streamItemContents).Methods(http.MethodPost).Name("StreamItemsContents") - sr.PathPrefix("/").HandlerFunc(handler.serve).Methods(http.MethodPost, http.MethodGet).Name("GoogleReaderApiEndpoint") + sr.HandleFunc("/token", handler.tokenHandler).Methods(http.MethodGet).Name("Token") + sr.HandleFunc("/edit-tag", handler.editTagHandler).Methods(http.MethodPost).Name("EditTag") + sr.HandleFunc("/rename-tag", handler.renameTagHandler).Methods(http.MethodPost).Name("Rename Tag") + sr.HandleFunc("/disable-tag", handler.disableTagHandler).Methods(http.MethodPost).Name("Disable Tag") + sr.HandleFunc("/tag/list", handler.tagListHandler).Methods(http.MethodGet).Name("TagList") + sr.HandleFunc("/user-info", handler.userInfoHandler).Methods(http.MethodGet).Name("UserInfo") + sr.HandleFunc("/subscription/list", handler.subscriptionListHandler).Methods(http.MethodGet).Name("SubscriptonList") + sr.HandleFunc("/subscription/edit", handler.editSubscriptionHandler).Methods(http.MethodPost).Name("SubscriptionEdit") + sr.HandleFunc("/subscription/quickadd", handler.quickAddHandler).Methods(http.MethodPost).Name("QuickAdd") + sr.HandleFunc("/stream/items/ids", handler.streamItemIDsHandler).Methods(http.MethodGet).Name("StreamItemIDs") + sr.HandleFunc("/stream/items/contents", handler.streamItemContentsHandler).Methods(http.MethodPost).Name("StreamItemsContents") + sr.PathPrefix("/").HandlerFunc(handler.serveHandler).Methods(http.MethodPost, http.MethodGet).Name("GoogleReaderApiEndpoint") } func getStreamFilterModifiers(r *http.Request) (RequestModifiers, error) { @@ -276,8 +278,7 @@ func getStream(streamID string, userID int64) (Stream, error) { case Like: return Stream{LikeStream, ""}, nil default: - err := fmt.Errorf("uknown stream with id: %s", id) - return Stream{NoStream, ""}, err + return Stream{NoStream, ""}, fmt.Errorf("googlereader: unknown stream with id: %s", id) } } else if strings.HasPrefix(streamID, fmt.Sprintf(UserLabelPrefix, userID)) || strings.HasPrefix(streamID, LabelPrefix) { id := strings.TrimPrefix(streamID, fmt.Sprintf(UserLabelPrefix, userID)) @@ -286,8 +287,8 @@ func getStream(streamID string, userID int64) (Stream, error) { } else if streamID == "" { return Stream{NoStream, ""}, nil } - err := fmt.Errorf("uknown stream type: %s", streamID) - return Stream{NoStream, ""}, err + + return Stream{NoStream, ""}, fmt.Errorf("googlereader: unknown stream type: %s", streamID) } func getStreams(streamIDs []string, userID int64) ([]Stream, error) { @@ -308,43 +309,43 @@ func checkAndSimplifyTags(addTags []Stream, removeTags []Stream) (map[StreamType switch s.Type { case ReadStream: if _, ok := tags[KeptUnreadStream]; ok { - return nil, fmt.Errorf(KeptUnread + " and " + Read + " should not be supplied simultaneously") + return nil, fmt.Errorf("googlereader: %s ad %s should not be supplied simultaneously", KeptUnread, Read) } tags[ReadStream] = true case KeptUnreadStream: if _, ok := tags[ReadStream]; ok { - return nil, fmt.Errorf(KeptUnread + " and " + Read + " should not be supplied simultaneously") + return nil, fmt.Errorf("googlereader: %s ad %s should not be supplied simultaneously", KeptUnread, Read) } tags[ReadStream] = false case StarredStream: tags[StarredStream] = true case BroadcastStream, LikeStream: - logger.Info("Broadcast & Like tags are not implemented!") + slog.Debug("Broadcast & Like tags are not implemented!") default: - return nil, fmt.Errorf("unsupported tag type: %s", s.Type) + return nil, fmt.Errorf("googlereader: unsupported tag type: %s", s.Type) } } for _, s := range removeTags { switch s.Type { case ReadStream: if _, ok := tags[ReadStream]; ok { - return nil, fmt.Errorf(KeptUnread + " and " + Read + " should not be supplied simultaneously") + return nil, fmt.Errorf("googlereader: %s ad %s should not be supplied simultaneously", KeptUnread, Read) } tags[ReadStream] = false case KeptUnreadStream: if _, ok := tags[ReadStream]; ok { - return nil, fmt.Errorf(KeptUnread + " and " + Read + " should not be supplied simultaneously") + return nil, fmt.Errorf("googlereader: %s ad %s should not be supplied simultaneously", KeptUnread, Read) } tags[ReadStream] = true case StarredStream: if _, ok := tags[StarredStream]; ok { - return nil, fmt.Errorf(Starred + " should not be supplied for add and remove simultaneously") + return nil, fmt.Errorf("googlereader: %s should not be supplied for add and remove simultaneously", Starred) } tags[StarredStream] = false case BroadcastStream, LikeStream: - logger.Info("Broadcast & Like tags are not implemented!") + slog.Debug("Broadcast & Like tags are not implemented!") default: - return nil, fmt.Errorf("unsupported tag type: %s", s.Type) + return nil, fmt.Errorf("googlereader: unsupported tag type: %s", s.Type) } } @@ -354,7 +355,7 @@ func checkAndSimplifyTags(addTags []Stream, removeTags []Stream) (map[StreamType func getItemIDs(r *http.Request) ([]int64, error) { items := r.Form[ParamItemIDs] if len(items) == 0 { - return nil, fmt.Errorf("no items requested") + return nil, fmt.Errorf("googlereader: no items requested") } itemIDs := make([]int64, len(items)) @@ -365,7 +366,7 @@ func getItemIDs(r *http.Request) ([]int64, error) { if err != nil { itemID, err = strconv.ParseInt(item, 16, 64) if err != nil { - return nil, fmt.Errorf("could not parse item: %v", item) + return nil, fmt.Errorf("googlereader: could not parse item: %v", item) } } itemIDs[i] = itemID @@ -385,66 +386,191 @@ func checkOutputFormat(w http.ResponseWriter, r *http.Request) error { output = request.QueryStringParam(r, "output", "") } if output != "json" { - err := fmt.Errorf("output only as json supported") + err := fmt.Errorf("googlereader: only json output is supported") return err } return nil } -func (h *handler) editTag(w http.ResponseWriter, r *http.Request) { - userID := request.UserID(r) +func (h *handler) clientLoginHandler(w http.ResponseWriter, r *http.Request) { clientIP := request.ClientIP(r) - logger.Info("[GoogleReader][/edit-tag][ClientIP=%s] Incoming Request for userID #%d", clientIP, userID) + slog.Debug("[GoogleReader] Handle /accounts/ClientLogin", + slog.String("handler", "clientLoginHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) + + if err := r.ParseForm(); err != nil { + slog.Warn("[GoogleReader] Could not parse request form data", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Any("error", err), + ) + json.Unauthorized(w, r) + return + } - err := r.ParseForm() + username := r.Form.Get("Email") + password := r.Form.Get("Passwd") + output := r.Form.Get("output") + + if username == "" || password == "" { + slog.Warn("[GoogleReader] Empty username or password", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) + json.Unauthorized(w, r) + return + } + + if err := h.store.GoogleReaderUserCheckPassword(username, password); err != nil { + slog.Warn("[GoogleReader] Invalid username or password", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.String("username", username), + slog.Any("error", err), + ) + json.Unauthorized(w, r) + return + } + + slog.Info("[GoogleReader] User authenticated successfully", + slog.Bool("authentication_successful", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.String("username", username), + ) + + integration, err := h.store.GoogleReaderUserGetIntegration(username) if err != nil { - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] %v", clientIP, err) + json.ServerError(w, r, err) + return + } + + h.store.SetLastLogin(integration.UserID) + + token := getAuthToken(integration.GoogleReaderUsername, integration.GoogleReaderPassword) + slog.Debug("[GoogleReader] Created token", + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.String("username", username), + ) + + result := login{SID: token, LSID: token, Auth: token} + if output == "json" { + json.OK(w, r, result) + return + } + + builder := response.New(w, r) + builder.WithHeader("Content-Type", "text/plain; charset=UTF-8") + builder.WithBody(result.String()) + builder.Write() +} + +func (h *handler) tokenHandler(w http.ResponseWriter, r *http.Request) { + clientIP := request.ClientIP(r) + + slog.Debug("[GoogleReader] Handle /token", + slog.String("handler", "tokenHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) + + if !request.IsAuthenticated(r) { + slog.Warn("[GoogleReader] User is not authenticated", + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) + json.Unauthorized(w, r) + return + } + + token := request.GoolgeReaderToken(r) + if token == "" { + slog.Warn("[GoogleReader] User does not have token", + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", request.UserID(r)), + ) + json.Unauthorized(w, r) + return + } + + slog.Debug("[GoogleReader] Token handler", + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", request.UserID(r)), + slog.String("token", token), + ) + + w.Header().Add("Content-Type", "text/plain; charset=UTF-8") + w.WriteHeader(http.StatusOK) + w.Write([]byte(token)) +} + +func (h *handler) editTagHandler(w http.ResponseWriter, r *http.Request) { + userID := request.UserID(r) + clientIP := request.ClientIP(r) + + slog.Debug("[GoogleReader] Handle /edit-tag", + slog.String("handler", "editTagHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", userID), + ) + + if err := r.ParseForm(); err != nil { json.ServerError(w, r, err) return } addTags, err := getStreams(r.PostForm[ParamTagsAdd], userID) if err != nil { - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } removeTags, err := getStreams(r.PostForm[ParamTagsRemove], userID) if err != nil { - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } if len(addTags) == 0 && len(removeTags) == 0 { - err = fmt.Errorf("add or/and remove tags should be supplied") - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] ", clientIP, err) + err = fmt.Errorf("googlreader: add or/and remove tags should be supplied") json.ServerError(w, r, err) return } tags, err := checkAndSimplifyTags(addTags, removeTags) if err != nil { - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } itemIDs, err := getItemIDs(r) if err != nil { - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } - logger.Debug("[GoogleReader][/edit-tag] [ClientIP=%s] itemIDs: %v", clientIP, itemIDs) - logger.Debug("[GoogleReader][/edit-tag] [ClientIP=%s] tags: %v", clientIP, tags) + slog.Debug("[GoogleReader] Edited tags", + slog.String("handler", "editTagHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", userID), + slog.Any("item_ids", itemIDs), + slog.Any("tags", tags), + ) + builder := h.store.NewEntryQueryBuilder(userID) builder.WithEntryIDs(itemIDs) builder.WithoutStatus(model.EntryStatusRemoved) entries, err := builder.GetEntries() if err != nil { - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -477,7 +603,6 @@ func (h *handler) editTag(w http.ResponseWriter, r *http.Request) { if len(readEntryIDs) > 0 { err = h.store.SetEntriesStatus(userID, readEntryIDs, model.EntryStatusRead) if err != nil { - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -486,7 +611,6 @@ func (h *handler) editTag(w http.ResponseWriter, r *http.Request) { if len(unreadEntryIDs) > 0 { err = h.store.SetEntriesStatus(userID, unreadEntryIDs, model.EntryStatusUnread) if err != nil { - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -495,7 +619,6 @@ func (h *handler) editTag(w http.ResponseWriter, r *http.Request) { if len(unstarredEntryIDs) > 0 { err = h.store.SetEntriesBookmarkedState(userID, unstarredEntryIDs, false) if err != nil { - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -504,7 +627,6 @@ func (h *handler) editTag(w http.ResponseWriter, r *http.Request) { if len(starredEntryIDs) > 0 { err = h.store.SetEntriesBookmarkedState(userID, starredEntryIDs, true) if err != nil { - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -513,7 +635,6 @@ func (h *handler) editTag(w http.ResponseWriter, r *http.Request) { if len(entries) > 0 { settings, err := h.store.Integration(userID) if err != nil { - logger.Error("[GoogleReader][/edit-tag] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -529,22 +650,26 @@ func (h *handler) editTag(w http.ResponseWriter, r *http.Request) { OK(w, r) } -func (h *handler) quickAdd(w http.ResponseWriter, r *http.Request) { +func (h *handler) quickAddHandler(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) clientIP := request.ClientIP(r) - logger.Info("[GoogleReader][/subscription/quickadd][ClientIP=%s] Incoming Request for userID #%d", clientIP, userID) + slog.Debug("[GoogleReader] Handle /subscription/quickadd", + slog.String("handler", "quickAddHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", userID), + ) err := r.ParseForm() if err != nil { - logger.Error("[GoogleReader][/subscription/quickadd] [ClientIP=%s] %v", clientIP, err) json.BadRequest(w, r, err) return } url := r.Form.Get(ParamQuickAdd) if !validator.IsValidURL(url) { - json.BadRequest(w, r, fmt.Errorf("invalid URL: %s", url)) + json.BadRequest(w, r, fmt.Errorf("googlereader: invalid URL: %s", url)) return } @@ -568,6 +693,15 @@ func (h *handler) quickAdd(w http.ResponseWriter, r *http.Request) { json.ServerError(w, r, err) return } + + slog.Debug("[GoogleReader] Added a new feed", + slog.String("handler", "quickAddHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", userID), + slog.String("feed_url", newFeed.FeedURL), + ) + json.OK(w, r, quickAddResponse{ NumResults: 1, Query: newFeed.FeedURL, @@ -675,34 +809,37 @@ func move(stream Stream, destination Stream, store *storage.Storage, userID int6 return store.UpdateFeed(feed) } -func (h *handler) editSubscription(w http.ResponseWriter, r *http.Request) { +func (h *handler) editSubscriptionHandler(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) clientIP := request.ClientIP(r) - logger.Info("[GoogleReader][/subscription/edit][ClientIP=%s] Incoming Request for userID #%d", clientIP, userID) + slog.Debug("[GoogleReader] Handle /subscription/edit", + slog.String("handler", "editSubscriptionHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", userID), + ) - err := r.ParseForm() - if err != nil { - logger.Error("[GoogleReader][/subscription/edit] [ClientIP=%s] %v", clientIP, err) + if err := r.ParseForm(); err != nil { json.BadRequest(w, r, err) return } streamIds, err := getStreams(r.Form[ParamStreamID], userID) if err != nil || len(streamIds) == 0 { - json.BadRequest(w, r, errors.New("no valid stream IDs provided")) + json.BadRequest(w, r, errors.New("googlereader: no valid stream IDs provided")) return } newLabel, err := getStream(r.Form.Get(ParamTagsAdd), userID) if err != nil { - json.BadRequest(w, r, fmt.Errorf("invalid data in %s", ParamTagsAdd)) + json.BadRequest(w, r, fmt.Errorf("googlereader: invalid data in %s", ParamTagsAdd)) return } title := r.Form.Get(ParamTitle) - action := r.Form.Get(ParamSubscribeAction) + switch action { case "subscribe": _, err := subscribe(streamIds[0], newLabel, title, h.store, userID) @@ -735,41 +872,42 @@ func (h *handler) editSubscription(w http.ResponseWriter, r *http.Request) { } } default: - json.ServerError(w, r, fmt.Errorf("unrecognized action %s", action)) + json.ServerError(w, r, fmt.Errorf("googlereader: unrecognized action %s", action)) return } OK(w, r) } -func (h *handler) streamItemContents(w http.ResponseWriter, r *http.Request) { +func (h *handler) streamItemContentsHandler(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) clientIP := request.ClientIP(r) - logger.Info("[GoogleReader][/stream/items/contents][ClientIP=%s] Incoming Request for userID #%d", clientIP, userID) + slog.Debug("[GoogleReader] Handle /stream/items/contents", + slog.String("handler", "streamItemContentsHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", userID), + ) if err := checkOutputFormat(w, r); err != nil { - logger.Error("[GoogleReader][/stream/items/contents] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } err := r.ParseForm() if err != nil { - logger.Error("[GoogleReader][/stream/items/contents] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } var user *model.User if user, err = h.store.UserByID(userID); err != nil { - logger.Error("[GoogleReader][/stream/items/contents] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } requestModifiers, err := getStreamFilterModifiers(r) if err != nil { - logger.Error("[GoogleReader][/stream/items/contents] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -780,11 +918,17 @@ func (h *handler) streamItemContents(w http.ResponseWriter, r *http.Request) { itemIDs, err := getItemIDs(r) if err != nil { - logger.Error("[GoogleReader][/stream/items/contents] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } - logger.Debug("[GoogleReader][/stream/items/contents] [ClientIP=%s] itemIDs: %v", clientIP, itemIDs) + + slog.Debug("[GoogleReader] Fetching item contents", + slog.String("handler", "streamItemContentsHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", userID), + slog.Any("item_ids", itemIDs), + ) builder := h.store.NewEntryQueryBuilder(userID) builder.WithoutStatus(model.EntryStatusRemoved) @@ -796,12 +940,12 @@ func (h *handler) streamItemContents(w http.ResponseWriter, r *http.Request) { json.ServerError(w, r, err) return } + if len(entries) == 0 { - err = fmt.Errorf("no items returned from the database") - logger.Error("[GoogleReader][/stream/items/contents] [ClientIP=%s] %v", clientIP, err) - json.ServerError(w, r, err) + json.ServerError(w, r, fmt.Errorf("googlereader: no items returned from the database")) return } + result := streamContentItems{ Direction: "ltr", ID: fmt.Sprintf("feed/%d", entries[0].FeedID), @@ -893,29 +1037,33 @@ func (h *handler) streamItemContents(w http.ResponseWriter, r *http.Request) { json.OK(w, r, result) } -func (h *handler) disableTag(w http.ResponseWriter, r *http.Request) { +func (h *handler) disableTagHandler(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) clientIP := request.ClientIP(r) - logger.Info("[GoogleReader][/disable-tag][ClientIP=%s] Incoming Request for userID #%d", clientIP, userID) + slog.Debug("[GoogleReader] Handle /disable-tags", + slog.String("handler", "disableTagHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", userID), + ) err := r.ParseForm() if err != nil { - logger.Error("[GoogleReader][/disable-tag] [ClientIP=%s] %v", clientIP, err) json.BadRequest(w, r, err) return } streams, err := getStreams(r.Form[ParamStreamID], userID) if err != nil { - json.BadRequest(w, r, fmt.Errorf("invalid data in %s", ParamStreamID)) + json.BadRequest(w, r, fmt.Errorf("googlereader: invalid data in %s", ParamStreamID)) return } titles := make([]string, len(streams)) for i, stream := range streams { if stream.Type != LabelStream { - json.BadRequest(w, r, errors.New("only labels are supported")) + json.BadRequest(w, r, errors.New("googlereader: only labels are supported")) return } titles[i] = stream.ID @@ -930,38 +1078,41 @@ func (h *handler) disableTag(w http.ResponseWriter, r *http.Request) { OK(w, r) } -func (h *handler) renameTag(w http.ResponseWriter, r *http.Request) { +func (h *handler) renameTagHandler(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) clientIP := request.ClientIP(r) - logger.Info("[GoogleReader][/rename-tag][ClientIP=%s] Incoming Request for userID #%d", clientIP, userID) + slog.Debug("[GoogleReader] Handle /rename-tag", + slog.String("handler", "renameTagHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) err := r.ParseForm() if err != nil { - logger.Error("[GoogleReader][/rename-tag] [ClientIP=%s] %v", clientIP, err) json.BadRequest(w, r, err) return } source, err := getStream(r.Form.Get(ParamStreamID), userID) if err != nil { - json.BadRequest(w, r, fmt.Errorf("invalid data in %s", ParamStreamID)) + json.BadRequest(w, r, fmt.Errorf("googlereader: invalid data in %s", ParamStreamID)) return } destination, err := getStream(r.Form.Get(ParamDestination), userID) if err != nil { - json.BadRequest(w, r, fmt.Errorf("invalid data in %s", ParamDestination)) + json.BadRequest(w, r, fmt.Errorf("googlereader: invalid data in %s", ParamDestination)) return } if source.Type != LabelStream || destination.Type != LabelStream { - json.BadRequest(w, r, errors.New("only labels supported")) + json.BadRequest(w, r, errors.New("googlereader: only labels supported")) return } if destination.ID == "" { - json.BadRequest(w, r, errors.New("empty destination name")) + json.BadRequest(w, r, errors.New("googlereader: empty destination name")) return } @@ -991,14 +1142,17 @@ func (h *handler) renameTag(w http.ResponseWriter, r *http.Request) { OK(w, r) } -func (h *handler) tagList(w http.ResponseWriter, r *http.Request) { +func (h *handler) tagListHandler(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) clientIP := request.ClientIP(r) - logger.Info("[GoogleReader][tags/list][ClientIP=%s] Incoming Request for userID #%d", clientIP, userID) + slog.Debug("[GoogleReader] Handle /tags/list", + slog.String("handler", "tagListHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) if err := checkOutputFormat(w, r); err != nil { - logger.Error("[GoogleReader][OutputFormat] %v", err) json.BadRequest(w, r, err) return } @@ -1023,14 +1177,17 @@ func (h *handler) tagList(w http.ResponseWriter, r *http.Request) { json.OK(w, r, result) } -func (h *handler) subscriptionList(w http.ResponseWriter, r *http.Request) { +func (h *handler) subscriptionListHandler(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) clientIP := request.ClientIP(r) - logger.Info("[GoogleReader][/subscription/list][ClientIP=%s] Incoming Request for userID #%d", clientIP, userID) + slog.Debug("[GoogleReader] Handle /subscription/list", + slog.String("handler", "subscriptionListHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) if err := checkOutputFormat(w, r); err != nil { - logger.Error("[GoogleReader][/subscription/list] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -1055,27 +1212,34 @@ func (h *handler) subscriptionList(w http.ResponseWriter, r *http.Request) { json.OK(w, r, result) } -func (h *handler) serve(w http.ResponseWriter, r *http.Request) { +func (h *handler) serveHandler(w http.ResponseWriter, r *http.Request) { clientIP := request.ClientIP(r) - dump, _ := httputil.DumpRequest(r, true) - logger.Info("[GoogleReader][UNKNOWN] [ClientIP=%s] URL: %s", clientIP, dump) - logger.Error("Call to Google Reader API not implemented yet!!") + + slog.Debug("[GoogleReader] API endpoint not implemented yet", + slog.Any("url", r.RequestURI), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) + json.OK(w, r, []string{}) } -func (h *handler) userInfo(w http.ResponseWriter, r *http.Request) { +func (h *handler) userInfoHandler(w http.ResponseWriter, r *http.Request) { clientIP := request.ClientIP(r) - logger.Info("[GoogleReader][UserInfo] [ClientIP=%s] Sending", clientIP) + + slog.Debug("[GoogleReader] Handle /user-info", + slog.String("handler", "userInfoHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) if err := checkOutputFormat(w, r); err != nil { - logger.Error("[GoogleReader][/user-info] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } user, err := h.store.UserByID(request.UserID(r)) if err != nil { - logger.Error("[GoogleReader][/user-info] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -1083,16 +1247,19 @@ func (h *handler) userInfo(w http.ResponseWriter, r *http.Request) { json.OK(w, r, userInfo) } -func (h *handler) streamItemIDs(w http.ResponseWriter, r *http.Request) { +func (h *handler) streamItemIDsHandler(w http.ResponseWriter, r *http.Request) { userID := request.UserID(r) clientIP := request.ClientIP(r) - logger.Info("[GoogleReader][/stream/items/ids][ClientIP=%s] Incoming Request for userID #%d", clientIP, userID) + slog.Debug("[GoogleReader] Handle /stream/items/ids", + slog.String("handler", "streamItemIDsHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", userID), + ) if err := checkOutputFormat(w, r); err != nil { - err := fmt.Errorf("output only as json supported") - logger.Error("[GoogleReader][/stream/items/ids] [ClientIP=%s] %v", clientIP, err) - json.ServerError(w, r, err) + json.ServerError(w, r, fmt.Errorf("googlereader: output only as json supported")) return } @@ -1101,44 +1268,62 @@ func (h *handler) streamItemIDs(w http.ResponseWriter, r *http.Request) { json.ServerError(w, r, err) return } - logger.Debug("Request Modifiers: %v", rm) + + slog.Debug("[GoogleReader] Request modifiers", + slog.String("handler", "streamItemIDsHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Any("modifiers", rm), + ) + if len(rm.Streams) != 1 { - err := fmt.Errorf("only one stream type expected") - logger.Error("[GoogleReader][/stream/items/ids] [ClientIP=%s] %v", clientIP, err) - json.ServerError(w, r, err) + json.ServerError(w, r, fmt.Errorf("googlereader: only one stream type expected")) return } switch rm.Streams[0].Type { case ReadingListStream: - h.handleReadingListStream(w, r, rm) + h.handleReadingListStreamHandler(w, r, rm) case StarredStream: - h.handleStarredStream(w, r, rm) + h.handleStarredStreamHandler(w, r, rm) case ReadStream: - h.handleReadStream(w, r, rm) + h.handleReadStreamHandler(w, r, rm) case FeedStream: - h.handleFeedStream(w, r, rm) + h.handleFeedStreamHandler(w, r, rm) default: - dump, _ := httputil.DumpRequest(r, true) - logger.Info("[GoogleReader][/stream/items/ids] [ClientIP=%s] Unknown Stream: %s", clientIP, dump) - err := fmt.Errorf("unknown stream type") - logger.Error("[GoogleReader][/stream/items/ids] [ClientIP=%s] %v", clientIP, err) - json.ServerError(w, r, err) - return + slog.Warn("[GoogleReader] Unknown Stream", + slog.String("handler", "streamItemIDsHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Any("stream_type", rm.Streams[0].Type), + ) + json.ServerError(w, r, fmt.Errorf("googlereader: unknown stream type %s", rm.Streams[0].Type)) } } -func (h *handler) handleReadingListStream(w http.ResponseWriter, r *http.Request, rm RequestModifiers) { +func (h *handler) handleReadingListStreamHandler(w http.ResponseWriter, r *http.Request, rm RequestModifiers) { clientIP := request.ClientIP(r) + slog.Debug("[GoogleReader] Handle ReadingListStream", + slog.String("handler", "handleReadingListStreamHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) + builder := h.store.NewEntryQueryBuilder(rm.UserID) for _, s := range rm.ExcludeTargets { switch s.Type { case ReadStream: builder.WithStatus(model.EntryStatusUnread) default: - logger.Info("[GoogleReader][ReadingListStreamIDs][ClientIP=%s] xt filter type: %#v", clientIP, s) + slog.Warn("[GoogleReader] Unknown ExcludeTargets filter type", + slog.String("handler", "handleReadingListStreamHandler"), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Any("filter_type", s.Type), + ) } } + builder.WithoutStatus(model.EntryStatusRemoved) builder.WithLimit(rm.Count) builder.WithOffset(rm.Offset) @@ -1152,7 +1337,6 @@ func (h *handler) handleReadingListStream(w http.ResponseWriter, r *http.Request rawEntryIDs, err := builder.GetEntryIDs() if err != nil { - logger.Error("[GoogleReader][/stream/items/ids#reading-list] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -1164,7 +1348,6 @@ func (h *handler) handleReadingListStream(w http.ResponseWriter, r *http.Request totalEntries, err := builder.CountEntries() if err != nil { - logger.Error("[GoogleReader][/stream/items/ids#reading-list] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -1176,9 +1359,7 @@ func (h *handler) handleReadingListStream(w http.ResponseWriter, r *http.Request json.OK(w, r, streamIDResponse{itemRefs, continuation}) } -func (h *handler) handleStarredStream(w http.ResponseWriter, r *http.Request, rm RequestModifiers) { - clientIP := request.ClientIP(r) - +func (h *handler) handleStarredStreamHandler(w http.ResponseWriter, r *http.Request, rm RequestModifiers) { builder := h.store.NewEntryQueryBuilder(rm.UserID) builder.WithoutStatus(model.EntryStatusRemoved) builder.WithStarred(true) @@ -1194,7 +1375,6 @@ func (h *handler) handleStarredStream(w http.ResponseWriter, r *http.Request, rm rawEntryIDs, err := builder.GetEntryIDs() if err != nil { - logger.Error("[GoogleReader][/stream/items/ids#starred] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -1206,7 +1386,6 @@ func (h *handler) handleStarredStream(w http.ResponseWriter, r *http.Request, rm totalEntries, err := builder.CountEntries() if err != nil { - logger.Error("[GoogleReader][/stream/items/ids#starred] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -1218,9 +1397,7 @@ func (h *handler) handleStarredStream(w http.ResponseWriter, r *http.Request, rm json.OK(w, r, streamIDResponse{itemRefs, continuation}) } -func (h *handler) handleReadStream(w http.ResponseWriter, r *http.Request, rm RequestModifiers) { - clientIP := request.ClientIP(r) - +func (h *handler) handleReadStreamHandler(w http.ResponseWriter, r *http.Request, rm RequestModifiers) { builder := h.store.NewEntryQueryBuilder(rm.UserID) builder.WithoutStatus(model.EntryStatusRemoved) builder.WithStatus(model.EntryStatusRead) @@ -1236,7 +1413,6 @@ func (h *handler) handleReadStream(w http.ResponseWriter, r *http.Request, rm Re rawEntryIDs, err := builder.GetEntryIDs() if err != nil { - logger.Error("[GoogleReader][/stream/items/ids#read] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -1248,7 +1424,6 @@ func (h *handler) handleReadStream(w http.ResponseWriter, r *http.Request, rm Re totalEntries, err := builder.CountEntries() if err != nil { - logger.Error("[GoogleReader][/stream/items/ids#read] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -1260,11 +1435,9 @@ func (h *handler) handleReadStream(w http.ResponseWriter, r *http.Request, rm Re json.OK(w, r, streamIDResponse{itemRefs, continuation}) } -func (h *handler) handleFeedStream(w http.ResponseWriter, r *http.Request, rm RequestModifiers) { - clientIP := request.ClientIP(r) +func (h *handler) handleFeedStreamHandler(w http.ResponseWriter, r *http.Request, rm RequestModifiers) { feedID, err := strconv.ParseInt(rm.Streams[0].ID, 10, 64) if err != nil { - logger.Error("[GoogleReader][/stream/items/ids#feed] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -1284,7 +1457,6 @@ func (h *handler) handleFeedStream(w http.ResponseWriter, r *http.Request, rm Re rawEntryIDs, err := builder.GetEntryIDs() if err != nil { - logger.Error("[GoogleReader][/stream/items/ids#feed] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } @@ -1296,7 +1468,6 @@ func (h *handler) handleFeedStream(w http.ResponseWriter, r *http.Request, rm Re totalEntries, err := builder.CountEntries() if err != nil { - logger.Error("[GoogleReader][/stream/items/ids#feed] [ClientIP=%s] %v", clientIP, err) json.ServerError(w, r, err) return } diff --git a/internal/googlereader/middleware.go b/internal/googlereader/middleware.go index 1bfc1a6e..280868b8 100644 --- a/internal/googlereader/middleware.go +++ b/internal/googlereader/middleware.go @@ -8,13 +8,11 @@ import ( "crypto/hmac" "crypto/sha1" "encoding/hex" + "log/slog" "net/http" "strings" "miniflux.app/v2/internal/http/request" - "miniflux.app/v2/internal/http/response" - "miniflux.app/v2/internal/http/response/json" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/storage" ) @@ -27,75 +25,6 @@ func newMiddleware(s *storage.Storage) *middleware { return &middleware{s} } -func (m *middleware) clientLogin(w http.ResponseWriter, r *http.Request) { - clientIP := request.ClientIP(r) - var username, password, output string - var integration *model.Integration - err := r.ParseForm() - if err != nil { - logger.Error("[GoogleReader][Login] [ClientIP=%s] Could not parse form", clientIP) - json.Unauthorized(w, r) - return - } - username = r.Form.Get("Email") - password = r.Form.Get("Passwd") - output = r.Form.Get("output") - - if username == "" || password == "" { - logger.Error("[GoogleReader][Login] [ClientIP=%s] Empty username or password", clientIP) - json.Unauthorized(w, r) - return - } - - if err = m.store.GoogleReaderUserCheckPassword(username, password); err != nil { - logger.Error("[GoogleReader][Login] [ClientIP=%s] Invalid username or password: %s", clientIP, username) - json.Unauthorized(w, r) - return - } - - logger.Info("[GoogleReader][Login] [ClientIP=%s] User authenticated: %s", clientIP, username) - - if integration, err = m.store.GoogleReaderUserGetIntegration(username); err != nil { - logger.Error("[GoogleReader][Login] [ClientIP=%s] Could not load integration: %s", clientIP, username) - json.Unauthorized(w, r) - return - } - - m.store.SetLastLogin(integration.UserID) - - token := getAuthToken(integration.GoogleReaderUsername, integration.GoogleReaderPassword) - logger.Info("[GoogleReader][Login] [ClientIP=%s] Created token: %s", clientIP, token) - result := login{SID: token, LSID: token, Auth: token} - if output == "json" { - json.OK(w, r, result) - return - } - builder := response.New(w, r) - builder.WithHeader("Content-Type", "text/plain; charset=UTF-8") - builder.WithBody(result.String()) - builder.Write() -} - -func (m *middleware) token(w http.ResponseWriter, r *http.Request) { - clientIP := request.ClientIP(r) - - if !request.IsAuthenticated(r) { - logger.Error("[GoogleReader][Token] [ClientIP=%s] User is not authenticated", clientIP) - json.Unauthorized(w, r) - return - } - token := request.GoolgeReaderToken(r) - if token == "" { - logger.Error("[GoogleReader][Token] [ClientIP=%s] User does not have token: %s", clientIP, request.UserID(r)) - json.Unauthorized(w, r) - return - } - logger.Info("[GoogleReader][Token] [ClientIP=%s] token: %s", clientIP, token) - w.Header().Add("Content-Type", "text/plain; charset=UTF-8") - w.WriteHeader(http.StatusOK) - w.Write([]byte(token)) -} - func (m *middleware) handleCORS(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Access-Control-Allow-Origin", "*") @@ -115,15 +44,24 @@ func (m *middleware) apiKeyAuth(next http.Handler) http.Handler { var token string if r.Method == http.MethodPost { - err := r.ParseForm() - if err != nil { - logger.Error("[GoogleReader][Login] [ClientIP=%s] Could not parse form", clientIP) + if err := r.ParseForm(); err != nil { + slog.Warn("[GoogleReader] Could not parse request form data", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Any("error", err), + ) Unauthorized(w, r) return } + token = r.Form.Get("T") if token == "" { - logger.Error("[GoogleReader][Auth] [ClientIP=%s] Post-Form T field is empty", clientIP) + slog.Warn("[GoogleReader] Post-Form T field is empty", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) Unauthorized(w, r) return } @@ -131,29 +69,49 @@ func (m *middleware) apiKeyAuth(next http.Handler) http.Handler { authorization := r.Header.Get("Authorization") if authorization == "" { - logger.Error("[GoogleReader][Auth] [ClientIP=%s] No token provided", clientIP) + slog.Warn("[GoogleReader] No token provided", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) Unauthorized(w, r) return } fields := strings.Fields(authorization) if len(fields) != 2 { - logger.Error("[GoogleReader][Auth] [ClientIP=%s] Authorization header does not have the expected structure GoogleLogin auth=xxxxxx - '%s'", clientIP, authorization) + slog.Warn("[GoogleReader] Authorization header does not have the expected GoogleLogin format auth=xxxxxx", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) Unauthorized(w, r) return } if fields[0] != "GoogleLogin" { - logger.Error("[GoogleReader][Auth] [ClientIP=%s] Authorization header does not begin with GoogleLogin - '%s'", clientIP, authorization) + slog.Warn("[GoogleReader] Authorization header does not begin with GoogleLogin", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) Unauthorized(w, r) return } auths := strings.Split(fields[1], "=") if len(auths) != 2 { - logger.Error("[GoogleReader][Auth] [ClientIP=%s] Authorization header does not have the expected structure GoogleLogin auth=xxxxxx - '%s'", clientIP, authorization) + slog.Warn("[GoogleReader] Authorization header does not have the expected GoogleLogin format auth=xxxxxx", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) Unauthorized(w, r) return } if auths[0] != "auth" { - logger.Error("[GoogleReader][Auth] [ClientIP=%s] Authorization header does not have the expected structure GoogleLogin auth=xxxxxx - '%s'", clientIP, authorization) + slog.Warn("[GoogleReader] Authorization header does not have the expected GoogleLogin format auth=xxxxxx", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) Unauthorized(w, r) return } @@ -162,7 +120,12 @@ func (m *middleware) apiKeyAuth(next http.Handler) http.Handler { parts := strings.Split(token, "/") if len(parts) != 2 { - logger.Error("[GoogleReader][Auth] [ClientIP=%s] Auth token does not have the expected structure username/hash - '%s'", clientIP, token) + slog.Warn("[GoogleReader] Auth token does not have the expected structure username/hash", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.String("token", token), + ) Unauthorized(w, r) return } @@ -170,23 +133,54 @@ func (m *middleware) apiKeyAuth(next http.Handler) http.Handler { var user *model.User var err error if integration, err = m.store.GoogleReaderUserGetIntegration(parts[0]); err != nil { - logger.Error("[GoogleReader][Auth] [ClientIP=%s] token: %s", clientIP, token) - logger.Error("[GoogleReader][Auth] [ClientIP=%s] No user found with the given google reader username: %s", clientIP, parts[0]) + slog.Warn("[GoogleReader] No user found with the given Google Reader username", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Any("error", err), + ) Unauthorized(w, r) return } expectedToken := getAuthToken(integration.GoogleReaderUsername, integration.GoogleReaderPassword) if expectedToken != token { - logger.Error("[GoogleReader][Auth] [ClientIP=%s] Token does not match: %s", clientIP, token) + slog.Warn("[GoogleReader] Token does not match", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) Unauthorized(w, r) return } if user, err = m.store.UserByID(integration.UserID); err != nil { - logger.Error("[GoogleReader][Auth] [ClientIP=%s] No user found with the userID: %d", clientIP, integration.UserID) + slog.Error("[GoogleReader] Unable to fetch user from database", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Any("error", err), + ) Unauthorized(w, r) return } + if user == nil { + slog.Warn("[GoogleReader] No user found with the given Google Reader credentials", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + ) + Unauthorized(w, r) + return + } + + slog.Info("[GoogleReader] User authenticated successfully", + slog.Bool("authentication_successful", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", user.ID), + slog.String("username", user.Username), + ) + m.store.SetLastLogin(integration.UserID) ctx := r.Context() diff --git a/internal/googlereader/response.go b/internal/googlereader/response.go index 6d97bf38..9a6ad378 100644 --- a/internal/googlereader/response.go +++ b/internal/googlereader/response.go @@ -8,7 +8,6 @@ import ( "net/http" "miniflux.app/v2/internal/http/response" - "miniflux.app/v2/internal/logger" ) type login struct { @@ -122,8 +121,6 @@ type contentItemOrigin struct { // Unauthorized sends a not authorized error to the client. func Unauthorized(w http.ResponseWriter, r *http.Request) { - logger.Error("[HTTP:Unauthorized] %s", r.URL) - builder := response.New(w, r) builder.WithStatus(http.StatusUnauthorized) builder.WithHeader("Content-Type", "text/plain") @@ -134,8 +131,6 @@ func Unauthorized(w http.ResponseWriter, r *http.Request) { // OK sends a ok response to the client. func OK(w http.ResponseWriter, r *http.Request) { - logger.Info("[HTTP:OK] %s", r.URL) - builder := response.New(w, r) builder.WithStatus(http.StatusOK) builder.WithHeader("Content-Type", "text/plain") diff --git a/internal/http/client/client.go b/internal/http/client/client.go index de7c9d48..00baf650 100644 --- a/internal/http/client/client.go +++ b/internal/http/client/client.go @@ -7,19 +7,16 @@ import ( "bytes" "crypto/tls" "crypto/x509" - "encoding/json" "fmt" "io" + "log/slog" "net" "net/http" "net/url" - "strings" "time" "miniflux.app/v2/internal/config" "miniflux.app/v2/internal/errors" - "miniflux.app/v2/internal/logger" - "miniflux.app/v2/internal/timer" ) const ( @@ -74,28 +71,6 @@ func NewClientWithConfig(url string, opts *config.Options) *Client { } } -func (c *Client) String() string { - etagHeader := c.requestEtagHeader - if c.requestEtagHeader == "" { - etagHeader = "None" - } - - lastModifiedHeader := c.requestLastModifiedHeader - if c.requestLastModifiedHeader == "" { - lastModifiedHeader = "None" - } - - return fmt.Sprintf( - `InputURL=%q ETag=%s LastMod=%s Auth=%v UserAgent=%q Verify=%v`, - c.inputURL, - etagHeader, - lastModifiedHeader, - c.requestAuthorizationHeader != "" || (c.requestUsername != "" && c.requestPassword != ""), - c.requestUserAgent, - !c.AllowSelfSignedCertificates, - ) -} - // WithCredentials defines the username/password for HTTP Basic authentication. func (c *Client) WithCredentials(username, password string) *Client { if username != "" && password != "" { @@ -105,12 +80,6 @@ func (c *Client) WithCredentials(username, password string) *Client { return c } -// WithAuthorization defines the authorization HTTP header value. -func (c *Client) WithAuthorization(authorization string) *Client { - c.requestAuthorizationHeader = authorization - return c -} - // WithCustomHeaders defines custom HTTP headers. func (c *Client) WithCustomHeaders(customHeaders map[string]string) *Client { c.customHeaders = customHeaders @@ -162,55 +131,21 @@ func (c *Client) Get() (*Response, error) { return c.executeRequest(request) } -// PostForm performs a POST HTTP request with form encoded values. -func (c *Client) PostForm(values url.Values) (*Response, error) { - request, err := c.buildRequest(http.MethodPost, strings.NewReader(values.Encode())) - if err != nil { - return nil, err - } - - request.Header.Add("Content-Type", "application/x-www-form-urlencoded") - return c.executeRequest(request) -} - -// PostJSON performs a POST HTTP request with a JSON payload. -func (c *Client) PostJSON(data interface{}) (*Response, error) { - b, err := json.Marshal(data) - if err != nil { - return nil, err - } - - request, err := c.buildRequest(http.MethodPost, bytes.NewReader(b)) - if err != nil { - return nil, err - } - - request.Header.Add("Content-Type", "application/json") - return c.executeRequest(request) -} - -// PatchJSON performs a Patch HTTP request with a JSON payload. -func (c *Client) PatchJSON(data interface{}) (*Response, error) { - b, err := json.Marshal(data) - if err != nil { - return nil, err - } - - request, err := c.buildRequest(http.MethodPatch, bytes.NewReader(b)) - if err != nil { - return nil, err - } - - request.Header.Add("Content-Type", "application/json") - return c.executeRequest(request) -} - func (c *Client) executeRequest(request *http.Request) (*Response, error) { - defer timer.ExecutionTime(time.Now(), fmt.Sprintf("[HttpClient] inputURL=%s", c.inputURL)) - - logger.Debug("[HttpClient:Before] Method=%s %s", - request.Method, - c.String(), + startTime := time.Now() + + slog.Debug("Executing outgoing HTTP request", + slog.Group("request", + slog.String("method", request.Method), + slog.String("url", request.URL.String()), + slog.String("user_agent", request.UserAgent()), + slog.Bool("is_authenticated", c.requestAuthorizationHeader != "" || (c.requestUsername != "" && c.requestPassword != "")), + slog.Bool("has_cookie", c.requestCookie != ""), + slog.Bool("with_redirects", !c.doNotFollowRedirects), + slog.Bool("with_proxy", c.useProxy), + slog.String("proxy_url", c.ClientProxyURL), + slog.Bool("with_caching_headers", c.requestEtagHeader != "" || c.requestLastModifiedHeader != ""), + ), ) client := c.buildClient() @@ -257,15 +192,32 @@ func (c *Client) executeRequest(request *http.Request) (*Response, error) { ContentLength: resp.ContentLength, } - logger.Debug("[HttpClient:After] Method=%s %s; Response => %s", - request.Method, - c.String(), - response, + slog.Debug("Completed outgoing HTTP request", + slog.Duration("duration", time.Since(startTime)), + slog.Group("request", + slog.String("method", request.Method), + slog.String("url", request.URL.String()), + slog.String("user_agent", request.UserAgent()), + slog.Bool("is_authenticated", c.requestAuthorizationHeader != "" || (c.requestUsername != "" && c.requestPassword != "")), + slog.Bool("has_cookie", c.requestCookie != ""), + slog.Bool("with_redirects", !c.doNotFollowRedirects), + slog.Bool("with_proxy", c.useProxy), + slog.String("proxy_url", c.ClientProxyURL), + slog.Bool("with_caching_headers", c.requestEtagHeader != "" || c.requestLastModifiedHeader != ""), + ), + slog.Group("response", + slog.Int("status_code", response.StatusCode), + slog.String("effective_url", response.EffectiveURL), + slog.String("content_type", response.ContentType), + slog.Int64("content_length", response.ContentLength), + slog.String("last_modified", response.LastModified), + slog.String("etag", response.ETag), + slog.String("expires", response.Expires), + ), ) // Ignore caching headers for feeds that do not want any cache. if resp.Header.Get("Expires") == "0" { - logger.Debug("[HttpClient] Ignore caching headers for %q", response.EffectiveURL) response.ETag = "" response.LastModified = "" } @@ -323,9 +275,11 @@ func (c *Client) buildClient() http.Client { if c.useProxy && c.ClientProxyURL != "" { proxyURL, err := url.Parse(c.ClientProxyURL) if err != nil { - logger.Error("[HttpClient] Proxy URL error: %v", err) + slog.Error("Unable to parse proxy URL", + slog.String("proxy_url", c.ClientProxyURL), + slog.Any("error", err), + ) } else { - logger.Debug("[HttpClient] Use proxy: %s", proxyURL) transport.Proxy = http.ProxyURL(proxyURL) } } diff --git a/internal/http/response/builder.go b/internal/http/response/builder.go index 017da1b6..97f00733 100644 --- a/internal/http/response/builder.go +++ b/internal/http/response/builder.go @@ -8,11 +8,10 @@ import ( "compress/gzip" "fmt" "io" + "log/slog" "net/http" "strings" "time" - - "miniflux.app/v2/internal/logger" ) const compressionThreshold = 1024 @@ -91,7 +90,7 @@ func (b *Builder) Write() { b.writeHeaders() _, err := io.Copy(b.w, v) if err != nil { - logger.Error("%v", err) + slog.Error("Unable to write response body", slog.Any("error", err)) } } } diff --git a/internal/http/response/html/html.go b/internal/http/response/html/html.go index 184bc9b6..eeaeb1ef 100644 --- a/internal/http/response/html/html.go +++ b/internal/http/response/html/html.go @@ -4,10 +4,11 @@ package html // import "miniflux.app/v2/internal/http/response/html" import ( + "log/slog" "net/http" + "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response" - "miniflux.app/v2/internal/logger" ) // OK creates a new HTML response with a 200 status code. @@ -21,7 +22,18 @@ func OK(w http.ResponseWriter, r *http.Request, body interface{}) { // ServerError sends an internal error to the client. func ServerError(w http.ResponseWriter, r *http.Request, err error) { - logger.Error("[HTTP:Internal Server Error] %s => %v", r.URL, err) + slog.Error(http.StatusText(http.StatusInternalServerError), + slog.Any("error", err), + slog.String("client_ip", request.ClientIP(r)), + slog.Group("request", + slog.String("method", r.Method), + slog.String("uri", r.RequestURI), + slog.String("user_agent", r.UserAgent()), + ), + slog.Group("response", + slog.Int("status_code", http.StatusInternalServerError), + ), + ) builder := response.New(w, r) builder.WithStatus(http.StatusInternalServerError) @@ -34,7 +46,18 @@ func ServerError(w http.ResponseWriter, r *http.Request, err error) { // BadRequest sends a bad request error to the client. func BadRequest(w http.ResponseWriter, r *http.Request, err error) { - logger.Error("[HTTP:Bad Request] %s => %v", r.URL, err) + slog.Warn(http.StatusText(http.StatusBadRequest), + slog.Any("error", err), + slog.String("client_ip", request.ClientIP(r)), + slog.Group("request", + slog.String("method", r.Method), + slog.String("uri", r.RequestURI), + slog.String("user_agent", r.UserAgent()), + ), + slog.Group("response", + slog.Int("status_code", http.StatusBadRequest), + ), + ) builder := response.New(w, r) builder.WithStatus(http.StatusBadRequest) @@ -47,7 +70,17 @@ func BadRequest(w http.ResponseWriter, r *http.Request, err error) { // Forbidden sends a forbidden error to the client. func Forbidden(w http.ResponseWriter, r *http.Request) { - logger.Error("[HTTP:Forbidden] %s", r.URL) + slog.Warn(http.StatusText(http.StatusForbidden), + slog.String("client_ip", request.ClientIP(r)), + slog.Group("request", + slog.String("method", r.Method), + slog.String("uri", r.RequestURI), + slog.String("user_agent", r.UserAgent()), + ), + slog.Group("response", + slog.Int("status_code", http.StatusForbidden), + ), + ) builder := response.New(w, r) builder.WithStatus(http.StatusForbidden) @@ -59,7 +92,17 @@ func Forbidden(w http.ResponseWriter, r *http.Request) { // NotFound sends a page not found error to the client. func NotFound(w http.ResponseWriter, r *http.Request) { - logger.Error("[HTTP:Not Found] %s", r.URL) + slog.Warn(http.StatusText(http.StatusNotFound), + slog.String("client_ip", request.ClientIP(r)), + slog.Group("request", + slog.String("method", r.Method), + slog.String("uri", r.RequestURI), + slog.String("user_agent", r.UserAgent()), + ), + slog.Group("response", + slog.Int("status_code", http.StatusNotFound), + ), + ) builder := response.New(w, r) builder.WithStatus(http.StatusNotFound) @@ -76,7 +119,17 @@ func Redirect(w http.ResponseWriter, r *http.Request, uri string) { // RequestedRangeNotSatisfiable sends a range not satisfiable error to the client. func RequestedRangeNotSatisfiable(w http.ResponseWriter, r *http.Request, contentRange string) { - logger.Error("[HTTP:Range Not Satisfiable] %s", r.URL) + slog.Warn(http.StatusText(http.StatusRequestedRangeNotSatisfiable), + slog.String("client_ip", request.ClientIP(r)), + slog.Group("request", + slog.String("method", r.Method), + slog.String("uri", r.RequestURI), + slog.String("user_agent", r.UserAgent()), + ), + slog.Group("response", + slog.Int("status_code", http.StatusRequestedRangeNotSatisfiable), + ), + ) builder := response.New(w, r) builder.WithStatus(http.StatusRequestedRangeNotSatisfiable) diff --git a/internal/http/response/json/json.go b/internal/http/response/json/json.go index 5e6024ea..8e99681a 100644 --- a/internal/http/response/json/json.go +++ b/internal/http/response/json/json.go @@ -6,10 +6,11 @@ package json // import "miniflux.app/v2/internal/http/response/json" import ( "encoding/json" "errors" + "log/slog" "net/http" + "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response" - "miniflux.app/v2/internal/logger" ) const contentTypeHeader = `application/json` @@ -48,7 +49,18 @@ func Accepted(w http.ResponseWriter, r *http.Request) { // ServerError sends an internal error to the client. func ServerError(w http.ResponseWriter, r *http.Request, err error) { - logger.Error("[HTTP:Internal Server Error] %s => %v", r.URL, err) + slog.Error(http.StatusText(http.StatusInternalServerError), + slog.Any("error", err), + slog.String("client_ip", request.ClientIP(r)), + slog.Group("request", + slog.String("method", r.Method), + slog.String("uri", r.RequestURI), + slog.String("user_agent", r.UserAgent()), + ), + slog.Group("response", + slog.Int("status_code", http.StatusInternalServerError), + ), + ) builder := response.New(w, r) builder.WithStatus(http.StatusInternalServerError) @@ -59,7 +71,18 @@ func ServerError(w http.ResponseWriter, r *http.Request, err error) { // BadRequest sends a bad request error to the client. func BadRequest(w http.ResponseWriter, r *http.Request, err error) { - logger.Error("[HTTP:Bad Request] %s => %v", r.URL, err) + slog.Warn(http.StatusText(http.StatusBadRequest), + slog.Any("error", err), + slog.String("client_ip", request.ClientIP(r)), + slog.Group("request", + slog.String("method", r.Method), + slog.String("uri", r.RequestURI), + slog.String("user_agent", r.UserAgent()), + ), + slog.Group("response", + slog.Int("status_code", http.StatusBadRequest), + ), + ) builder := response.New(w, r) builder.WithStatus(http.StatusBadRequest) @@ -70,7 +93,17 @@ func BadRequest(w http.ResponseWriter, r *http.Request, err error) { // Unauthorized sends a not authorized error to the client. func Unauthorized(w http.ResponseWriter, r *http.Request) { - logger.Error("[HTTP:Unauthorized] %s", r.URL) + slog.Warn(http.StatusText(http.StatusUnauthorized), + slog.String("client_ip", request.ClientIP(r)), + slog.Group("request", + slog.String("method", r.Method), + slog.String("uri", r.RequestURI), + slog.String("user_agent", r.UserAgent()), + ), + slog.Group("response", + slog.Int("status_code", http.StatusUnauthorized), + ), + ) builder := response.New(w, r) builder.WithStatus(http.StatusUnauthorized) @@ -81,7 +114,17 @@ func Unauthorized(w http.ResponseWriter, r *http.Request) { // Forbidden sends a forbidden error to the client. func Forbidden(w http.ResponseWriter, r *http.Request) { - logger.Error("[HTTP:Forbidden] %s", r.URL) + slog.Warn(http.StatusText(http.StatusForbidden), + slog.String("client_ip", request.ClientIP(r)), + slog.Group("request", + slog.String("method", r.Method), + slog.String("uri", r.RequestURI), + slog.String("user_agent", r.UserAgent()), + ), + slog.Group("response", + slog.Int("status_code", http.StatusForbidden), + ), + ) builder := response.New(w, r) builder.WithStatus(http.StatusForbidden) @@ -92,7 +135,17 @@ func Forbidden(w http.ResponseWriter, r *http.Request) { // NotFound sends a page not found error to the client. func NotFound(w http.ResponseWriter, r *http.Request) { - logger.Error("[HTTP:Not Found] %s", r.URL) + slog.Warn(http.StatusText(http.StatusNotFound), + slog.String("client_ip", request.ClientIP(r)), + slog.Group("request", + slog.String("method", r.Method), + slog.String("uri", r.RequestURI), + slog.String("user_agent", r.UserAgent()), + ), + slog.Group("response", + slog.Int("status_code", http.StatusNotFound), + ), + ) builder := response.New(w, r) builder.WithStatus(http.StatusNotFound) @@ -112,7 +165,7 @@ func toJSONError(err error) []byte { func toJSON(v interface{}) []byte { b, err := json.Marshal(v) if err != nil { - logger.Error("[HTTP:JSON] %v", err) + slog.Error("Unable to marshal JSON response", slog.Any("error", err)) return []byte("") } diff --git a/internal/http/route/route.go b/internal/http/route/route.go index 601fbd67..c5e3b36f 100644 --- a/internal/http/route/route.go +++ b/internal/http/route/route.go @@ -7,14 +7,13 @@ import ( "strconv" "github.com/gorilla/mux" - "miniflux.app/v2/internal/logger" ) // Path returns the defined route based on given arguments. -func Path(router *mux.Router, name string, args ...interface{}) string { +func Path(router *mux.Router, name string, args ...any) string { route := router.Get(name) if route == nil { - logger.Fatal("[Route] Route not found: %s", name) + panic("route not found: " + name) } var pairs []string @@ -29,7 +28,7 @@ func Path(router *mux.Router, name string, args ...interface{}) string { result, err := route.URLPath(pairs...) if err != nil { - logger.Fatal("[Route] %v", err) + panic(err) } return result.String() diff --git a/internal/http/server/httpd.go b/internal/http/server/httpd.go index c99761e6..7fe45ac7 100644 --- a/internal/http/server/httpd.go +++ b/internal/http/server/httpd.go @@ -5,6 +5,8 @@ package httpd // import "miniflux.app/v2/internal/http/server" import ( "crypto/tls" + "fmt" + "log/slog" "net" "net/http" "os" @@ -17,7 +19,6 @@ import ( "miniflux.app/v2/internal/fever" "miniflux.app/v2/internal/googlereader" "miniflux.app/v2/internal/http/request" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/storage" "miniflux.app/v2/internal/ui" "miniflux.app/v2/internal/version" @@ -66,12 +67,12 @@ func startSystemdSocketServer(server *http.Server) { f := os.NewFile(3, "systemd socket") listener, err := net.FileListener(f) if err != nil { - logger.Fatal(`Unable to create listener from systemd socket: %v`, err) + printErrorAndExit(`Unable to create listener from systemd socket: %v`, err) } - logger.Info(`Listening on systemd socket`) + slog.Info(`Starting server using systemd socket`) if err := server.Serve(listener); err != http.ErrServerClosed { - logger.Fatal(`Server failed to start: %v`, err) + printErrorAndExit(`Server failed to start: %v`, err) } }() } @@ -82,17 +83,17 @@ func startUnixSocketServer(server *http.Server, socketFile string) { go func(sock string) { listener, err := net.Listen("unix", sock) if err != nil { - logger.Fatal(`Server failed to start: %v`, err) + printErrorAndExit(`Server failed to start: %v`, err) } defer listener.Close() if err := os.Chmod(sock, 0666); err != nil { - logger.Fatal(`Unable to change socket permission: %v`, err) + printErrorAndExit(`Unable to change socket permission: %v`, err) } - logger.Info(`Listening on Unix socket %q`, sock) + slog.Info("Starting server using a Unix socket", slog.String("socket", sock)) if err := server.Serve(listener); err != http.ErrServerClosed { - logger.Fatal(`Server failed to start: %v`, err) + printErrorAndExit(`Server failed to start: %v`, err) } }(socketFile) } @@ -137,9 +138,12 @@ func startAutoCertTLSServer(server *http.Server, certDomain string, store *stora go s.ListenAndServe() go func() { - logger.Info(`Listening on %q by using auto-configured certificate for %q`, server.Addr, certDomain) + slog.Info("Starting TLS server using automatic certificate management", + slog.String("listen_address", server.Addr), + slog.String("domain", certDomain), + ) if err := server.ListenAndServeTLS("", ""); err != http.ErrServerClosed { - logger.Fatal(`Server failed to start: %v`, err) + printErrorAndExit(`Server failed to start: %v`, err) } }() } @@ -147,18 +151,24 @@ func startAutoCertTLSServer(server *http.Server, certDomain string, store *stora func startTLSServer(server *http.Server, certFile, keyFile string) { server.TLSConfig = tlsConfig() go func() { - logger.Info(`Listening on %q by using certificate %q and key %q`, server.Addr, certFile, keyFile) + slog.Info("Starting TLS server using a certificate", + slog.String("listen_address", server.Addr), + slog.String("cert_file", certFile), + slog.String("key_file", keyFile), + ) if err := server.ListenAndServeTLS(certFile, keyFile); err != http.ErrServerClosed { - logger.Fatal(`Server failed to start: %v`, err) + printErrorAndExit(`Server failed to start: %v`, err) } }() } func startHTTPServer(server *http.Server) { go func() { - logger.Info(`Listening on %q without TLS`, server.Addr) + slog.Info("Starting HTTP server", + slog.String("listen_address", server.Addr), + ) if err := server.ListenAndServe(); err != http.ErrServerClosed { - logger.Fatal(`Server failed to start: %v`, err) + printErrorAndExit(`Server failed to start: %v`, err) } }() } @@ -206,7 +216,11 @@ func setupHandler(store *storage.Storage, pool *worker.Pool) *mux.Router { // Returns a 404 if the client is not authorized to access the metrics endpoint. if route.GetName() == "metrics" && !isAllowedToAccessMetricsEndpoint(r) { - logger.Error(`[Metrics] [ClientIP=%s] Client not allowed (%s)`, request.ClientIP(r), r.RemoteAddr) + slog.Warn("Authentication failed while accessing the metrics endpoint", + slog.String("client_ip", request.ClientIP(r)), + slog.String("client_user_agent", r.UserAgent()), + slog.String("client_remote_addr", r.RemoteAddr), + ) http.NotFound(w, r) return } @@ -220,21 +234,37 @@ func setupHandler(store *storage.Storage, pool *worker.Pool) *mux.Router { } func isAllowedToAccessMetricsEndpoint(r *http.Request) bool { + clientIP := request.ClientIP(r) + if config.Opts.MetricsUsername() != "" && config.Opts.MetricsPassword() != "" { - clientIP := request.ClientIP(r) username, password, authOK := r.BasicAuth() if !authOK { - logger.Info("[Metrics] [ClientIP=%s] No authentication header sent", clientIP) + slog.Warn("Metrics endpoint accessed without authentication header", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("client_user_agent", r.UserAgent()), + slog.String("client_remote_addr", r.RemoteAddr), + ) return false } if username == "" || password == "" { - logger.Info("[Metrics] [ClientIP=%s] Empty username or password", clientIP) + slog.Warn("Metrics endpoint accessed with empty username or password", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("client_user_agent", r.UserAgent()), + slog.String("client_remote_addr", r.RemoteAddr), + ) return false } if username != config.Opts.MetricsUsername() || password != config.Opts.MetricsPassword() { - logger.Error("[Metrics] [ClientIP=%s] Invalid username or password", clientIP) + slog.Warn("Metrics endpoint accessed with invalid username or password", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("client_user_agent", r.UserAgent()), + slog.String("client_remote_addr", r.RemoteAddr), + ) return false } } @@ -242,7 +272,14 @@ func isAllowedToAccessMetricsEndpoint(r *http.Request) bool { for _, cidr := range config.Opts.MetricsAllowedNetworks() { _, network, err := net.ParseCIDR(cidr) if err != nil { - logger.Fatal(`[Metrics] Unable to parse CIDR %v`, err) + slog.Error("Metrics endpoint accessed with invalid CIDR", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("client_user_agent", r.UserAgent()), + slog.String("client_remote_addr", r.RemoteAddr), + slog.String("cidr", cidr), + ) + return false } // We use r.RemoteAddr in this case because HTTP headers like X-Forwarded-For can be easily spoofed. @@ -254,3 +291,10 @@ func isAllowedToAccessMetricsEndpoint(r *http.Request) bool { return false } + +func printErrorAndExit(format string, a ...any) { + message := fmt.Sprintf(format, a...) + slog.Error(message) + fmt.Fprintf(os.Stderr, "%v\n", message) + os.Exit(1) +} diff --git a/internal/http/server/middleware.go b/internal/http/server/middleware.go index e23cdcc4..41978471 100644 --- a/internal/http/server/middleware.go +++ b/internal/http/server/middleware.go @@ -5,11 +5,12 @@ package httpd // import "miniflux.app/v2/internal/http/server" import ( "context" + "log/slog" "net/http" + "time" "miniflux.app/v2/internal/config" "miniflux.app/v2/internal/http/request" - "miniflux.app/v2/internal/logger" ) func middleware(next http.Handler) http.Handler { @@ -22,12 +23,18 @@ func middleware(next http.Handler) http.Handler { config.Opts.HTTPS = true } - protocol := "HTTP" - if config.Opts.HTTPS { - protocol = "HTTPS" - } - - logger.Debug("[%s] %s %s %s", protocol, clientIP, r.Method, r.RequestURI) + t1 := time.Now() + defer func() { + slog.Debug("Incoming request", + slog.String("client_ip", clientIP), + slog.Group("request", + slog.String("method", r.Method), + slog.String("uri", r.RequestURI), + slog.String("protocol", r.Proto), + slog.Duration("execution_time", time.Since(t1)), + ), + ) + }() if config.Opts.HTTPS && config.Opts.HasHSTS() { w.Header().Set("Strict-Transport-Security", "max-age=31536000") diff --git a/internal/integration/integration.go b/internal/integration/integration.go index 7c7c3b22..7d71844c 100644 --- a/internal/integration/integration.go +++ b/internal/integration/integration.go @@ -4,6 +4,8 @@ package integration // import "miniflux.app/v2/internal/integration" import ( + "log/slog" + "miniflux.app/v2/internal/config" "miniflux.app/v2/internal/integration/apprise" "miniflux.app/v2/internal/integration/espial" @@ -20,160 +22,269 @@ import ( "miniflux.app/v2/internal/integration/telegrambot" "miniflux.app/v2/internal/integration/wallabag" "miniflux.app/v2/internal/integration/webhook" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" ) // SendEntry sends the entry to third-party providers when the user click on "Save". -func SendEntry(entry *model.Entry, integration *model.Integration) { - if integration.PinboardEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to Pinboard", entry.ID, entry.URL, integration.UserID) +func SendEntry(entry *model.Entry, userIntegrations *model.Integration) { + if userIntegrations.PinboardEnabled { + slog.Debug("Sending entry to Pinboard", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) - client := pinboard.NewClient(integration.PinboardToken) + client := pinboard.NewClient(userIntegrations.PinboardToken) err := client.CreateBookmark( entry.URL, entry.Title, - integration.PinboardTags, - integration.PinboardMarkAsUnread, + userIntegrations.PinboardTags, + userIntegrations.PinboardMarkAsUnread, ) if err != nil { - logger.Error("[Integration] UserID #%d: %v", integration.UserID, err) + slog.Error("Unable to send entry to Pinboard", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } - if integration.InstapaperEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to Instapaper", entry.ID, entry.URL, integration.UserID) + if userIntegrations.InstapaperEnabled { + slog.Debug("Sending entry to Instapaper", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) - client := instapaper.NewClient(integration.InstapaperUsername, integration.InstapaperPassword) + client := instapaper.NewClient(userIntegrations.InstapaperUsername, userIntegrations.InstapaperPassword) if err := client.AddURL(entry.URL, entry.Title); err != nil { - logger.Error("[Integration] UserID #%d: %v", integration.UserID, err) + slog.Error("Unable to send entry to Instapaper", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } - if integration.WallabagEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to Wallabag", entry.ID, entry.URL, integration.UserID) + if userIntegrations.WallabagEnabled { + slog.Debug("Sending entry to Wallabag", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) client := wallabag.NewClient( - integration.WallabagURL, - integration.WallabagClientID, - integration.WallabagClientSecret, - integration.WallabagUsername, - integration.WallabagPassword, - integration.WallabagOnlyURL, + userIntegrations.WallabagURL, + userIntegrations.WallabagClientID, + userIntegrations.WallabagClientSecret, + userIntegrations.WallabagUsername, + userIntegrations.WallabagPassword, + userIntegrations.WallabagOnlyURL, ) if err := client.CreateEntry(entry.URL, entry.Title, entry.Content); err != nil { - logger.Error("[Integration] UserID #%d: %v", integration.UserID, err) + slog.Error("Unable to send entry to Wallabag", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } - if integration.NotionEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to Notion", entry.ID, entry.URL, integration.UserID) + if userIntegrations.NotionEnabled { + slog.Debug("Sending entry to Notion", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) client := notion.NewClient( - integration.NotionToken, - integration.NotionPageID, + userIntegrations.NotionToken, + userIntegrations.NotionPageID, ) if err := client.UpdateDocument(entry.URL, entry.Title); err != nil { - logger.Error("[Integration] UserID #%d: %v", integration.UserID, err) + slog.Error("Unable to send entry to Notion", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } - if integration.NunuxKeeperEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to NunuxKeeper", entry.ID, entry.URL, integration.UserID) + if userIntegrations.NunuxKeeperEnabled { + slog.Debug("Sending entry to NunuxKeeper", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) client := nunuxkeeper.NewClient( - integration.NunuxKeeperURL, - integration.NunuxKeeperAPIKey, + userIntegrations.NunuxKeeperURL, + userIntegrations.NunuxKeeperAPIKey, ) if err := client.AddEntry(entry.URL, entry.Title, entry.Content); err != nil { - logger.Error("[Integration] UserID #%d: %v", integration.UserID, err) + slog.Error("Unable to send entry to NunuxKeeper", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } - if integration.EspialEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to Espial", entry.ID, entry.URL, integration.UserID) + if userIntegrations.EspialEnabled { + slog.Debug("Sending entry to Espial", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) client := espial.NewClient( - integration.EspialURL, - integration.EspialAPIKey, + userIntegrations.EspialURL, + userIntegrations.EspialAPIKey, ) - if err := client.CreateLink(entry.URL, entry.Title, integration.EspialTags); err != nil { - logger.Error("[Integration] Unable to send entry #%d to Espial for user #%d: %v", entry.ID, integration.UserID, err) + if err := client.CreateLink(entry.URL, entry.Title, userIntegrations.EspialTags); err != nil { + slog.Error("Unable to send entry to Espial", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } - if integration.PocketEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to Pocket", entry.ID, entry.URL, integration.UserID) + if userIntegrations.PocketEnabled { + slog.Debug("Sending entry to Pocket", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) - client := pocket.NewClient(config.Opts.PocketConsumerKey(integration.PocketConsumerKey), integration.PocketAccessToken) + client := pocket.NewClient(config.Opts.PocketConsumerKey(userIntegrations.PocketConsumerKey), userIntegrations.PocketAccessToken) if err := client.AddURL(entry.URL, entry.Title); err != nil { - logger.Error("[Integration] UserID #%d: %v", integration.UserID, err) + slog.Error("Unable to send entry to Pocket", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } - if integration.LinkdingEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to Linkding", entry.ID, entry.URL, integration.UserID) + if userIntegrations.LinkdingEnabled { + slog.Debug("Sending entry to Linkding", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) client := linkding.NewClient( - integration.LinkdingURL, - integration.LinkdingAPIKey, - integration.LinkdingTags, - integration.LinkdingMarkAsUnread, + userIntegrations.LinkdingURL, + userIntegrations.LinkdingAPIKey, + userIntegrations.LinkdingTags, + userIntegrations.LinkdingMarkAsUnread, ) if err := client.CreateBookmark(entry.URL, entry.Title); err != nil { - logger.Error("[Integration] UserID #%d: %v", integration.UserID, err) + slog.Error("Unable to send entry to Linkding", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } - if integration.ReadwiseEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to Readwise Reader", entry.ID, entry.URL, integration.UserID) + if userIntegrations.ReadwiseEnabled { + slog.Debug("Sending entry to Readwise", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) client := readwise.NewClient( - integration.ReadwiseAPIKey, + userIntegrations.ReadwiseAPIKey, ) if err := client.CreateDocument(entry.URL); err != nil { - logger.Error("[Integration] UserID #%d: %v", integration.UserID, err) + slog.Error("Unable to send entry to Readwise", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } - if integration.ShioriEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to Shiori", entry.ID, entry.URL, integration.UserID) + if userIntegrations.ShioriEnabled { + slog.Debug("Sending entry to Shiori", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) client := shiori.NewClient( - integration.ShioriURL, - integration.ShioriUsername, - integration.ShioriPassword, + userIntegrations.ShioriURL, + userIntegrations.ShioriUsername, + userIntegrations.ShioriPassword, ) if err := client.CreateBookmark(entry.URL, entry.Title); err != nil { - logger.Error("[Integration] Unable to send entry #%d to Shiori for user #%d: %v", entry.ID, integration.UserID, err) + slog.Error("Unable to send entry to Shiori", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } - if integration.ShaarliEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to Shaarli", entry.ID, entry.URL, integration.UserID) + if userIntegrations.ShaarliEnabled { + slog.Debug("Sending entry to Shaarli", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) client := shaarli.NewClient( - integration.ShaarliURL, - integration.ShaarliAPISecret, + userIntegrations.ShaarliURL, + userIntegrations.ShaarliAPISecret, ) if err := client.CreateLink(entry.URL, entry.Title); err != nil { - logger.Error("[Integration] Unable to send entry #%d to Shaarli for user #%d: %v", entry.ID, integration.UserID, err) + slog.Error("Unable to send entry to Shaarli", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } - if integration.WebhookEnabled { - logger.Debug("[Integration] Sending entry #%d %q for user #%d to Webhook URL: %s", entry.ID, entry.URL, integration.UserID, integration.WebhookURL) + if userIntegrations.WebhookEnabled { + slog.Debug("Sending entry to Webhook", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.String("webhook_url", userIntegrations.WebhookURL), + ) - webhookClient := webhook.NewClient(integration.WebhookURL, integration.WebhookSecret) + webhookClient := webhook.NewClient(userIntegrations.WebhookURL, userIntegrations.WebhookSecret) if err := webhookClient.SendSaveEntryWebhookEvent(entry); err != nil { - logger.Error("[Integration] UserID #%d: %v", integration.UserID, err) + slog.Error("Unable to send entry to Webhook", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.String("webhook_url", userIntegrations.WebhookURL), + slog.Any("error", err), + ) } } } @@ -181,20 +292,47 @@ func SendEntry(entry *model.Entry, integration *model.Integration) { // PushEntries pushes a list of entries to activated third-party providers during feed refreshes. func PushEntries(feed *model.Feed, entries model.Entries, userIntegrations *model.Integration) { if userIntegrations.MatrixBotEnabled { - logger.Debug("[Integration] Sending %d entries for user #%d to Matrix", len(entries), userIntegrations.UserID) + slog.Debug("Sending new entries to Matrix", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int("nb_entries", len(entries)), + slog.Int64("feed_id", feed.ID), + ) - err := matrixbot.PushEntries(feed, entries, userIntegrations.MatrixBotURL, userIntegrations.MatrixBotUser, userIntegrations.MatrixBotPassword, userIntegrations.MatrixBotChatID) + err := matrixbot.PushEntries( + feed, + entries, + userIntegrations.MatrixBotURL, + userIntegrations.MatrixBotUser, + userIntegrations.MatrixBotPassword, + userIntegrations.MatrixBotChatID, + ) if err != nil { - logger.Error("[Integration] push entries to matrix bot failed: %v", err) + slog.Error("Unable to send new entries to Matrix", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int("nb_entries", len(entries)), + slog.Int64("feed_id", feed.ID), + slog.Any("error", err), + ) } } if userIntegrations.WebhookEnabled { - logger.Debug("[Integration] Sending %d entries for user #%d to Webhook URL: %s", len(entries), userIntegrations.UserID, userIntegrations.WebhookURL) + slog.Debug("Sending new entries to Webhook", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int("nb_entries", len(entries)), + slog.Int64("feed_id", feed.ID), + slog.String("webhook_url", userIntegrations.WebhookURL), + ) webhookClient := webhook.NewClient(userIntegrations.WebhookURL, userIntegrations.WebhookSecret) if err := webhookClient.SendNewEntriesWebhookEvent(feed, entries); err != nil { - logger.Error("[Integration] sending entries to webhook failed: %v", err) + slog.Debug("Unable to send new entries to Webhook", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int("nb_entries", len(entries)), + slog.Int64("feed_id", feed.ID), + slog.String("webhook_url", userIntegrations.WebhookURL), + slog.Any("error", err), + ) } } @@ -202,7 +340,11 @@ func PushEntries(feed *model.Feed, entries model.Entries, userIntegrations *mode if userIntegrations.TelegramBotEnabled || userIntegrations.AppriseEnabled { for _, entry := range entries { if userIntegrations.TelegramBotEnabled { - logger.Debug("[Integration] Sending entry %q for user #%d to Telegram", entry.URL, userIntegrations.UserID) + slog.Debug("Sending a new entry to Telegram", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) if err := telegrambot.PushEntry( feed, @@ -213,12 +355,21 @@ func PushEntries(feed *model.Feed, entries model.Entries, userIntegrations *mode userIntegrations.TelegramBotDisableWebPagePreview, userIntegrations.TelegramBotDisableNotification, ); err != nil { - logger.Error("[Integration] %v", err) + slog.Error("Unable to send entry to Telegram", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } if userIntegrations.AppriseEnabled { - logger.Debug("[Integration] Sending entry %q for user #%d to Apprise", entry.URL, userIntegrations.UserID) + slog.Debug("Sending a new entry to Apprise", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + ) appriseServiceURLs := userIntegrations.AppriseURL if feed.AppriseServiceURLs != "" { @@ -231,7 +382,12 @@ func PushEntries(feed *model.Feed, entries model.Entries, userIntegrations *mode ) if err := client.SendNotification(entry); err != nil { - logger.Error("[Integration] %v", err) + slog.Error("Unable to send entry to Apprise", + slog.Int64("user_id", userIntegrations.UserID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Any("error", err), + ) } } } diff --git a/internal/logger/logger.go b/internal/logger/logger.go deleted file mode 100644 index 70b93a75..00000000 --- a/internal/logger/logger.go +++ /dev/null @@ -1,97 +0,0 @@ -// SPDX-FileCopyrightText: Copyright The Miniflux Authors. All rights reserved. -// SPDX-License-Identifier: Apache-2.0 - -package logger // import "miniflux.app/v2/internal/logger" - -import ( - "fmt" - "os" - "time" -) - -var requestedLevel = InfoLevel -var displayDateTime = false - -// LogLevel type. -type LogLevel uint32 - -const ( - // FatalLevel should be used in fatal situations, the app will exit. - FatalLevel LogLevel = iota - - // ErrorLevel should be used when someone should really look at the error. - ErrorLevel - - // InfoLevel should be used during normal operations. - InfoLevel - - // DebugLevel should be used only during development. - DebugLevel -) - -func (level LogLevel) String() string { - switch level { - case DebugLevel: - return "DEBUG" - case InfoLevel: - return "INFO" - case ErrorLevel: - return "ERROR" - case FatalLevel: - return "FATAL" - default: - return "UNKNOWN" - } -} - -// EnableDateTime enables date time in log messages. -func EnableDateTime() { - displayDateTime = true -} - -// EnableDebug increases logging, more verbose (debug) -func EnableDebug() { - requestedLevel = DebugLevel - formatMessage(InfoLevel, "Debug mode enabled") -} - -// Debug sends a debug log message. -func Debug(format string, v ...interface{}) { - if requestedLevel >= DebugLevel { - formatMessage(DebugLevel, format, v...) - } -} - -// Info sends an info log message. -func Info(format string, v ...interface{}) { - if requestedLevel >= InfoLevel { - formatMessage(InfoLevel, format, v...) - } -} - -// Error sends an error log message. -func Error(format string, v ...interface{}) { - if requestedLevel >= ErrorLevel { - formatMessage(ErrorLevel, format, v...) - } -} - -// Fatal sends a fatal log message and stop the execution of the program. -func Fatal(format string, v ...interface{}) { - if requestedLevel >= FatalLevel { - formatMessage(FatalLevel, format, v...) - os.Exit(1) - } -} - -func formatMessage(level LogLevel, format string, v ...interface{}) { - var prefix string - - if displayDateTime { - prefix = fmt.Sprintf("[%s] [%s] ", time.Now().Format("2006-01-02T15:04:05"), level) - } else { - prefix = fmt.Sprintf("[%s] ", level) - } - - fmt.Fprintf(os.Stderr, prefix+format+"\n", v...) -} diff --git a/internal/metric/metric.go b/internal/metric/metric.go index 7653c447..1c0f4c82 100644 --- a/internal/metric/metric.go +++ b/internal/metric/metric.go @@ -4,9 +4,9 @@ package metric // import "miniflux.app/v2/internal/metric" import ( + "log/slog" "time" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/storage" "github.com/prometheus/client_golang/prometheus" @@ -164,7 +164,7 @@ func NewCollector(store *storage.Storage, refreshInterval int) *Collector { // GatherStorageMetrics polls the database to fetch metrics. func (c *Collector) GatherStorageMetrics() { for range time.Tick(time.Duration(c.refreshInterval) * time.Second) { - logger.Debug("[Metric] Collecting database metrics") + slog.Debug("Collecting metrics from the database") usersGauge.Set(float64(c.store.CountUsers())) brokenFeedsGauge.Set(float64(c.store.CountAllFeedsWithErrors())) diff --git a/internal/oauth2/manager.go b/internal/oauth2/manager.go index 04c6ef2a..7ee10015 100644 --- a/internal/oauth2/manager.go +++ b/internal/oauth2/manager.go @@ -6,8 +6,7 @@ package oauth2 // import "miniflux.app/v2/internal/oauth2" import ( "context" "errors" - - "miniflux.app/v2/internal/logger" + "log/slog" ) type Manager struct { @@ -32,7 +31,9 @@ func NewManager(ctx context.Context, clientID, clientSecret, redirectURL, oidcDi if oidcDiscoveryEndpoint != "" { if genericOidcProvider, err := NewOidcProvider(ctx, clientID, clientSecret, redirectURL, oidcDiscoveryEndpoint); err != nil { - logger.Error("[OAuth2] failed to initialize OIDC provider: %v", err) + slog.Error("Failed to initialize OIDC provider", + slog.Any("error", err), + ) } else { m.AddProvider("oidc", genericOidcProvider) } diff --git a/internal/reader/atom/atom_03.go b/internal/reader/atom/atom_03.go index d7e99ae6..aff0af47 100644 --- a/internal/reader/atom/atom_03.go +++ b/internal/reader/atom/atom_03.go @@ -6,11 +6,11 @@ package atom // import "miniflux.app/v2/internal/reader/atom" import ( "encoding/base64" "html" + "log/slog" "strings" "time" "miniflux.app/v2/internal/crypto" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/reader/date" "miniflux.app/v2/internal/reader/sanitizer" @@ -126,7 +126,11 @@ func (a *atom03Entry) entryDate() time.Time { if dateText != "" { result, err := date.Parse(dateText) if err != nil { - logger.Error("atom: %v", err) + slog.Warn("Unable to parse date from Atom 0.3 feed", + slog.String("date", dateText), + slog.String("id", a.ID), + slog.Any("error", err), + ) return time.Now() } diff --git a/internal/reader/atom/atom_10.go b/internal/reader/atom/atom_10.go index 8eee69bf..5d561d43 100644 --- a/internal/reader/atom/atom_10.go +++ b/internal/reader/atom/atom_10.go @@ -6,12 +6,12 @@ package atom // import "miniflux.app/v2/internal/reader/atom" import ( "encoding/xml" "html" + "log/slog" "strconv" "strings" "time" "miniflux.app/v2/internal/crypto" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/reader/date" "miniflux.app/v2/internal/reader/media" @@ -144,7 +144,11 @@ func (a *atom10Entry) entryDate() time.Time { if dateText != "" { result, err := date.Parse(dateText) if err != nil { - logger.Error("atom: %v (entry ID = %s)", err, a.ID) + slog.Warn("Unable to parse date from Atom 0.3 feed", + slog.String("date", dateText), + slog.String("id", a.ID), + slog.Any("error", err), + ) return time.Now() } diff --git a/internal/reader/handler/handler.go b/internal/reader/handler/handler.go index 43ccfe47..91b7e394 100644 --- a/internal/reader/handler/handler.go +++ b/internal/reader/handler/handler.go @@ -4,22 +4,19 @@ package handler // import "miniflux.app/v2/internal/reader/handler" import ( - "fmt" - "time" + "log/slog" "miniflux.app/v2/internal/config" "miniflux.app/v2/internal/errors" "miniflux.app/v2/internal/http/client" "miniflux.app/v2/internal/integration" "miniflux.app/v2/internal/locale" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/reader/browser" "miniflux.app/v2/internal/reader/icon" "miniflux.app/v2/internal/reader/parser" "miniflux.app/v2/internal/reader/processor" "miniflux.app/v2/internal/storage" - "miniflux.app/v2/internal/timer" ) var ( @@ -30,7 +27,10 @@ var ( // CreateFeed fetch, parse and store a new feed. func CreateFeed(store *storage.Storage, userID int64, feedCreationRequest *model.FeedCreationRequest) (*model.Feed, error) { - defer timer.ExecutionTime(time.Now(), fmt.Sprintf("[CreateFeed] FeedURL=%s", feedCreationRequest.FeedURL)) + slog.Debug("Begin feed creation process", + slog.Int64("user_id", userID), + slog.String("feed_url", feedCreationRequest.FeedURL), + ) user, storeErr := store.UserByID(userID) if storeErr != nil { @@ -90,7 +90,11 @@ func CreateFeed(store *storage.Storage, userID int64, feedCreationRequest *model return nil, storeErr } - logger.Debug("[CreateFeed] Feed saved with ID: %d", subscription.ID) + slog.Debug("Created feed", + slog.Int64("user_id", userID), + slog.Int64("feed_id", subscription.ID), + slog.String("feed_url", subscription.FeedURL), + ) checkFeedIcon( store, @@ -106,7 +110,12 @@ func CreateFeed(store *storage.Storage, userID int64, feedCreationRequest *model // RefreshFeed refreshes a feed. func RefreshFeed(store *storage.Storage, userID, feedID int64, forceRefresh bool) error { - defer timer.ExecutionTime(time.Now(), fmt.Sprintf("[RefreshFeed] feedID=%d", feedID)) + slog.Debug("Begin feed refresh process", + slog.Int64("user_id", userID), + slog.Int64("feed_id", feedID), + slog.Bool("force_refresh", forceRefresh), + ) + user, storeErr := store.UserByID(userID) if storeErr != nil { return storeErr @@ -164,7 +173,10 @@ func RefreshFeed(store *storage.Storage, userID, feedID int64, forceRefresh bool } if originalFeed.IgnoreHTTPCache || response.IsModified(originalFeed.EtagHeader, originalFeed.LastModifiedHeader) { - logger.Debug("[RefreshFeed] Feed #%d has been modified", feedID) + slog.Debug("Feed modified", + slog.Int64("user_id", userID), + slog.Int64("feed_id", feedID), + ) updatedFeed, parseErr := parser.ParseFeed(response.EffectiveURL, response.BodyAsString()) if parseErr != nil { @@ -187,7 +199,11 @@ func RefreshFeed(store *storage.Storage, userID, feedID int64, forceRefresh bool userIntegrations, intErr := store.Integration(userID) if intErr != nil { - logger.Error("[RefreshFeed] Fetching integrations for user %d failed: %v; the refresh process will go on, but no integrations will run this time.", userID, intErr) + slog.Error("Fetching integrations failed; the refresh process will go on, but no integrations will run this time", + slog.Int64("user_id", userID), + slog.Int64("feed_id", feedID), + slog.Any("error", intErr), + ) } else if userIntegrations != nil && len(newEntries) > 0 { go integration.PushEntries(originalFeed, newEntries, userIntegrations) } @@ -206,7 +222,10 @@ func RefreshFeed(store *storage.Storage, userID, feedID int64, forceRefresh bool originalFeed.AllowSelfSignedCertificates, ) } else { - logger.Debug("[RefreshFeed] Feed #%d not modified", feedID) + slog.Debug("Feed not modified", + slog.Int64("user_id", userID), + slog.Int64("feed_id", feedID), + ) } originalFeed.ResetErrorCounter() @@ -224,12 +243,26 @@ func checkFeedIcon(store *storage.Storage, feedID int64, websiteURL, feedIconURL if !store.HasIcon(feedID) { icon, err := icon.FindIcon(websiteURL, feedIconURL, userAgent, fetchViaProxy, allowSelfSignedCertificates) if err != nil { - logger.Debug(`[CheckFeedIcon] %v (feedID=%d websiteURL=%s)`, err, feedID, websiteURL) + slog.Warn("Unable to find feed icon", + slog.Int64("feed_id", feedID), + slog.String("website_url", websiteURL), + slog.String("feed_icon_url", feedIconURL), + slog.Any("error", err), + ) } else if icon == nil { - logger.Debug(`[CheckFeedIcon] No icon found (feedID=%d websiteURL=%s)`, feedID, websiteURL) + slog.Debug("No icon found", + slog.Int64("feed_id", feedID), + slog.String("website_url", websiteURL), + slog.String("feed_icon_url", feedIconURL), + ) } else { if err := store.CreateFeedIcon(feedID, icon); err != nil { - logger.Debug(`[CheckFeedIcon] %v (feedID=%d websiteURL=%s)`, err, feedID, websiteURL) + slog.Error("Unable to store feed icon", + slog.Int64("feed_id", feedID), + slog.String("website_url", websiteURL), + slog.String("feed_icon_url", feedIconURL), + slog.Any("error", err), + ) } } } diff --git a/internal/reader/icon/finder.go b/internal/reader/icon/finder.go index afc032e3..f7669d07 100644 --- a/internal/reader/icon/finder.go +++ b/internal/reader/icon/finder.go @@ -13,7 +13,6 @@ import ( "miniflux.app/v2/internal/config" "miniflux.app/v2/internal/crypto" "miniflux.app/v2/internal/http/client" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/urllib" @@ -65,7 +64,6 @@ func generateIconURL(websiteURL, feedIconURL string) (iconURL string, err error) func fetchHTMLDocumentAndFindIconURL(websiteURL, userAgent string, fetchViaProxy, allowSelfSignedCertificates bool) (string, error) { rootURL := urllib.RootURL(websiteURL) - logger.Debug("[FindIcon] Find icon from HTML webpage: %s", rootURL) clt := client.NewClientWithConfig(rootURL, config.Opts) clt.WithUserAgent(userAgent) diff --git a/internal/reader/json/json.go b/internal/reader/json/json.go index 68f4c0f8..6786af74 100644 --- a/internal/reader/json/json.go +++ b/internal/reader/json/json.go @@ -4,11 +4,11 @@ package json // import "miniflux.app/v2/internal/reader/json" import ( + "log/slog" "strings" "time" "miniflux.app/v2/internal/crypto" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/reader/date" "miniflux.app/v2/internal/reader/sanitizer" @@ -110,7 +110,11 @@ func (j *jsonItem) GetDate() time.Time { if value != "" { d, err := date.Parse(value) if err != nil { - logger.Error("json: %v", err) + slog.Warn("Unable to parse date from JSON feed", + slog.String("date", value), + slog.String("url", j.URL), + slog.Any("error", err), + ) return time.Now() } diff --git a/internal/reader/opml/handler.go b/internal/reader/opml/handler.go index 1d874a87..c3e972b9 100644 --- a/internal/reader/opml/handler.go +++ b/internal/reader/opml/handler.go @@ -4,11 +4,9 @@ package opml // import "miniflux.app/v2/internal/reader/opml" import ( - "errors" "fmt" "io" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/storage" ) @@ -53,21 +51,18 @@ func (h *Handler) Import(userID int64, data io.Reader) error { if subscription.CategoryName == "" { category, err = h.store.FirstCategory(userID) if err != nil { - logger.Error("[OPML:Import] %v", err) - return errors.New("unable to find first category") + return fmt.Errorf("opml: unable to find first category: %w", err) } } else { category, err = h.store.CategoryByTitle(userID, subscription.CategoryName) if err != nil { - logger.Error("[OPML:Import] %v", err) - return errors.New("unable to search category by title") + return fmt.Errorf("opml: unable to search category by title: %w", err) } if category == nil { category, err = h.store.CreateCategory(userID, &model.CategoryRequest{Title: subscription.CategoryName}) if err != nil { - logger.Error("[OPML:Import] %v", err) - return fmt.Errorf(`unable to create this category: %q`, subscription.CategoryName) + return fmt.Errorf(`opml: unable to create this category: %q`, subscription.CategoryName) } } } diff --git a/internal/reader/opml/serializer.go b/internal/reader/opml/serializer.go index 69581100..b1638e4c 100644 --- a/internal/reader/opml/serializer.go +++ b/internal/reader/opml/serializer.go @@ -7,10 +7,9 @@ import ( "bufio" "bytes" "encoding/xml" + "log/slog" "sort" "time" - - "miniflux.app/v2/internal/logger" ) // Serialize returns a SubcriptionList in OPML format. @@ -23,7 +22,9 @@ func Serialize(subscriptions SubcriptionList) string { encoder := xml.NewEncoder(writer) encoder.Indent("", " ") if err := encoder.Encode(opmlDocument); err != nil { - logger.Error("[OPML:Serialize] %v", err) + slog.Error("Unable to serialize OPML document", + slog.Any("error", err), + ) return "" } diff --git a/internal/reader/processor/processor.go b/internal/reader/processor/processor.go index d56d4289..c6514bf6 100644 --- a/internal/reader/processor/processor.go +++ b/internal/reader/processor/processor.go @@ -6,6 +6,7 @@ package processor import ( "errors" "fmt" + "log/slog" "math" "regexp" "strconv" @@ -15,7 +16,6 @@ import ( "miniflux.app/v2/internal/config" "miniflux.app/v2/internal/http/client" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/metric" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/reader/browser" @@ -43,7 +43,13 @@ func ProcessFeedEntries(store *storage.Storage, feed *model.Feed, user *model.Us for i := len(feed.Entries) - 1; i >= 0; i-- { entry := feed.Entries[i] - logger.Debug("[Processor] Processing entry %q from feed %q", entry.URL, feed.FeedURL) + slog.Debug("Processing entry", + slog.Int64("user_id", user.ID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Int64("feed_id", feed.ID), + slog.String("feed_url", feed.FeedURL), + ) if isBlockedEntry(feed, entry) || !isAllowedEntry(feed, entry) { continue @@ -52,7 +58,13 @@ func ProcessFeedEntries(store *storage.Storage, feed *model.Feed, user *model.Us url := getUrlFromEntry(feed, entry) entryIsNew := !store.EntryURLExists(feed.ID, entry.URL) if feed.Crawler && (entryIsNew || forceRefresh) { - logger.Debug("[Processor] Crawling entry %q from feed %q", url, feed.FeedURL) + slog.Debug("Scraping entry", + slog.Int64("user_id", user.ID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Int64("feed_id", feed.ID), + slog.String("feed_url", feed.FeedURL), + ) startTime := time.Now() content, scraperErr := scraper.Fetch( @@ -73,7 +85,14 @@ func ProcessFeedEntries(store *storage.Storage, feed *model.Feed, user *model.Us } if scraperErr != nil { - logger.Error(`[Processor] Unable to crawl this entry: %q => %v`, entry.URL, scraperErr) + slog.Warn("Unable to scrape entry", + slog.Int64("user_id", user.ID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Int64("feed_id", feed.ID), + slog.String("feed_url", feed.FeedURL), + slog.Any("error", scraperErr), + ) } else if content != "" { // We replace the entry content only if the scraper doesn't return any error. entry.Content = content @@ -96,7 +115,13 @@ func isBlockedEntry(feed *model.Feed, entry *model.Entry) bool { if feed.BlocklistRules != "" { match, _ := regexp.MatchString(feed.BlocklistRules, entry.Title) if match { - logger.Debug("[Processor] Blocking entry %q from feed %q based on rule %q", entry.Title, feed.FeedURL, feed.BlocklistRules) + slog.Debug("Blocking entry based on rule", + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Int64("feed_id", feed.ID), + slog.String("feed_url", feed.FeedURL), + slog.String("rule", feed.BlocklistRules), + ) return true } } @@ -107,7 +132,13 @@ func isAllowedEntry(feed *model.Feed, entry *model.Entry) bool { if feed.KeeplistRules != "" { match, _ := regexp.MatchString(feed.KeeplistRules, entry.Title) if match { - logger.Debug("[Processor] Allow entry %q from feed %q based on rule %q", entry.Title, feed.FeedURL, feed.KeeplistRules) + slog.Debug("Allow entry based on rule", + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Int64("feed_id", feed.ID), + slog.String("feed_url", feed.FeedURL), + slog.String("rule", feed.KeeplistRules), + ) return true } return false @@ -160,9 +191,22 @@ func getUrlFromEntry(feed *model.Feed, entry *model.Entry) string { if len(parts) >= 3 { re := regexp.MustCompile(parts[1]) url = re.ReplaceAllString(entry.URL, parts[2]) - logger.Debug(`[Processor] Rewriting entry URL %s to %s`, entry.URL, url) + slog.Debug("Rewriting entry URL", + slog.Int64("entry_id", entry.ID), + slog.String("original_entry_url", entry.URL), + slog.String("rewritten_entry_url", url), + slog.Int64("feed_id", feed.ID), + slog.String("feed_url", feed.FeedURL), + ) } else { - logger.Debug("[Processor] Cannot find search and replace terms for replace rule %s", feed.UrlRewriteRules) + slog.Debug("Cannot find search and replace terms for replace rule", + slog.Int64("entry_id", entry.ID), + slog.String("original_entry_url", entry.URL), + slog.String("rewritten_entry_url", url), + slog.Int64("feed_id", feed.ID), + slog.String("feed_url", feed.FeedURL), + slog.String("url_rewrite_rules", feed.UrlRewriteRules), + ) } } return url @@ -173,7 +217,14 @@ func updateEntryReadingTime(store *storage.Storage, feed *model.Feed, entry *mod if entryIsNew { watchTime, err := fetchYouTubeWatchTime(entry.URL) if err != nil { - logger.Error("[Processor] Unable to fetch YouTube watch time: %q => %v", entry.URL, err) + slog.Warn("Unable to fetch YouTube watch time", + slog.Int64("user_id", user.ID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Int64("feed_id", feed.ID), + slog.String("feed_url", feed.FeedURL), + slog.Any("error", err), + ) } entry.ReadingTime = watchTime } else { @@ -185,7 +236,14 @@ func updateEntryReadingTime(store *storage.Storage, feed *model.Feed, entry *mod if entryIsNew { watchTime, err := fetchOdyseeWatchTime(entry.URL) if err != nil { - logger.Error("[Processor] Unable to fetch Odysee watch time: %q => %v", entry.URL, err) + slog.Warn("Unable to fetch Odysee watch time", + slog.Int64("user_id", user.ID), + slog.Int64("entry_id", entry.ID), + slog.String("entry_url", entry.URL), + slog.Int64("feed_id", feed.ID), + slog.String("feed_url", feed.FeedURL), + slog.Any("error", err), + ) } entry.ReadingTime = watchTime } else { diff --git a/internal/reader/rdf/rdf.go b/internal/reader/rdf/rdf.go index ca74cb2a..fa89f60f 100644 --- a/internal/reader/rdf/rdf.go +++ b/internal/reader/rdf/rdf.go @@ -6,11 +6,11 @@ package rdf // import "miniflux.app/v2/internal/reader/rdf" import ( "encoding/xml" "html" + "log/slog" "strings" "time" "miniflux.app/v2/internal/crypto" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/reader/date" "miniflux.app/v2/internal/reader/dublincore" @@ -100,7 +100,11 @@ func (r *rdfItem) entryDate() time.Time { if r.DublinCoreDate != "" { result, err := date.Parse(r.DublinCoreDate) if err != nil { - logger.Error("rdf: %v (entry link = %s)", err, r.Link) + slog.Warn("Unable to parse date from RDF feed", + slog.String("date", r.DublinCoreDate), + slog.String("link", r.Link), + slog.Any("error", err), + ) return time.Now() } diff --git a/internal/reader/readability/readability.go b/internal/reader/readability/readability.go index 27b45052..f857cd71 100644 --- a/internal/reader/readability/readability.go +++ b/internal/reader/readability/readability.go @@ -7,12 +7,11 @@ import ( "bytes" "fmt" "io" + "log/slog" "math" "regexp" "strings" - "miniflux.app/v2/internal/logger" - "github.com/PuerkitoBio/goquery" "golang.org/x/net/html" ) @@ -83,10 +82,12 @@ func ExtractContent(page io.Reader) (string, error) { removeUnlikelyCandidates(document) candidates := getCandidates(document) - logger.Debug("[Readability] Candidates: %v", candidates) - topCandidate := getTopCandidate(document, candidates) - logger.Debug("[Readability] TopCandidate: %v", topCandidate) + + slog.Debug("Readability parsing", + slog.Any("candidates", candidates), + slog.Any("topCandidate", topCandidate), + ) output := getArticle(topCandidate, candidates) return output, nil diff --git a/internal/reader/rewrite/rewrite_functions.go b/internal/reader/rewrite/rewrite_functions.go index 6950c333..249ee183 100644 --- a/internal/reader/rewrite/rewrite_functions.go +++ b/internal/reader/rewrite/rewrite_functions.go @@ -7,12 +7,12 @@ import ( "encoding/base64" "fmt" "html" + "log/slog" "net/url" "regexp" "strings" "miniflux.app/v2/internal/config" - "miniflux.app/v2/internal/logger" "github.com/PuerkitoBio/goquery" "github.com/yuin/goldmark" @@ -359,7 +359,9 @@ func addHackerNewsLinksUsing(entryContent, app string) string { open_with_hack := `<a href="` + url + `">Open with HACK</a>` a.Parent().AppendHtml(" " + open_with_hack) } else { - logger.Error("[openHackerNewsLinksWith] unknown app provided: %q", app) + slog.Warn("Unknown app provided for openHackerNewsLinksWith rewrite rule", + slog.String("app", app), + ) return } }) diff --git a/internal/reader/rewrite/rewriter.go b/internal/reader/rewrite/rewriter.go index 65c66ff2..9885890f 100644 --- a/internal/reader/rewrite/rewriter.go +++ b/internal/reader/rewrite/rewriter.go @@ -4,11 +4,11 @@ package rewrite // import "miniflux.app/v2/internal/reader/rewrite" import ( + "log/slog" "strconv" "strings" "text/scanner" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/urllib" ) @@ -28,7 +28,10 @@ func Rewriter(entryURL string, entry *model.Entry, customRewriteRules string) { rules := parseRules(rulesList) rules = append(rules, rule{name: "add_pdf_download_link"}) - logger.Debug(`[Rewrite] Applying rules %v for %q`, rules, entryURL) + slog.Debug("Rewrite rules applied", + slog.Any("rules", rules), + slog.String("entry_url", entryURL), + ) for _, rule := range rules { applyRule(entryURL, entry, rule) @@ -89,21 +92,30 @@ func applyRule(entryURL string, entry *model.Entry, rule rule) { if len(rule.args) >= 2 { entry.Content = replaceCustom(entry.Content, rule.args[0], rule.args[1]) } else { - logger.Debug("[Rewrite] Cannot find search and replace terms for replace rule %s", rule) + slog.Warn("Cannot find search and replace terms for replace rule", + slog.Any("rule", rule), + slog.String("entry_url", entryURL), + ) } case "replace_title": // Format: replace_title("search-term"|"replace-term") if len(rule.args) >= 2 { entry.Title = replaceCustom(entry.Title, rule.args[0], rule.args[1]) } else { - logger.Debug("[Rewrite] Cannot find search and replace terms for replace rule %s", rule) + slog.Warn("Cannot find search and replace terms for replace_title rule", + slog.Any("rule", rule), + slog.String("entry_url", entryURL), + ) } case "remove": // Format: remove("#selector > .element, .another") if len(rule.args) >= 1 { entry.Content = removeCustom(entry.Content, rule.args[0]) } else { - logger.Debug("[Rewrite] Cannot find selector for remove rule %s", rule) + slog.Warn("Cannot find selector for remove rule", + slog.Any("rule", rule), + slog.String("entry_url", entryURL), + ) } case "add_castopod_episode": entry.Content = addCastopodEpisode(entryURL, entry.Content) diff --git a/internal/reader/rss/rss.go b/internal/reader/rss/rss.go index f2ecdaec..a62dabd7 100644 --- a/internal/reader/rss/rss.go +++ b/internal/reader/rss/rss.go @@ -6,13 +6,13 @@ package rss // import "miniflux.app/v2/internal/reader/rss" import ( "encoding/xml" "html" + "log/slog" "path" "strconv" "strings" "time" "miniflux.app/v2/internal/crypto" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/reader/date" "miniflux.app/v2/internal/reader/dublincore" @@ -216,7 +216,11 @@ func (r *rssItem) entryDate() time.Time { if value != "" { result, err := date.Parse(value) if err != nil { - logger.Error("rss: %v (entry GUID = %s)", err, r.GUID) + slog.Warn("Unable to parse date from RSS feed", + slog.String("date", value), + slog.String("guid", r.GUID.Data), + slog.Any("error", err), + ) return time.Now() } diff --git a/internal/reader/scraper/scraper.go b/internal/reader/scraper/scraper.go index b6ddf39d..c74946c3 100644 --- a/internal/reader/scraper/scraper.go +++ b/internal/reader/scraper/scraper.go @@ -7,11 +7,11 @@ import ( "errors" "fmt" "io" + "log/slog" "strings" "miniflux.app/v2/internal/config" "miniflux.app/v2/internal/http/client" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/reader/readability" "miniflux.app/v2/internal/urllib" @@ -55,10 +55,15 @@ func Fetch(websiteURL, rules, userAgent string, cookie string, allowSelfSignedCe var content string if sameSite && rules != "" { - logger.Debug(`[Scraper] Using rules %q for %q`, rules, websiteURL) + slog.Debug("Extracting content with custom rules", + "url", websiteURL, + "rules", rules, + ) content, err = scrapContent(response.Body, rules) } else { - logger.Debug(`[Scraper] Using readability for %q`, websiteURL) + slog.Debug("Extracting content with readability", + "url", websiteURL, + ) content, err = readability.ExtractContent(response.Body) } diff --git a/internal/storage/category.go b/internal/storage/category.go index 5ee8404b..285b3f97 100644 --- a/internal/storage/category.go +++ b/internal/storage/category.go @@ -238,7 +238,7 @@ func (s *Storage) RemoveCategory(userID, categoryID int64) error { func (s *Storage) RemoveAndReplaceCategoriesByName(userid int64, titles []string) error { tx, err := s.db.Begin() if err != nil { - return errors.New("unable to begin transaction") + return errors.New("store: unable to begin transaction") } titleParam := pq.Array(titles) @@ -247,11 +247,11 @@ func (s *Storage) RemoveAndReplaceCategoriesByName(userid int64, titles []string err = tx.QueryRow(query, userid, titleParam).Scan(&count) if err != nil { tx.Rollback() - return errors.New("unable to retrieve category count") + return errors.New("store: unable to retrieve category count") } if count < 1 { tx.Rollback() - return errors.New("at least 1 category must remain after deletion") + return errors.New("store: at least 1 category must remain after deletion") } query = ` @@ -268,14 +268,14 @@ func (s *Storage) RemoveAndReplaceCategoriesByName(userid int64, titles []string _, err = tx.Exec(query, userid, titleParam) if err != nil { tx.Rollback() - return fmt.Errorf("unable to replace categories: %v", err) + return fmt.Errorf("store: unable to replace categories: %v", err) } query = "DELETE FROM categories WHERE user_id = $1 AND title = ANY($2)" _, err = tx.Exec(query, userid, titleParam) if err != nil { tx.Rollback() - return fmt.Errorf("unable to delete categories: %v", err) + return fmt.Errorf("store: unable to delete categories: %v", err) } tx.Commit() return nil diff --git a/internal/storage/entry.go b/internal/storage/entry.go index 718f50d1..e36646b4 100644 --- a/internal/storage/entry.go +++ b/internal/storage/entry.go @@ -7,10 +7,10 @@ import ( "database/sql" "errors" "fmt" + "log/slog" "time" "miniflux.app/v2/internal/crypto" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "github.com/lib/pq" @@ -52,7 +52,10 @@ func (s *Storage) CountUnreadEntries(userID int64) int { n, err := builder.CountEntries() if err != nil { - logger.Error(`store: unable to count unread entries for user #%d: %v`, userID, err) + slog.Error("Unable to count unread entries", + slog.Int64("user_id", userID), + slog.Any("error", err), + ) return 0 } @@ -316,7 +319,11 @@ func (s *Storage) RefreshFeedEntries(userID, feedID int64, entries model.Entries go func() { if err := s.cleanupEntries(feedID, entryHashes); err != nil { - logger.Error(`store: feed #%d: %v`, feedID, err) + slog.Error("Unable to cleanup entries", + slog.Int64("user_id", userID), + slog.Int64("feed_id", feedID), + slog.Any("error", err), + ) } }() @@ -463,7 +470,10 @@ func (s *Storage) MarkAllAsRead(userID int64) error { } count, _ := result.RowsAffected() - logger.Debug("[Storage:MarkAllAsRead] %d items marked as read", count) + slog.Debug("Marked all entries as read", + slog.Int64("user_id", userID), + slog.Int64("nb_entries", count), + ) return nil } @@ -490,7 +500,10 @@ func (s *Storage) MarkGloballyVisibleFeedsAsRead(userID int64) error { } count, _ := result.RowsAffected() - logger.Debug("[Storage:MarkGloballyVisibleFeedsAsRead] %d items marked as read", count) + slog.Debug("Marked globally visible feed entries as read", + slog.Int64("user_id", userID), + slog.Int64("nb_entries", count), + ) return nil } @@ -512,7 +525,11 @@ func (s *Storage) MarkFeedAsRead(userID, feedID int64, before time.Time) error { } count, _ := result.RowsAffected() - logger.Debug("[Storage:MarkFeedAsRead] %d items marked as read", count) + slog.Debug("Marked feed entries as read", + slog.Int64("user_id", userID), + slog.Int64("feed_id", feedID), + slog.Int64("nb_entries", count), + ) return nil } @@ -540,7 +557,11 @@ func (s *Storage) MarkCategoryAsRead(userID, categoryID int64, before time.Time) } count, _ := result.RowsAffected() - logger.Debug("[Storage:MarkCategoryAsRead] %d items marked as read", count) + slog.Debug("Marked category entries as read", + slog.Int64("user_id", userID), + slog.Int64("category_id", categoryID), + slog.Int64("nb_entries", count), + ) return nil } diff --git a/internal/storage/entry_pagination_builder.go b/internal/storage/entry_pagination_builder.go index b4f77c8c..bab478d3 100644 --- a/internal/storage/entry_pagination_builder.go +++ b/internal/storage/entry_pagination_builder.go @@ -7,10 +7,8 @@ import ( "database/sql" "fmt" "strings" - "time" "miniflux.app/v2/internal/model" - "miniflux.app/v2/internal/timer" ) // EntryPaginationBuilder is a builder for entry prev/next queries. @@ -101,8 +99,6 @@ func (e *EntryPaginationBuilder) Entries() (*model.Entry, *model.Entry, error) { } func (e *EntryPaginationBuilder) getPrevNextID(tx *sql.Tx) (prevID int64, nextID int64, err error) { - defer timer.ExecutionTime(time.Now(), fmt.Sprintf("[EntryPaginationBuilder] %v, %v", e.conditions, e.args)) - cte := ` WITH entry_pagination AS ( SELECT diff --git a/internal/storage/feed.go b/internal/storage/feed.go index 5cf32181..b7f52e65 100644 --- a/internal/storage/feed.go +++ b/internal/storage/feed.go @@ -7,11 +7,10 @@ import ( "database/sql" "errors" "fmt" - "runtime" + "log/slog" "sort" "miniflux.app/v2/internal/config" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" ) @@ -432,7 +431,11 @@ func (s *Storage) RemoveFeed(userID, feedID int64) error { return fmt.Errorf(`store: unable to read user feed entry ID: %v`, err) } - logger.Debug(`[FEED DELETION] Deleting entry #%d of feed #%d for user #%d (%d GoRoutines)`, entryID, feedID, userID, runtime.NumGoroutine()) + slog.Debug("Deleting entry", + slog.Int64("user_id", userID), + slog.Int64("feed_id", feedID), + slog.Int64("entry_id", entryID), + ) if _, err := s.db.Exec(`DELETE FROM entries WHERE id=$1 AND user_id=$2`, entryID, userID); err != nil { return fmt.Errorf(`store: unable to delete user feed entries #%d: %v`, entryID, err) diff --git a/internal/storage/user.go b/internal/storage/user.go index 0c5fcad0..bde2bf15 100644 --- a/internal/storage/user.go +++ b/internal/storage/user.go @@ -6,11 +6,11 @@ package storage // import "miniflux.app/v2/internal/storage" import ( "database/sql" "fmt" + "log/slog" "runtime" "strings" "miniflux.app/v2/internal/crypto" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "github.com/lib/pq" @@ -506,14 +506,20 @@ func (s *Storage) RemoveUser(userID int64) error { func (s *Storage) RemoveUserAsync(userID int64) { go func() { if err := s.deleteUserFeeds(userID); err != nil { - logger.Error(`%v`, err) + slog.Error("Unable to delete user feedd", + slog.Int64("user_id", userID), + slog.Any("error", err), + ) return } s.db.Exec(`DELETE FROM users WHERE id=$1`, userID) s.db.Exec(`DELETE FROM integrations WHERE user_id=$1`, userID) - logger.Debug(`[MASS DELETE] User #%d has been deleted (%d GoRoutines)`, userID, runtime.NumGoroutine()) + slog.Debug("User deleted", + slog.Int64("user_id", userID), + slog.Int("goroutines", runtime.NumGoroutine()), + ) }() } @@ -528,7 +534,11 @@ func (s *Storage) deleteUserFeeds(userID int64) error { var feedID int64 rows.Scan(&feedID) - logger.Debug(`[USER DELETION] Deleting feed #%d for user #%d (%d GoRoutines)`, feedID, userID, runtime.NumGoroutine()) + slog.Debug("Deleting feed", + slog.Int64("user_id", userID), + slog.Int64("feed_id", feedID), + slog.Int("goroutines", runtime.NumGoroutine()), + ) if err := s.RemoveFeed(userID, feedID); err != nil { return err diff --git a/internal/template/engine.go b/internal/template/engine.go index a156101d..4104e019 100644 --- a/internal/template/engine.go +++ b/internal/template/engine.go @@ -7,12 +7,12 @@ import ( "bytes" "embed" "html/template" + "log/slog" "strings" "time" "miniflux.app/v2/internal/errors" "miniflux.app/v2/internal/locale" - "miniflux.app/v2/internal/logger" "github.com/gorilla/mux" ) @@ -73,7 +73,10 @@ func (e *Engine) ParseTemplates() error { templateContents.WriteString(commonTemplateContents.String()) templateContents.Write(fileData) - logger.Debug("[Template] Parsing: %s", templateName) + slog.Debug("Parsing template", + slog.String("template_name", templateName), + ) + e.templates[templateName] = template.Must(template.New("main").Funcs(e.funcMap.Map()).Parse(templateContents.String())) } @@ -89,7 +92,9 @@ func (e *Engine) ParseTemplates() error { return err } - logger.Debug("[Template] Parsing: %s", templateName) + slog.Debug("Parsing template", + slog.String("template_name", templateName), + ) e.templates[templateName] = template.Must(template.New("base").Funcs(e.funcMap.Map()).Parse(string(fileData))) } @@ -100,7 +105,7 @@ func (e *Engine) ParseTemplates() error { func (e *Engine) Render(name string, data map[string]interface{}) []byte { tpl, ok := e.templates[name] if !ok { - logger.Fatal("[Template] The template %s does not exists", name) + panic("This template does not exists: " + name) } printer := locale.NewPrinter(data["language"].(string)) @@ -132,7 +137,7 @@ func (e *Engine) Render(name string, data map[string]interface{}) []byte { var b bytes.Buffer err := tpl.ExecuteTemplate(&b, "base", data) if err != nil { - logger.Fatal("[Template] Unable to render template: %v", err) + panic(err) } return b.Bytes() diff --git a/internal/timer/timer.go b/internal/timer/timer.go deleted file mode 100644 index 8122136c..00000000 --- a/internal/timer/timer.go +++ /dev/null @@ -1,16 +0,0 @@ -// SPDX-FileCopyrightText: Copyright The Miniflux Authors. All rights reserved. -// SPDX-License-Identifier: Apache-2.0 - -package timer // import "miniflux.app/v2/internal/timer" - -import ( - "time" - - "miniflux.app/v2/internal/logger" -) - -// ExecutionTime returns the elapsed time of a block of code. -func ExecutionTime(start time.Time, name string) { - elapsed := time.Since(start) - logger.Debug("%s took %s", name, elapsed) -} diff --git a/internal/ui/api_key_remove.go b/internal/ui/api_key_remove.go index c478cd98..3730240c 100644 --- a/internal/ui/api_key_remove.go +++ b/internal/ui/api_key_remove.go @@ -9,14 +9,14 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" ) func (h *handler) removeAPIKey(w http.ResponseWriter, r *http.Request) { keyID := request.RouteInt64Param(r, "keyID") err := h.store.RemoveAPIKey(request.UserID(r), keyID) if err != nil { - logger.Error("[UI:RemoveAPIKey] %v", err) + html.ServerError(w, r, err) + return } html.Redirect(w, r, route.Path(h.router, "apiKeys")) diff --git a/internal/ui/api_key_save.go b/internal/ui/api_key_save.go index f311e311..ebadd300 100644 --- a/internal/ui/api_key_save.go +++ b/internal/ui/api_key_save.go @@ -9,7 +9,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/ui/form" "miniflux.app/v2/internal/ui/session" @@ -47,9 +46,7 @@ func (h *handler) saveAPIKey(w http.ResponseWriter, r *http.Request) { apiKey := model.NewAPIKey(user.ID, apiKeyForm.Description) if err = h.store.CreateAPIKey(apiKey); err != nil { - logger.Error("[UI:SaveAPIKey] %v", err) - view.Set("errorMessage", "error.unable_to_create_api_key") - html.OK(w, r, view.Render("create_api_key")) + html.ServerError(w, r, err) return } diff --git a/internal/ui/category_save.go b/internal/ui/category_save.go index bfdd3afe..e4708b5a 100644 --- a/internal/ui/category_save.go +++ b/internal/ui/category_save.go @@ -9,7 +9,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/ui/form" "miniflux.app/v2/internal/ui/session" @@ -43,9 +42,7 @@ func (h *handler) saveCategory(w http.ResponseWriter, r *http.Request) { } if _, err = h.store.CreateCategory(loggedUser.ID, categoryRequest); err != nil { - logger.Error("[UI:SaveCategory] %v", err) - view.Set("errorMessage", "error.unable_to_create_category") - html.OK(w, r, view.Render("create_category")) + html.ServerError(w, r, err) return } diff --git a/internal/ui/category_update.go b/internal/ui/category_update.go index 5a8483fa..8dad9375 100644 --- a/internal/ui/category_update.go +++ b/internal/ui/category_update.go @@ -9,7 +9,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/ui/form" "miniflux.app/v2/internal/ui/session" @@ -60,9 +59,7 @@ func (h *handler) updateCategory(w http.ResponseWriter, r *http.Request) { categoryRequest.Patch(category) if err := h.store.UpdateCategory(category); err != nil { - logger.Error("[UI:UpdateCategory] %v", err) - view.Set("errorMessage", "error.unable_to_update_category") - html.OK(w, r, view.Render("edit_category")) + html.ServerError(w, r, err) return } diff --git a/internal/ui/feed_refresh.go b/internal/ui/feed_refresh.go index 22f87d01..11c5cff5 100644 --- a/internal/ui/feed_refresh.go +++ b/internal/ui/feed_refresh.go @@ -4,12 +4,12 @@ package ui // import "miniflux.app/v2/internal/ui" import ( + "log/slog" "net/http" "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" feedHandler "miniflux.app/v2/internal/reader/handler" ) @@ -17,7 +17,12 @@ func (h *handler) refreshFeed(w http.ResponseWriter, r *http.Request) { feedID := request.RouteInt64Param(r, "feedID") forceRefresh := request.QueryBoolParam(r, "forceRefresh", false) if err := feedHandler.RefreshFeed(h.store, request.UserID(r), feedID, forceRefresh); err != nil { - logger.Error("[UI:RefreshFeed] %v", err) + slog.Warn("Unable to refresh feed", + slog.Int64("user_id", request.UserID(r)), + slog.Int64("feed_id", feedID), + slog.Bool("force_refresh", forceRefresh), + slog.Any("error", err), + ) } html.Redirect(w, r, route.Path(h.router, "feedEntries", "feedID", feedID)) diff --git a/internal/ui/feed_update.go b/internal/ui/feed_update.go index cdefab35..773c61b2 100644 --- a/internal/ui/feed_update.go +++ b/internal/ui/feed_update.go @@ -10,7 +10,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/ui/form" "miniflux.app/v2/internal/ui/session" @@ -74,9 +73,7 @@ func (h *handler) updateFeed(w http.ResponseWriter, r *http.Request) { err = h.store.UpdateFeed(feedForm.Merge(feed)) if err != nil { - logger.Error("[UI:UpdateFeed] %v", err) - view.Set("errorMessage", "error.unable_to_update_feed") - html.OK(w, r, view.Render("edit_feed")) + html.ServerError(w, r, err) return } diff --git a/internal/ui/integration_pocket.go b/internal/ui/integration_pocket.go index 752394f5..7da6b072 100644 --- a/internal/ui/integration_pocket.go +++ b/internal/ui/integration_pocket.go @@ -4,6 +4,7 @@ package ui // import "miniflux.app/v2/internal/ui" import ( + "log/slog" "net/http" "miniflux.app/v2/internal/config" @@ -12,7 +13,6 @@ import ( "miniflux.app/v2/internal/http/route" "miniflux.app/v2/internal/integration/pocket" "miniflux.app/v2/internal/locale" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/ui/session" ) @@ -35,7 +35,10 @@ func (h *handler) pocketAuthorize(w http.ResponseWriter, r *http.Request) { redirectURL := config.Opts.RootURL() + route.Path(h.router, "pocketCallback") requestToken, err := connector.RequestToken(redirectURL) if err != nil { - logger.Error("[Pocket:Authorize] %v", err) + slog.Warn("Pocket authorization request failed", + slog.Any("user_id", user.ID), + slog.Any("error", err), + ) sess.NewFlashErrorMessage(printer.Printf("error.pocket_request_token")) html.Redirect(w, r, route.Path(h.router, "integrations")) return @@ -64,7 +67,10 @@ func (h *handler) pocketCallback(w http.ResponseWriter, r *http.Request) { connector := pocket.NewConnector(config.Opts.PocketConsumerKey(integration.PocketConsumerKey)) accessToken, err := connector.AccessToken(request.PocketRequestToken(r)) if err != nil { - logger.Error("[Pocket:Callback] %v", err) + slog.Warn("Unable to get Pocket access token", + slog.Any("user_id", user.ID), + slog.Any("error", err), + ) sess.NewFlashErrorMessage(printer.Printf("error.pocket_access_token")) html.Redirect(w, r, route.Path(h.router, "integrations")) return diff --git a/internal/ui/login_check.go b/internal/ui/login_check.go index ba15b7c6..9ae56c47 100644 --- a/internal/ui/login_check.go +++ b/internal/ui/login_check.go @@ -4,6 +4,7 @@ package ui // import "miniflux.app/v2/internal/ui" import ( + "log/slog" "net/http" "miniflux.app/v2/internal/config" @@ -11,7 +12,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/ui/form" "miniflux.app/v2/internal/ui/session" "miniflux.app/v2/internal/ui/view" @@ -27,13 +27,25 @@ func (h *handler) checkLogin(w http.ResponseWriter, r *http.Request) { view.Set("form", authForm) if err := authForm.Validate(); err != nil { - logger.Error("[UI:CheckLogin] %v", err) + slog.Warn("Validation error during login check", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.String("username", authForm.Username), + slog.Any("error", err), + ) html.OK(w, r, view.Render("login")) return } if err := h.store.CheckPassword(authForm.Username, authForm.Password); err != nil { - logger.Error("[UI:CheckLogin] [ClientIP=%s] %v", clientIP, err) + slog.Warn("Incorrect username or password", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.String("username", authForm.Username), + slog.Any("error", err), + ) html.OK(w, r, view.Render("login")) return } @@ -44,7 +56,14 @@ func (h *handler) checkLogin(w http.ResponseWriter, r *http.Request) { return } - logger.Info("[UI:CheckLogin] username=%s just logged in", authForm.Username) + slog.Info("User authenticated successfully with username/password", + slog.Bool("authentication_successful", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", userID), + slog.String("username", authForm.Username), + ) + h.store.SetLastLogin(userID) user, err := h.store.UserByID(userID) diff --git a/internal/ui/logout.go b/internal/ui/logout.go index 40e51b0d..92896050 100644 --- a/internal/ui/logout.go +++ b/internal/ui/logout.go @@ -11,7 +11,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/ui/session" ) @@ -27,7 +26,8 @@ func (h *handler) logout(w http.ResponseWriter, r *http.Request) { sess.SetTheme(user.Theme) if err := h.store.RemoveUserSessionByToken(user.ID, request.UserSessionToken(r)); err != nil { - logger.Error("[UI:Logout] %v", err) + html.ServerError(w, r, err) + return } http.SetCookie(w, cookie.Expired( diff --git a/internal/ui/middleware.go b/internal/ui/middleware.go index e06fb98e..7df1c6af 100644 --- a/internal/ui/middleware.go +++ b/internal/ui/middleware.go @@ -6,6 +6,7 @@ package ui // import "miniflux.app/v2/internal/ui" import ( "context" "errors" + "log/slog" "net/http" "miniflux.app/v2/internal/config" @@ -13,7 +14,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/storage" "miniflux.app/v2/internal/ui/session" @@ -38,11 +38,17 @@ func (m *middleware) handleUserSession(next http.Handler) http.Handler { if m.isPublicRoute(r) { next.ServeHTTP(w, r) } else { - logger.Debug("[UI:UserSession] Session not found, redirect to login page") + slog.Debug("Redirecting to login page because no user session has been found", + slog.Any("url", r.RequestURI), + ) html.Redirect(w, r, route.Path(m.router, "login")) } } else { - logger.Debug("[UI:UserSession] %s", session) + slog.Debug("User session found", + slog.Any("url", r.RequestURI), + slog.Int64("user_id", session.UserID), + slog.Int64("user_session_id", session.ID), + ) ctx := r.Context() ctx = context.WithValue(ctx, request.UserIDContextKey, session.UserID) @@ -62,14 +68,16 @@ func (m *middleware) handleAppSession(next http.Handler) http.Handler { if session == nil { if request.IsAuthenticated(r) { userID := request.UserID(r) - logger.Debug("[UI:AppSession] Cookie expired but user #%d is logged: creating a new session", userID) + slog.Debug("Cookie expired but user is logged: creating a new app session", + slog.Int64("user_id", userID), + ) session, err = m.store.CreateAppSessionWithUserPrefs(userID) if err != nil { html.ServerError(w, r, err) return } } else { - logger.Debug("[UI:AppSession] Session not found, creating a new one") + slog.Debug("App session not found, creating a new one") session, err = m.store.CreateAppSession() if err != nil { html.ServerError(w, r, err) @@ -78,8 +86,6 @@ func (m *middleware) handleAppSession(next http.Handler) http.Handler { } http.SetCookie(w, cookie.New(cookie.CookieAppSessionID, session.ID, config.Opts.HTTPS, config.Opts.BasePath())) - } else { - logger.Debug("[UI:AppSession] %s", session) } if r.Method == http.MethodPost { @@ -87,7 +93,11 @@ func (m *middleware) handleAppSession(next http.Handler) http.Handler { headerValue := r.Header.Get("X-Csrf-Token") if session.Data.CSRF != formValue && session.Data.CSRF != headerValue { - logger.Error(`[UI:AppSession] Invalid or missing CSRF token: Form="%s", Header="%s"`, formValue, headerValue) + slog.Warn("Invalid or missing CSRF token", + slog.Any("url", r.RequestURI), + slog.String("form_csrf", formValue), + slog.String("header_csrf", headerValue), + ) if mux.CurrentRoute(r).GetName() == "checkLogin" { html.Redirect(w, r, route.Path(m.router, "login")) @@ -121,7 +131,10 @@ func (m *middleware) getAppSessionValueFromCookie(r *http.Request) *model.Sessio session, err := m.store.AppSession(cookieValue) if err != nil { - logger.Error("[UI:AppSession] %v", err) + slog.Debug("Unable to fetch app session from the database; another session will be created", + slog.Any("cookie_value", cookieValue), + slog.Any("error", err), + ) return nil } @@ -159,7 +172,10 @@ func (m *middleware) getUserSessionFromCookie(r *http.Request) *model.UserSessio session, err := m.store.UserSessionByToken(cookieValue) if err != nil { - logger.Error("[UI:UserSession] %v", err) + slog.Error("Unable to fetch user session from the database", + slog.Any("cookie_value", cookieValue), + slog.Any("error", err), + ) return nil } @@ -180,7 +196,11 @@ func (m *middleware) handleAuthProxy(next http.Handler) http.Handler { } clientIP := request.ClientIP(r) - logger.Info("[AuthProxy] [ClientIP=%s] Received authenticated requested for %q", clientIP, username) + slog.Debug("[AuthProxy] Received authenticated requested", + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.String("username", username), + ) user, err := m.store.UserByUsername(username) if err != nil { @@ -189,9 +209,13 @@ func (m *middleware) handleAuthProxy(next http.Handler) http.Handler { } if user == nil { - logger.Error("[AuthProxy] [ClientIP=%s] %q doesn't exist", clientIP, username) - if !config.Opts.IsAuthProxyUserCreationAllowed() { + slog.Debug("[AuthProxy] User doesn't exist and user creation is not allowed", + slog.Bool("authentication_failed", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.String("username", username), + ) html.Forbidden(w, r) return } @@ -208,7 +232,13 @@ func (m *middleware) handleAuthProxy(next http.Handler) http.Handler { return } - logger.Info("[AuthProxy] [ClientIP=%s] username=%s just logged in", clientIP, user.Username) + slog.Info("[AuthProxy] User authenticated successfully", + slog.Bool("authentication_successful", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", user.ID), + slog.String("username", user.Username), + ) m.store.SetLastLogin(user.ID) diff --git a/internal/ui/oauth2_callback.go b/internal/ui/oauth2_callback.go index 01e7abdc..4810afab 100644 --- a/internal/ui/oauth2_callback.go +++ b/internal/ui/oauth2_callback.go @@ -6,6 +6,7 @@ package ui // import "miniflux.app/v2/internal/ui" import ( "crypto/subtle" "errors" + "log/slog" "net/http" "miniflux.app/v2/internal/config" @@ -14,7 +15,6 @@ import ( "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" "miniflux.app/v2/internal/locale" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/ui/session" ) @@ -26,41 +26,48 @@ func (h *handler) oauth2Callback(w http.ResponseWriter, r *http.Request) { provider := request.RouteStringParam(r, "provider") if provider == "" { - logger.Error("[OAuth2] Invalid or missing provider") + slog.Warn("Invalid or missing OAuth2 provider") html.Redirect(w, r, route.Path(h.router, "login")) return } code := request.QueryStringParam(r, "code", "") if code == "" { - logger.Error("[OAuth2] No code received on callback") + slog.Warn("No code received on OAuth2 callback") html.Redirect(w, r, route.Path(h.router, "login")) return } state := request.QueryStringParam(r, "state", "") if subtle.ConstantTimeCompare([]byte(state), []byte(request.OAuth2State(r))) == 0 { - logger.Error(`[OAuth2] Invalid state value: got "%s" instead of "%s"`, state, request.OAuth2State(r)) + slog.Warn("Invalid OAuth2 state value received", + slog.String("expected", request.OAuth2State(r)), + slog.String("received", state), + ) html.Redirect(w, r, route.Path(h.router, "login")) return } authProvider, err := getOAuth2Manager(r.Context()).FindProvider(provider) if err != nil { - logger.Error("[OAuth2] %v", err) + slog.Error("Unable to initialize OAuth2 provider", + slog.String("provider", provider), + slog.Any("error", err), + ) html.Redirect(w, r, route.Path(h.router, "login")) return } profile, err := authProvider.GetProfile(r.Context(), code, request.OAuth2CodeVerifier(r)) if err != nil { - logger.Error("[OAuth2] %v", err) + slog.Warn("Unable to get OAuth2 profile from provider", + slog.String("provider", provider), + slog.Any("error", err), + ) html.Redirect(w, r, route.Path(h.router, "login")) return } - logger.Info("[OAuth2] [ClientIP=%s] Successful auth for %s", clientIP, profile) - if request.IsAuthenticated(r) { loggedUser, err := h.store.UserByID(request.UserID(r)) if err != nil { @@ -69,7 +76,11 @@ func (h *handler) oauth2Callback(w http.ResponseWriter, r *http.Request) { } if h.store.AnotherUserWithFieldExists(loggedUser.ID, profile.Key, profile.ID) { - logger.Error("[OAuth2] User #%d cannot be associated because it is already associated with another user", loggedUser.ID) + slog.Error("Oauth2 user cannot be associated because it is already associated with another user", + slog.Int64("user_id", loggedUser.ID), + slog.String("oauth2_provider", provider), + slog.String("oauth2_profile_id", profile.ID), + ) sess.NewFlashErrorMessage(printer.Printf("error.duplicate_linked_account")) html.Redirect(w, r, route.Path(h.router, "settings")) return @@ -119,7 +130,13 @@ func (h *handler) oauth2Callback(w http.ResponseWriter, r *http.Request) { return } - logger.Info("[OAuth2] [ClientIP=%s] username=%s (%s) just logged in", clientIP, user.Username, profile) + slog.Info("User authenticated successfully using OAuth2", + slog.Bool("authentication_successful", true), + slog.String("client_ip", clientIP), + slog.String("user_agent", r.UserAgent()), + slog.Int64("user_id", user.ID), + slog.String("username", user.Username), + ) h.store.SetLastLogin(user.ID) sess.SetLanguage(user.Language) diff --git a/internal/ui/oauth2_redirect.go b/internal/ui/oauth2_redirect.go index 622b544c..78f9fd1a 100644 --- a/internal/ui/oauth2_redirect.go +++ b/internal/ui/oauth2_redirect.go @@ -4,12 +4,12 @@ package ui // import "miniflux.app/v2/internal/ui" import ( + "log/slog" "net/http" "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/oauth2" "miniflux.app/v2/internal/ui/session" ) @@ -19,14 +19,17 @@ func (h *handler) oauth2Redirect(w http.ResponseWriter, r *http.Request) { provider := request.RouteStringParam(r, "provider") if provider == "" { - logger.Error("[OAuth2] Invalid or missing provider: %s", provider) + slog.Warn("Invalid or missing OAuth2 provider") html.Redirect(w, r, route.Path(h.router, "login")) return } authProvider, err := getOAuth2Manager(r.Context()).FindProvider(provider) if err != nil { - logger.Error("[OAuth2] %v", err) + slog.Error("Unable to initialize OAuth2 provider", + slog.String("provider", provider), + slog.Any("error", err), + ) html.Redirect(w, r, route.Path(h.router, "login")) return } diff --git a/internal/ui/oauth2_unlink.go b/internal/ui/oauth2_unlink.go index 6fe44cbb..8a698a3e 100644 --- a/internal/ui/oauth2_unlink.go +++ b/internal/ui/oauth2_unlink.go @@ -4,13 +4,13 @@ package ui // import "miniflux.app/v2/internal/ui" import ( + "log/slog" "net/http" "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" "miniflux.app/v2/internal/locale" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/ui/session" ) @@ -18,14 +18,17 @@ func (h *handler) oauth2Unlink(w http.ResponseWriter, r *http.Request) { printer := locale.NewPrinter(request.UserLanguage(r)) provider := request.RouteStringParam(r, "provider") if provider == "" { - logger.Info("[OAuth2] Invalid or missing provider") + slog.Warn("Invalid or missing OAuth2 provider") html.Redirect(w, r, route.Path(h.router, "login")) return } authProvider, err := getOAuth2Manager(r.Context()).FindProvider(provider) if err != nil { - logger.Error("[OAuth2] %v", err) + slog.Error("Unable to initialize OAuth2 provider", + slog.String("provider", provider), + slog.Any("error", err), + ) html.Redirect(w, r, route.Path(h.router, "settings")) return } diff --git a/internal/ui/opml_upload.go b/internal/ui/opml_upload.go index 0d7c0507..0121952a 100644 --- a/internal/ui/opml_upload.go +++ b/internal/ui/opml_upload.go @@ -4,6 +4,7 @@ package ui // import "miniflux.app/v2/internal/ui" import ( + "log/slog" "net/http" "miniflux.app/v2/internal/config" @@ -11,14 +12,14 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/reader/opml" "miniflux.app/v2/internal/ui/session" "miniflux.app/v2/internal/ui/view" ) func (h *handler) uploadOPML(w http.ResponseWriter, r *http.Request) { - user, err := h.store.UserByID(request.UserID(r)) + loggedUserID := request.UserID(r) + user, err := h.store.UserByID(loggedUserID) if err != nil { html.ServerError(w, r, err) return @@ -26,17 +27,20 @@ func (h *handler) uploadOPML(w http.ResponseWriter, r *http.Request) { file, fileHeader, err := r.FormFile("file") if err != nil { - logger.Error("[UI:UploadOPML] %v", err) + slog.Error("OPML file upload error", + slog.Int64("user_id", loggedUserID), + slog.Any("error", err), + ) + html.Redirect(w, r, route.Path(h.router, "import")) return } defer file.Close() - logger.Debug( - "[UI:UploadOPML] User #%d uploaded this file: %s (%d bytes)", - user.ID, - fileHeader.Filename, - fileHeader.Size, + slog.Info("OPML file uploaded", + slog.Int64("user_id", loggedUserID), + slog.String("file_name", fileHeader.Filename), + slog.Int64("file_size", fileHeader.Size), ) sess := session.New(h.store, request.SessionID(r)) @@ -62,7 +66,8 @@ func (h *handler) uploadOPML(w http.ResponseWriter, r *http.Request) { } func (h *handler) fetchOPML(w http.ResponseWriter, r *http.Request) { - user, err := h.store.UserByID(request.UserID(r)) + loggedUserID := request.UserID(r) + user, err := h.store.UserByID(loggedUserID) if err != nil { html.ServerError(w, r, err) return @@ -74,10 +79,9 @@ func (h *handler) fetchOPML(w http.ResponseWriter, r *http.Request) { return } - logger.Debug( - "[UI:FetchOPML] User #%d fetching this URL: %s", - user.ID, - url, + slog.Info("Fetching OPML file remotely", + slog.Int64("user_id", loggedUserID), + slog.String("opml_file_url", url), ) sess := session.New(h.store, request.SessionID(r)) diff --git a/internal/ui/proxy.go b/internal/ui/proxy.go index ce0c39b1..1af18ec1 100644 --- a/internal/ui/proxy.go +++ b/internal/ui/proxy.go @@ -8,6 +8,7 @@ import ( "crypto/sha256" "encoding/base64" "errors" + "log/slog" "net/http" "time" @@ -16,7 +17,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response" "miniflux.app/v2/internal/http/response/html" - "miniflux.app/v2/internal/logger" ) func (h *handler) mediaProxy(w http.ResponseWriter, r *http.Request) { @@ -29,19 +29,19 @@ func (h *handler) mediaProxy(w http.ResponseWriter, r *http.Request) { encodedDigest := request.RouteStringParam(r, "encodedDigest") encodedURL := request.RouteStringParam(r, "encodedURL") if encodedURL == "" { - html.BadRequest(w, r, errors.New("No URL provided")) + html.BadRequest(w, r, errors.New("no URL provided")) return } decodedDigest, err := base64.URLEncoding.DecodeString(encodedDigest) if err != nil { - html.BadRequest(w, r, errors.New("Unable to decode this Digest")) + html.BadRequest(w, r, errors.New("unable to decode this digest")) return } decodedURL, err := base64.URLEncoding.DecodeString(encodedURL) if err != nil { - html.BadRequest(w, r, errors.New("Unable to decode this URL")) + html.BadRequest(w, r, errors.New("unable to decode this URL")) return } @@ -55,7 +55,9 @@ func (h *handler) mediaProxy(w http.ResponseWriter, r *http.Request) { } mediaURL := string(decodedURL) - logger.Debug(`[Proxy] Fetching %q`, mediaURL) + slog.Debug("MediaProxy: Fetching remote resource", + slog.String("media_url", mediaURL), + ) req, err := http.NewRequest("GET", mediaURL, nil) if err != nil { @@ -82,19 +84,28 @@ func (h *handler) mediaProxy(w http.ResponseWriter, r *http.Request) { resp, err := clt.Do(req) if err != nil { - logger.Error(`[Proxy] Unable to initialize HTTP client: %v`, err) + slog.Error("MediaProxy: Unable to initialize HTTP client", + slog.String("media_url", mediaURL), + slog.Any("error", err), + ) http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError) return } defer resp.Body.Close() if resp.StatusCode == http.StatusRequestedRangeNotSatisfiable { - logger.Error(`[Proxy] Status Code is %d for URL %q`, resp.StatusCode, mediaURL) + slog.Warn("MediaProxy: "+http.StatusText(http.StatusRequestedRangeNotSatisfiable), + slog.String("media_url", mediaURL), + slog.Int("status_code", resp.StatusCode), + ) html.RequestedRangeNotSatisfiable(w, r, resp.Header.Get("Content-Range")) return } if resp.StatusCode != http.StatusOK && resp.StatusCode != http.StatusPartialContent { - logger.Error(`[Proxy] Status Code is %d for URL %q`, resp.StatusCode, mediaURL) + slog.Warn("MediaProxy: Unexpected response status code", + slog.String("media_url", mediaURL), + slog.Int("status_code", resp.StatusCode), + ) html.NotFound(w, r) return } diff --git a/internal/ui/session_remove.go b/internal/ui/session_remove.go index 59e58881..84ed63b9 100644 --- a/internal/ui/session_remove.go +++ b/internal/ui/session_remove.go @@ -9,14 +9,14 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" ) func (h *handler) removeSession(w http.ResponseWriter, r *http.Request) { sessionID := request.RouteInt64Param(r, "sessionID") err := h.store.RemoveUserSessionByID(request.UserID(r), sessionID) if err != nil { - logger.Error("[UI:RemoveSession] %v", err) + html.ServerError(w, r, err) + return } html.Redirect(w, r, route.Path(h.router, "sessions")) diff --git a/internal/ui/settings_update.go b/internal/ui/settings_update.go index 9bd51552..a9a8b519 100644 --- a/internal/ui/settings_update.go +++ b/internal/ui/settings_update.go @@ -10,7 +10,6 @@ import ( "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" "miniflux.app/v2/internal/locale" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/ui/form" "miniflux.app/v2/internal/ui/session" @@ -74,9 +73,7 @@ func (h *handler) updateSettings(w http.ResponseWriter, r *http.Request) { err = h.store.UpdateUser(settingsForm.Merge(loggedUser)) if err != nil { - logger.Error("[UI:UpdateSettings] %v", err) - view.Set("errorMessage", "error.unable_to_update_user") - html.OK(w, r, view.Render("settings")) + html.ServerError(w, r, err) return } diff --git a/internal/ui/subscription_submit.go b/internal/ui/subscription_submit.go index 42a5c8e6..75774c2e 100644 --- a/internal/ui/subscription_submit.go +++ b/internal/ui/subscription_submit.go @@ -10,7 +10,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" feedHandler "miniflux.app/v2/internal/reader/handler" "miniflux.app/v2/internal/reader/subscription" @@ -61,15 +60,12 @@ func (h *handler) submitSubscription(w http.ResponseWriter, r *http.Request) { subscriptionForm.AllowSelfSignedCertificates, ) if findErr != nil { - logger.Error("[UI:SubmitSubscription] %q -> %s", subscriptionForm.URL, findErr) v.Set("form", subscriptionForm) v.Set("errorMessage", findErr) html.OK(w, r, v.Render("add_subscription")) return } - logger.Debug("[UI:SubmitSubscription] %s", subscriptions) - n := len(subscriptions) switch { case n == 0: diff --git a/internal/ui/ui.go b/internal/ui/ui.go index 3acc32ad..64149658 100644 --- a/internal/ui/ui.go +++ b/internal/ui/ui.go @@ -6,7 +6,6 @@ package ui // import "miniflux.app/v2/internal/ui" import ( "net/http" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/storage" "miniflux.app/v2/internal/template" "miniflux.app/v2/internal/worker" @@ -20,7 +19,7 @@ func Serve(router *mux.Router, store *storage.Storage, pool *worker.Pool) { templateEngine := template.NewEngine(router) if err := templateEngine.ParseTemplates(); err != nil { - logger.Fatal(`Unable to parse templates: %v`, err) + panic(err) } handler := &handler{router, store, templateEngine, pool} diff --git a/internal/ui/user_remove.go b/internal/ui/user_remove.go index eab3eec4..bd2a9caf 100644 --- a/internal/ui/user_remove.go +++ b/internal/ui/user_remove.go @@ -37,7 +37,7 @@ func (h *handler) removeUser(w http.ResponseWriter, r *http.Request) { } if selectedUser.ID == loggedUser.ID { - html.BadRequest(w, r, errors.New("You cannot remove yourself")) + html.BadRequest(w, r, errors.New("you cannot remove yourself")) return } diff --git a/internal/ui/user_save.go b/internal/ui/user_save.go index 79b4bc36..982c4973 100644 --- a/internal/ui/user_save.go +++ b/internal/ui/user_save.go @@ -9,7 +9,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/model" "miniflux.app/v2/internal/ui/form" "miniflux.app/v2/internal/ui/session" @@ -64,9 +63,7 @@ func (h *handler) saveUser(w http.ResponseWriter, r *http.Request) { } if _, err := h.store.CreateUser(userCreationRequest); err != nil { - logger.Error("[UI:SaveUser] %v", err) - view.Set("errorMessage", "error.unable_to_create_user") - html.OK(w, r, view.Render("create_user")) + html.ServerError(w, r, err) return } diff --git a/internal/ui/user_update.go b/internal/ui/user_update.go index a3eb5b8d..3e4229c1 100644 --- a/internal/ui/user_update.go +++ b/internal/ui/user_update.go @@ -9,7 +9,6 @@ import ( "miniflux.app/v2/internal/http/request" "miniflux.app/v2/internal/http/response/html" "miniflux.app/v2/internal/http/route" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/ui/form" "miniflux.app/v2/internal/ui/session" "miniflux.app/v2/internal/ui/view" @@ -64,9 +63,7 @@ func (h *handler) updateUser(w http.ResponseWriter, r *http.Request) { userForm.Merge(selectedUser) if err := h.store.UpdateUser(selectedUser); err != nil { - logger.Error("[UI:UpdateUser] %v", err) - view.Set("errorMessage", "error.unable_to_update_user") - html.OK(w, r, view.Render("edit_user")) + html.ServerError(w, r, err) return } diff --git a/internal/worker/worker.go b/internal/worker/worker.go index 8cd59a56..d7cd2e8c 100644 --- a/internal/worker/worker.go +++ b/internal/worker/worker.go @@ -4,10 +4,10 @@ package worker // import "miniflux.app/v2/internal/worker" import ( + "log/slog" "time" "miniflux.app/v2/internal/config" - "miniflux.app/v2/internal/logger" "miniflux.app/v2/internal/metric" "miniflux.app/v2/internal/model" feedHandler "miniflux.app/v2/internal/reader/handler" @@ -22,11 +22,17 @@ type Worker struct { // Run wait for a job and refresh the given feed. func (w *Worker) Run(c chan model.Job) { - logger.Debug("[Worker] #%d started", w.id) + slog.Debug("Worker started", + slog.Int("worker_id", w.id), + ) for { job := <-c - logger.Debug("[Worker #%d] Received feed #%d for user #%d", w.id, job.FeedID, job.UserID) + slog.Debug("Job received by worker", + slog.Int("worker_id", w.id), + slog.Int64("user_id", job.UserID), + slog.Int64("feed_id", job.FeedID), + ) startTime := time.Now() refreshErr := feedHandler.RefreshFeed(w.store, job.UserID, job.FeedID, false) @@ -40,7 +46,11 @@ func (w *Worker) Run(c chan model.Job) { } if refreshErr != nil { - logger.Error("[Worker] Refreshing the feed #%d returned this error: %v", job.FeedID, refreshErr) + slog.Warn("Unable to refresh a feed", + slog.Int64("user_id", job.UserID), + slog.Int64("feed_id", job.FeedID), + slog.Any("error", refreshErr), + ) } } } @@ -1,5 +1,5 @@ .\" Manpage for miniflux. -.TH "MINIFLUX" "1" "July 21, 2023" "\ \&" "\ \&" +.TH "MINIFLUX" "1" "September 24, 2023" "\ \&" "\ \&" .SH NAME miniflux \- Minimalist and opinionated feed reader @@ -36,7 +36,7 @@ Create admin user\&. .PP .B \-debug .RS 4 -Show debug logs\&. +Set log level to debug\&. .RE .PP .B \-flush-sessions @@ -113,11 +113,6 @@ Environment variables override the values defined in the config file. .SH ENVIRONMENT .TP -.B DEBUG -Set the value to 1 to enable debug logs\&. -.br -Disabled by default\&. -.TP .B FETCH_ODYSEE_WATCH_TIME Set the value to 1 to scrape video duration from Odysee website and use it as a reading time\&. @@ -145,6 +140,21 @@ Display the date and time in log messages\&. .br Disabled by default\&. .TP +.B LOG_FILE +Supported values are "stderr", "stdout", or a file name\&. +.br +Default is "stderr"\&. +.TP +.B LOG_FORMAT +Supported log formats are "text" or "json"\&. +.br +Default is "text"\&. +.TP +.B LOG_LEVEL +Supported values are "debug", "info", "warning", or "error"\&. +.br +Default is "info"\&. +.TP .B WORKER_POOL_SIZE Number of background workers\&. .br |