add structured logging / logfmt

4 files changed, 164 insertions, 7 deletions

diff --git a/go.mod b/go.mod
index 97c10a6..4a884fa 100644
--- a/go.mod
+++ b/go.mod
@@ -8,5 +8,6 @@ go 1.14
 
 require (
 	github.com/eclipse/paho.mqtt.golang v1.2.0
+	github.com/sirupsen/logrus v1.6.0
 	golang.org/x/net v0.0.0-20200602114024-627f9648deb9 // indirect
 )
diff --git a/go.sum b/go.sum
index d996e7c..cf4cce8 100644
--- a/go.sum
+++ b/go.sum
@@ -1,8 +1,16 @@
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/eclipse/paho.mqtt.golang v1.2.0 h1:1F8mhG9+aO5/xpdtFkW4SxOJB67ukuDC3t2y2qayIX0=
 github.com/eclipse/paho.mqtt.golang v1.2.0/go.mod h1:H9keYFcgq3Qr5OUJm/JZI/i6U7joQ8SYLhZwfeOo6Ts=
+github.com/konsorten/go-windows-terminal-sequences v1.0.3/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
+github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/sirupsen/logrus v1.6.0 h1:UBcNElsrwanuuMsnGSlYmtmgbb23qDR5dG+6X6Oo89I=
+github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88=
+github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=
 golang.org/x/net v0.0.0-20200602114024-627f9648deb9 h1:pNX+40auqi2JqRfOP1akLGtYcn15TUbkhwuCO3foqqM=
 golang.org/x/net v0.0.0-20200602114024-627f9648deb9/go.mod h1:qpuaurCH72eLCgpAm/N6yyVIVM9cpaDIP3A8BGJEC5A=
 golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY=
+golang.org/x/sys v0.0.0-20190422165155-953cdadca894/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20200323222414-85ca7c5b95cd h1:xhmwyvizuTgC2qz7ZlMluP20uW+C3Rm0FD/WLDX8884=
 golang.org/x/sys v0.0.0-20200323222414-85ca7c5b95cd/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
diff --git a/logger/log.go b/logger/log.go
new file mode 100644
index 0000000..a47d27d
--- /dev/null
+++ b/logger/log.go
@@ -0,0 +1,131 @@
+// SPDX-FileCopyrightText: 2020 Ethel Morgan
+//
+// SPDX-License-Identifier: MIT
+
+package logger
+
+import (
+	"context"
+	"fmt"
+	"sync"
+
+	log "github.com/sirupsen/logrus"
+)
+
+type (
+	// log, ctx := logger.FromContext(ctx)
+	// log.WithField("error", err).Warninging(...)
+	// log.AddField("transport", udn)
+	// log.Info(...)
+	Logger interface {
+		// AddField adds a field to the current logger.
+		AddField(name string, value interface{})
+
+		// WithField forks a logger, adding context.
+		WithField(name string, value interface{}) Logger
+
+		// WithError is a convenience method for one-off forks to log error messages under the key "error".
+		WithError(err error) Logger
+
+		// Fork returns a copy of the Logger and a fork of the context.Context to pass through.
+		Fork(context.Context) (Logger, context.Context)
+
+		Debug(string)
+		Info(string)
+		Warning(string)
+		Error(string)
+		Fatal(string)
+	}
+
+	logger struct {
+		mu     sync.Mutex
+		values map[string]interface{}
+	}
+
+	// contextKey is a separate type to prevent collisions with other packages.
+	contextKey int
+)
+
+const (
+	loggerKey contextKey = iota
+)
+
+func FromContext(ctx context.Context) (Logger, context.Context) {
+	maybeLogger := ctx.Value(loggerKey)
+
+	if maybeLogger == nil {
+		l := Background()
+		return l, context.WithValue(ctx, loggerKey, l)
+	}
+
+	if l, ok := maybeLogger.(*logger); ok {
+		return l, ctx
+	}
+
+	panic(fmt.Sprintf("expected logger in context, found %+v", maybeLogger))
+}
+func Background() Logger {
+	return &logger{
+		values: map[string]interface{}{},
+	}
+}
+
+func (l *logger) AddField(name string, value interface{}) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	// TODO: check it doesn't exist already?
+	l.values[name] = value
+}
+func (l *logger) WithField(name string, value interface{}) Logger {
+	clone, _ := l.Fork(context.Background())
+	clone.AddField(name, value)
+	return clone
+}
+func (l *logger) WithError(err error) Logger {
+	return l.WithField("error", err)
+}
+
+func (l *logger) Fork(ctx context.Context) (Logger, context.Context) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	clone := &logger{
+		values: map[string]interface{}{},
+	}
+	for k, v := range l.values {
+		clone.values[k] = v
+	}
+	return clone, context.WithValue(ctx, loggerKey, clone)
+}
+
+func (l *logger) Debug(message string) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	log.WithFields(log.Fields(l.values)).Debug(message)
+}
+func (l *logger) Info(message string) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	log.WithFields(log.Fields(l.values)).Info(message)
+}
+func (l *logger) Warning(message string) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	log.WithFields(log.Fields(l.values)).Warning(message)
+}
+func (l *logger) Error(message string) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	log.WithFields(log.Fields(l.values)).Error(message)
+}
+func (l *logger) Fatal(message string) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	log.WithFields(log.Fields(l.values)).Fatal(message)
+}
diff --git a/main.go b/main.go
index 0a15ac7..a3ca9d3 100644
--- a/main.go
+++ b/main.go
@@ -5,10 +5,12 @@
 package main
 
 import (
+	"context"
 	"flag"
 	"log"
 
 	"go.eth.moe/catbus-actuator-wakeonlan/config"
+	"go.eth.moe/catbus-actuator-wakeonlan/logger"
 	"go.eth.moe/catbus-actuator-wakeonlan/mqtt"
 	"go.eth.moe/catbus-actuator-wakeonlan/wakeonlan"
 )
