From 69e532fb805d1da1bfb3c75b6539d162462e9774 Mon Sep 17 00:00:00 2001 From: Patrik Lundin Date: Wed, 27 Nov 2024 10:55:04 +0100 Subject: [PATCH 1/5] Improve paho logging and debug logging in general Make it so we can tag messages from paho internal logging in the slog messages, so we can now what part of paho created the message. This also resulted in using the slog Debug level properly. edm will now set the slog loglevel to debug if the --debug flag is passed. This also resulted in some cleanup of the more verbose debug messages left in the code so it is actuallu possible to run edm on a real system with --debug enabled without generating massive amount of log messages. --- cmd/root.go | 8 +++++--- cmd/run.go | 2 +- main.go | 6 ++++-- pkg/runner/mqtt.go | 42 +++++++++++++++++++++++++++++++----------- pkg/runner/runner.go | 22 +++++----------------- 5 files changed, 46 insertions(+), 34 deletions(-) diff --git a/cmd/root.go b/cmd/root.go index 267b4ff..f85f5c4 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -9,8 +9,9 @@ import ( ) var ( - cfgFile string - edmLogger *slog.Logger + cfgFile string + edmLogger *slog.Logger + edmLoggerLevel *slog.LevelVar ) // rootCmd represents the base command when called without any subcommands @@ -26,9 +27,10 @@ outputting minimised output data.`, // Execute adds all child commands to the root command and sets flags appropriately. // This is called by main.main(). It only needs to happen once to the rootCmd. -func Execute(logger *slog.Logger) { +func Execute(logger *slog.Logger, loggerLevel *slog.LevelVar) { // Set global variables so it can be used from run.go edmLogger = logger + edmLoggerLevel = loggerLevel err := rootCmd.Execute() if err != nil { os.Exit(1) diff --git a/cmd/run.go b/cmd/run.go index c72839b..d7d3cca 100644 --- a/cmd/run.go +++ b/cmd/run.go @@ -13,7 +13,7 @@ var runCmd = &cobra.Command{ Use: "run", Short: "Run edm in dnstap capture mode", Run: func(_ *cobra.Command, _ []string) { - runner.Run(edmLogger) + runner.Run(edmLogger, edmLoggerLevel) }, } diff --git a/main.go b/main.go index 32e6a79..f3d3a8c 100644 --- a/main.go +++ b/main.go @@ -20,8 +20,10 @@ func main() { hostname = defaultHostname } + loggerLevel := new(slog.LevelVar) // Info by default + // Logger used for all output - logger := slog.New(slog.NewJSONHandler(os.Stderr, nil)) + logger := slog.New(slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{Level: loggerLevel})) logger = logger.With("service", "edm") logger = logger.With("hostname", hostname) logger = logger.With("go_version", runtime.Version()) @@ -31,5 +33,5 @@ func main() { // well slog.SetDefault(logger) - cmd.Execute(logger) + cmd.Execute(logger, loggerLevel) } diff --git a/pkg/runner/mqtt.go b/pkg/runner/mqtt.go index 59bfd25..53bcc47 100644 --- a/pkg/runner/mqtt.go +++ b/pkg/runner/mqtt.go @@ -5,18 +5,43 @@ import ( "crypto/tls" "crypto/x509" "fmt" - "log" + "log/slog" "net/url" "github.com/eclipse/paho.golang/autopaho" "github.com/eclipse/paho.golang/autopaho/queue/file" "github.com/eclipse/paho.golang/paho" - paholog "github.com/eclipse/paho.golang/paho/log" "github.com/lestrrat-go/jwx/v2/jwa" "github.com/lestrrat-go/jwx/v2/jwk" "github.com/lestrrat-go/jwx/v2/jws" ) +// Small structs that implements paho/log.Logger so we can use slog with extra info in +// autopaho config logging +type pahoDebugLogger struct { + logger *slog.Logger +} + +func (pdl pahoDebugLogger) Println(v ...interface{}) { + pdl.logger.Debug(fmt.Sprintln(v...)) +} + +func (pdl pahoDebugLogger) Printf(format string, v ...interface{}) { + pdl.logger.Debug(fmt.Sprintf(format, v...)) +} + +type pahoErrorLogger struct { + logger *slog.Logger +} + +func (pel pahoErrorLogger) Println(v ...interface{}) { + pel.logger.Error(fmt.Sprintln(v...)) +} + +func (pel pahoErrorLogger) Printf(format string, v ...interface{}) { + pel.logger.Error(fmt.Sprintf(format, v...)) +} + func (edm *dnstapMinimiser) newAutoPahoClientConfig(caCertPool *x509.CertPool, server string, clientID string, clientCertStore *certStore, mqttKeepAlive uint16, localFileQueue *file.Queue) (autopaho.ClientConfig, error) { u, err := url.Parse(server) if err != nil { @@ -33,10 +58,10 @@ func (edm *dnstapMinimiser) newAutoPahoClientConfig(caCertPool *x509.CertPool, s KeepAlive: mqttKeepAlive, OnConnectionUp: func(*autopaho.ConnectionManager, *paho.Connack) { edm.log.Info("mqtt connection up") }, OnConnectError: func(err error) { edm.log.Error("error whilst attempting connection", "error", err) }, - Debug: paholog.NOOPLogger{}, - Errors: log.Default(), - PahoDebug: paholog.NOOPLogger{}, - PahoErrors: log.Default(), + Debug: pahoDebugLogger{logger: edm.log.With("paho_log_type", "debug")}, + Errors: pahoErrorLogger{logger: edm.log.With("paho_log_type", "errors")}, + PahoDebug: pahoDebugLogger{logger: edm.log.With("paho_log_type", "paho_debug")}, + PahoErrors: pahoErrorLogger{logger: edm.log.With("paho_log_type", "paho_errors")}, ClientConfig: paho.ClientConfig{ ClientID: clientID, OnClientError: func(err error) { edm.log.Error("server requested disconnect", "error", err) }, @@ -55,11 +80,6 @@ func (edm *dnstapMinimiser) newAutoPahoClientConfig(caCertPool *x509.CertPool, s cliCfg.Queue = localFileQueue } - if edm.debug { - cliCfg.Debug = log.Default() - cliCfg.PahoDebug = log.Default() - } - return cliCfg, nil } diff --git a/pkg/runner/runner.go b/pkg/runner/runner.go index 35b77d4..26fd8d0 100644 --- a/pkg/runner/runner.go +++ b/pkg/runner/runner.go @@ -276,26 +276,17 @@ func (edm *dnstapMinimiser) reverseLabelsBounded(labels []string, maxLen int) [] // Append all labels except the last one for i := len(labels) - 1; i > remainderElems; i-- { - if edm.debug { - edm.log.Debug("reverseLabelsBounded", "label", labels[i], "index", i) - } boundedReverseLabels = append(boundedReverseLabels, labels[i]) } // If the labels fit inside maxLen then just append the last remaining // label as-is if len(labels) <= maxLen { - if edm.debug { - edm.log.Debug("appending final label", "label", labels[0], "index", 0) - } boundedReverseLabels = append(boundedReverseLabels, labels[0]) } else { // If there are more labels than maxLen we need to concatenate // them before appending the last element if remainderElems > 0 { - if edm.debug { - edm.log.Debug("building slices of remainders") - } remainderLabels := []string{} for i := remainderElems; i >= 0; i-- { remainderLabels = append(remainderLabels, labels[i]) @@ -750,7 +741,7 @@ func (edm *dnstapMinimiser) registerFSWatcher(filename string, callback func(str return nil } -func Run(logger *slog.Logger) { +func Run(logger *slog.Logger, loggerLevel *slog.LevelVar) { if viper.GetBool("debug-enable-blockprofiling") { logger.Info("enabling blocking profiling") runtime.SetBlockProfileRate(int(time.Millisecond)) @@ -765,6 +756,10 @@ func Run(logger *slog.Logger) { os.Exit(1) } + if viper.GetBool("debug") { + loggerLevel.Set(slog.LevelDebug) + } + // Create an instance of the minimiser edm, err := newDnstapMinimiser(logger, viper.GetString("cryptopan-key"), viper.GetString("cryptopan-key-salt"), viper.GetInt("cryptopan-address-entries"), viper.GetBool("debug"), viper.GetBool("disable-histogram-sender"), viper.GetBool("disable-mqtt")) if err != nil { @@ -1597,9 +1592,6 @@ minimiserLoop: dawgIndex, suffixMatch, dawgModTime := wkdTracker.lookup(msg) if dawgIndex != dawgNotFound { wkdTracker.sendUpdate(dangerRealClientIP, msg, dawgIndex, suffixMatch, dawgModTime) - if edm.debug { - edm.log.Debug("skipping well-known domain", "domain", msg.Question[0].Name, "minimiser_id", minimiserID) - } continue } @@ -2222,10 +2214,6 @@ func certPoolFromFile(fileName string) (*x509.CertPool, error) { func (edm *dnstapMinimiser) pseudonymiseDnstap(dt *dnstap.Dnstap) { var err error - if edm.debug { - edm.log.Debug("pseudonymiseDnstap: modifying dnstap message") - } - // Lock is used here because the cryptopan instance can get updated at runtime. edm.cryptopanMutex.RLock() From 46dcf11c64a856389cc0f0fefb65658983adea43 Mon Sep 17 00:00:00 2001 From: Patrik Lundin Date: Wed, 27 Nov 2024 11:13:32 +0100 Subject: [PATCH 2/5] Group debug flags together --- cmd/run.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/cmd/run.go b/cmd/run.go index d7d3cca..527a032 100644 --- a/cmd/run.go +++ b/cmd/run.go @@ -30,7 +30,6 @@ func init() { // is called directly, e.g.: // runCmd.Flags().BoolP("toggle", "t", false, "Help message for toggle") - runCmd.Flags().Bool("debug", false, "print debug logging during operation") runCmd.Flags().Bool("disable-session-files", false, "do not write out session parquet files") runCmd.Flags().Bool("disable-histogram-sender", false, "do not check for histogram files to upload to core") runCmd.Flags().Bool("disable-mqtt", false, "disable MQTT message sending") @@ -76,8 +75,9 @@ func init() { runCmd.Flags().String("http-client-cert-file", "edm-http-client.pem", "ECSDSA client cert used for authenticating to aggregate-receiver") runCmd.Flags().String("http-url", "https://127.0.0.1:8443", "Service we will POST aggregates to") + // Debug options + runCmd.Flags().Bool("debug", false, "print debug logging during operation") runCmd.Flags().String("debug-dnstap-filename", "", "File for dumping unmodified (sensitive) JSON-formatted dnstap packets we are about to process, for debugging") - runCmd.Flags().Bool("debug-enable-blockprofiling", false, "Enable profiling of goroutine blocking events") runCmd.Flags().Bool("debug-enable-mutexprofiling", false, "Enable profiling of mutex contention events") From 0d4cfd0c43552ab330dc75b532847bc084843c51 Mon Sep 17 00:00:00 2001 From: Patrik Lundin Date: Wed, 27 Nov 2024 11:22:44 +0100 Subject: [PATCH 3/5] No need to include newline in slog messages --- pkg/runner/mqtt.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/pkg/runner/mqtt.go b/pkg/runner/mqtt.go index 53bcc47..b9e0a72 100644 --- a/pkg/runner/mqtt.go +++ b/pkg/runner/mqtt.go @@ -23,7 +23,7 @@ type pahoDebugLogger struct { } func (pdl pahoDebugLogger) Println(v ...interface{}) { - pdl.logger.Debug(fmt.Sprintln(v...)) + pdl.logger.Debug(fmt.Sprint(v...)) } func (pdl pahoDebugLogger) Printf(format string, v ...interface{}) { @@ -35,7 +35,7 @@ type pahoErrorLogger struct { } func (pel pahoErrorLogger) Println(v ...interface{}) { - pel.logger.Error(fmt.Sprintln(v...)) + pel.logger.Error(fmt.Sprint(v...)) } func (pel pahoErrorLogger) Printf(format string, v ...interface{}) { From f5c2cda1c09295e735b36113978ba919ffad5cda Mon Sep 17 00:00:00 2001 From: Patrik Lundin Date: Wed, 27 Nov 2024 11:36:29 +0100 Subject: [PATCH 4/5] Add comment about loggerLevel --- main.go | 1 + 1 file changed, 1 insertion(+) diff --git a/main.go b/main.go index f3d3a8c..599d92f 100644 --- a/main.go +++ b/main.go @@ -20,6 +20,7 @@ func main() { hostname = defaultHostname } + // loggerLevel controls the global logging level for the application loggerLevel := new(slog.LevelVar) // Info by default // Logger used for all output From 21b09c71330c4c4c623eaf5800f0aea6fce55c88 Mon Sep 17 00:00:00 2001 From: Patrik Lundin Date: Wed, 27 Nov 2024 11:42:23 +0100 Subject: [PATCH 5/5] Update comments and use consts for log types --- pkg/runner/mqtt.go | 19 +++++++++++++------ 1 file changed, 13 insertions(+), 6 deletions(-) diff --git a/pkg/runner/mqtt.go b/pkg/runner/mqtt.go index b9e0a72..1c9a77d 100644 --- a/pkg/runner/mqtt.go +++ b/pkg/runner/mqtt.go @@ -16,8 +16,14 @@ import ( "github.com/lestrrat-go/jwx/v2/jws" ) -// Small structs that implements paho/log.Logger so we can use slog with extra info in -// autopaho config logging +const ( + pahoLogTypeDebug = "debug" + pahoLogTypeErrors = "errors" + pahoLogTypePahoDebug = "paho_debug" + pahoLogTypePahoErrors = "paho_errors" +) + +// pahoDebugLogger implements paho/log.Logger interface for debug-level logging type pahoDebugLogger struct { logger *slog.Logger } @@ -30,6 +36,7 @@ func (pdl pahoDebugLogger) Printf(format string, v ...interface{}) { pdl.logger.Debug(fmt.Sprintf(format, v...)) } +// pahoErrorLogger implements paho/log.Logger interface for error-level logging type pahoErrorLogger struct { logger *slog.Logger } @@ -58,10 +65,10 @@ func (edm *dnstapMinimiser) newAutoPahoClientConfig(caCertPool *x509.CertPool, s KeepAlive: mqttKeepAlive, OnConnectionUp: func(*autopaho.ConnectionManager, *paho.Connack) { edm.log.Info("mqtt connection up") }, OnConnectError: func(err error) { edm.log.Error("error whilst attempting connection", "error", err) }, - Debug: pahoDebugLogger{logger: edm.log.With("paho_log_type", "debug")}, - Errors: pahoErrorLogger{logger: edm.log.With("paho_log_type", "errors")}, - PahoDebug: pahoDebugLogger{logger: edm.log.With("paho_log_type", "paho_debug")}, - PahoErrors: pahoErrorLogger{logger: edm.log.With("paho_log_type", "paho_errors")}, + Debug: pahoDebugLogger{logger: edm.log.With("paho_log_type", pahoLogTypeDebug)}, + Errors: pahoErrorLogger{logger: edm.log.With("paho_log_type", pahoLogTypeErrors)}, + PahoDebug: pahoDebugLogger{logger: edm.log.With("paho_log_type", pahoLogTypePahoDebug)}, + PahoErrors: pahoErrorLogger{logger: edm.log.With("paho_log_type", pahoLogTypePahoErrors)}, ClientConfig: paho.ClientConfig{ ClientID: clientID, OnClientError: func(err error) { edm.log.Error("server requested disconnect", "error", err) },