Improve logging handling (#57)

pkg/config/config.go

@@ -56,7 +56,6 @@ func init() {
 	viper.SetDefault("database.password", "")
 	viper.SetDefault("database.database", "vikunja")
 	viper.SetDefault("database.path", "./vikunja.db")
-	viper.SetDefault("database.showqueries", false)
 	viper.SetDefault("database.openconnections", 100)
 	// Cacher
 	viper.SetDefault("cache.enabled", false)
@@ -77,6 +76,14 @@ func init() {
 	viper.SetDefault("redis.host", "localhost:6379")
 	viper.SetDefault("redis.password", "")
 	viper.SetDefault("redis.db", 0)
+	// Logger
+	viper.SetDefault("log.enabled", true)
+	viper.SetDefault("log.errors", "stdout")
+	viper.SetDefault("log.standard", "stdout")
+	viper.SetDefault("log.database", "off")
+	viper.SetDefault("log.http", "stdout")
+	viper.SetDefault("log.echo", "off")
+	viper.SetDefault("log.path", viper.GetString("service.rootpath")+"/logs")
 
 	// Init checking for environment variables
 	viper.SetEnvPrefix("vikunja")

pkg/log/logging.go

@@ -18,19 +18,82 @@ package log
 
 import (
 	"github.com/op/go-logging"
+	"github.com/spf13/viper"
+	"io"
+	"log"
 	"os"
+	"time"
 )
 
+// ErrFmt holds the format for all the console logging
+const ErrFmt = `${time_rfc3339_nano}: ${level} ` + "\t" + `▶ ${prefix} ${short_file}:${line}`
+
+// WebFmt holds the format for all logging related to web requests
+const WebFmt = `${time_rfc3339_nano}: WEB ` + "\t" + `▶ ${remote_ip} ${id} ${method} ${status} ${uri} ${latency_human} - ${user_agent}`
+
+// Fmt is the general log format
+const Fmt = `%{color}%{time:` + time.RFC3339Nano + `}: %{level}` + "\t" + `▶ %{shortpkg}/%{shortfunc} %{id:03x}%{color:reset} %{message}`
+
 // Log is the handler for the logger
 var Log = logging.MustGetLogger("vikunja")
 
-var format = logging.MustStringFormatter(
-	`%{color}%{time:2006-01-02 15:04:05.000} %{shortfunc} ▶ %{level:.4s} %{id:03x}%{color:reset} %{message}`,
-)
-
 // InitLogger initializes the global log handler
 func InitLogger() {
-	backend := logging.NewLogBackend(os.Stderr, "", 0)
-	backendFormatter := logging.NewBackendFormatter(backend, format)
-	logging.SetBackend(backendFormatter)
+	if !viper.GetBool("log.enabled") {
+		// Disable all logging when loggin in general is disabled, overwriting everything a user might have set.
+		viper.Set("log.errors", "off")
+		viper.Set("log.standard", "off")
+		viper.Set("log.database", "off")
+		viper.Set("log.http", "off")
+		viper.Set("log.echo", "off")
+		return
+	}
+
+	if viper.GetString("log.errors") == "file" || viper.GetString("log.standard") == "file" {
+		err := os.Mkdir(viper.GetString("log.path"), 0744)
+		if err != nil && !os.IsExist(err) {
+			log.Fatal("Could not create log folder: ", err.Error())
+		}
+	}
+
+	var logBackends []logging.Backend
+
+	// We define our two backends
+	if viper.GetString("log.standard") != "off" {
+		stdWriter := GetLogWriter("standard")
+		stdBackend := logging.NewLogBackend(stdWriter, "", 0)
+
+		// Set the standard backend
+		logBackends = append(logBackends, logging.NewBackendFormatter(stdBackend, logging.MustStringFormatter(Fmt+"\n")))
+	}
+
+	if viper.GetString("log.error") != "off" {
+		errWriter := GetLogWriter("error")
+		errBackend := logging.NewLogBackend(errWriter, "", 0)
+
+		// Only warnings and more severe messages should go to the error backend
+		errBackendLeveled := logging.AddModuleLevel(errBackend)
+		errBackendLeveled.SetLevel(logging.WARNING, "")
+		logBackends = append(logBackends, errBackendLeveled)
+	}
+
+	// Set our backends
+	logging.SetBackend(logBackends...)
+}
+
+// GetLogWriter returns the writer to where the normal log goes, depending on the config
+func GetLogWriter(logfile string) (writer io.Writer) {
+	switch viper.GetString("log." + logfile) {
+	case "file":
+		f, err := os.OpenFile(viper.GetString("log.path")+"/"+logfile+".log", os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
+		if err != nil {
+			log.Fatal(err)
+		}
+		writer = f
+		break
+	case "stdout":
+	default:
+		writer = os.Stdout
+	}
+	return
 }

pkg/models/models.go

@@ -17,6 +17,7 @@
 package models
 
 import (
+	"code.vikunja.io/api/pkg/log"
 	"encoding/gob"
 	"fmt"
 	_ "github.com/go-sql-driver/mysql" // Because.
@@ -111,7 +112,7 @@ func SetEngine() (err error) {
 			gob.Register(tablesWithPointer) // Need to register tables with pointer as well...
 			break
 		default:
-			fmt.Println("Did not find a valid cache type. Caching disabled. Please refer to the docs for poosible cache types.")
+			log.Log.Info("Did not find a valid cache type. Caching disabled. Please refer to the docs for poosible cache types.")
 		}
 	}
 
@@ -122,7 +123,8 @@ func SetEngine() (err error) {
 		return fmt.Errorf("sync database struct error: %v", err)
 	}
 
-	x.ShowSQL(viper.GetBool("database.showqueries"))
+	x.ShowSQL(viper.GetString("log.database") != "off")
+	x.SetLogger(xorm.NewSimpleLogger(log.GetLogWriter("database")))
 
 	return nil
 }

pkg/routes/routes.go

@@ -49,6 +49,7 @@ import (
 	"github.com/asaskevich/govalidator"
 	"github.com/labstack/echo"
 	"github.com/labstack/echo/middleware"
+	elog "github.com/labstack/gommon/log"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 	"github.com/spf13/viper"
 )
@@ -84,10 +85,22 @@ func NewEcho() *echo.Echo {
 
 	e.HideBanner = true
 
+	if l, ok := e.Logger.(*elog.Logger); ok {
+		if viper.GetString("log.echo") == "off" {
+			l.SetLevel(elog.OFF)
+		}
+		l.EnableColor()
+		l.SetHeader(log.ErrFmt)
+		l.SetOutput(log.GetLogWriter("echo"))
+	}
+
 	// Logger
-	e.Use(middleware.LoggerWithConfig(middleware.LoggerConfig{
-		Format: "${time_rfc3339_nano}: ${remote_ip} ${method} ${status} ${uri} ${latency_human} - ${user_agent}\n",
-	}))
+	if viper.GetString("log.http") != "off" {
+		e.Use(middleware.LoggerWithConfig(middleware.LoggerConfig{
+			Format: log.WebFmt + "\n",
+			Output: log.GetLogWriter("http"),
+		}))
+	}
 
 	// Validation
 	e.Validator = &CustomValidator{}