How to handle initializeDevice failure? #2996

Closed
opened 2022-12-12 16:51:44 +00:00 by gfwilliams · 9 comments
Member

Before reporting a bug, please confirm the following:

  • I have read the wiki, and I didn't find a solution to my problem / an answer to my question.
  • I have searched the issues, and I didn't find a solution to my problem / an answer to my question.
  • If you upload an image or other content, please make sure you have read and understood the Codeberg Terms of Use

Where did you get Gadgetbridge from:

  • F-Droid
  • Gadgetbridge Nightly F-Droid repository
  • Bangle.js Gadgetbridge from the Play Store
  • I built it myself from source code (specify tag / commit)
  • I previously used Gadgetbridge from other sources and then updated to F-Droid version

Your Gadgetbridge version is:

0.71.3-banglejs (this has been an issue since Bangle.js got added though)

Your issue is:

Under some circumstances a device's initializeDevice can be called without the relevant Bluetooth characteristics having been found. In this case, getCharacteristic returns null and then TransactionBuilder write calls to that all fail.

It's quite rare, and it's possible it's due to an Android implementation issue, or maybe even just radio interference while the characteristics are being fetched.

(Also AbstractBTLEDeviceSupport.performInitialized can call it, seemingly without ever getting the services)

But the repurcussions are bad: In Bangle.js, initializeDevice still runs through, although a bunch of stuff fails. The device stays connected, but nothing works, and eventually Bangle.js is buffering up data to send and the watch just hangs, waiting for Gadgetbridge to enable notifications so it can send its data.

I checked and I can't find any other devices that check if getCharacteristic returns non-null, so I think this must apply to other watches too.

So, what I'd like to do is when getCharacteristic returns null in initializeDevice, just ask Gadgetbridge to disconnect and retry the connection which should fix it.

Can I literally just add:

        if (rxCharacteristic==null || txCharacteristic==null) {
            LOG.warn("Unable to get characteristics, forcing a disconnect.");
            GBApplication.deviceService(gbDevice).disconnect();
            return builder;
        }

Or it seems this will break stuff? It seems like AbstractBTLEDeviceSupport may be expecting that initializeDevice will always complete. Is there a better way? Can mQueue.disconnect() be called? I'm not sure it's ever used.

I also wonder if the fix for this could maybe help with #2880

Log of this happening is attached, the issue happens around 11:10:22.931.

Sorry for the ACTION_DEVICE_CHANGED spam messages - I just fixed this.

Expected

initializeDevice
20:49:12.085 [Binder:3980_A] DEBUG n.f.g.s.d.b.BangleJSDeviceSupport - discovered unsupported service: Generic Access: 00001800-0000-1000-8000-00805f9b34fb
20:49:12.086 [Binder:3980_A] DEBUG n.f.g.s.d.b.BangleJSDeviceSupport - discovered unsupported service: Generic Attribute: 00001801-0000-1000-8000-00805f9b34fb
20:49:12.086 [Binder:3980_A] DEBUG n.f.g.s.d.b.BangleJSDeviceSupport - discovered supported service: Unknown Service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e
20:49:12.086 [Binder:3980_A] INFO  n.f.g.s.d.b.BangleJSDeviceSupport -     characteristic: Unknown Characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e
20:49:12.086 [Binder:3980_A] INFO  n.f.g.s.d.b.BangleJSDeviceSupport -     characteristic: Unknown Characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e
20:49:12.086 [Binder:3980_A] INFO  n.f.g.s.d.b.BangleJSDeviceSupport - Initializing
20:49:12.087 [Binder:3980_A] INFO  n.f.g.s.d.b.BangleJSDeviceSupport - UART TX:  .....
20:49:12.087 [Binder:3980_A] INFO  n.f.g.s.d.b.BangleJSDeviceSupport - Initialization Done

When it occasionally breaks

11:10:22.931 [Binder:3980_3] DEBUG n.f.g.s.d.b.BangleJSDeviceSupport - discovered unsupported service: Generic Access: 00001800-0000-1000-8000-00805f9b34fb
11:10:22.933 [Binder:3980_3] INFO  n.f.g.s.d.b.BangleJSDeviceSupport - Initializing
11:10:22.934 [Binder:3980_3] WARN  n.f.g.s.b.TransactionBuilder - Unable to notify characteristic: null
11:10:22.934 [Binder:3980_3] INFO  n.f.g.s.d.b.BangleJSDeviceSupport - UART TX:  ...
11:10:22.934 [Binder:3980_3] WARN  n.f.g.s.b.TransactionBuilder - Unable to write characteristic: null
...
11:10:22.937 [Binder:3980_3] INFO  n.f.g.s.d.b.BangleJSDeviceSupport - Initialization Done
...
# and whenever it writes we get: TransactionBuilder - Unable to write characteristic: null

