feat: implement structured logging

cmd/certspotter/main.go

@@ -25,6 +25,8 @@ import (
 	"syscall"
 	"time"
 
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 	"software.sslmate.com/src/certspotter/loglist"
 	"software.sslmate.com/src/certspotter/monitor"
 )
@@ -151,6 +153,15 @@ func appendFunc(slice *[]string) func(string) error {
 }
 
 func main() {
+	encoderCfg := zap.NewProductionEncoderConfig()
+	atom := zap.NewAtomicLevel()
+	logger := zap.New(zapcore.NewCore(
+		zapcore.NewJSONEncoder(encoderCfg),
+		zapcore.Lock(os.Stdout),
+		atom,
+	))
+	defer logger.Sync()
+
 	loglist.UserAgent = fmt.Sprintf("certspotter/%s (%s; %s; %s)", certspotterVersion(), runtime.Version(), runtime.GOOS, runtime.GOARCH)
 
 	var flags struct {
@@ -182,16 +193,20 @@ func main() {
 	flag.BoolVar(&flags.version, "version", false, "Print version and exit")
 	flag.StringVar(&flags.watchlist, "watchlist", defaultWatchListPathIfExists(), "File containing domain names to watch")
 	flag.Parse()
-
 	if flags.version {
-		fmt.Fprintf(os.Stdout, "certspotter version %s\n", certspotterVersion())
+		logger.Sugar().Infof("certspotter version %s", certspotterVersion())
 		os.Exit(0)
 	}
 	if flags.watchlist == "" {
-		fmt.Fprintf(os.Stderr, "%s: watch list not found: please create %s or specify alternative path using -watchlist\n", programName, defaultWatchListPath())
+		logger.Sugar().Warnf("%s: watch list not found: please create %s or specify alternative path using -watchlist", programName, defaultWatchListPath())
 		os.Exit(2)
 	}
 
+	if flags.verbose {
+		atom.SetLevel(zap.DebugLevel)
+	}
+	zap.ReplaceGlobals(logger)
+
 	config := &monitor.Config{
 		LogListSource:       flags.logs,
 		StateDir:            flags.stateDir,
@@ -211,32 +226,32 @@ func main() {
 		emailFileExists = true
 		config.Email = append(config.Email, emailRecipients...)
 	} else if !errors.Is(err, fs.ErrNotExist) {
-		fmt.Fprintf(os.Stderr, "%s: error reading email recipients file %q: %s\n", programName, defaultEmailFile(), err)
+		logger.Sugar().Warnf("%s: error reading email recipients file %q: %s", programName, defaultEmailFile(), err)
 		os.Exit(1)
 	}
 
 	if len(config.Email) == 0 && !emailFileExists && config.Script == "" && !fileExists(config.ScriptDir) && !config.Stdout {
-		fmt.Fprintf(os.Stderr, "%s: no notification methods were specified\n", programName)
-		fmt.Fprintf(os.Stderr, "Please specify at least one of the following notification methods:\n")
-		fmt.Fprintf(os.Stderr, " - Place one or more email addresses in %s (one address per line)\n", defaultEmailFile())
-		fmt.Fprintf(os.Stderr, " - Place one or more executable scripts in the %s directory\n", config.ScriptDir)
-		fmt.Fprintf(os.Stderr, " - Specify an email address using the -email flag\n")
-		fmt.Fprintf(os.Stderr, " - Specify the path to an executable script using the -script flag\n")
-		fmt.Fprintf(os.Stderr, " - Specify the -stdout flag\n")
+		logger.Sugar().Warnf("%s: no notification methods were specified", programName)
+		logger.Sugar().Warnf("Please specify at least one of the following notification methods:")
+		logger.Sugar().Warnf(" - Place one or more email addresses in %s (one address per line)", defaultEmailFile())
+		logger.Sugar().Warnf(" - Place one or more executable scripts in the %s directory", config.ScriptDir)
+		logger.Sugar().Warnf(" - Specify an email address using the -email flag")
+		logger.Sugar().Warnf(" - Specify the path to an executable script using the -script flag")
+		logger.Sugar().Warnf(" - Specify the -stdout flag")
 		os.Exit(2)
 	}
 
 	if flags.watchlist == "-" {
 		watchlist, err := monitor.ReadWatchList(os.Stdin)
 		if err != nil {
-			fmt.Fprintf(os.Stderr, "%s: error reading watchlist from standard in: %s\n", programName, err)
+			logger.Sugar().Warnf("%s: error reading watchlist from standard in: %s", programName, err)
 			os.Exit(1)
 		}
 		config.WatchList = watchlist
 	} else {
 		watchlist, err := readWatchListFile(flags.watchlist)
 		if err != nil {
-			fmt.Fprintf(os.Stderr, "%s: error reading watchlist from %q: %s\n", programName, flags.watchlist, err)
+			logger.Sugar().Warnf("%s: error reading watchlist from %q: %s", programName, flags.watchlist, err)
 			os.Exit(1)
 		}
 		config.WatchList = watchlist
@@ -246,7 +261,7 @@ func main() {
 	defer stop()
 
 	if err := monitor.Run(ctx, config); err != nil && !errors.Is(err, context.Canceled) {
-		fmt.Fprintf(os.Stderr, "%s: %s\n", programName, err)
+		logger.Sugar().Warnf("%s: %s", programName, err)
 		os.Exit(1)
 	}
 }

go.mod

@@ -7,4 +7,9 @@ require (
 	golang.org/x/sync v0.5.0
 )
 
-require golang.org/x/text v0.14.0 // indirect
+require go.uber.org/multierr v1.10.0 // indirect
+
+require (
+	go.uber.org/zap v1.26.0
+	golang.org/x/text v0.14.0 // indirect
+)

go.sum

@@ -1,3 +1,7 @@
+go.uber.org/multierr v1.10.0 h1:S0h4aNzvfcFsC3dRF1jLoaov7oRaKqRGC/pUEJ2yvPQ=
+go.uber.org/multierr v1.10.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y=
+go.uber.org/zap v1.26.0 h1:sI7k6L95XOKS281NhVKOFCUNIvv9e0w4BF8N3u+tCRo=
+go.uber.org/zap v1.26.0/go.mod h1:dtElttAiwGvoJ/vj4IwHBS/gXsEu/pZ50mUIRWuG0so=
 golang.org/x/net v0.17.0 h1:pVaXccu2ozPjCXewfr1S7xza/zcXTity9cCdXQYSjIM=
 golang.org/x/net v0.17.0/go.mod h1:NxSsAGuq816PNPmqtQdLE42eU2Fs7NoRIZrHJAlaCOE=
 golang.org/x/net v0.19.0 h1:zTwKpTd2XuCqf8huc7Fo2iSy+4RHPd10s4KzeTnVr1c=

monitor/daemon.go

@@ -13,12 +13,13 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"golang.org/x/sync/errgroup"
-	"log"
 	insecurerand "math/rand"
 	"path/filepath"
-	"software.sslmate.com/src/certspotter/loglist"
 	"time"
+
+	"go.uber.org/zap"
+	"golang.org/x/sync/errgroup"
+	"software.sslmate.com/src/certspotter/loglist"
 )
 
 const (
@@ -81,7 +82,7 @@ func (daemon *daemon) startTask(ctx context.Context, ctlog *loglist.Log) task {
 		defer cancel()
 		err := monitorLogContinously(ctx, daemon.config, ctlog)
 		if daemon.config.Verbose {
-			log.Printf("task for log %s stopped with error %s", ctlog.URL, err)
+			zap.S().Errorf("task for log %s stopped with error %s", ctlog.URL, err)
 		}
 		if ctx.Err() == context.Canceled && errors.Is(err, context.Canceled) {
 			return nil
@@ -101,15 +102,15 @@ func (daemon *daemon) loadLogList(ctx context.Context) error {
 	}
 
 	if daemon.config.Verbose {
-		log.Printf("fetched %d logs from %q", len(newLogList), daemon.config.LogListSource)
+		zap.S().Debugf("fetched %d logs from %q", len(newLogList), daemon.config.LogListSource)
 	}
 
 	for logID, task := range daemon.tasks {
 		if _, exists := newLogList[logID]; exists {
 			continue
 		}
 		if daemon.config.Verbose {
-			log.Printf("stopping task for log %s", logID.Base64String())
+			zap.S().Debugf("stopping task for log %s", logID.Base64String())
 		}
 		task.stop()
 		delete(daemon.tasks, logID)
@@ -119,7 +120,7 @@ func (daemon *daemon) loadLogList(ctx context.Context) error {
 			continue
 		}
 		if daemon.config.Verbose {
-			log.Printf("starting task for log %s (%s)", logID.Base64String(), ctlog.URL)
+			zap.S().Debugf("starting task for log %s (%s)", logID.Base64String(), ctlog.URL)
 		}
 		daemon.tasks[logID] = daemon.startTask(ctx, ctlog)
 	}

monitor/discoveredcert.go

@@ -12,13 +12,14 @@ package monitor
 import (
 	"bytes"
 	"encoding/hex"
-	"encoding/json"
 	"encoding/pem"
 	"fmt"
 	"net"
 	"strings"
 	"time"
 
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
 	"software.sslmate.com/src/certspotter"
 	"software.sslmate.com/src/certspotter/ct"
 )
@@ -132,7 +133,7 @@ func (cert *discoveredCert) Environ() []string {
 	return env
 }
 
-func (cert *discoveredCert) Json() string {
+func (cert *discoveredCert) Json() []zap.Field {
 	log := struct {
 		Sha256    string
 		DNSNames  []string
@@ -160,11 +161,22 @@ func (cert *discoveredCert) Json() string {
 		log.NotBefore = fmt.Sprintf("[unable to parse: %s]", cert.Info.ValidityParseError)
 		log.NotAfter = fmt.Sprintf("[unable to parse: %s]", cert.Info.ValidityParseError)
 	}
-	json, err := json.Marshal(log)
-	if err != nil {
-		fmt.Printf("error marshaling log entry: %s\n", err)
+	return []zapcore.Field{
+		zap.String("notBefore", log.NotBefore),
+		zap.String("notAfter", log.NotAfter),
+		zap.String("sha256", log.Sha256),
+		zap.Strings("dnsNames", log.DNSNames),
+		zap.Strings("ips", ips(log.IPs)),
+		zap.String("issuer", log.Issuer),
+		zap.String("pubkey", log.Pubkey)}
+}
+
+func ips(data []net.IP) []string {
+	ips := []string{}
+	for _, ip := range data {
+		ips = append(ips, ip.String())
 	}
-	return string(json)
+	return ips
 }
 
 func (cert *discoveredCert) Text() string {

monitor/errors.go

@@ -9,10 +9,8 @@
 
 package monitor
 
-import (
-	"log"
-)
+import "go.uber.org/zap"
 
 func recordError(err error) {
-	log.Print(err)
+	zap.Error(err)
 }

monitor/healthcheck.go

@@ -18,6 +18,7 @@ import (
 	"strings"
 	"time"
 
+	"go.uber.org/zap"
 	"software.sslmate.com/src/certspotter/ct"
 	"software.sslmate.com/src/certspotter/loglist"
 )
@@ -136,14 +137,14 @@ func (e *staleLogListEvent) Summary() string {
 	return fmt.Sprintf("Unable to retrieve log list since %s", e.LastSuccess)
 }
 
-func (cert *staleLogListEvent) Json() string {
-	return ""
+func (cert *staleLogListEvent) Json() []zap.Field {
+	return []zap.Field{}
 }
-func (cert *backlogEvent) Json() string {
-	return ""
+func (cert *backlogEvent) Json() []zap.Field {
+	return []zap.Field{}
 }
-func (cert *staleSTHEvent) Json() string {
-	return ""
+func (cert *staleSTHEvent) Json() []zap.Field {
+	return []zap.Field{}
 }
 
 func (e *staleSTHEvent) Text() string {

monitor/malformed.go

@@ -10,9 +10,10 @@
 package monitor
 
 import (
-	"encoding/json"
 	"fmt"
 	"strings"
+
+	"go.uber.org/zap"
 )
 
 type malformedLogEntry struct {
@@ -56,20 +57,17 @@ func (malformed *malformedLogEntry) Environ() []string {
 	}
 }
 
-func (cert *malformedLogEntry) Json() string {
-	json, err := json.Marshal(struct {
+func (cert *malformedLogEntry) Json() []zap.Field {
+	data := struct {
 		LogEntry string
 		LeafHash string
 		Error    string
 	}{
 		LogEntry: fmt.Sprintf("%d @ %s", cert.Entry.Index, cert.Entry.Log.URL),
 		LeafHash: cert.Entry.LeafHash.Base64String(),
 		Error:    cert.Error,
-	})
-	if err != nil {
-		fmt.Printf("error marshaling malformed log entry: %s\n", err)
 	}
-	return string(json)
+	return []zap.Field{zap.String("LogEntry", data.LogEntry), zap.String("LeafHash", data.LeafHash), zap.String("Error", data.Error)}
 }
 
 func (malformed *malformedLogEntry) Text() string {

monitor/monitor.go

@@ -15,12 +15,12 @@ import (
 	"errors"
 	"fmt"
 	"io/fs"
-	"log"
 	"os"
 	"path/filepath"
 	"strings"
 	"time"
 
+	"go.uber.org/zap"
 	"software.sslmate.com/src/certspotter/ct"
 	"software.sslmate.com/src/certspotter/ct/client"
 	"software.sslmate.com/src/certspotter/loglist"
@@ -124,7 +124,7 @@ func monitorLog(ctx context.Context, config *Config, ctlog *loglist.Log, logClie
 			}
 		}
 		if config.Verbose {
-			log.Printf("brand new log %s (starting from %d)", ctlog.URL, state.DownloadPosition.Size())
+			zap.S().Debugf("brand new log %s (starting from %d)", ctlog.URL, state.DownloadPosition.Size())
 		}
 		if err := state.store(stateFilePath); err != nil {
 			return fmt.Errorf("error storing state file: %w", err)
@@ -148,7 +148,7 @@ func monitorLog(ctx context.Context, config *Config, ctlog *loglist.Log, logClie
 
 	defer func() {
 		if config.Verbose {
-			log.Printf("saving state in defer for %s", ctlog.URL)
+			zap.S().Debugf("saving state in defer for %s", ctlog.URL)
 		}
 		if err := state.store(stateFilePath); err != nil && returnedErr == nil {
 			returnedErr = fmt.Errorf("error storing state file: %w", err)
@@ -167,7 +167,7 @@ func monitorLog(ctx context.Context, config *Config, ctlog *loglist.Log, logClie
 		downloadErr   error
 	)
 	if config.Verbose {
-		log.Printf("downloading entries from %s in range [%d, %d)", ctlog.URL, downloadBegin, downloadEnd)
+		zap.S().Debugf("downloading entries from %s in range [%d, %d)", ctlog.URL, downloadBegin, downloadEnd)
 	}
 	go func() {
 		defer close(entries)
@@ -225,7 +225,7 @@ func monitorLog(ctx context.Context, config *Config, ctlog *loglist.Log, logClie
 	}
 
 	if config.Verbose {
-		log.Printf("finished downloading entries from %s", ctlog.URL)
+		zap.S().Debugf("finished downloading entries from %s", ctlog.URL)
 	}
 
 	state.LastSuccess = startTime.UTC()

monitor/notify.go

@@ -21,6 +21,8 @@ import (
 	"strings"
 	"sync"
 	"time"
+
+	"go.uber.org/zap"
 )
 
 var stdoutMu sync.Mutex
@@ -29,7 +31,7 @@ type notification interface {
 	Environ() []string
 	Summary() string
 	Text() string
-	Json() string
+	Json() []zap.Field
 }
 
 func notify(ctx context.Context, config *Config, notif notification) error {
@@ -62,7 +64,7 @@ func notify(ctx context.Context, config *Config, notif notification) error {
 func writeJsonToStdout(notif notification) {
 	stdoutMu.Lock()
 	defer stdoutMu.Unlock()
-	os.Stdout.WriteString(notif.Json() + "\n")
+	zap.L().Info("New certificate detected", notif.Json()...)
 }
 
 func writeToStdout(notif notification) {