Merge pull request #12 from nsmith5/logging

Refactor logging for clarity and structure

agent.go

@@ -3,48 +3,79 @@ package main
 import (
 	"context"
 	"errors"
-	"fmt"
+	"os"
 	"time"
 
 	"github.com/nsmith5/rekor-sidekick/outputs"
 	"github.com/nsmith5/rekor-sidekick/policy"
 	"github.com/nsmith5/rekor-sidekick/rekor"
+	logrus "github.com/sirupsen/logrus"
 )
 
 type agent struct {
 	rc       *rekor.Client
 	policies []policy.Policy
 	outs     []outputs.Output
 
+	log *logrus.Logger
+
 	quit chan struct{}
 }
 
 // newAgent constructs an agent from config or bails
 func newAgent(c config) (*agent, error) {
+	log := logrus.New()
+	log.SetOutput(os.Stdout)
+	switch c.Logging.Level {
+	case "panic":
+		log.SetLevel(logrus.PanicLevel)
+	case "fatal":
+		log.SetLevel(logrus.FatalLevel)
+	case "error":
+		log.SetLevel(logrus.ErrorLevel)
+	case "warn":
+		log.SetLevel(logrus.WarnLevel)
+	case "info":
+		log.SetLevel(logrus.InfoLevel)
+	case "debug":
+		log.SetLevel(logrus.DebugLevel)
+	case "trace":
+		log.SetLevel(logrus.TraceLevel)
+	}
+	log.SetFormatter(&logrus.JSONFormatter{})
+	log.SetReportCaller(true)
+
 	rc, err := rekor.NewClient(c.RekorServerURL)
 	if err != nil {
+		log.WithFields(logrus.Fields{
+			"err": err,
+		}).Error(`failed to create rekor client when creating client`)
 		return nil, err
 	}
 
 	policies := c.Policies
 
-	fmt.Println("debug: outputs in config", c.Outputs)
-
 	var outs []outputs.Output
 	for name, conf := range c.Outputs {
 		output, err := outputs.LoadDriver(name, conf)
 		if err != nil {
-			// Huh... log this issue I guess?
+			log.WithFields(logrus.Fields{
+				"err": err,
+			}).Errorf("failed to load driver %s", name)
 			continue
 		}
+		log.Infof("Loaded output driver %s", name)
 		outs = append(outs, output)
 	}
 
-	fmt.Printf("debug: output drivers %#v\n", outs)
+	if len(outs) == 0 {
+		log.Errorf("zero output drivers configured")
+		return nil, errors.New(`zero output drivers configured`)
+	}
 
 	quit := make(chan struct{})
 
-	return &agent{rc, policies, outs, quit}, nil
+	return &agent{rc, policies, outs, log, quit}, nil
 }
 
 // run starts off the agent. The call blocks or exits returning an error