Your wearable device is:

Bangle.js

Your Android version/manufacturer flavor is:

Android 11 (MIUI 12.5.8)

But it happens on many other phones too.

#### Before reporting a bug, please confirm the following: - [x] I have read the [wiki](https://codeberg.org/Freeyourgadget/Gadgetbridge/wiki), and I didn't find a solution to my problem / an answer to my question. - [x] I have searched the [issues](https://codeberg.org/Freeyourgadget/Gadgetbridge/issues), and I didn't find a solution to my problem / an answer to my question. - [x] If you upload an image or other content, please make sure you have read and understood the [Codeberg Terms of Use](https://codeberg.org/Codeberg/org/src/branch/main/TermsOfUse.md) ### Where did you get Gadgetbridge from: * [x] F-Droid * [x] Gadgetbridge Nightly F-Droid repository * [x] Bangle.js Gadgetbridge from the Play Store * [ ] I built it myself from source code (specify tag / commit) * [ ] I previously used Gadgetbridge from other sources and then updated to F-Droid version ### Your Gadgetbridge version is: 0.71.3-banglejs (this has been an issue since Bangle.js got added though) #### Your issue is: Under some circumstances a device's `initializeDevice` can be called without the relevant Bluetooth characteristics having been found. In this case, getCharacteristic returns `null` and then `TransactionBuilder` `write` calls to that all fail. It's quite rare, and it's possible it's due to an Android implementation issue, or maybe even just radio interference while the characteristics are being fetched. (Also AbstractBTLEDeviceSupport.performInitialized can call it, seemingly without ever getting the services) But the repurcussions are bad: In Bangle.js, initializeDevice still runs through, although a bunch of stuff fails. The device stays connected, but nothing works, and eventually Bangle.js is buffering up data to send and the watch just hangs, waiting for Gadgetbridge to enable notifications so it can send its data. I checked and I can't find any other devices that check if getCharacteristic returns non-null, so I think this must apply to other watches too. So, what I'd like to do is when getCharacteristic returns null in initializeDevice, just ask Gadgetbridge to disconnect and retry the connection which should fix it. Can I literally just add: ``` if (rxCharacteristic==null || txCharacteristic==null) { LOG.warn("Unable to get characteristics, forcing a disconnect."); GBApplication.deviceService(gbDevice).disconnect(); return builder; } ``` Or it seems this will break stuff? It seems like AbstractBTLEDeviceSupport may be expecting that initializeDevice will always complete. Is there a better way? Can `mQueue.disconnect()` be called? I'm not sure it's ever used. I also wonder if the fix for this could maybe help with https://codeberg.org/Freeyourgadget/Gadgetbridge/issues/2880 Log of this happening is attached, the issue happens around 11:10:22.931. Sorry for the ACTION_DEVICE_CHANGED spam messages - I just fixed this. **Expected** ``` initializeDevice 20:49:12.085 [Binder:3980_A] DEBUG n.f.g.s.d.b.BangleJSDeviceSupport - discovered unsupported service: Generic Access: 00001800-0000-1000-8000-00805f9b34fb 20:49:12.086 [Binder:3980_A] DEBUG n.f.g.s.d.b.BangleJSDeviceSupport - discovered unsupported service: Generic Attribute: 00001801-0000-1000-8000-00805f9b34fb 20:49:12.086 [Binder:3980_A] DEBUG n.f.g.s.d.b.BangleJSDeviceSupport - discovered supported service: Unknown Service: 6e400001-b5a3-f393-e0a9-e50e24dcca9e 20:49:12.086 [Binder:3980_A] INFO n.f.g.s.d.b.BangleJSDeviceSupport - characteristic: Unknown Characteristic: 6e400002-b5a3-f393-e0a9-e50e24dcca9e 20:49:12.086 [Binder:3980_A] INFO n.f.g.s.d.b.BangleJSDeviceSupport - characteristic: Unknown Characteristic: 6e400003-b5a3-f393-e0a9-e50e24dcca9e 20:49:12.086 [Binder:3980_A] INFO n.f.g.s.d.b.BangleJSDeviceSupport - Initializing 20:49:12.087 [Binder:3980_A] INFO n.f.g.s.d.b.BangleJSDeviceSupport - UART TX: ..... 20:49:12.087 [Binder:3980_A] INFO n.f.g.s.d.b.BangleJSDeviceSupport - Initialization Done ``` **When it occasionally breaks** ``` 11:10:22.931 [Binder:3980_3] DEBUG n.f.g.s.d.b.BangleJSDeviceSupport - discovered unsupported service: Generic Access: 00001800-0000-1000-8000-00805f9b34fb 11:10:22.933 [Binder:3980_3] INFO n.f.g.s.d.b.BangleJSDeviceSupport - Initializing 11:10:22.934 [Binder:3980_3] WARN n.f.g.s.b.TransactionBuilder - Unable to notify characteristic: null 11:10:22.934 [Binder:3980_3] INFO n.f.g.s.d.b.BangleJSDeviceSupport - UART TX: ... 11:10:22.934 [Binder:3980_3] WARN n.f.g.s.b.TransactionBuilder - Unable to write characteristic: null ... 11:10:22.937 [Binder:3980_3] INFO n.f.g.s.d.b.BangleJSDeviceSupport - Initialization Done ... # and whenever it writes we get: TransactionBuilder - Unable to write characteristic: null ``` #### Your wearable device is: Bangle.js #### Your Android version/manufacturer flavor is: Android 11 (MIUI 12.5.8) But it happens on many other phones too.
Author
Member

