improved logging

example/example.go

@@ -3,7 +3,7 @@ package main
 import (
 	"encoding/hex"
 	"fmt"
-	"purb"
+	"purb/purb"
 
 	"go.dedis.ch/kyber/v3/group/curve25519"
 	"go.dedis.ch/kyber/v3/util/key"
@@ -14,13 +14,11 @@ func main() {
 	// this is public and fixed across all purbs
 	suitesInfo := getDummySuiteInfo()
 	simplified := false // when "true", does not use hash tables (but linear mapping)
-	verbose := false
 
 	p := purb.NewPurb(
 		suitesInfo,
 		simplified,
 		random.New(),
-		verbose,
 	)
 
 	msg := "And presently I was driving through the drizzle of the dying day, with the windshield wipers in full action but unable to cope with my tears."
@@ -30,7 +28,7 @@ func main() {
 	fmt.Println()
 
 	// Encode (this sets-up many things, but does not output []bytes)
-	p.recipients = createRecipients(1)
+	p.Recipients = createRecipients(1)
 	err := p.Encode([]byte(msg))
 	if err != nil {
 		panic(err.Error())

go.mod

@@ -3,13 +3,16 @@ module purb
 go 1.21
 
 require (
+	github.com/rs/zerolog v1.31.0
 	github.com/stretchr/testify v1.8.4
 	go.dedis.ch/kyber/v3 v3.1.1-0.20231024084410-31ea167adbbb
 )
 
 require (
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/kr/pretty v0.1.0 // indirect
+	github.com/mattn/go-colorable v0.1.13 // indirect
+	github.com/mattn/go-isatty v0.0.19 // indirect
 	github.com/pmezard/go-difflib v1.0.0 // indirect
 	go.dedis.ch/fixbuf v1.0.3 // indirect
 	golang.org/x/crypto v0.14.0 // indirect

go.sum

@@ -1,12 +1,23 @@
+github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
 github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
 github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
 github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE=
 github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
+github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA=
+github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg=
+github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM=
+github.com/mattn/go-isatty v0.0.19 h1:JITubQf0MOLdlGRuRq+jtsDlekdYPia9ZFsB8h/APPA=
+github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
+github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.31.0 h1:FcTR3NnLWW+NnTwwhFWiJSZr4ECLpqCm6QsEnyvbV4A=
+github.com/rs/zerolog v1.31.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss=
 github.com/stretchr/testify v1.8.4 h1:CcVxjf3Q8PM0mHUKJCdn+eZZtm5yQwehR5yeSVQQcUk=
 github.com/stretchr/testify v1.8.4/go.mod h1:sz/lmYIOXD/1dqDmKjjqLyZ2RngseejIcXlSw2iwfAo=
 go.dedis.ch/fixbuf v1.0.3 h1:hGcV9Cd/znUxlusJ64eAlExS+5cJDIyTyEG+otu5wQs=
@@ -15,6 +26,9 @@ go.dedis.ch/kyber/v3 v3.1.1-0.20231024084410-31ea167adbbb h1:G7GmitWgVMlkBaSzHJJ
 go.dedis.ch/kyber/v3 v3.1.1-0.20231024084410-31ea167adbbb/go.mod h1:nL0a5f3E//lnOCKumtzMmb8qzykxOVsihqp8C1Eb5rc=
 golang.org/x/crypto v0.14.0 h1:wBqGXzWJW6m1XrIKlAH0Hs1JJ7+9KBwnIO8v66Q9cHc=
 golang.org/x/crypto v0.14.0/go.mod h1:MVFd36DqK4CsrnJYDkBA3VC4m2GkXAM0PvzMCn4JQf4=
+golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.13.0 h1:Af8nKPmuFypiUBjVoU9V20FiaFXOcuZI21p0ycVYYGE=
 golang.org/x/sys v0.13.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=

mod.go

@@ -1,5 +1,13 @@
+// Package purb defines the logger.
 package purb
 
+import (
+	"os"
+	"time"
+
+	"github.com/rs/zerolog"
+)
+
 type Purb interface {
 	Decode(
 		blob []byte,
@@ -11,5 +19,72 @@ type Purb interface {
 
 	ToBytes() []byte
 
-	VisualRepresentation(verbose bool) string
+	VisualRepresentation() string
 }
+
+// purb is using a global logger with some default parameters. It is disabled by
+// default and the level can be increased using an environment variable:
+//
+//	LLVL=trace go test ./...
+//	LLVL=info go test ./...
+//	LLVL=debug LOGF=$HOME/dela.log go test ./...
+
+// EnvLogLevel is the name of the environment variable to change the logging
+// level.
+const EnvLogLevel = "LLVL"
+
+// EnvLogFile is the name of the environment variable to log in a given file.
+const EnvLogFile = "LOGF"
+
+const defaultLevel = zerolog.NoLevel
+
+func init() {
+	logLevel := os.Getenv(EnvLogLevel)
+
+	var level zerolog.Level
+
+	switch logLevel {
+	case "error":
+		level = zerolog.ErrorLevel
+	case "warn":
+		level = zerolog.WarnLevel
+	case "info":
+		level = zerolog.InfoLevel
+	case "debug":
+		level = zerolog.DebugLevel
+	case "trace":
+		level = zerolog.TraceLevel
+	case "":
+		level = defaultLevel
+	default:
+		level = zerolog.TraceLevel
+	}
+
+	Logger = Logger.Level(level)
+
+	logFile := os.Getenv(EnvLogFile)
+	if len(logFile) > 3 {
+		fileOut, err := os.OpenFile(logFile, os.O_CREATE|os.O_APPEND|os.O_RDWR, 0666)
+		if err != nil {
+			Logger.Error().Msgf("COULD NOT OPEN %v", logFile)
+			os.Exit(2)
+		}
+
+		multiWriter := zerolog.MultiLevelWriter(fileOut, consoleOut)
+		Logger = Logger.Output(multiWriter)
+		Logger.Info().Msgf("Using log file: %v", logFile)
+	}
+
+	Logger.Info().Msgf("PURB Logger initialized!")
+}
+
+var consoleOut = zerolog.ConsoleWriter{
+	Out:        os.Stdout,
+	TimeFormat: time.RFC3339,
+}
+
+// Logger is a globally available logger instance. By default, it only prints
+// error level messages but it can be changed through a environment variable.
+var Logger = zerolog.New(consoleOut).Level(defaultLevel).
+	With().Timestamp().Logger().
+	With().Caller().Logger()

purb/decode.go

@@ -5,7 +5,7 @@ import (
 	"crypto/sha256"
 	"encoding/binary"
 	"errors"
-	"log"
+	"purb"
 
 	"go.dedis.ch/kyber/v3"
 )
@@ -14,13 +14,12 @@ import (
 func (p *Purb) Decode(
 	blob []byte,
 ) (bool, []byte, error) {
-	suiteName := p.recipients[0].SuiteName
+	suiteName := p.Recipients[0].SuiteName
 	suiteInfo := p.config.suiteInfoMap[suiteName]
 
-	if p.isVerbose {
-		log.Printf("Attempting to decode using suite %v, len %v, positions %v", suiteName,
-			suiteInfo.CornerstoneLength, suiteInfo.AllowedPositions)
-	}
+	purb.Logger.Info().Msgf("Attempting to decode using suite %v, len %v, positions %v",
+		suiteName,
+		suiteInfo.CornerstoneLength, suiteInfo.AllowedPositions)
 
 	if suiteInfo == nil {
 		return false, nil, errors.New("no positions suiteInfo for this suite")
@@ -41,49 +40,46 @@ func (p *Purb) Decode(
 		}
 		cornerstoneBytes := blob[startPos:endPos]
 
-		if p.isVerbose {
-			log.Printf("XORing in the bytes [%v:%v], value %v", startPos, endPos, cornerstoneBytes)
-		}
+		purb.Logger.Debug().Msgf("XORing in the bytes [%v:%v], value %v", startPos, endPos,
+			cornerstoneBytes)
 
 		for j := range cornerstoneBytes {
 			cornerstone[j] ^= cornerstoneBytes[j]
 		}
 	}
 
-	if p.isVerbose {
-		log.Printf("Recovered cornerstone has value %v, len %v", cornerstone, len(cornerstone))
-	}
+	purb.Logger.Debug().Msgf("Recovered cornerstone has value %v, len %v", cornerstone,
+		len(cornerstone))
 
 	//Now that we have the SessionKey for our suite, calculate the shared SessionKey
-	pubKey := p.recipients[0].Suite.Point()
+	pubKey := p.Recipients[0].Suite.Point()
 	pubKey.(kyber.Hiding).HideDecode(cornerstone)
 
-	sharedKey := p.recipients[0].Suite.Point().Mul(p.recipients[0].PrivateKey, pubKey)
+	sharedKey := p.Recipients[0].Suite.Point().Mul(p.Recipients[0].PrivateKey, pubKey)
 	sharedBytes, err := sharedKey.MarshalBinary()
 	if err != nil {
 		return false, nil, err
 	}
 	sharedSecret := KDF("", sharedBytes)
 
-	if p.isVerbose {
-		log.Printf("Recovered sharedbytes value %v, len %v", sharedBytes, len(sharedBytes))
-		log.Printf("Recovered sharedsecret value %v, len %v", sharedSecret, len(sharedSecret))
-	}
+	purb.Logger.Debug().Msgf("Recovered sharedbytes value %v, len %v", sharedBytes,
+		len(sharedBytes))
+	purb.Logger.Debug().Msgf("Recovered sharedsecret value %v, len %v", sharedSecret,
+		len(sharedSecret))
 
 	// Now we try to decrypt iteratively the entrypoints and check if the decrypted SessionKey works for AEAD of payload
 	if !p.config.simplifiedEntrypointsPlacement {
 		return entrypointTrialDecode(blob, sharedSecret, suiteInfo,
-			p.config.hashTableCollisionLinearResolutionAttempts, p.isVerbose)
+			p.config.hashTableCollisionLinearResolutionAttempts)
 	}
-	return entrypointTrialDecodeSimplified(blob, sharedSecret, suiteInfo, p.isVerbose)
+	return entrypointTrialDecodeSimplified(blob, sharedSecret, suiteInfo)
 }
 
 func entrypointTrialDecode(
 	blob []byte,
 	sharedSecret []byte,
 	suiteInfo *SuiteInfo,
 	hashTableLinearResolutionCollisionAttempt int,
-	verbose bool,
 ) (bool, []byte, error) {
 
 	intOfHashedValue := int(binary.BigEndian.Uint32(KDF("pos",
@@ -115,12 +111,12 @@ func entrypointTrialDecode(
 				continue // it is not the correct entry point so we move one to try again
 			}
 
-			if verbose {
-				log.Printf("Recovering potential entrypoint [%v:%v], value %v", entrypointStartPos,
-					entrypointEndPos, data[entrypointStartPos:entrypointEndPos])
-				log.Printf("  Attempting decryption with sharedSecret %v", sharedSecret)
-				log.Printf("  yield %v", decrypted)
-			}
+			purb.Logger.Debug().Msgf("Recovering potential entrypoint [%v:%v], value %v",
+				entrypointStartPos,
+				entrypointEndPos, data[entrypointStartPos:entrypointEndPos])
+			purb.Logger.Debug().Msgf("  Attempting decryption with sharedSecret %v",
+				sharedSecret)
+			purb.Logger.Debug().Msgf("  yield %v", decrypted)
 
 			ok := verifyMAC(decrypted, blob)
 			if !ok {
@@ -129,9 +125,8 @@ func entrypointTrialDecode(
 
 			found, errorReason, message := payloadDecrypt(decrypted, data)
 
-			if verbose {
-				log.Printf("  found=%v, reason=%v, decrypted=%v", found, errorReason, message)
-			}
+			purb.Logger.Debug().Msgf("  found=%v, reason=%v, decrypted=%v", found, errorReason,
+				message)
 
 			if found {
 				return found, message, nil
@@ -153,7 +148,6 @@ func entrypointTrialDecodeSimplified(
 	blob []byte,
 	sharedSecret []byte,
 	suiteInfo *SuiteInfo,
-	verbose bool,
 ) (bool, []byte, error) {
 	startPos := suiteInfo.AllowedPositions[0] + suiteInfo.CornerstoneLength
 
@@ -175,9 +169,8 @@ func entrypointTrialDecodeSimplified(
 
 		found, errorReason, message := payloadDecrypt(decrypted, data)
 
-		if verbose {
-			log.Printf("  found=%v, reason=%v, decrypted=%v", found, errorReason, message)
-		}
+		purb.Logger.Debug().Msgf("  found=%v, reason=%v, decrypted=%v",
+			found, errorReason, message)
 		if found {
 			return found, message, nil
 		}