Add syncer debug mode (like assigner debug mode). Rename variables fo…

…r clarity. Split out decision of assignment for clarity.

cmd/depsyncer/main.go

@@ -30,6 +30,7 @@ func main() {
 		flLimit   = flag.Int("limit", 0, "limit fetch and sync calls to this many devices (0 for server default)")
 		flDebug   = flag.Bool("debug", false, "log debug messages")
 		flADebug  = flag.Bool("debug-assigner", false, "additional debug logging of the device assigner")
+		flSDebug  = flag.Bool("debug-syncer", false, "additional debug logging of the device syncer")
 		flStorage = flag.String("storage", "file", "storage backend")
 		flDSN     = flag.String("storage-dsn", "", "storage data source name")
 		flWebhook = flag.String("webhook-url", "", "URL to send requests to")
@@ -128,7 +129,7 @@ func main() {
 			depsync.WithAssignerLogger(logger.With("component", "assigner")),
 		}
 		if *flADebug {
-			assignerOpts = append(assignerOpts, depsync.WithDebug())
+			assignerOpts = append(assignerOpts, depsync.WithAssignerDebug())
 		}
 		assigner := depsync.NewAssigner(
 			client,
@@ -171,6 +172,9 @@ func main() {
 		if *flLimit > 0 {
 			syncerOpts = append(syncerOpts, depsync.WithLimit(*flLimit))
 		}
+		if *flSDebug {
+			syncerOpts = append(syncerOpts, depsync.WithDebug())
+		}
 		syncer := depsync.NewSyncer(
 			client,
 			name,

sync/assigner.go

@@ -51,8 +51,8 @@ func WithAssignerLogger(logger log.Logger) AssignerOption {
 	}
 }
 
-// WithDebug enables additional assigner-specific debug logging for troubleshooting.
-func WithDebug() AssignerOption {
+// WithAssignerDebug enables additional assigner-specific debug logging for troubleshooting.
+func WithAssignerDebug() AssignerOption {
 	return func(a *Assigner) {
 		a.debug = true
 	}
@@ -82,32 +82,22 @@ func (a *Assigner) ProcessDeviceResponse(ctx context.Context, resp *godep.Device
 		return nil
 	}
 
-	var serials []string
+	var serialsToAssign []string
 	for _, device := range resp.Devices {
 		if a.debug {
-			logger.Debug(
-				"msg", "device",
-				"serial_number", device.SerialNumber,
-				"device_assigned_by", device.DeviceAssignedBy,
-				"device_assigned_date", device.DeviceAssignedDate,
-				"op_date", device.OpDate,
-				"op_type", device.OpType,
-				"profile_assign_time", device.ProfileAssignTime,
-				"push_push_time", device.ProfilePushTime,
-				"profile_uuid", device.ProfileUUID,
-			)
+			logs := []interface{}{"msg", "device"}
+			logs = append(logs, logDevice(device)...)
+			logger.Debug(logs...)
 		}
-		if strings.ToLower(device.OpType) == "added" {
-			// we currently only listen for an op_type of "added." the other
-			// op_types are ambiguous and it would be needless to assign the
-			// profile UUID every single time we get an update.
-			serials = append(serials, device.SerialNumber)
+		// note that we may see multiple serial number "events"
+		if shouldAssignDevice(device) {
+			serialsToAssign = append(serialsToAssign, device.SerialNumber)
 		}
 	}
 
 	logger = logger.With("profile_uuid", profileUUID)
 
-	if len(serials) < 1 {
+	if len(serialsToAssign) < 1 {
 		if a.debug {
 			logger.Debug(
 				"msg", "no serials to assign",
@@ -117,26 +107,38 @@ func (a *Assigner) ProcessDeviceResponse(ctx context.Context, resp *godep.Device
 		return nil
 	}
 
-	apiResp, err := a.client.AssignProfile(ctx, a.name, profileUUID, serials...)
+	apiResp, err := a.client.AssignProfile(ctx, a.name, profileUUID, serialsToAssign...)
 	if err != nil {
 		logger.Info(
 			"msg", "assign profile",
-			"devices", len(serials),
+			"devices", len(serialsToAssign),
 			"err", err,
 		)
 		return fmt.Errorf("assign profile: %w", err)
 	}
 
 	logs := []interface{}{
 		"msg", "profile assigned",
-		"devices", len(serials),
+		"devices", len(serialsToAssign),
 	}
 	logs = append(logs, logCountsForResults(apiResp.Devices)...)
 	logger.Info(logs...)
 
 	return nil
 }
 
+// shouldAssignDevice decides whether a device "event" should be passed
+// off to the assigner.
+func shouldAssignDevice(device godep.Device) bool {
+	// we currently only listen for an op_type of "added." the other
+	// op_types are ambiguous and it would be needless to assign the
+	// profile UUID every single time we get an update.
+	if strings.ToLower(device.OpType) == "added" {
+		return true
+	}
+	return false
+}
+
 // logCountsForResults tries to aggregate the result types and log the counts.
 func logCountsForResults(deviceResults map[string]string) (out []interface{}) {
 	results := map[string]int{"success": 0, "not_accessible": 0, "failed": 0, "other": 0}

sync/syncer.go

@@ -34,6 +34,7 @@ type Syncer struct {
 	duration time.Duration
 	limitOpt godep.DeviceRequestOption
 	callback DeviceResponseCallback
+	debug    bool
 	// in "continuous" mode this is a channel that is selected on to interrupt
 	// the duration wait to immediately perform the next sync operation(s).
 	syncNow <-chan struct{}
@@ -80,6 +81,13 @@ func WithCallback(cb DeviceResponseCallback) SyncerOption {
 	}
 }
 
+// WithDebug enables additional syncer-specific debug logging for troubleshooting.
+func WithDebug() SyncerOption {
+	return func(s *Syncer) {
+		s.debug = true
+	}
+}
+
 // NewSyncer creates a new Syncer using client and uses store for cursor
 // storage. DEP name is specified with name.
 func NewSyncer(client *godep.Client, name string, store CursorStorage, opts ...SyncerOption) *Syncer {
@@ -181,6 +189,14 @@ func (s *Syncer) Run(ctx context.Context) error {
 			logs = append(logs, logCountsForOpTypes(doFetch, resp.Devices)...)
 			logger.Info(logs...)
 
+			if s.debug {
+				for _, device := range resp.Devices {
+					logs := []interface{}{"msg", "device"}
+					logs = append(logs, logDevice(device)...)
+					logger.Debug(logs...)
+				}
+			}
+
 			if s.callback != nil {
 				err = s.callback(ctx, doFetch, resp)
 				if err != nil {
@@ -246,3 +262,17 @@ func logCountsForOpTypes(isFetch bool, devices []godep.Device) []interface{} {
 	}
 	return logs
 }
+
+func logDevice(device godep.Device) []interface{} {
+	logs := []interface{}{
+		"serial_number", device.SerialNumber,
+		"device_assigned_by", device.DeviceAssignedBy,
+		"device_assigned_date", device.DeviceAssignedDate,
+		"op_date", device.OpDate,
+		"op_type", device.OpType,
+		"profile_assign_time", device.ProfileAssignTime,
+		"push_push_time", device.ProfilePushTime,
+		"profile_uuid", device.ProfileUUID,
+	}
+	return logs
+}