Hi - does anyone have any thoughts on this? @joserebelo ?

I realise the issue posted was a bit long, but basically:

How do I force a device reconnect from within the initializeDevice function?

Hi - does anyone have any thoughts on this? @joserebelo ? I realise the issue posted was a bit long, but basically: **How do I force a device reconnect from within the `initializeDevice` function?**
Member

@gfwilliams sorry, I missed this issue.

I think this is actually not as rare as you think. I'm fairily sure this is what's causing reconnects to fail on my Amazfit GTR 4, and probably a lot of other devices - the symptoms are similar:

  • Connection is lost
  • Connection is re-established
  • Enabling the notifications on characteristics fails (they are null)
  • We write the initialization payload, but never get a reply because there are no notifications, so it gets stuck "Reconnecting" permanently.
Logs here
12:24:20.056 [binder:16285_3] DEBUG n.f.g.s.b.BtLEQueue - connection state change, newState: 0 (success)
12:24:20.057 [binder:16285_3] INFO  n.f.g.s.b.BtLEQueue - Disconnected from GATT server.
12:24:20.058 [binder:16285_3] DEBUG n.f.g.s.b.BtLEQueue - handleDisconnected: 0
12:24:20.058 [binder:16285_3] DEBUG n.f.g.s.b.BtLEQueue - internal gatt callback set to null
12:24:20.058 [binder:16285_3] DEBUG n.f.g.s.b.BtLEQueue - new device connection state: NOT_CONNECTED
12:24:20.059 [binder:16285_3] INFO  n.f.g.s.b.BtLEQueue - Enabling automatic ble reconnect...
12:24:20.066 [binder:16285_3] DEBUG n.f.g.s.b.BtLEQueue - new device connection state: WAITING_FOR_RECONNECT
12:24:20.121 [main] INFO  n.f.g.s.DeviceCommunicationService - Setting broadcast receivers to: true
12:24:20.142 [main] INFO  n.f.g.s.DeviceCommunicationService - Setting broadcast receivers to: true
12:24:20.152 [main] INFO  n.f.g.s.r.AutoConnectIntervalReceiver - scheduling reconnect in 8 seconds
12:24:20.159 [main] INFO  n.f.g.s.r.AutoConnectIntervalReceiver - scheduling reconnect in 16 seconds
12:24:34.632 [binder:16285_7] DEBUG n.f.g.s.b.BtLEQueue - connection state change, newState: 2 (success)
12:24:34.633 [binder:16285_7] INFO  n.f.g.s.b.BtLEQueue - Connected to GATT server.
12:24:34.633 [binder:16285_7] DEBUG n.f.g.s.b.BtLEQueue - new device connection state: CONNECTED
12:24:34.634 [binder:16285_7] INFO  n.f.g.s.b.BtLEQueue - Using cached services, skipping discovery
12:24:34.634 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Generic Attribute: 00001801-0000-1000-8000-00805f9b34fb
12:24:34.634 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Service Changed: 00002a05-0000-1000-8000-00805f9b34fb
12:24:34.635 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Generic Access: 00001800-0000-1000-8000-00805f9b34fb
12:24:34.635 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Device Name: 00002a00-0000-1000-8000-00805f9b34fb
12:24:34.635 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Appearance: 00002a01-0000-1000-8000-00805f9b34fb
12:24:34.635 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Peripheral Preferred Connection Parameters: 00002a04-0000-1000-8000-00805f9b34fb
12:24:34.636 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 00002aa6-0000-1000-8000-00805f9b34fb
12:24:34.636 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Alert Notification Service: 00001811-0000-1000-8000-00805f9b34fb
12:24:34.636 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: New Alert: 00002a46-0000-1000-8000-00805f9b34fb
12:24:34.636 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Device Information: 0000180a-0000-1000-8000-00805f9b34fb
12:24:34.636 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: System ID: 00002a23-0000-1000-8000-00805f9b34fb
12:24:34.637 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Serial Number String: 00002a25-0000-1000-8000-00805f9b34fb
12:24:34.637 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Hardware Revision String: 00002a27-0000-1000-8000-00805f9b34fb
12:24:34.637 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Software Revision String: 00002a28-0000-1000-8000-00805f9b34fb
12:24:34.637 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: PnP ID: 00002a50-0000-1000-8000-00805f9b34fb
12:24:34.637 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Unknown Service: 0000fee0-0000-1000-8000-00805f9b34fb
12:24:34.637 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Current Time: 00002a2b-0000-1000-8000-00805f9b34fb
12:24:34.638 [main] INFO  n.f.g.e.BluetoothConnectReceiver - connection attempt detected from XX:XX:XX:XX:XX:XX(Amazfit GTR 4)
12:24:34.638 [main] INFO  n.f.g.e.BluetoothConnectReceiver - Will re-connect to XX:XX:XX:XX:XX:XX(Amazfit GTR 4)
12:24:34.638 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 00000016-0000-3512-2118-0009af100700
12:24:34.642 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 00000017-0000-3512-2118-0009af100700
12:24:34.649 [main] INFO  n.f.g.s.DeviceCommunicationService - Setting broadcast receivers to: true
12:24:34.652 [main] DEBUG n.f.g.s.DeviceCommunicationService - Service startcommand: nodomain.freeyourgadget.gadgetbridge.devices.action.connect
12:24:34.643 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 00000001-0000-3512-2118-0009af100700
12:24:34.654 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 00000002-0000-3512-2118-0009af100700
12:24:34.654 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 00000004-0000-3512-2118-0009af100700
12:24:34.655 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 00000005-0000-3512-2118-0009af100700
12:24:34.655 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 00000006-0000-3512-2118-0009af100700
12:24:34.656 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: (Propr: Xiaomi Weight Service): 00001530-0000-3512-2118-0009af100700
12:24:34.656 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 00001531-0000-3512-2118-0009af100700
12:24:34.656 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 00001532-0000-3512-2118-0009af100700
12:24:34.656 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Heart Rate: 0000180d-0000-1000-8000-00805f9b34fb
12:24:34.656 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Heart Rate Measurement: 00002a37-0000-1000-8000-00805f9b34fb
12:24:34.657 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Unknown Service: 0000fee1-0000-1000-8000-00805f9b34fb
12:24:34.657 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 0000fedd-0000-1000-8000-00805f9b34fb
12:24:34.657 [binder:16285_7] INFO  n.f.g.s.d.h.Huami2021Support -     characteristic: Unknown Characteristic: 0000fede-0000-1000-8000-00805f9b34fb
12:24:34.657 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered unsupported service: Unknown Service: 00003802-0000-1000-8000-00805f9b34fb
12:24:34.658 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered unsupported service: Unknown Service: cc353442-be58-4ea2-876e-11d8d6976366
12:24:34.658 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered unsupported service: Human Interface Device: 00001812-0000-1000-8000-00805f9b34fb
12:24:34.658 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered unsupported service: Battery Service: 0000180f-0000-1000-8000-00805f9b34fb
12:24:34.663 [binder:16285_7] WARN  n.f.g.s.b.TransactionBuilder - Unable to notify characteristic: null
12:24:34.664 [binder:16285_7] WARN  n.f.g.s.b.TransactionBuilder - Unable to notify characteristic: null
12:24:34.664 [binder:16285_7] WARN  n.f.g.s.b.TransactionBuilder - Unable to notify characteristic: null
12:24:34.748 [binder:16285_7] DEBUG n.f.g.s.b.BtLEQueue - about to add: 12:24:34: Transaction task: Initializing device with 3 actions
12:24:34.751 [Gadgetbridge GATT Dispatcher] DEBUG n.f.g.s.b.BtLEQueue - About to run action: July 12, 12:24: NotifyAction on characteristic: 00000017-0000-3512-2118-0009af100700
12:24:34.766 [Gadgetbridge GATT Dispatcher] DEBUG n.f.g.s.b.a.NotifyAction - use NOTIFICATION
12:24:34.856 [binder:16285_7] DEBUG n.f.g.s.b.BtLEQueue - descriptor write: 00002902-0000-1000-8000-00805f9b34fb (success)
12:24:34.859 [Gadgetbridge GATT Dispatcher] DEBUG n.f.g.s.b.BtLEQueue - About to run action: July 12, 12:24: SetDeviceStateAction to INITIALIZING
12:24:34.866 [main] INFO  n.f.g.s.DeviceCommunicationService - Setting broadcast receivers to: true
12:24:34.868 [Gadgetbridge GATT Dispatcher] DEBUG n.f.g.s.b.BtLEQueue - About to run action: July 12, 12:24: WriteAction on characteristic: 00000016-0000-3512-2118-0009af100700
12:24:34.882 [Gadgetbridge GATT Dispatcher] DEBUG n.f.g.s.b.a.WriteAction - writing to characteristic: 00000016-0000-3512-2118-0009af100700: 0x...
12:24:34.916 [binder:16285_7] DEBUG n.f.g.s.b.BtLEQueue - characteristic write: 00000016-0000-3512-2118-0009af100700 (success)

