Merge pull request #31 from dnstapir/improve-debug-logging

Improve paho logging and debug logging in general

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

main.go

@@ -20,8 +20,11 @@ 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
-	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 +34,5 @@ func main() {
 	// well
 	slog.SetDefault(logger)
 
-	cmd.Execute(logger)
+	cmd.Execute(logger, loggerLevel)
 }

pkg/runner/mqtt.go

@@ -5,18 +5,50 @@ 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"
 )
 
+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
+}
+
+func (pdl pahoDebugLogger) Println(v ...interface{}) {
+	pdl.logger.Debug(fmt.Sprint(v...))
+}
+
+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
+}
+
+func (pel pahoErrorLogger) Println(v ...interface{}) {
+	pel.logger.Error(fmt.Sprint(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 +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:          paholog.NOOPLogger{},
-		Errors:         log.Default(),
-		PahoDebug:      paholog.NOOPLogger{},
-		PahoErrors:     log.Default(),
+		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) },
@@ -55,11 +87,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()