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

@@ -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)

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

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

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
 }
 

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()