... does not recover until a manual disconnect and reconnect
    
    

Fixing this would probably fix reconnects across all devices.

As for your question - I have no idea. This is actually one of the few areas of Gadgetbridge in which I do not yet have a lot of experience, I have to take some time in the weekend to dive into the code. We will probably have to run a few tests and see how it behaves.

I do get this issue multiple times per day, so once we have some changes that we want to test I can probably just use them for a while.

@gfwilliams sorry, I missed this issue. I think this is actually not as rare as you think. I'm fairily sure this is what's causing reconnects to fail on my Amazfit GTR 4, and probably a lot of other devices - the symptoms are similar: - Connection is lost - Connection is re-established - Enabling the notifications on characteristics fails (they are null) - We write the initialization payload, but never get a reply because there are no notifications, so it gets stuck "Reconnecting" permanently. <details> <summary>Logs here</summary> ``` 12:24:20.056 [binder:16285_3] DEBUG n.f.g.s.b.BtLEQueue - connection state change, newState: 0 (success) 12:24:20.057 [binder:16285_3] INFO n.f.g.s.b.BtLEQueue - Disconnected from GATT server. 12:24:20.058 [binder:16285_3] DEBUG n.f.g.s.b.BtLEQueue - handleDisconnected: 0 12:24:20.058 [binder:16285_3] DEBUG n.f.g.s.b.BtLEQueue - internal gatt callback set to null 12:24:20.058 [binder:16285_3] DEBUG n.f.g.s.b.BtLEQueue - new device connection state: NOT_CONNECTED 12:24:20.059 [binder:16285_3] INFO n.f.g.s.b.BtLEQueue - Enabling automatic ble reconnect... 12:24:20.066 [binder:16285_3] DEBUG n.f.g.s.b.BtLEQueue - new device connection state: WAITING_FOR_RECONNECT 12:24:20.121 [main] INFO n.f.g.s.DeviceCommunicationService - Setting broadcast receivers to: true 12:24:20.142 [main] INFO n.f.g.s.DeviceCommunicationService - Setting broadcast receivers to: true 12:24:20.152 [main] INFO n.f.g.s.r.AutoConnectIntervalReceiver - scheduling reconnect in 8 seconds 12:24:20.159 [main] INFO n.f.g.s.r.AutoConnectIntervalReceiver - scheduling reconnect in 16 seconds 12:24:34.632 [binder:16285_7] DEBUG n.f.g.s.b.BtLEQueue - connection state change, newState: 2 (success) 12:24:34.633 [binder:16285_7] INFO n.f.g.s.b.BtLEQueue - Connected to GATT server. 12:24:34.633 [binder:16285_7] DEBUG n.f.g.s.b.BtLEQueue - new device connection state: CONNECTED 12:24:34.634 [binder:16285_7] INFO n.f.g.s.b.BtLEQueue - Using cached services, skipping discovery 12:24:34.634 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Generic Attribute: 00001801-0000-1000-8000-00805f9b34fb 12:24:34.634 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Service Changed: 00002a05-0000-1000-8000-00805f9b34fb 12:24:34.635 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Generic Access: 00001800-0000-1000-8000-00805f9b34fb 12:24:34.635 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Device Name: 00002a00-0000-1000-8000-00805f9b34fb 12:24:34.635 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Appearance: 00002a01-0000-1000-8000-00805f9b34fb 12:24:34.635 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Peripheral Preferred Connection Parameters: 00002a04-0000-1000-8000-00805f9b34fb 12:24:34.636 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 00002aa6-0000-1000-8000-00805f9b34fb 12:24:34.636 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Alert Notification Service: 00001811-0000-1000-8000-00805f9b34fb 12:24:34.636 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: New Alert: 00002a46-0000-1000-8000-00805f9b34fb 12:24:34.636 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Device Information: 0000180a-0000-1000-8000-00805f9b34fb 12:24:34.636 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: System ID: 00002a23-0000-1000-8000-00805f9b34fb 12:24:34.637 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Serial Number String: 00002a25-0000-1000-8000-00805f9b34fb 12:24:34.637 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Hardware Revision String: 00002a27-0000-1000-8000-00805f9b34fb 12:24:34.637 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Software Revision String: 00002a28-0000-1000-8000-00805f9b34fb 12:24:34.637 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: PnP ID: 00002a50-0000-1000-8000-00805f9b34fb 12:24:34.637 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Unknown Service: 0000fee0-0000-1000-8000-00805f9b34fb 12:24:34.637 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Current Time: 00002a2b-0000-1000-8000-00805f9b34fb 12:24:34.638 [main] INFO n.f.g.e.BluetoothConnectReceiver - connection attempt detected from XX:XX:XX:XX:XX:XX(Amazfit GTR 4) 12:24:34.638 [main] INFO n.f.g.e.BluetoothConnectReceiver - Will re-connect to XX:XX:XX:XX:XX:XX(Amazfit GTR 4) 12:24:34.638 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 00000016-0000-3512-2118-0009af100700 12:24:34.642 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 00000017-0000-3512-2118-0009af100700 12:24:34.649 [main] INFO n.f.g.s.DeviceCommunicationService - Setting broadcast receivers to: true 12:24:34.652 [main] DEBUG n.f.g.s.DeviceCommunicationService - Service startcommand: nodomain.freeyourgadget.gadgetbridge.devices.action.connect 12:24:34.643 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 00000001-0000-3512-2118-0009af100700 12:24:34.654 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 00000002-0000-3512-2118-0009af100700 12:24:34.654 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 00000004-0000-3512-2118-0009af100700 12:24:34.655 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 00000005-0000-3512-2118-0009af100700 12:24:34.655 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 00000006-0000-3512-2118-0009af100700 12:24:34.656 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: (Propr: Xiaomi Weight Service): 00001530-0000-3512-2118-0009af100700 12:24:34.656 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 00001531-0000-3512-2118-0009af100700 12:24:34.656 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 00001532-0000-3512-2118-0009af100700 12:24:34.656 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Heart Rate: 0000180d-0000-1000-8000-00805f9b34fb 12:24:34.656 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Heart Rate Measurement: 00002a37-0000-1000-8000-00805f9b34fb 12:24:34.657 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered supported service: Unknown Service: 0000fee1-0000-1000-8000-00805f9b34fb 12:24:34.657 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 0000fedd-0000-1000-8000-00805f9b34fb 12:24:34.657 [binder:16285_7] INFO n.f.g.s.d.h.Huami2021Support - characteristic: Unknown Characteristic: 0000fede-0000-1000-8000-00805f9b34fb 12:24:34.657 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered unsupported service: Unknown Service: 00003802-0000-1000-8000-00805f9b34fb 12:24:34.658 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered unsupported service: Unknown Service: cc353442-be58-4ea2-876e-11d8d6976366 12:24:34.658 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered unsupported service: Human Interface Device: 00001812-0000-1000-8000-00805f9b34fb 12:24:34.658 [binder:16285_7] DEBUG n.f.g.s.d.h.Huami2021Support - discovered unsupported service: Battery Service: 0000180f-0000-1000-8000-00805f9b34fb 12:24:34.663 [binder:16285_7] WARN n.f.g.s.b.TransactionBuilder - Unable to notify characteristic: null 12:24:34.664 [binder:16285_7] WARN n.f.g.s.b.TransactionBuilder - Unable to notify characteristic: null 12:24:34.664 [binder:16285_7] WARN n.f.g.s.b.TransactionBuilder - Unable to notify characteristic: null 12:24:34.748 [binder:16285_7] DEBUG n.f.g.s.b.BtLEQueue - about to add: 12:24:34: Transaction task: Initializing device with 3 actions 12:24:34.751 [Gadgetbridge GATT Dispatcher] DEBUG n.f.g.s.b.BtLEQueue - About to run action: July 12, 12:24: NotifyAction on characteristic: 00000017-0000-3512-2118-0009af100700 12:24:34.766 [Gadgetbridge GATT Dispatcher] DEBUG n.f.g.s.b.a.NotifyAction - use NOTIFICATION 12:24:34.856 [binder:16285_7] DEBUG n.f.g.s.b.BtLEQueue - descriptor write: 00002902-0000-1000-8000-00805f9b34fb (success) 12:24:34.859 [Gadgetbridge GATT Dispatcher] DEBUG n.f.g.s.b.BtLEQueue - About to run action: July 12, 12:24: SetDeviceStateAction to INITIALIZING 12:24:34.866 [main] INFO n.f.g.s.DeviceCommunicationService - Setting broadcast receivers to: true 12:24:34.868 [Gadgetbridge GATT Dispatcher] DEBUG n.f.g.s.b.BtLEQueue - About to run action: July 12, 12:24: WriteAction on characteristic: 00000016-0000-3512-2118-0009af100700 12:24:34.882 [Gadgetbridge GATT Dispatcher] DEBUG n.f.g.s.b.a.WriteAction - writing to characteristic: 00000016-0000-3512-2118-0009af100700: 0x... 12:24:34.916 [binder:16285_7] DEBUG n.f.g.s.b.BtLEQueue - characteristic write: 00000016-0000-3512-2118-0009af100700 (success) ... does not recover until a manual disconnect and reconnect ``` </details> Fixing this would probably fix reconnects across all devices. As for your question - I have no idea. This is actually one of the few areas of Gadgetbridge in which I do not yet have a lot of experience, I have to take some time in the weekend to dive into the code. We will probably have to run a few tests and see how it behaves. I do get this issue multiple times per day, so once we have some changes that we want to test I can probably just use them for a while.
Author
Member

