Add debug logging

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

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
 			}

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
 }

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])
 			}