@@ -24,19 +26,28 @@ func main() {
 		log.Fatal("must set -config-path")
 	}
 
+	log, _ := logger.FromContext(context.Background())
+
 	config, err := config.ParseFile(*configPath)
 	if err != nil {
-		log.Fatalf("could not parse config file: %q", err)
+		log.AddField("config-path", *configPath)
+		log.WithError(err).Fatal("could not parse config file")
 	}
 
+	log.AddField("broker-uri", config.Broker)
+
 	brokerOptions := mqtt.NewClientOptions()
 	brokerOptions.AddBroker(config.Broker)
 	brokerOptions.SetAutoReconnect(true)
 	brokerOptions.SetConnectionLostHandler(func(_ mqtt.Client, err error) {
-		log.Printf("disconnected from MQTT broker %s: %v", config.Broker, err)
+		log := log
+		if err != nil {
+			log = log.WithError(err)
+		}
+		log.Error("disconnected from MQTT broker")
 	})
 	brokerOptions.SetOnConnectHandler(func(broker mqtt.Client) {
-		log.Printf("connected to MQTT broker %v", config.Broker)
+		log.Info("connected to MQTT broker")
 
 		for topic := range config.MACsByTopic {
 			token := broker.Subscribe(topic, mqtt.AtLeastOnce, func(_ mqtt.Client, msg mqtt.Message) {
@@ -44,20 +55,26 @@ func main() {
 				if !ok {
 					return
 				}
+
+				log.AddField("mac", mac)
+				log.AddField("topic", topic)
 				if err := wakeonlan.Wake(mac); err != nil {
-					log.Printf("could not send wake-on-lan: %v")
+					log.WithError(err).Error("could not send wake-on-lan packet")
+					return
 				}
+				log.Info("sent wake-on-lan packet")
 			})
 			if err := token.Error(); err != nil {
-				log.Printf("could not subscribe to %q: %v", topic, err)
-
+				log := log.WithError(err)
+				log.AddField("topic", topic)
+				log.Error("could not subscribe to MQTT topic")
 			}
 		}
 	})
 
 	broker := mqtt.NewClient(brokerOptions)
 	if token := broker.Connect(); token.Error() != nil {
-		log.Fatalf("could not connect to MQTT broker: %v", token.Error())
+		log.WithError(token.Error()).Fatal("could not connect to MQTT broker")
 	}
 
 	select {}