No offense, but it's great news that it's affecting you! I had it happen once or twice but it hasn't happened in months for me (although it is affecting others).

We'd have to look but if getCharacteristic was always used in such a way that it shouldn't give a non-null response, we could add a check in there and it'd fix all watches.

Either that or for each watch we just check that the characteristics it cares about are non-null, and if they are we force a reconnect. I guess that could be safer.

No offense, but it's great news that it's affecting you! I had it happen once or twice but it hasn't happened in months for me (although it is affecting others). We'd have to look but if `getCharacteristic` was always used in such a way that it shouldn't give a non-null response, we could add a check in there and it'd fix all watches. Either that or for each watch we just check that the characteristics it cares about are non-null, and if they are we force a reconnect. I guess that could be safer.
Contributor

I have a Casio GW-B5600 and all the characteristics are null on the first connectino (when pairing), but I did not observe this on any later connection.

For me the following workaround works: 2d0cd54136

The workaronud consists of calling mQueue.disconnect() followed by connect().

I have a Casio GW-B5600 and all the characteristics are null on the first connectino (when pairing), but I did not observe this on any later connection. For me the following workaround works: https://codeberg.org/johannesk/Gadgetbridge/commit/2d0cd54136977a3024c03353712788d95fbda30d The workaronud consists of calling `mQueue.disconnect()` followed by `connect()`.
Member

