search

j-kaltes / Juggluco

Android app for Freestyle Libre 1,2 and 3, Dexcom G7 and Chinese Sibionics 1 sensors
https://www.juggluco.nl
GNU General Public License v3.0
228 stars 62 forks source link

Libre2 reconnect failed with status=19 #65

Closed ah7675 closed 1 year ago

ah7675 commented 1 year ago

Phone: Pixel 4a Android 13, TQ3A.230805.001 (2023 Aug.5) Juggluco: 5.1.5 Sensor: Libre2 CA

First, really appreciate your work for all libre2/3 users!

Recently, I switched from stock librelink app 2.8.4 to juggulco to get continuous readings. However, I have experienced serious disconnection issue. More precisely, it takes long time to reconnect, could vary from 5mins to hour. And none of workaround helps (Wakelock/Android 13/Turbo).

From my observation, bluetooth connection seems always got terminated with status 19 after sending authentication message to sensor. Sometimes it succeed after only few retries, but sometimes not. NFC scan doesn't seem help either.

Please advise how to address this issue, or what should I provide for further investigation. Thank you.

Below are some logs for both failure and success case.

Failure case:

08-11 10:48:56.116 16037 17379 D BluetoothGatt: onClientConnectionState() - status=0 clientIf=6 device=BC:6E:6D:AD:3D:3D
08-11 10:48:56.117 16037 17379 I logno   : I/MyGattCallback 3MH00LQZZT0 onConnectionStateChange, status:0, state: CONNECTED
08-11 10:48:56.117 16037 17379 D BluetoothGatt: readRssi() - device: BC:6E:6D:AD:3D:3D
08-11 10:48:56.122 16037 17379 D BluetoothGatt: discoverServices() - device: BC:6E:6D:AD:3D:3D
08-11 10:48:56.125 16037 17379 D BluetoothGatt: requestConnectionPriority() - params: 1
08-11 10:48:56.135 16037 17379 I logno   : I/MyGattCallback onReadRemoteRssi(BluetoothGatt,-84,0 SUCCESS
08-11 10:48:56.520 16037 17379 D BluetoothGatt: onConnectionUpdated() - Device=BC:6E:6D:AD:3D:3D interval=10 latency=0 timeout=500 status=0
08-11 10:48:56.976 16037 17379 D BluetoothGatt: onSearchComplete() = Device=BC:6E:6D:AD:3D:3D Status=0
08-11 10:48:56.977 16037 17379 I logno   : I/MyGattCallback BLE onServicesDiscovered invoked, status: 0
08-11 10:48:56.977 16037 17379 D BluetoothGatt: readRssi() - device: BC:6E:6D:AD:3D:3D
08-11 10:48:56.980 16037 17379 I logno   : I/MyGattCallback Using security generation 2
08-11 10:48:56.981 16037 17379 D BluetoothGatt: setCharacteristicNotification() - uuid: 0000f001-0000-1000-8000-00805f9b34fb enable: true
08-11 10:48:56.986 16037 17379 I logno   : I/MyGattCallback Enabled Security notification
08-11 10:48:56.986 16037 17379 I logno   : I/MyGattCallback onReadRemoteRssi(BluetoothGatt,-91,0 SUCCESS
08-11 10:48:57.006 16037 17379 I logn    : onDescriptorWrite null
08-11 10:48:57.006 16037 17379 I logno   : I/MyGattCallback Sent read security challenge
08-11 10:48:57.032 16037 17379 I logno   : I/MyGattCallback UUID: with str=false without=false
08-11 10:48:57.032 16037 17379 I logno   : I/MyGattCallback onCharacteristicChanged 0000f001-0000-1000-8000-00805f9b34fb
08-11 10:48:57.063 16037 17379 I cpp     : V1(37400,25,0x0,0x0)=0
08-11 10:48:57.064 16037 17379 I logno   : I/MyGattCallback sensdorident: C8FFDF0900A407E0
08-11 10:48:57.064 16037 17379 I cpp     : getstreamingAuthenticationData 0x724d003590
08-11 10:48:57.064 16037 17379 I logno   : I/MyGattCallback Authenticationdata: 9D7E9A44834E8B77CE570100
08-11 10:48:57.139 16037 17379 I cpp     : V1(28960,1,0x720527d9d0,0x0)=26
08-11 10:48:57.259 16037 17379 I cpp     : V2(6505,26,0x720527d9d0,0x720527d9d4)=0x1
08-11 10:48:57.260 16037 17379 D BluetoothGatt: onConnectionUpdated() - Device=BC:6E:6D:AD:3D:3D interval=10 latency=0 timeout=500 status=0
08-11 10:48:59.197 16037 16078 D BluetoothGatt: onClientConnectionState() - status=19 clientIf=6 device=BC:6E:6D:AD:3D:3D
08-11 10:48:59.197 16037 16078 I logno   : I/MyGattCallback 3MH00LQZZT0 onConnectionStateChange, status:19, state: DISCONNECTED
08-11 10:48:59.197 16037 16078 I cpp     : resetbluetooth 0

Success case:

08-11 10:50:49.707 16037 16037 I logno   : D/SuperGattCallback 3MH00LQZZT0 Try connection to BC:6E:6D:AD:3D:3D
08-11 10:50:49.708 16037 16037 D BluetoothGatt: connect() - device: BC:6E:6D:AD:3D:3D, auto: true
08-11 10:50:49.708 16037 16037 D BluetoothGatt: registerApp()
08-11 10:50:49.708 16037 16037 D BluetoothGatt: registerApp() - UUID=df2f4a4b-d636-488b-aa56-a4206d468ecb
08-11 10:50:49.712 16037 16037 D BluetoothGatt: requestConnectionPriority() - params: 1
08-11 10:50:49.714 16037 17346 D BluetoothGatt: onClientRegistered() - status=0 clientIf=6
08-11 10:50:55.255 16037 17346 D BluetoothGatt: onClientConnectionState() - status=0 clientIf=6 device=BC:6E:6D:AD:3D:3D
08-11 10:50:55.255 16037 17346 I logno   : I/MyGattCallback 3MH00LQZZT0 onConnectionStateChange, status:0, state: CONNECTED
08-11 10:50:55.255 16037 17346 D BluetoothGatt: readRssi() - device: BC:6E:6D:AD:3D:3D
08-11 10:50:55.260 16037 17346 D BluetoothGatt: discoverServices() - device: BC:6E:6D:AD:3D:3D
08-11 10:50:55.264 16037 17346 D BluetoothGatt: requestConnectionPriority() - params: 1
08-11 10:50:55.270 16037 17346 I logno   : I/MyGattCallback onReadRemoteRssi(BluetoothGatt,-86,0 SUCCESS
08-11 10:50:55.653 16037 17346 D BluetoothGatt: onConnectionUpdated() - Device=BC:6E:6D:AD:3D:3D interval=10 latency=0 timeout=500 status=0
08-11 10:50:56.063 16037 17346 D BluetoothGatt: onSearchComplete() = Device=BC:6E:6D:AD:3D:3D Status=0
08-11 10:50:56.063 16037 17346 I logno   : I/MyGattCallback BLE onServicesDiscovered invoked, status: 0
08-11 10:50:56.063 16037 17346 D BluetoothGatt: readRssi() - device: BC:6E:6D:AD:3D:3D
08-11 10:50:56.068 16037 17346 I logno   : I/MyGattCallback Using security generation 2
08-11 10:50:56.068 16037 17346 D BluetoothGatt: setCharacteristicNotification() - uuid: 0000f001-0000-1000-8000-00805f9b34fb enable: true
08-11 10:50:56.075 16037 17346 I logno   : I/MyGattCallback Enabled Security notification
08-11 10:50:56.075 16037 17346 I logno   : I/MyGattCallback onReadRemoteRssi(BluetoothGatt,-82,0 SUCCESS
08-11 10:50:56.102 16037 17346 I logn    : onDescriptorWrite null
08-11 10:50:56.102 16037 17346 I logno   : I/MyGattCallback Sent read security challenge
08-11 10:50:56.127 16037 17346 I logno   : I/MyGattCallback UUID: with str=false without=false
08-11 10:50:56.127 16037 17346 I logno   : I/MyGattCallback onCharacteristicChanged 0000f001-0000-1000-8000-00805f9b34fb
08-11 10:50:56.141 16037 17346 I cpp     : V1(37400,26,0x0,0x0)=0
08-11 10:50:56.141 16037 17346 I logno   : I/MyGattCallback sensdorident: C8FFDF0900A407E0
08-11 10:50:56.142 16037 17346 I cpp     : getstreamingAuthenticationData 0x724d003590
08-11 10:50:56.142 16037 17346 I logno   : I/MyGattCallback Authenticationdata: 9D7E9A44834E8B88FAC40100
08-11 10:50:56.202 16037 17346 I cpp     : V1(28960,1,0x720517f9d0,0x0)=29
08-11 10:50:56.270 16037 17346 I cpp     : V2(6505,29,0x720517f9d0,0x720517f9d4)=0x1
08-11 10:50:56.273 16037 17346 D BluetoothGatt: onConnectionUpdated() - Device=BC:6E:6D:AD:3D:3D interval=10 latency=0 timeout=500 status=0
j-kaltes commented 1 year ago

I can think of four possibilities:

  1. Librelink is still running in the background;
  2. Another device used with the sensor is still running;
  3. Battery optimisations are not disabled for Juggluco;
  4. Juggluco is not allowed to run in the background.

The logcat of the success case stops immediately at the point the failure case had an error. It would be more informative if it displayed what happened instead of the status=19 connection error. EDIT: In the displayed case the connection succeeded less than two minutes after the failure. So this wasn't serious. It is possible that in cases that the connection errors lasted for an hour something else happened.

ah7675 commented 1 year ago

Thanks for quick response.

  1. librelink is stopped and permission is removed. Also wiped storage.
  2. No other device
  3. Battery optimization is set as unrestricted for juggluco.
  4. Pixel don't have such configuration, not sure how to check.
  5. As I mentioned, sometimes it's recovered in few minutes. But sometimes it takes an hour even I scanned multiple times.
  6. The screenshot, which is started about 30 minutes ago. Screenshot_20230811-160945

EDIT: Another screenshot, shows that streaming was stopped about 30 minutes, got 1 reading then disconnected again. (I have removed librelink this time) Screenshot_20230811-163020

EDIT2: Since libre2 CA couldn't activate by juggluco, the sensor was activated by librelink and then handover to juggluco after warm-up.

MasterPlexus commented 1 year ago

May it helps to clean the cache of the Bluetooth stack: Android settings, Apps , then all Apps, top right the three dots, show system apps, scroll to "Bluetooth" , tick, then ram, then clear it. Then check that Bluetooth is set to on (it will be switched off by this process sometimes). I did not loose Bluetooth settings by this, but I can not guarantee that may a linkage will be lost, but libre should still stay. This helped me in the past if Bluetooth is not working correctly for a device...

ah7675 commented 1 year ago

May it helps to clean the cache of the Bluetooth stack: Android settings, Apps , then all Apps, top right the three dots, show system apps, scroll to "Bluetooth" , tick, then ram, then clear it. Then check that Bluetooth is set to on (it will be switched off by this process sometimes). I did not loose Bluetooth settings by this, but I can not guarantee that may a linkage will be lost, but libre should still stay. This helped me in the past if Bluetooth is not working correctly for a device...

Thanks for your advice. However, those options are grayed-out in my phone. Maybe Android 13 doesn't allow it.

MasterPlexus commented 1 year ago

I have a pixel 7pro, with 13, and see.alos now, that it is greyed out (I did not need it for a longer time to do). Maybe it is under Bluetooth legacy now...

j-kaltes commented 1 year ago

I read somewhere that one should clear the data of the Bluetooth app, not just the cache. It was a very long time ago, I last tried it. Rebooting the phone is sometimes nessessary to get bluetooth working again.

ah7675 commented 1 year ago

The issue seems has gone since I changed to new sensor. Time of Active is improved a lot. Not sure if it's a faulty sensor or maybe new firmware. But anyway, close ticket for now. Thank you all.

ah7675 commented 1 year ago

Now I got more detail on this. In summary, phase2 authenticateStream is not delivered to BLE stack via writeCharacteristic, since BluetoothGatt. mDeviceBusy == true.

In regular case, callback sequence should like

  1. Sent read security challenge
  2. onCharacteristicWrite (write acked)
  3. onCharacteristicChanged (challenge advertised)
  4. Phase 2 - Sent authenticateStream
  5. Phase 2 - onCharacteristicWrite (write acked) 
    08-30 15:44:50.566  6785  6800 I logno   : I/MyGattCallback BLE onServicesDiscovered invoked, status: 0
08-30 15:44:50.566  6785  6800 I logno   : I/MyGattCallback Using security generation 2
08-30 15:44:50.576  6785  6800 I logno   : I/MyGattCallback Enabled Security notification: true
08-30 15:44:50.611  6785  6800 I logno   : I/MyGattCallback Before writeBLELogin, isDeviceBusy = false
08-30 15:44:50.611  6785  6800 I logno   : I/MyGattCallback Sent read security challenge
08-30 15:44:50.616  6785  6800 I logno   : I/MyGattCallback After writeBLELogin, isDeviceBusy = true
08-30 15:44:50.630 6785 10272 D BtGatt.GattService: onWriteCharacteristic() - increasing permit for address=C0:D0:63:B4:74:12
08-30 15:44:50.635  6785  6800 I logn    : onCharacteristicWrite, status: 0 UUID: 0000f001-0000-1000-8000-00805f9b34fb 20
08-30 15:44:50.636  6785  6800 I logno   : I/MyGattCallback UUID: with str=false without=false conphase=2
08-30 15:44:50.636  6785  6800 I logno   : I/MyGattCallback onCharacteristicChanged 0000f001-0000-1000-8000-00805f9b34fb isDeviceBusy = false
08-30 15:44:50.663  6785  6800 I logno   : I/MyGattCallback sensdorident: 15D6200900A407E0
08-30 15:44:50.663  6785  6800 I logno   : I/MyGattCallback Authenticationdata: 6A21D9CCCD81932E62E10100
08-30 15:44:50.873  6785  6800 I logn    : onCharacteristicWrite, status: 0 UUID: 0000f001-0000-1000-8000-00805f9b34fb AE 88 29 A6 48 34 D6 25 03 00 00 04 C0 AE
08-30 15:44:50.884  6785  6800 I logno   : I/MyGattCallback UUID: with str=false without=false conphase=3
08-30 15:44:50.884  6785  6800 I logno   : I/MyGattCallback onCharacteristicChanged 0000f001-0000-1000-8000-00805f9b34fb isDeviceBusy = false

However, this is what happened on my Pixel 4a & Redmi Note 11 pro 5G.

08-30 15:58:59.742  8340  8354 I logno   : I/MyGattCallback BLE onServicesDiscovered invoked, status: 0
08-30 15:58:59.742  8340  8354 I logno   : I/MyGattCallback Using security generation 2
08-30 15:58:59.753  8340  8354 I logno   : I/MyGattCallback Enabled Security notification: true
08-30 15:58:59.874  8340  8340 I logno   : I/MyGattCallback Sent read security challenge
08-30 15:58:59.940  8340 10272 D BtGatt.GattService: onWriteCharacteristic() - increasing permit for address=C0:D0:63:B4:74:12
08-30 15:58:59.942  8340  8354 I logno   : I/MyGattCallback UUID: with str=false without=false conphase=2
08-30 15:58:59.942  8340  8354 I logno   : I/MyGattCallback onCharacteristicChanged 0000f001-0000-1000-8000-00805f9b34fb isDeviceBusy = true
08-30 15:58:59.970  8340  8354 I logno   : I/MyGattCallback sensdorident: 15D6200900A407E0
08-30 15:58:59.970  8340  8354 I logno   : I/MyGattCallback Authenticationdata: 6A21D9CCCD81932E62E10100
08-30 15:59:00.128  8340  8354 I logno   : E/MyGattCallback phase2 writeCharacteristic(BLELogincharacteristic) ret=201 isDeviceBusy=true

Despite HCI snoop log shows "Write Response" is delivered before "Value Notification" and BtGatt.GattService does called onWriteCharacteristic, but MyGattCallback.onWriteCharacteristic is delayed hence didn't get the chance to set BluetoothGatt.mDeviceBusy as false.

image

I have tried call Thread.sleep then call writeCharacteristic again directly in method phase2, but it doesn't help. As prove of concept, I have added something like the following to see if any differences.

public void onCharacteristicChanged(...
        ....
        } else if (conphase == 2) {
            Runnable runnable = new Runnable(){
                public void run(){
                    phase2(value);
                }
            };
            Applic.app.getHandler().postDelayed(runnable, 100);

Refs:

ah7675 commented 1 year ago

After 24hrs test. I have never seen the status=19 again. And "Time Active" exceed 95%, I had never reach 85% in the past month. Please review https://github.com/j-kaltes/Juggluco/pull/78. Thanks.

j-kaltes commented 1 year ago

Do you still have the trace.log content from before and after the modification? I would like to see what it is doing?

j-kaltes commented 1 year ago

Why is this PostDelayed needed? Can't it only repeat with a postDelayed when it failed the previous time?

        else {          
                mBLELoginHandler = () -> {
                        if (conphase == 2) {
                                phase2(value);
                                }
                        else if (conphase == 3) {
                                phase3(value);
                                }
                        };
                Applic.app.getHandler().postDelayed(mBLELoginHandler, 100);
                }
ah7675 commented 1 year ago

Do you still have the trace.log content from before and after the modification? I would like to see what it is doing?

I build my own version and fetch log vi adb bugreport. Let me check if it still there.

Why is this PostDelayed needed? Can't it only repeat with a postDelayed when it failed the previous time?

Well, in my case, most of time it failed at the first attempt. Any concern?

j-kaltes commented 1 year ago

I like only the PostDelayed after a failed attempt, because for others it works the first time without PostDelayed and I don't want to break something.

j-kaltes commented 1 year ago

I have uploaded a version that the first time doesn't use PostDelayed and only retries 5 times. It also only modifies MyGattCallback.java

ah7675 commented 1 year ago

Do you still have the trace.log content from before and after the modification? I would like to see what it is doing?

before.log after.log - version of postDelayed at first attempt

ah7675 commented 1 year ago

I have uploaded a version that the first time doesn't use PostDelayed and only retries 5 times. It also only modifies MyGattCallback.java

Rebased on top of your latest version, testing.

ah7675 commented 1 year ago

It doesn't work, since L582 has changed conphase to 3 hence mBLELoginHandler will run with phase3 while retrying. It supposed to run with phase2 when phase2 writeCharacteristic failed.

My previous version has the same issue but never hit , because delayed at first attempt makes it always succeed.

j-kaltes commented 1 year ago

You are right. I had taken it over without looking. I have now uploaded a new version.

ah7675 commented 1 year ago

This time failed at phase3 - enableNotification.

09-01 00:26:05.112  4834  5145 I logno   : I/MyGattCallback BLE onServicesDiscovered invoked, status: 0
09-01 00:26:05.112  4834  5145 I logno   : I/MyGattCallback Using security generation 2
09-01 00:26:05.123  4834  5145 I logno   : I/MyGattCallback Enabled Security notification: true
09-01 00:26:05.141  4834  5145 I logn    : onDescriptorWrite null
09-01 00:26:05.141  4834  5145 I logno   : I/MyGattCallback Sent read security challenge
09-01 00:26:05.163  4834  5145 I logno   : D/MyGattCallback C0:D0:63:B4:74:12 onCharacteristicWrite, status:0 UUID:0000f001-0000-1000-8000-00805f9b34fb
09-01 00:26:05.164  4834  5145 I logno   : I/MyGattCallback UUID: with str=false without=false
09-01 00:26:05.164  4834  5145 I logno   : I/MyGattCallback onCharacteristicChanged 0000f001-0000-1000-8000-00805f9b34fb
09-01 00:26:05.164  4834  5145 I logno   : I/MyGattCallback sensdorident: 15D6200900A407E0
09-01 00:26:05.164  4834  5145 I cpp     : getstreamingAuthenticationData 0x75cd884dd0
09-01 00:26:05.164  4834  5145 I logno   : I/MyGattCallback Authenticationdata: 6A21D9CCCD8193A87C740100
09-01 00:26:05.164  4834  5145 I cpp     : debugclone(0,2)
09-01 00:26:05.188  4834  5145 I cpp     : gettimeofday
09-01 00:26:05.253  4834  5145 I cpp     : V1(28960,1,0x7582116040,0x0)=4
09-01 00:26:05.253  4834  5145 I cpp     : debugclone(0,2)
09-01 00:26:05.271  4834  5145 I cpp     : gettimeofday
09-01 00:26:05.372  4834  5145 I cpp     : V2(6505,4,0x7582116040,0x7582116044)=0x5
09-01 00:26:05.468  4834  5145 I logno   : I/MyGattCallback UUID: with str=false without=false
09-01 00:26:05.468  4834  5145 I logno   : I/MyGattCallback onCharacteristicChanged 0000f001-0000-1000-8000-00805f9b34fb
09-01 00:26:05.468  4834  5145 I logno   : I/MyGattCallback UUID: with str=false without=false
09-01 00:26:05.468  4834  5145 I logno   : I/MyGattCallback onCharacteristicChanged 0000f001-0000-1000-8000-00805f9b34fb
09-01 00:26:05.468  4834  5145 I cpp     : debugclone(0,2)
09-01 00:26:05.476  4834  5145 I cpp     : gettimeofday
09-01 00:26:05.530  4834  5145 I cpp     : V1(29465,4,0x7582116170,0x7582116174)=0
09-01 00:26:05.530  4834  5145 I logno   : I/MyGattCallback Gen2 session 4
09-01 00:26:05.543  4834  5145 I logno   : D/MyGattCallback C0:D0:63:B4:74:12 onCharacteristicWrite, status:0 UUID:0000f001-0000-1000-8000-00805f9b34fb
09-01 00:26:05.547  4834  5145 I logno   : I/MyGattCallback 3MH00K86P2M onConnectionStateChange, status:0, state: DISCONNECTED
09-01 00:26:05.551  4834  5145 I logno   : I/SensorBluetooth connectToActiveDevice(SuperGattCallback cb,0)

EDIT: full log

j-kaltes commented 1 year ago

You think that enableNotification(CompositeRawDatacharacteristic) failed? Why is there then an onCharacteristicWrite between Gen2 session and onConnectionStateChange?

ah7675 commented 1 year ago

You think that enableNotification(CompositeRawDatacharacteristic) failed? Why is there then an onCharacteristicWrite between Gen2 session and onConnectionStateChange?

  1. I saw "enable failed" on sensor dialog.
  2. From my observation, onConnectionStateChange, status:0 state: DISCONNECTED usually happens if gatt.disconnect was called by application.
  3. Indeed, onCharacteristicWrite is result from phase2 characteristicWrite, not enableNotification. This is exactly the same pattern as phase2 characteristicWrite fail.

EDIT: I have attached full log in https://github.com/j-kaltes/Juggluco/issues/65#issuecomment-1701375780. As you can see, there is no onCharacteristicWrite between V2 and onCharacteristicChanged, which is delayed until enableNotification is being called.

ah7675 commented 1 year ago

In summary, somehow onCharacteristicChanged take precedence over onDescriptorWrite/onCharacteristicWrite. Therefore BluetoothGatt doesn't allow to write descriptor/Characteristic when onCharacteristicChanged is invoked. So that Libre2 Gen2 handshake cannot be completed.

The solution is that schedule and defer write descriptor/Characteristic whenever BluetoothGatt.descriptorWrite/BluetoothGatt.characteristicWrite return false or BluetoothStatusCodes .ERROR_GATT_WRITE_REQUEST_BUSY.

The fix has been merged and will be part of Juggluco 5.1.13 and above.