From 2def4b13ace19df30a3eef332ac01f3a4189887d Mon Sep 17 00:00:00 2001 From: Arsen Musayelyan Date: Sat, 23 Apr 2022 19:58:00 -0700 Subject: [PATCH] Add debug logging --- btsetup.go | 1 + dfu.go | 10 ++++++++++ infinitime.go | 46 +++++++++++++++++++++++++++++++++++++++++++++- music.go | 1 + 4 files changed, 57 insertions(+), 1 deletion(-) diff --git a/btsetup.go b/btsetup.go index 3d33516..6a65157 100644 --- a/btsetup.go +++ b/btsetup.go @@ -73,6 +73,7 @@ func (a *Agent) RequestPasskey(device dbus.ObjectPath) (uint32, *dbus.Error) { if a.ReqPasskey == nil { return 0, errAuthFailed } + log.Debug().Msg("Passkey requested, calling onReqPasskey callback") passkey, err := a.ReqPasskey() if err != nil { return 0, errAuthFailed diff --git a/dfu.go b/dfu.go index 5a7365f..de27bdd 100644 --- a/dfu.go +++ b/dfu.go @@ -313,6 +313,7 @@ func (dfu *DFU) Reset() { // on waits for the given command to be received on // the control point characteristic, then runs the callback. func (dfu *DFU) on(cmd []byte, onCmdCb func(data []byte) error) error { + log.Debug().Hex("expecting", cmd).Msg("Waiting for command") // Use for loop in case of invalid property for { select { @@ -324,6 +325,10 @@ func (dfu *DFU) on(cmd []byte, onCmdCb func(data []byte) error) error { } // Assert propery value as byte slice data := propChanged.Value.([]byte) + log.Debug(). + Hex("expecting", cmd). + Hex("received", data). + Msg("Received command") // If command has prefix of given command if bytes.HasPrefix(data, cmd) { // Return callback with data after command @@ -408,6 +413,7 @@ func (dfu *DFU) stepSeven() error { if err != nil { return err } + log.Debug().Msg("Sent firmware image segment") // Increment bytes sent by amount read dfu.bytesSent += len(segment) } @@ -415,6 +421,10 @@ func (dfu *DFU) stepSeven() error { err := dfu.on(DFUNotifPktRecvd, func(data []byte) error { // Set bytes received to data returned by InfiniTime dfu.bytesRecvd = int(binary.LittleEndian.Uint32(data)) + log.Debug(). + Int("sent", dfu.bytesSent). + Int("rcvd", dfu.bytesRecvd). + Msg("Received packet receipt notification") if dfu.bytesRecvd != dfu.bytesSent { return ErrDFUSizeMismatch } diff --git a/infinitime.go b/infinitime.go index 8fa0fe4..f2ab1b0 100644 --- a/infinitime.go +++ b/infinitime.go @@ -18,6 +18,11 @@ import ( "go.arsenm.dev/infinitime/blefs" ) +// This global is used to store the logger. +// log.Logger is not used as it would interfere +// with the package importing the library +var log zerolog.Logger + const BTName = "InfiniTime" const ( @@ -90,7 +95,7 @@ func Connect(opts *Options) (*Device, error) { opts = DefaultOptions } - opts.Logger = opts.Logger.Level(opts.LogLevel) + log = opts.Logger.Level(opts.LogLevel) // Set passkey request callback setOnPasskeyReq(opts.OnReqPasskey) @@ -131,16 +136,25 @@ func connect(opts *Options, first bool) (dev *device.Device1, err error) { // device, skip if opts.WhitelistEnabled && !contains(opts.Whitelist, listDev.Properties.Address) { + log.Debug(). + Str("mac", listDev.Properties.Address). + Msg("InfiniTime device skipped as it is not in whitelist") continue } // Set device dev = listDev + + log.Debug(). + Str("mac", dev.Properties.Address). + Msg("InfiniTime device found in list") + break } // If device not set if dev == nil { + log.Debug().Msg("No device found in list, attempting to discover") // Discover devices on adapter discoverCh, cancel, err := bt.Discover(defaultAdapter, &adapter.DiscoveryFilter{Transport: "le"}) if err != nil { @@ -168,11 +182,18 @@ func connect(opts *Options, first bool) (dev *device.Device1, err error) { // device, skip if opts.WhitelistEnabled && !contains(opts.Whitelist, discovered.Properties.Address) { + log.Debug(). + Str("mac", discovered.Properties.Address). + Msg("Discovered InfiniTime device skipped as it is not in whitelist") continue } // Set device dev = discovered + + log.Debug(). + Str("mac", dev.Properties.Address). + Msg("InfiniTime device discovered") break } // Stop discovery @@ -189,6 +210,7 @@ func connect(opts *Options, first bool) (dev *device.Device1, err error) { reconnRequired := false // If device is not connected if !dev.Properties.Connected { + log.Debug().Msg("Device not connected, connecting") // Connect to device err = dev.Connect() if err != nil { @@ -200,6 +222,7 @@ func connect(opts *Options, first bool) (dev *device.Device1, err error) { // If device is not paired if !dev.Properties.Paired { + log.Debug().Msg("Device not paired, pairing") // Pair device err = dev.Pair() if err != nil { @@ -217,6 +240,7 @@ func connect(opts *Options, first bool) (dev *device.Device1, err error) { // was required, and the OnReconnect callback exists, // run it if !first && reconnRequired && opts.OnReconnect != nil { + log.Debug().Msg("Reconnected to device, running OnReconnect callback") opts.OnReconnect() } @@ -338,6 +362,7 @@ func (i *Device) resolveChars() error { } // For every discovered characteristics for _, char := range chars { + charResolved := true // Set correct characteristics switch char.Properties.UUID { case NewAlertChar: @@ -376,6 +401,13 @@ func (i *Device) resolveChars() error { i.fsVersionChar = char case WeatherDataChar: i.weatherDataChar = char + default: + charResolved = false + } + if charResolved { + log.Debug(). + Str("uuid", char.Properties.UUID). + Msg("Resolved characteristic") } } return nil @@ -478,6 +510,7 @@ func (i *Device) WatchHeartRate() (<-chan uint8, func(), error) { for { select { case <-done: + log.Debug().Str("func", "WatchMotion").Msg("Received done signal") close(out) close(done) i.heartRateChar.StopNotify() @@ -488,6 +521,7 @@ func (i *Device) WatchHeartRate() (<-chan uint8, func(), error) { // Send heart rate to channel out <- uint8(event.Value.([]byte)[1]) } else if event.Name == "Notifying" && !event.Value.(bool) { + log.Debug().Str("func", "WatchMotion").Msg("Notifications stopped, restarting") i.heartRateChar.StartNotify() } } @@ -522,6 +556,7 @@ func (i *Device) WatchBatteryLevel() (<-chan uint8, func(), error) { for { select { case <-done: + log.Debug().Str("func", "WatchMotion").Msg("Received done signal") close(out) close(done) i.battLevelChar.StopNotify() @@ -532,6 +567,7 @@ func (i *Device) WatchBatteryLevel() (<-chan uint8, func(), error) { // Send heart rate to channel out <- uint8(event.Value.([]byte)[0]) } else if event.Name == "Notifying" && !event.Value.(bool) { + log.Debug().Str("func", "WatchMotion").Msg("Notifications stopped, restarting") i.battLevelChar.StartNotify() } } @@ -566,6 +602,7 @@ func (i *Device) WatchStepCount() (<-chan uint32, func(), error) { for { select { case <-done: + log.Debug().Str("func", "WatchMotion").Msg("Received done signal") close(out) close(done) i.stepCountChar.StopNotify() @@ -576,6 +613,7 @@ func (i *Device) WatchStepCount() (<-chan uint32, func(), error) { // Send step count to channel out <- binary.LittleEndian.Uint32(event.Value.([]byte)) } else if event.Name == "Notifying" && !event.Value.(bool) { + log.Debug().Str("func", "WatchMotion").Msg("Notifications stopped, restarting") i.stepCountChar.StartNotify() } } @@ -610,6 +648,7 @@ func (i *Device) WatchMotion() (<-chan MotionValues, func(), error) { for { select { case <-done: + log.Debug().Str("func", "WatchMotion").Msg("Received done signal") close(out) close(done) i.motionValChar.StopNotify() @@ -622,6 +661,7 @@ func (i *Device) WatchMotion() (<-chan MotionValues, func(), error) { // Send step count to channel out <- motionVals } else if event.Name == "Notifying" && !event.Value.(bool) { + log.Debug().Str("func", "WatchMotion").Msg("Notifications stopped, restarting") i.motionValChar.StartNotify() } } @@ -758,11 +798,13 @@ func (i *Device) AddWeatherEvent(event interface{}) error { return err } + log.Debug().Interface("event", event).Msg("Adding weather event") // Write data to weather data characteristic return i.weatherDataChar.WriteValue(data, nil) } func (i *Device) checkStatus(char *gatt.GattCharacteristic1) error { + log.Debug().Msg("Checking characteristic status") connected, err := i.device.GetConnected() if err != nil { return err @@ -771,7 +813,9 @@ func (i *Device) checkStatus(char *gatt.GattCharacteristic1) error { return ErrNotConnected } if char == nil { + log.Debug().Msg("Characteristic not available (nil)") return ErrCharNotAvail } + log.Debug().Str("uuid", char.Properties.UUID).Msg("Characteristic available") return nil } diff --git a/music.go b/music.go index a18b240..52066cc 100644 --- a/music.go +++ b/music.go @@ -72,6 +72,7 @@ func (mc MusicCtrl) WatchEvents() (<-chan MusicEvent, error) { for event := range ch { // If value changes if event.Name == "Value" { + log.Debug().Bytes("value", event.Value.([]byte)).Msg("Received music event from watch") // Send music event to channel musicEventCh <- MusicEvent(event.Value.([]byte)[0]) }