@gfwilliams @johannesk I was experimenting with my Amazfit GTR 4, and managed to make the issue somewhat reproducible by turning bluetooth off and on on the watch.

Instead of disconnecting and reconnecting, I set the device as waiting for reconnect, and let the reconnection mechanism trigger the reconnect at a slightly later time - this includes a back-off mechanism, which does not exist when calling disconnect and connect - which might actually enter a loop in quick succession?

This seems to have fixed the issue on my side, I will now run it for a while to check if it keeps reconnecting without issues through normal usage.

See #3219

@gfwilliams @johannesk I was experimenting with my Amazfit GTR 4, and managed to make the issue somewhat reproducible by turning bluetooth off and on on the watch. Instead of disconnecting and reconnecting, I set the device as waiting for reconnect, and let the reconnection mechanism trigger the reconnect at a slightly later time - this includes a back-off mechanism, which does not exist when calling disconnect and connect - which might actually enter a loop in quick succession? This seems to have fixed the issue on my side, I will now run it for a while to check if it keeps reconnecting without issues through normal usage. See #3219
joserebelo added the
pairing/connecting
label 2023-07-22 13:46:06 +00:00
Author
Member

I set the device as waiting for reconnect, and let the reconnection mechanism trigger the reconnect at a slightly later time - this includes a back-off mechanism

