Added std type to logging level.

Added demux-ing of logging to stdout/err working around
https://github.com/sirupsen/logrus/issues/403

Turned off the default logging in favour of using hooks always.

Added fallback, if no stdout/err logger was configured, add one
automatically. This prevents unexpected lack of logging after an
upgrade in case the user's configuration file is not updated.

Fixes: https://github.com/matrix-org/dendrite/issues/2054
Signed-off-by: Martin Ashby <martin@ashbysoft.com>

dendrite-config.yaml

@@ -370,9 +370,10 @@ tracing:
     baggage_restrictions: null
     throttler: null
 
-# Logging configuration, in addition to the standard logging that is sent to
+# Logging configuration
-# stdout by Dendrite.
 logging:
+- type: std
+  level: info
 - type: file
   level: info
   params:

go.mod

@@ -4,6 +4,7 @@ require (
 	github.com/Arceliar/ironwood v0.0.0-20210619124114-6ad55cae5031
 	github.com/DATA-DOG/go-sqlmock v1.5.0
 	github.com/HdrHistogram/hdrhistogram-go v1.0.1 // indirect
+	github.com/MFAshby/stdemuxerhook v1.0.0 // indirect
 	github.com/Masterminds/semver/v3 v3.1.1
 	github.com/Shopify/sarama v1.29.1
 	github.com/codeclysm/extract v2.2.0+incompatible

go.sum

@@ -59,6 +59,8 @@ github.com/HdrHistogram/hdrhistogram-go v1.0.1 h1:GX8GAYDuhlFQnI2fRDHQhTlkHMz8bE
 github.com/HdrHistogram/hdrhistogram-go v1.0.1/go.mod h1:BWJ+nMSHY3L41Zj7CA3uXnloDp7xxV0YvstAE7nKTaM=
 github.com/Joker/hpp v1.0.0/go.mod h1:8x5n+M1Hp5hC0g8okX3sR3vFQwynaX/UgSOM9MeBKzY=
 github.com/Kubuxu/go-os-helper v0.0.1/go.mod h1:N8B+I7vPCT80IcP58r50u4+gEEcsZETFUpAzWW2ep1Y=
+github.com/MFAshby/stdemuxerhook v1.0.0 h1:1XFGzakrsHMv76AeanPDL26NOgwjPl/OUxbGhJthwMc=
+github.com/MFAshby/stdemuxerhook v1.0.0/go.mod h1:nLMI9FUf9Hz98n+yAXsTMUR4RZQy28uCTLG1Fzvj/uY=
 github.com/Masterminds/semver/v3 v3.1.1 h1:hLg3sBzpNErnxhQtUy/mmLR2I9foDujNK030IGemrRc=
 github.com/Masterminds/semver/v3 v3.1.1/go.mod h1:VPu/7SZ7ePZ3QOrcuXROw5FAcLl4a0cBrbBpGY/8hQs=
 github.com/Microsoft/go-winio v0.4.11/go.mod h1:VhR8bwka0BXejwEJY73c50VrPtXAaKcyvVC4A4RozmA=

internal/log.go

@@ -91,21 +91,6 @@ func SetupPprof() {
 	}
 }
 
-// SetupStdLogging configures the logging format to standard output. Typically, it is called when the config is not yet loaded.
-func SetupStdLogging() {
-	logrus.SetReportCaller(true)
-	logrus.SetFormatter(&utcFormatter{
-		&logrus.TextFormatter{
-			TimestampFormat:  "2006-01-02T15:04:05.000000000Z07:00",
-			FullTimestamp:    true,
-			DisableColors:    false,
-			DisableTimestamp: false,
-			QuoteEmptyFields: true,
-			CallerPrettyfier: callerPrettyfier,
-		},
-	})
-}
-
 // File type hooks should be provided a path to a directory to store log files
 func checkFileHookParams(params map[string]interface{}) {
 	path, ok := params["path"]

internal/log_unix.go

@@ -17,18 +17,31 @@
 package internal
 
 import (
+	"io/ioutil"
 	"log/syslog"
 
+	"github.com/MFAshby/stdemuxerhook"
 	"github.com/matrix-org/dendrite/setup/config"
 	"github.com/sirupsen/logrus"
 	lSyslog "github.com/sirupsen/logrus/hooks/syslog"
 )
 
-// SetupHookLogging configures the logging hooks defined in the configuration.
+// SetupLogging configures the logging hooks defined in the configuration.
 // If something fails here it means that the logging was improperly configured,
 // so we just exit with the error
-func SetupHookLogging(hooks []config.LogrusHook, componentName string) {
+func SetupLogging(hooks []config.LogrusHook, componentName string) {
 	logrus.SetReportCaller(true)
+	logrus.SetFormatter(&utcFormatter{
+		&logrus.TextFormatter{
+			TimestampFormat:  "2006-01-02T15:04:05.000000000Z07:00",
+			FullTimestamp:    true,
+			DisableColors:    false,
+			DisableTimestamp: false,
+			QuoteEmptyFields: true,
+			CallerPrettyfier: callerPrettyfier,
+		},
+	})
+	stdLogAdded := false
 	for _, hook := range hooks {
 		// Check we received a proper logging level
 		level, err := logrus.ParseLevel(hook.Level)
@@ -49,10 +62,19 @@ func SetupHookLogging(hooks []config.LogrusHook, componentName string) {
 		case "syslog":
 			checkSyslogHookParams(hook.Params)
 			setupSyslogHook(hook, level, componentName)
+		case "std":
+			setupStdLogHook(level)
+			stdLogAdded = true
 		default:
 			logrus.Fatalf("Unrecognised logging hook type: %s", hook.Type)
 		}
 	}
+	if !stdLogAdded {
+		logrus.Info("No std logger config found. Enabling at INFO level by default")
+		setupStdLogHook(logrus.InfoLevel)
+	}
+	// Hooks are now configured for stdout/err, so throw away the default logger output
+	logrus.SetOutput(ioutil.Discard)
 }
 
 func checkSyslogHookParams(params map[string]interface{}) {
@@ -76,6 +98,10 @@ func checkSyslogHookParams(params map[string]interface{}) {
 
 }
 
+func setupStdLogHook(level logrus.Level) {
+	logrus.AddHook(&logLevelHook{level, stdemuxerhook.New(logrus.StandardLogger())})
+}
+
 func setupSyslogHook(hook config.LogrusHook, level logrus.Level, componentName string) {
 	syslogHook, err := lSyslog.NewSyslogHook(hook.Params["protocol"].(string), hook.Params["address"].(string), syslog.LOG_INFO, componentName)
 	if err == nil {

setup/base/base.go

@@ -123,8 +123,7 @@ func NewBaseDendrite(cfg *config.Dendrite, componentName string, options ...Base
 		logrus.Fatalf("Failed to start due to configuration errors")
 	}
 
-	internal.SetupStdLogging()
+	internal.SetupLogging(cfg.Logging, componentName)
-	internal.SetupHookLogging(cfg.Logging, componentName)
 	internal.SetupPprof()
 
 	logrus.Infof("Dendrite version %s", internal.VersionString())