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 <Berengar.Lehr@uni-jena.de> Reviewed-on: vikunja/api#1606 Reviewed-by: konrad <k@knt.li> Co-authored-by: Peter H0ffmann <hoffmannp@noreply.kolaente.de> Co-committed-by: Peter H0ffmann <hoffmannp@noreply.kolaente.de>
2023-10-03 09:28:28 +00:00 · 2023-10-03 09:28:28 +00:00 · ad04d302af
commit ad04d302af
parent c217233e08
13 changed files with 93 additions and 70 deletions
--- 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
--- 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)
 	}
 }
--- 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
--- 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())
--- 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{},
--- 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
--- 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())
--- 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)
--- 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"))
 	}

--- 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:
--- 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(),
 	}

--- 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
--- 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"),
 		}))
 	}