That sounds perfect! Exactly what I was after - do you think you could add it to the Bangle.js build as well, or shall I do that?

Just looking at #3219 you call builder.add(new SetDeviceStateAction(getDevice(), State.WAITING_FOR_RECONNECT, getContext())); if either of the characteristics is null?

That doesn't actually cause a disconnect though? Or does WAITING_FOR_RECONNECT automatically disconnect if the watch was connected?

> I set the device as waiting for reconnect, and let the reconnection mechanism trigger the reconnect at a slightly later time - this includes a back-off mechanism That sounds perfect! Exactly what I was after - do you think you could add it to the Bangle.js build as well, or shall I do that? Just looking at https://codeberg.org/Freeyourgadget/Gadgetbridge/pulls/3219 you call `builder.add(new SetDeviceStateAction(getDevice(), State.WAITING_FOR_RECONNECT, getContext()));` if either of the characteristics is null? That doesn't actually cause a disconnect though? Or does `WAITING_FOR_RECONNECT` automatically disconnect if the watch was connected?
Member

It seems to only trigger a connect, without disconnecting first: a02a6cba14/app/src/main/java/nodomain/freeyourgadget/gadgetbridge/service/receivers/AutoConnectIntervalReceiver.java (L87)

I can add it to the Bangle if you want, just need to try and reproduce the issue there first, maybe by toggling bluetooth on the watch too.

