Merge pull request #13 from nsmith5/logging/middleware

Use a middleware pattern for all logging.

agent/agent.go

@@ -3,79 +3,49 @@ package agent
 import (
 	"context"
 	"errors"
-	"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 impl struct {
-	rc       *rekor.Client
+	rc       rekor.Client
 	policies []policy.Policy
 	outs     []outputs.Output
 
-	log *logrus.Logger
-
 	quit chan struct{}
 }
 
 // New constructs an agent from config or bails
 func New(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)
+	log := newLogger(c)
 
 	rc, err := rekor.NewClient(c.Server)
 	if err != nil {
-		log.WithFields(logrus.Fields{
-			"err": err,
-		}).Error(`failed to create rekor client when creating client`)
 		return nil, err
 	}
+	rc = rekor.WithLogging(rc, log)
 
 	policies := c.Policies
 
 	var outs []outputs.Output
 	for name, conf := range c.Outputs {
 		output, err := outputs.LoadDriver(name, conf)
 		if err != nil {
-			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)
+		outs = append(outs, outputs.WithLogging(output, log))
 	}
 
 	if len(outs) == 0 {
-		log.Errorf("zero output drivers configured")
 		return nil, errors.New(`zero output drivers configured`)
 	}
 
 	quit := make(chan struct{})
 
