From 30a24c58c209d031a765de3f87bf1cdc728d4d32 Mon Sep 17 00:00:00 2001 From: Jesse Peterson Date: Fri, 21 Oct 2022 15:47:00 -0700 Subject: [PATCH] Add syncer debug mode (like assigner debug mode). Rename variables for clarity. Split out decision of assignment for clarity. --- cmd/depsyncer/main.go | 6 +++++- sync/assigner.go | 48 ++++++++++++++++++++++--------------------- sync/syncer.go | 30 +++++++++++++++++++++++++++ 3 files changed, 60 insertions(+), 24 deletions(-) diff --git a/cmd/depsyncer/main.go b/cmd/depsyncer/main.go index f5d70f8..9e6642e 100644 --- a/cmd/depsyncer/main.go +++ b/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, diff --git a/sync/assigner.go b/sync/assigner.go index 0fb867c..ec02665 100644 --- a/sync/assigner.go +++ b/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,11 +107,11 @@ 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) @@ -129,7 +119,7 @@ func (a *Assigner) ProcessDeviceResponse(ctx context.Context, resp *godep.Device logs := []interface{}{ "msg", "profile assigned", - "devices", len(serials), + "devices", len(serialsToAssign), } logs = append(logs, logCountsForResults(apiResp.Devices)...) logger.Info(logs...) @@ -137,6 +127,18 @@ func (a *Assigner) ProcessDeviceResponse(ctx context.Context, resp *godep.Device 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} diff --git a/sync/syncer.go b/sync/syncer.go index 8117523..0f5777c 100644 --- a/sync/syncer.go +++ b/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 +}