@@ -72,41 +103,48 @@ func (a *agent) run() error {
 			if err != nil {
 				if err == rekor.ErrEntryDoesntExist {
 					// Log doesn't exist yet, lets just wait 10 seconds and try again
-					fmt.Println("debug: no entry available. time to snooze")
+					a.log.Debug("no more log entries. sleeping before retry")
 					time.Sleep(10 * time.Second)
 
 				} else {
 					// Lets assume a temporary outage and retry with exponential backoff
-					fmt.Println("debug: outage! backoff started")
+					a.log.WithFields(logrus.Fields{
+						`err`:     err,
+						`backoff`: currentBackoff,
+					}).Errorf("error pulling log entry. retrying with exponential backoff")
 					time.Sleep(currentBackoff * time.Second)
 					currentBackoff *= 2
 				}
 				break
 			}
 
-			fmt.Println("debug: got an entry!")
+			a.log.Debug(`pulled an entry`)
 
 			// Incase we just recovered from a temporary outage, lets reset the backoff
 			currentBackoff = initialBackoff
 
 			// Policy checks!
 			for _, p := range a.policies {
-				fmt.Printf("debug: iterating policies")
+				a.log.Tracef("checking policy %s", p.Name)
 
 				alert, err := p.Alert(entry.Body)
 				if err != nil {
-					// huh... what to do here?
+					a.log.WithFields(logrus.Fields{
+						`err`: err,
+					}).Errorf("failure to evalute policy %s against entry", p.Name)
 					continue
 				}
 
 				if alert {
-					fmt.Println("debug: violation!")
+					a.log.Debugf("alerting on policy %s", p.Name)
 					for _, out := range a.outs {
 						err = out.Send(outputs.Event{Policy: p, Entry: *entry})
 						if err != nil {
-							fmt.Println("debug: error sending output")
+							a.log.WithFields(logrus.Fields{
+								`err`: err,
+							}).Error("failed to send policy alert event")
 						} else {
-							fmt.Println("debug: successful sent output")
+							a.log.Debug("sent policy alert event")
 						}
 					}
 				}

config.go

@@ -6,4 +6,7 @@ type config struct {
 	RekorServerURL string                            `yaml:"rekorServerURL"`
 	Policies       []policy.Policy                   `yaml:"policies"`
 	Outputs        map[string]map[string]interface{} `yaml:"outputs"`
+	Logging        struct {
+		Level string
+	}
 }

etc/config.yaml

@@ -1,5 +1,8 @@
 rekorServerURL: https://rekor.sigstore.dev
 
+logging:
+  level: trace
+
 policies:
 - name: x509-used
   description: |-

go.mod

@@ -5,6 +5,7 @@ go 1.17
 require (
 	github.com/oklog/run v1.1.0
 	github.com/open-policy-agent/opa v0.36.0
+	github.com/sirupsen/logrus v1.8.1
 	github.com/spf13/cobra v1.3.0
 	github.com/spf13/viper v1.10.1
 )

go.sum

@@ -392,6 +392,7 @@ github.com/sean-/seed v0.0.0-20170313163322-e2103e2c3529/go.mod h1:DxrIzT+xaE7yg
 github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
 github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
 github.com/sirupsen/logrus v1.6.0/go.mod h1:7uNnSEd1DgxDLC74fIahvMZmmYsHGZGEOFrfsX/uA88=
+github.com/sirupsen/logrus v1.8.1 h1:dJKuHgqk1NNQlqoA6BTlM1Wf9DOH3NBjQyu0h9+AZZE=
 github.com/sirupsen/logrus v1.8.1/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0=
 github.com/spaolacci/murmur3 v0.0.0-20180118202830-f09979ecbc72/go.mod h1:JwIasOWyU6f++ZhiEuf87xNszmSA2myDM2Kzu9HwQUA=
 github.com/spaolacci/murmur3 v1.1.0/go.mod h1:JwIasOWyU6f++ZhiEuf87xNszmSA2myDM2Kzu9HwQUA=

outputs/registry.go

@@ -2,7 +2,6 @@ package outputs
 
 import (
 	"errors"
-	"fmt"
 )
 
 type CreatorFunc func(map[string]interface{}) (Output, error)
@@ -14,17 +13,14 @@ func init() {
 }
 
 func RegisterDriver(name string, maker CreatorFunc) {
-	fmt.Println("debug: registering driver", name)
 	drivers[name] = maker
 }
 
 func LoadDriver(name string, conf map[string]interface{}) (Output, error) {
 	f, ok := drivers[name]
 	if !ok {
-		fmt.Println("debug: failed to load driver", name)
 		return nil, errors.New(`driver doesn't exist or wasn't loaded`)
 	}
 
-	fmt.Println("debug: loading driver", name)
 	return f(conf)
 }

rekor/client.go

@@ -122,7 +122,7 @@ func (rc *Client) getLogEntry(index uint) (*LogEntry, error) {
 	}
 
 	// (1) UUID -> URL
-	entry.URL = fmt.Sprintf("%s/api/v1/entries/%s", rc.baseURL, uuid)
+	entry.URL = fmt.Sprintf("%s/api/v1/log/entries/%s", rc.baseURL, uuid)
 
 	// (2) Unix time -> created time
 	entry.IntegratedAt = time.Unix(int64(unix), 0)