From 1c7c9f0098ad672a2f4d70c545f09e62a3d8abb1 Mon Sep 17 00:00:00 2001
From: Jesse Peterson <jessepeterson@users.noreply.github.com>
Date: Sat, 5 May 2018 11:51:33 -0700
Subject: [PATCH] Structured logging for depsync (#403)

---
 cmd/micromdm/serve.go  | 11 +++++++----
 dep/depsync/depsync.go | 32 ++++++++++++++++++++------------
 2 files changed, 27 insertions(+), 16 deletions(-)

diff --git a/cmd/micromdm/serve.go b/cmd/micromdm/serve.go
index e8d06a39..fd1195a3 100644
--- a/cmd/micromdm/serve.go
+++ b/cmd/micromdm/serve.go
@@ -161,7 +161,7 @@ func serve(args []string) error {
 	sm.setupWebhooks()
 	sm.setupCommandQueue(logger)
 	sm.setupDepClient()
-	sm.setupDEPSync()
+	sm.setupDEPSync(logger)
 	if sm.err != nil {
 		stdlog.Fatal(sm.err)
 	}
@@ -769,17 +769,20 @@ func (c *server) setupDepClient() (dep.Client, error) {
 	return client, nil
 }
 
-func (c *server) setupDEPSync() {
+func (c *server) setupDEPSync(logger log.Logger) {
 	if c.err != nil {
 		return
 	}
 
 	client := c.depClient
-	var opts []depsync.Option
+	opts := []depsync.Option{
+		depsync.WithLogger(log.With(logger, "component", "depsync")),
+	}
 	if client != nil {
 		opts = append(opts, depsync.WithClient(client))
 	}
-	_, c.err = depsync.New(c.pubclient, c.db, opts...)
+
+	_, c.err = depsync.New(c.pubclient, c.db, logger, opts...)
 	if c.err != nil {
 		return
 	}
diff --git a/dep/depsync/depsync.go b/dep/depsync/depsync.go
index 6f9794f4..f776841d 100644
--- a/dep/depsync/depsync.go
+++ b/dep/depsync/depsync.go
@@ -3,13 +3,13 @@ package depsync
 import (
 	"context"
 	"encoding/json"
-	"fmt"
-	"log"
 	"strings"
 	"sync"
 	"time"
 
 	"github.com/boltdb/bolt"
+	"github.com/go-kit/kit/log"
+	"github.com/go-kit/kit/log/level"
 	"github.com/micromdm/dep"
 	"github.com/pkg/errors"
 
@@ -28,6 +28,7 @@ type Syncer interface {
 
 type watcher struct {
 	mtx    sync.RWMutex
+	logger log.Logger
 	client dep.Client
 
 	publisher pubsub.Publisher
@@ -57,18 +58,25 @@ func WithClient(client dep.Client) Option {
 	}
 }
 
-func New(pub pubsub.PublishSubscriber, db *bolt.DB, opts ...Option) (Syncer, error) {
+func WithLogger(logger log.Logger) Option {
+	return func(w *watcher) {
+		w.logger = logger
+	}
+}
+
+func New(pub pubsub.PublishSubscriber, db *bolt.DB, logger log.Logger, opts ...Option) (Syncer, error) {
 	conf, err := LoadConfig(db)
 	if err != nil {
 		return nil, err
 	}
 	if conf.Cursor.Valid() {
-		fmt.Printf("loaded dep config with cursor: %s\n", conf.Cursor.Value)
+		level.Info(logger).Log("msg", "loaded DEP config", "cursor", conf.Cursor.Value)
 	} else {
 		conf.Cursor.Value = ""
 	}
 
 	sync := &watcher{
+		logger:    log.NewNopLogger(),
 		publisher: pub,
 		conf:      conf,
 		startSync: make(chan bool),
@@ -84,21 +92,21 @@ func New(pub pubsub.PublishSubscriber, db *bolt.DB, opts ...Option) (Syncer, err
 
 	saveCursor := func() {
 		if err := conf.Save(); err != nil {
-			log.Printf("saving cursor %s\n", err)
+			level.Info(logger).Log("err", err, "msg", "saving cursor")
 			return
 		}
-		log.Printf("saved DEP cursor at value %s\n", conf.Cursor.Value)
+		level.Info(logger).Log("msg", "saved DEP config", "cursor", conf.Cursor.Value)
 	}
 
 	go func() {
 		defer saveCursor()
 		if sync.client == nil {
 			// block until we have a DEP client to start sync process
-			log.Println("depsync: waiting for DEP token to be added before starting sync")
+			level.Info(logger).Log("msg", "waiting for DEP token to be added before starting sync")
 			<-sync.startSync
 		}
 		if err := sync.Run(); err != nil {
-			log.Println("DEP watcher failed: ", err)
+			level.Info(logger).Log("err", err, "msg", "DEP watcher failed")
 		}
 	}()
 	return sync, nil
@@ -116,13 +124,13 @@ func (w *watcher) updateClient(pubsub pubsub.Subscriber) error {
 			case event := <-tokenAdded:
 				var token conf.DEPToken
 				if err := json.Unmarshal(event.Message, &token); err != nil {
-					log.Printf("unmarshalling tokenAdded to token: %s\n", err)
+					level.Info(w.logger).Log("err", err, "msg", "unmarshalling tokenAdd to token")
 					continue
 				}
 
 				client, err := token.Client()
 				if err != nil {
-					log.Printf("creating new DEP client: %s\n", err)
+					level.Info(w.logger).Log("err", err, "msg", "creating new DEP client")
 					continue
 				}
 
@@ -160,7 +168,7 @@ FETCH:
 		} else if err != nil {
 			return err
 		}
-		fmt.Printf("more=%v, cursor=%s, fetched=%v\n", resp.MoreToFollow, resp.Cursor, resp.FetchedUntil)
+		level.Info(w.logger).Log("msg", "DEP fetch", "more", resp.MoreToFollow, "cursor", resp.Cursor, "fetched", resp.FetchedUntil)
 		w.conf.Cursor = cursor{Value: resp.Cursor, CreatedAt: time.Now()}
 		if err := w.conf.Save(); err != nil {
 			return errors.Wrap(err, "saving cursor from fetch")
@@ -188,7 +196,7 @@ SYNC:
 			return err
 		}
 		if len(resp.Devices) != 0 {
-			fmt.Printf("more=%v, cursor=%s, synced=%v\n", resp.MoreToFollow, resp.Cursor, resp.FetchedUntil)
+			level.Info(w.logger).Log("msg", "DEP sync", "more", resp.MoreToFollow, "cursor", resp.Cursor, "fetched", resp.FetchedUntil)
 		}
 		w.conf.Cursor = cursor{Value: resp.Cursor, CreatedAt: time.Now()}
 		if err := w.conf.Save(); err != nil {