From 779e4c04adb1a1355670de3d1f21c9f30644070e Mon Sep 17 00:00:00 2001 From: Martin Ashby Date: Sat, 27 Nov 2021 09:13:10 +0000 Subject: [PATCH 1/4] 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 --- dendrite-config.yaml | 5 +++-- go.mod | 1 + go.sum | 2 ++ internal/log.go | 15 --------------- internal/log_unix.go | 30 ++++++++++++++++++++++++++++-- setup/base/base.go | 3 +-- 6 files changed, 35 insertions(+), 21 deletions(-) diff --git a/dendrite-config.yaml b/dendrite-config.yaml index 1204bd5463..bf3811a283 100644 --- a/dendrite-config.yaml +++ b/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 -# stdout by Dendrite. +# Logging configuration logging: +- type: std + level: info - type: file level: info params: diff --git a/go.mod b/go.mod index 300d226739..d3e9f0a6d5 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index d56241d358..01a3d9f0d4 100644 --- a/go.sum +++ b/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= diff --git a/internal/log.go b/internal/log.go index bba0ac6e6a..ea44e22b57 100644 --- a/internal/log.go +++ b/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"] diff --git a/internal/log_unix.go b/internal/log_unix.go index 25ad042056..d49c747ffb 100644 --- a/internal/log_unix.go +++ b/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 { diff --git a/setup/base/base.go b/setup/base/base.go index 9ba88bef74..a3f3a79f0f 100644 --- a/setup/base/base.go +++ b/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.SetupHookLogging(cfg.Logging, componentName) + internal.SetupLogging(cfg.Logging, componentName) internal.SetupPprof() logrus.Infof("Dendrite version %s", internal.VersionString()) From abd370a13376469b4041d588087fb54109ef8834 Mon Sep 17 00:00:00 2001 From: Martin Ashby Date: Fri, 3 Dec 2021 22:22:49 +0000 Subject: [PATCH 2/4] Fix build on Windows - revert function rename SetupHookLogging Fixes https://github.com/matrix-org/dendrite/pull/2060/files#r761692681 --- internal/log_unix.go | 4 ++-- setup/base/base.go | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/internal/log_unix.go b/internal/log_unix.go index d49c747ffb..44cb75bebc 100644 --- a/internal/log_unix.go +++ b/internal/log_unix.go @@ -26,10 +26,10 @@ import ( lSyslog "github.com/sirupsen/logrus/hooks/syslog" ) -// SetupLogging configures the logging hooks defined in the configuration. +// SetupHookLogging 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 SetupLogging(hooks []config.LogrusHook, componentName string) { +func SetupHookLogging(hooks []config.LogrusHook, componentName string) { logrus.SetReportCaller(true) logrus.SetFormatter(&utcFormatter{ &logrus.TextFormatter{ diff --git a/setup/base/base.go b/setup/base/base.go index a3f3a79f0f..1249e14222 100644 --- a/setup/base/base.go +++ b/setup/base/base.go @@ -123,7 +123,7 @@ func NewBaseDendrite(cfg *config.Dendrite, componentName string, options ...Base logrus.Fatalf("Failed to start due to configuration errors") } - internal.SetupLogging(cfg.Logging, componentName) + internal.SetupHookLogging(cfg.Logging, componentName) internal.SetupPprof() logrus.Infof("Dendrite version %s", internal.VersionString()) From f886fbc9170181bd282da16c23c457fa61912656 Mon Sep 17 00:00:00 2001 From: Martin Ashby Date: Tue, 7 Dec 2021 11:51:47 +0000 Subject: [PATCH 3/4] Revert logging formatter changes to log.go, base.go. The same formatting should be applied on both windows and unix, so it makes sense to keep it in files which are shared between both platforms. Fixes https://github.com/matrix-org/dendrite/pull/2060#discussion_r762557679 --- internal/log.go | 15 +++++++++++++++ internal/log_unix.go | 11 ----------- setup/base/base.go | 1 + 3 files changed, 16 insertions(+), 11 deletions(-) diff --git a/internal/log.go b/internal/log.go index ea44e22b57..bba0ac6e6a 100644 --- a/internal/log.go +++ b/internal/log.go @@ -91,6 +91,21 @@ 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"] diff --git a/internal/log_unix.go b/internal/log_unix.go index 44cb75bebc..27d9a8fe67 100644 --- a/internal/log_unix.go +++ b/internal/log_unix.go @@ -30,17 +30,6 @@ import ( // 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) { - 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 diff --git a/setup/base/base.go b/setup/base/base.go index 1249e14222..9ba88bef74 100644 --- a/setup/base/base.go +++ b/setup/base/base.go @@ -123,6 +123,7 @@ func NewBaseDendrite(cfg *config.Dendrite, componentName string, options ...Base logrus.Fatalf("Failed to start due to configuration errors") } + internal.SetupStdLogging() internal.SetupHookLogging(cfg.Logging, componentName) internal.SetupPprof() From c4d91fddf001262fb25422b5880e86cc7842d741 Mon Sep 17 00:00:00 2001 From: Martin Ashby Date: Tue, 7 Dec 2021 13:46:45 +0000 Subject: [PATCH 4/4] Remove unnecessary startup logging about info level logger. Fixes https://github.com/matrix-org/dendrite/pull/2060#discussion_r763959474 --- internal/log_unix.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/log_unix.go b/internal/log_unix.go index 27d9a8fe67..1e1094f231 100644 --- a/internal/log_unix.go +++ b/internal/log_unix.go @@ -12,6 +12,7 @@ // See the License for the specific language governing permissions and // limitations under the License. +//go:build !windows // +build !windows package internal @@ -59,7 +60,6 @@ func SetupHookLogging(hooks []config.LogrusHook, componentName string) { } } 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