It seems to only trigger a connect, without disconnecting first: https://codeberg.org/Freeyourgadget/Gadgetbridge/src/commit/a02a6cba148989c4cbfa6480826a6c048bffe9ab/app/src/main/java/nodomain/freeyourgadget/gadgetbridge/service/receivers/AutoConnectIntervalReceiver.java#L87 I can add it to the Bangle if you want, just need to try and reproduce the issue there first, maybe by toggling bluetooth on the watch too.
Author
Member

Thanks for checking that! Maybe wait a bit then - I think at least for Bangle.js it would probably help to force a disconnect first.

Maybe if this is a common thing we should have a method in AbstractBTLEDeviceSupport.java for it?

Thanks for checking that! Maybe wait a bit then - I think at least for Bangle.js it would probably help to force a disconnect first. Maybe if this is a common thing we should have a method in AbstractBTLEDeviceSupport.java for it?
Author
Member

At least one user is reporting problems still: https://forum.espruino.com/conversations/378217/?offset=25#comment17199563

So I just pushed a potential fix for this that copies that line - let's hope it has some effect.

At least one user is reporting problems still: https://forum.espruino.com/conversations/378217/?offset=25#comment17199563 So I just pushed a potential fix for this that copies that line - let's hope it has some effect.
Sign in to join this conversation.
No Milestone
No Assignees
3 Participants
Notifications
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: Freeyourgadget/Gadgetbridge#2996
No description provided.