From ad04d302af94fe3cf8e5a70ebb87af9002da5610 Mon Sep 17 00:00:00 2001 From: Peter H0ffmann Date: Tue, 3 Oct 2023 09:28:28 +0000 Subject: [PATCH] chore: reverse the coupling of module log and config (#1606) This way the config module can already use the log module with the same result (default logging to StdOut with Level INFO, same output as before) but ENV variables can already change the logging of config file related log output). It is now possible to dump as a cronjob without having to filter the default log about the used config file. Also: - all logging modules are now configurable when initializing which makes testing easier - viper dependency removed from logging - log correct settings when configured error level is invalid - deprecation of value "false" for log.standard and log.events (already not mentioned in https://vikunja.io/docs/config-options/) Co-authored-by: Berengar W. Lehr Reviewed-on: https://kolaente.dev/vikunja/api/pulls/1606 Reviewed-by: konrad Co-authored-by: Peter H0ffmann Co-committed-by: Peter H0ffmann --- .golangci.yml | 3 ++ pkg/config/config.go | 21 ++++++++---- pkg/db/db.go | 2 +- pkg/db/test.go | 2 +- pkg/events/events.go | 3 +- pkg/initialize/init.go | 6 ++-- pkg/log/logging.go | 64 ++++++++++++++++++++----------------- pkg/log/mail_logger.go | 16 ++++++---- pkg/log/watermill_logger.go | 15 +++++---- pkg/log/xorm_logger.go | 19 +++++------ pkg/mail/mail.go | 2 +- pkg/migration/migration.go | 2 +- pkg/routes/routes.go | 8 ++--- 13 files changed, 93 insertions(+), 70 deletions(-) diff --git a/.golangci.yml b/.golangci.yml index e0b55c189c2..24c9e5b035a 100644 --- a/.golangci.yml +++ b/.golangci.yml @@ -103,3 +103,6 @@ issues: - text: 'string `labels` has 3 occurrences, make it a constant' linters: - goconst + - text: 'string `off` has 6 occurrences, make it a constant' + linters: + - goconst diff --git a/pkg/config/config.go b/pkg/config/config.go index c8ad843acc2..57f7bef8f76 100644 --- a/pkg/config/config.go +++ b/pkg/config/config.go @@ -19,7 +19,6 @@ package config import ( "crypto/rand" "fmt" - "log" "os" "os/exec" "path" @@ -29,6 +28,7 @@ import ( "time" _ "time/tzdata" // Imports time zone data instead of relying on the os + "code.vikunja.io/api/pkg/log" "github.com/spf13/viper" ) @@ -400,13 +400,17 @@ func InitConfig() { viper.SetEnvKeyReplacer(strings.NewReplacer(".", "_")) viper.AutomaticEnv() + // Just load environment variables + _ = viper.ReadInConfig() + log.ConfigLogger(LogEnabled.GetBool(), LogStandard.GetString(), LogPath.GetString(), LogLevel.GetString()) + // Load the config file viper.AddConfigPath(ServiceRootpath.GetString()) viper.AddConfigPath("/etc/vikunja/") homeDir, err := os.UserHomeDir() if err != nil { - log.Printf("No home directory found, not using config from ~/.config/vikunja/. Error was: %s\n", err.Error()) + log.Debugf("No home directory found, not using config from ~/.config/vikunja/. Error was: %s\n", err.Error()) } else { viper.AddConfigPath(path.Join(homeDir, ".config", "vikunja")) } @@ -415,15 +419,18 @@ func InitConfig() { viper.SetConfigName("config") err = viper.ReadInConfig() + if viper.ConfigFileUsed() != "" { - log.Printf("Using config file: %s", viper.ConfigFileUsed()) + log.Infof("Using config file: %s", viper.ConfigFileUsed()) if err != nil { - log.Println(err.Error()) - log.Println("Using default config.") + log.Warning(err.Error()) + log.Warning("Using default config.") + } else { + log.ConfigLogger(LogEnabled.GetBool(), LogStandard.GetString(), LogPath.GetString(), LogLevel.GetString()) } } else { - log.Println("No config file found, using default or config from environment variables.") + log.Info("No config file found, using default or config from environment variables.") } if RateLimitStore.GetString() == "keyvalue" { @@ -455,7 +462,7 @@ func InitConfig() { } if ServiceEnableMetrics.GetBool() { - log.Println("WARNING: service.enablemetrics is deprecated and will be removed in a future release. Please use metrics.enable.") + log.Warning("service.enablemetrics is deprecated and will be removed in a future release. Please use metrics.enable.") MetricsEnabled.Set(true) } } diff --git a/pkg/db/db.go b/pkg/db/db.go index c46c2bcc351..dba8d7dc052 100644 --- a/pkg/db/db.go +++ b/pkg/db/db.go @@ -79,7 +79,7 @@ func CreateDBEngine() (engine *xorm.Engine, err error) { } engine.SetTZDatabase(loc) engine.SetMapper(names.GonicMapper{}) - logger := log.NewXormLogger("") + logger := log.NewXormLogger(config.LogEnabled.GetBool(), config.LogDatabase.GetString(), config.LogDatabaseLevel.GetString()) engine.SetLogger(logger) x = engine diff --git a/pkg/db/test.go b/pkg/db/test.go index 3be2cb1e928..a375d42187d 100644 --- a/pkg/db/test.go +++ b/pkg/db/test.go @@ -52,7 +52,7 @@ func CreateTestEngine() (engine *xorm.Engine, err error) { } engine.SetMapper(names.GonicMapper{}) - logger := log.NewXormLogger("DEBUG") + logger := log.NewXormLogger(config.LogEnabled.GetBool(), config.LogDatabase.GetString(), "DEBUG") logger.ShowSQL(os.Getenv("UNIT_TESTS_VERBOSE") == "1") engine.SetLogger(logger) engine.SetTZLocation(config.GetTimeZone()) diff --git a/pkg/events/events.go b/pkg/events/events.go index 1613f39af88..69c8cf7555e 100644 --- a/pkg/events/events.go +++ b/pkg/events/events.go @@ -21,6 +21,7 @@ import ( "encoding/json" "time" + "code.vikunja.io/api/pkg/config" "code.vikunja.io/api/pkg/log" vmetrics "code.vikunja.io/api/pkg/metrics" "github.com/ThreeDotsLabs/watermill" @@ -39,7 +40,7 @@ type Event interface { // InitEvents sets up everything needed to work with events func InitEvents() (err error) { - logger := log.NewWatermillLogger() + logger := log.NewWatermillLogger(config.LogEnabled.GetBool(), config.LogEvents.GetString(), config.LogEventsLevel.GetString()) router, err := message.NewRouter( message.RouterConfig{}, diff --git a/pkg/initialize/init.go b/pkg/initialize/init.go index 4ae3fb60b7c..e62b3817545 100644 --- a/pkg/initialize/init.go +++ b/pkg/initialize/init.go @@ -35,6 +35,9 @@ import ( // LightInit will only fullInit config, redis, logger but no db connection. func LightInit() { + // Set logger + log.InitLogger() + // Init the config config.InitConfig() @@ -43,9 +46,6 @@ func LightInit() { // Init keyvalue store keyvalue.InitStorage() - - // Set logger - log.InitLogger() } // InitEngines intializes all db connections diff --git a/pkg/log/logging.go b/pkg/log/logging.go index 1f12d8c2070..66971f4ef82 100644 --- a/pkg/log/logging.go +++ b/pkg/log/logging.go @@ -22,9 +22,7 @@ import ( "strings" "time" - "code.vikunja.io/api/pkg/config" "github.com/op/go-logging" - "github.com/spf13/viper" ) // ErrFmt holds the format for all the console logging @@ -41,42 +39,45 @@ const logModule = `vikunja` // loginstance is the instance of the logger which is used under the hood to log var logInstance = logging.MustGetLogger(logModule) +// logpath is the path in which log files will be written. +// This value is a mere fallback for other modules that could but shouldn't be used before calling ConfigLogger +var logPath = "." + // InitLogger initializes the global log handler func InitLogger() { - if !config.LogEnabled.GetBool() { - // Disable all logging when loggin in general is disabled, overwriting everything a user might have set. - config.LogStandard.Set("off") - config.LogDatabase.Set("off") - config.LogHTTP.Set("off") - config.LogEcho.Set("off") - config.LogEvents.Set("off") - return - } - // This show correct caller functions logInstance.ExtraCalldepth = 1 - if config.LogStandard.GetString() == "file" { - err := os.Mkdir(config.LogPath.GetString(), 0744) - if err != nil && !os.IsExist(err) { - Fatalf("Could not create log folder: %s", err.Error()) - } + // Init with stdout and INFO as default format and level + logBackend := logging.NewLogBackend(os.Stdout, "", 0) + backend := logging.NewBackendFormatter(logBackend, logging.MustStringFormatter(Fmt+"\n")) + + backendLeveled := logging.AddModuleLevel(backend) + backendLeveled.SetLevel(logging.INFO, logModule) + + logInstance.SetBackend(backendLeveled) +} + +// ConfigLogger configures the global log handler +func ConfigLogger(configLogEnabled bool, configLogStandard string, configLogPath string, configLogLevel string) { + lvl := strings.ToUpper(configLogLevel) + level, err := logging.LogLevel(lvl) + if err != nil { + Fatalf("Error setting standard log level %s: %s", lvl, err.Error()) } + logPath = configLogPath + // The backend is the part which actually handles logging the log entries somewhere. - cf := config.LogStandard.GetString() var backend logging.Backend backend = &NoopBackend{} - if cf != "off" && cf != "false" { - stdWriter := GetLogWriter("standard") - - logBackend := logging.NewLogBackend(stdWriter, "", 0) - backend = logging.NewBackendFormatter(logBackend, logging.MustStringFormatter(Fmt+"\n")) + if configLogStandard == "false" { + configLogStandard = "off" + Warning("log.standard value 'false' is deprecated and will be removed in a future release. Please use the value 'off'.") } - - level, err := logging.LogLevel(strings.ToUpper(config.LogLevel.GetString())) - if err != nil { - Fatalf("Error setting database log level: %s", err.Error()) + if configLogEnabled && configLogStandard != "off" { + logBackend := logging.NewLogBackend(GetLogWriter(configLogStandard, "standard"), "", 0) + backend = logging.NewBackendFormatter(logBackend, logging.MustStringFormatter(Fmt+"\n")) } backendLeveled := logging.AddModuleLevel(backend) @@ -86,11 +87,14 @@ func InitLogger() { } // GetLogWriter returns the writer to where the normal log goes, depending on the config -func GetLogWriter(logfile string) (writer io.Writer) { +func GetLogWriter(logfmt string, logfile string) (writer io.Writer) { writer = os.Stdout // Set the default case to prevent nil pointer panics - switch viper.GetString("log." + logfile) { + switch logfmt { case "file": - fullLogFilePath := config.LogPath.GetString() + "/" + logfile + ".log" + if err := os.MkdirAll(logPath, 0744); err != nil { + Fatalf("Could not create log path: %s", err.Error()) + } + fullLogFilePath := logPath + "/" + logfile + ".log" f, err := os.OpenFile(fullLogFilePath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0600) if err != nil { Fatalf("Could not create logfile %s: %s", fullLogFilePath, err.Error()) diff --git a/pkg/log/mail_logger.go b/pkg/log/mail_logger.go index 3cee481ff50..92da2ea0813 100644 --- a/pkg/log/mail_logger.go +++ b/pkg/log/mail_logger.go @@ -20,7 +20,6 @@ import ( "strings" "time" - "code.vikunja.io/api/pkg/config" "github.com/op/go-logging" "xorm.io/xorm/log" ) @@ -33,19 +32,24 @@ type MailLogger struct { const mailFormat = `%{color}%{time:` + time.RFC3339Nano + `}: %{level}` + "\t" + `▶ [MAIL] %{id:03x}%{color:reset} %{message}` const mailLogModule = `vikunja_mail` -func NewMailLogger() *MailLogger { - lvl := strings.ToUpper(config.LogMailLevel.GetString()) +// NewMailLogger creates and initializes a new mail logger +func NewMailLogger(configLogEnabled bool, configLogMail string, configLogMailLevel string) *MailLogger { + lvl := strings.ToUpper(configLogMailLevel) level, err := logging.LogLevel(lvl) if err != nil { - Criticalf("Error setting database log level: %s", err.Error()) + Criticalf("Error setting mail log level %s: %s", lvl, err.Error()) } mailLogger := &MailLogger{ logger: logging.MustGetLogger(mailLogModule), } - logBackend := logging.NewLogBackend(GetLogWriter("mail"), "", 0) - backend := logging.NewBackendFormatter(logBackend, logging.MustStringFormatter(mailFormat+"\n")) + var backend logging.Backend + backend = &NoopBackend{} + if configLogEnabled && configLogMail != "off" { + logBackend := logging.NewLogBackend(GetLogWriter(configLogMail, "mail"), "", 0) + backend = logging.NewBackendFormatter(logBackend, logging.MustStringFormatter(mailFormat+"\n")) + } backendLeveled := logging.AddModuleLevel(backend) backendLeveled.SetLevel(level, mailLogModule) diff --git a/pkg/log/watermill_logger.go b/pkg/log/watermill_logger.go index 4c9681ea2a9..1d9e3ef6928 100644 --- a/pkg/log/watermill_logger.go +++ b/pkg/log/watermill_logger.go @@ -21,7 +21,6 @@ import ( "strings" "time" - "code.vikunja.io/api/pkg/config" "github.com/ThreeDotsLabs/watermill" "github.com/op/go-logging" ) @@ -34,8 +33,9 @@ type WatermillLogger struct { logger *logging.Logger } -func NewWatermillLogger() *WatermillLogger { - lvl := strings.ToUpper(config.LogEventsLevel.GetString()) +// NewXormLogger creates and initializes a new watermill logger +func NewWatermillLogger(configLogEnabled bool, configLogEvents string, configLogEventsLevel string) *WatermillLogger { + lvl := strings.ToUpper(configLogEventsLevel) level, err := logging.LogLevel(lvl) if err != nil { Criticalf("Error setting events log level %s: %s", lvl, err.Error()) @@ -45,11 +45,14 @@ func NewWatermillLogger() *WatermillLogger { logger: logging.MustGetLogger(watermillLogModule), } - cf := config.LogEvents.GetString() var backend logging.Backend backend = &NoopBackend{} - if cf != "off" && cf != "false" { - logBackend := logging.NewLogBackend(GetLogWriter("events"), "", 0) + if configLogEvents == "false" { + configLogEvents = "off" + Warning("log.events value 'false' is deprecated and will be removed in a future release. Please use the value 'off'.") + } + if configLogEnabled && configLogEvents != "off" { + logBackend := logging.NewLogBackend(GetLogWriter(configLogEvents, "events"), "", 0) backend = logging.NewBackendFormatter(logBackend, logging.MustStringFormatter(watermillFmt+"\n")) } diff --git a/pkg/log/xorm_logger.go b/pkg/log/xorm_logger.go index fbcac999153..a987a93bf0e 100644 --- a/pkg/log/xorm_logger.go +++ b/pkg/log/xorm_logger.go @@ -20,7 +20,6 @@ import ( "strings" "time" - "code.vikunja.io/api/pkg/config" "github.com/op/go-logging" "xorm.io/xorm/log" ) @@ -38,21 +37,23 @@ type XormLogger struct { } // NewXormLogger creates and initializes a new xorm logger -func NewXormLogger(lvl string) *XormLogger { - if lvl == "" { - lvl = strings.ToUpper(config.LogDatabaseLevel.GetString()) - } +func NewXormLogger(configLogEnabled bool, configLogDatabase string, configLogDatabaseLevel string) *XormLogger { + lvl := strings.ToUpper(configLogDatabaseLevel) level, err := logging.LogLevel(lvl) if err != nil { - Criticalf("Error setting database log level: %s", err.Error()) + Criticalf("Error setting database log level %s: %s", lvl, err.Error()) } xormLogger := &XormLogger{ logger: logging.MustGetLogger(xormLogModule), } - logBackend := logging.NewLogBackend(GetLogWriter("database"), "", 0) - backend := logging.NewBackendFormatter(logBackend, logging.MustStringFormatter(XormFmt+"\n")) + var backend logging.Backend + backend = &NoopBackend{} + if configLogEnabled && configLogDatabase != "off" { + logBackend := logging.NewLogBackend(GetLogWriter(configLogDatabase, "database"), "", 0) + backend = logging.NewBackendFormatter(logBackend, logging.MustStringFormatter(XormFmt+"\n")) + } backendLeveled := logging.AddModuleLevel(backend) backendLeveled.SetLevel(level, xormLogModule) @@ -64,8 +65,8 @@ func NewXormLogger(lvl string) *XormLogger { case logging.ERROR: xormLogger.level = log.LOG_ERR case logging.WARNING: - case logging.NOTICE: xormLogger.level = log.LOG_WARNING + case logging.NOTICE: case logging.INFO: xormLogger.level = log.LOG_INFO case logging.DEBUG: diff --git a/pkg/mail/mail.go b/pkg/mail/mail.go index 6ba6c1fc67b..1da915cf6c5 100644 --- a/pkg/mail/mail.go +++ b/pkg/mail/mail.go @@ -56,7 +56,7 @@ func getClient() (*mail.Client, error) { ServerName: config.MailerHost.GetString(), }), mail.WithTimeout((config.MailerQueueTimeout.GetDuration() + 3) * time.Second), // 3s more for us to close before mail server timeout - mail.WithLogger(log.NewMailLogger()), + mail.WithLogger(log.NewMailLogger(config.LogEnabled.GetBool(), config.LogMail.GetString(), config.LogMailLevel.GetString())), mail.WithDebugLog(), } diff --git a/pkg/migration/migration.go b/pkg/migration/migration.go index 8cc9d873aef..f21b79b0047 100644 --- a/pkg/migration/migration.go +++ b/pkg/migration/migration.go @@ -56,7 +56,7 @@ func initMigration(x *xorm.Engine) *xormigrate.Xormigrate { }) m := xormigrate.New(x, migrations) - logger := log.NewXormLogger("") + logger := log.NewXormLogger(config.LogEnabled.GetBool(), config.LogEvents.GetString(), config.LogEventsLevel.GetString()) m.SetLogger(logger) m.InitSchema(initSchema) return m diff --git a/pkg/routes/routes.go b/pkg/routes/routes.go index bb1e280ecdc..c3428c47b32 100644 --- a/pkg/routes/routes.go +++ b/pkg/routes/routes.go @@ -95,19 +95,19 @@ func NewEcho() *echo.Echo { e.HideBanner = true if l, ok := e.Logger.(*elog.Logger); ok { - if config.LogEcho.GetString() == "off" { + if !config.LogEnabled.GetBool() || config.LogEcho.GetString() == "off" { l.SetLevel(elog.OFF) } l.EnableColor() l.SetHeader(log.ErrFmt) - l.SetOutput(log.GetLogWriter("echo")) + l.SetOutput(log.GetLogWriter(config.LogEcho.GetString(), "echo")) } // Logger - if config.LogHTTP.GetString() != "off" { + if !config.LogEnabled.GetBool() || config.LogHTTP.GetString() != "off" { e.Use(middleware.LoggerWithConfig(middleware.LoggerConfig{ Format: log.WebFmt + "\n", - Output: log.GetLogWriter("http"), + Output: log.GetLogWriter(config.LogHTTP.GetString(), "http"), })) }