-	return &impl{rc, policies, outs, log, quit}, nil
+	return withLogging(&impl{rc, policies, outs, quit}, log), nil
 }
 
 func (a *impl) Run() error {
@@ -97,53 +67,33 @@ func (a *impl) Run() error {
 			return nil
 
 		default:
-			entry, err := a.rc.GetNextLogEntry()
+			entry, err := a.rc.GetNextEntry()
 			if err != nil {
 				if err == rekor.ErrEntryDoesntExist {
 					// Log doesn't exist yet, lets just wait 10 seconds and try again
-					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
-					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
 			}
 
-			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 {
-				a.log.Tracef("checking policy %s", p.Name)
-
 				alert, err := p.Alert(entry.Body)
 				if err != nil {
-					a.log.WithFields(logrus.Fields{
-						`err`: err,
-					}).Errorf("failure to evalute policy %s against entry", p.Name)
 					continue
 				}
 
 				if alert {
-					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 {
-							a.log.WithFields(logrus.Fields{
-								`err`: err,
-							}).Error("failed to send policy alert event")
-						} else {
-							a.log.Debug("sent policy alert event")
-						}
+						out.Send(outputs.Event{Policy: p, Entry: *entry})
 					}
 				}
 			}

agent/logging.go

@@ -0,0 +1,69 @@
+package agent
+
+import (
+	"context"
+	"os"
+
+	logrus "github.com/sirupsen/logrus"
+)
+
+func newLogger(c Config) *logrus.Logger {
+	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)
+
+	return log
+}
+
+type logAgent struct {
+	inner Agent
+	log   *logrus.Logger
+}
+
+// WithLogging adds logging to agent
+func withLogging(a Agent, log *logrus.Logger) Agent {
+	return &logAgent{inner: a, log: log}
+}
+
+func (a *logAgent) Run() error {
+	a.log.Info("agent: run launching")
+	err := a.inner.Run()
+	if err != nil {
+		a.log.WithFields(logrus.Fields{
+			`err`: err,
+		}).Error("agent: exit with error")
+		return err
+	}
+	a.log.Debug("agent: run exit without error")
+	return nil
+}
+
+func (a *logAgent) Shutdown(ctx context.Context) error {
+	a.log.Info("agent: shutting down")
+	err := a.inner.Shutdown(ctx)
+	if err != nil {
+		a.log.WithFields(logrus.Fields{
+			`err`: err,
+		}).Error("agent: failed to shutdown gracefully")
+		return err
+	}
+	a.log.Debug("agent: successful graceful shutdown")
+	return nil
+}

outputs/interface.go

@@ -11,5 +11,9 @@ type Event struct {
 }
 
 type Output interface {
+	// Send pushes an alert event to a driver specific backend
 	Send(Event) error
+
+	// Name returns driver name
+	Name() string
 }

outputs/logging.go

@@ -0,0 +1,30 @@
+package outputs
+
+import "github.com/sirupsen/logrus"
+
+type ologger struct {
+	inner Output
+	log   *logrus.Logger
+}
+
+// WithLogging logs an output driver
+func WithLogging(o Output, log *logrus.Logger) Output {
+	return &ologger{inner: o, log: log}
+}
+
+func (ol *ologger) Send(e Event) error {
+	ol.log.Debugf("output: driver %s sending event", ol.inner.Name())
+	err := ol.inner.Send(e)
+	if err != nil {
+		ol.log.WithFields(logrus.Fields{
+			`err`:    err,
+			`driver`: ol.inner.Name(),
+		}).Error("output: failed to send event")
+		return err
+	}
+	return nil
+}
+
+func (ol *ologger) Name() string {
+	return ol.inner.Name()
+}

outputs/stdout/stdout.go

@@ -7,6 +7,8 @@ import (
 	"github.com/nsmith5/rekor-sidekick/outputs"
 )
 
+const driverName = `stdout`
+
 type impl struct {
 	enc *json.Encoder
 }
@@ -15,12 +17,16 @@ func (i *impl) Send(e outputs.Event) error {
 	return i.enc.Encode(e)
 }
 
+func (i *impl) Name() string {
+	return driverName
+}
+
 func New(map[string]interface{}) (outputs.Output, error) {
 	enc := json.NewEncoder(os.Stdout)
 	enc.SetIndent("", "\t")
 	return &impl{enc}, nil
 }
 
 func init() {
-	outputs.RegisterDriver("stdout", outputs.CreatorFunc(New))
+	outputs.RegisterDriver(driverName, outputs.CreatorFunc(New))
 }

rekor/client.go

@@ -10,29 +10,7 @@ import (
 	"time"
 )
 
-var (
-	// ErrEntryDoesntExist signals a log entry that hasn't made it into the Rekor log just yet
-	ErrEntryDoesntExist = errors.New(`Rekor entry doesn't exist yet`)
-)
-
-// LogEntry is a Rekor log entry
-type LogEntry struct {
-	URL          string
-	IntegratedAt time.Time
-	Index        uint
-	Body         map[string]interface{}
-}
-
-// treeState represents the current state of the transparency log (size
-// etc)
-type treeState struct {
-	RootHash       string
-	SignedTreeHead string
-	TreeSize       uint
-}
-
-// Client is a Rekor api client
-type Client struct {
+type impl struct {
 	baseURL      string
 	currentIndex uint
 
@@ -41,8 +19,8 @@ type Client struct {
 
 // NewClient returns a Rekor client or fails if the baseURL
 // is misconfigured.
-func NewClient(baseURL string) (*Client, error) {
-	rc := Client{
+func NewClient(baseURL string) (Client, error) {
+	rc := impl{
 		baseURL:      baseURL,
 		currentIndex: 0,
 		Client:       new(http.Client),
@@ -51,7 +29,7 @@ func NewClient(baseURL string) (*Client, error) {
 	// Grab the latest signed tree state and use the tree size as a starting
 	// point to start iterating log entries. Its not the very tip of the log,
 	// but its close enough for us.
-	state, err := rc.getTreeState()
+	state, err := rc.GetTreeState()
 	if err != nil {
 		// If this bailed... we're going to guess its probably misconfiguration
 		// not a temporary outage. Lets just bail hard.
@@ -62,7 +40,7 @@ func NewClient(baseURL string) (*Client, error) {
 	return &rc, nil
 }
 
-func (rc *Client) getLogEntry(index uint) (*LogEntry, error) {
+func (rc *impl) GetEntry(index uint) (*LogEntry, error) {
 	var entry LogEntry
 
 	entry.Index = index
@@ -140,18 +118,16 @@ func (rc *Client) getLogEntry(index uint) (*LogEntry, error) {
 	return &entry, nil
 }
 
-// GetNextLogEntry pulls the next entry in the Rekor log. If the
-// next log doesn't exist yet ErrEntryDoesntExist is returned.
-func (rc *Client) GetNextLogEntry() (*LogEntry, error) {
-	entry, err := rc.getLogEntry(rc.currentIndex)
+func (rc *impl) GetNextEntry() (*LogEntry, error) {
+	entry, err := rc.GetEntry(rc.currentIndex)
 	if err != nil {
 		return nil, err
 	}
 	rc.currentIndex++
 	return entry, nil
 }
 
-func (rc *Client) getTreeState() (*treeState, error) {
+func (rc *impl) GetTreeState() (*TreeState, error) {
 	url := fmt.Sprintf("%s/api/v1/log", rc.baseURL)
 
 	req, err := http.NewRequest(`GET`, url, nil)
@@ -165,7 +141,7 @@ func (rc *Client) getTreeState() (*treeState, error) {
 	}
 	defer resp.Body.Close()
 
-	var state treeState
+	var state TreeState
 	err = json.NewDecoder(resp.Body).Decode(&state)
 	if err != nil {
 		return nil, err

rekor/client_test.go

@@ -44,7 +44,7 @@ func TestGetLogEntry(t *testing.T) {
 		t.Fatal(err)
 	}
 
-	entry, err := rc.getLogEntry(1)
+	entry, err := rc.GetEntry(1)
 	if err != nil {
 		t.Fatal(err)
 	}
@@ -67,7 +67,7 @@ func TestGetTreeState(t *testing.T) {
 		t.Fatal(err)
 	}
 
-	_, err = rc.getTreeState()
+	_, err = rc.GetTreeState()
 	if err != nil {
 		t.Fatal(err)
 	}