search

NordicSemiconductor / Android-BLE-Library

A library that makes working with Bluetooth LE on Android a pleasure. Seriously.
BSD 3-Clause "New" or "Revised" License
2.06k stars 420 forks source link

v2.2.1 breaks connection on some devices, BLE not working at all. #210

Closed andybdahl closed 4 years ago

andybdahl commented 4 years ago

Released as 2.2.1.

Originally posted by @philips77 in https://github.com/NordicSemiconductor/Android-BLE-Library/issues/200#issuecomment-651738341

The original issue merged in PR#209 breaks connection attempts on some devices, where devices will no longer be able to enqueue any requests to characteristics after connecting. Verified to work when downgrading to v2.2.0.

philips77 commented 4 years ago

Can you describe how to reproduce this? What requests do you enqueue? Please provide log.

andybdahl commented 4 years ago

LogCat from unsuccesfull connect and subsequent write request (v2.2.1):

2020-07-02 12:32:55.518 27471-27822/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Connecting...
2020-07-02 12:32:55.519 27471-27822/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2020-07-02 12:32:56.377 27471-27508/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: [Callback] Connection state changed with status: 0 and new state: 2 (CONNECTED)
2020-07-02 12:32:56.377 27471-27508/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Connected to FB:CC:FD:FE:FD:70
2020-07-02 12:32:56.378 27471-27508/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: wait(300)
2020-07-02 12:32:56.681 27471-27471/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Discovering services...
2020-07-02 12:32:56.681 27471-27471/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.discoverServices()
2020-07-02 12:32:56.810 27471-27508/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
2020-07-02 12:32:56.955 27471-27508/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Services discovered
2020-07-02 12:32:56.958 27471-27508/com.metricorr.app D/[Koin]: | create instance for [type:Single,name:'RX_UUID', primary_type:'android.os.ParcelUuid']
2020-07-02 12:32:56.959 27471-27508/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Primary service found
2020-07-02 12:32:56.962 27471-27508/com.metricorr.app D/MasterLinkConnectionNRF$MasterLinkGattCallback: RX: android.bluetooth.BluetoothGattCharacteristic@152e745, TX: android.bluetooth.BluetoothGattCharacteristic@721ae9a
2020-07-02 12:32:56.964 27471-27508/com.metricorr.app W/BluetoothGatt: Unhandled exception in callback
    java.lang.NullPointerException: Attempt to invoke interface method 'boolean java.util.Deque.add(java.lang.Object)' on a null object reference
        at no.nordicsemi.android.ble.BleManagerHandler.enqueue(BleManagerHandler.java:1193)
        at no.nordicsemi.android.ble.Request.enqueue(Request.java:1166)
        at dk.makeable.metricorr.domain.bluetooth.MasterLinkConnectionNRF$MasterLinkGattCallback.initialize(MasterLinkConnectionNRF.kt:93)
        at no.nordicsemi.android.ble.BleManagerHandler$3.onServicesDiscovered(BleManagerHandler.java:1888)
        at android.bluetooth.BluetoothGatt$1$5.run(BluetoothGatt.java:330)
        at android.bluetooth.BluetoothGatt.runOrQueueCallback(BluetoothGatt.java:789)
        at android.bluetooth.BluetoothGatt.-wrap0(Unknown Source:0)
        at android.bluetooth.BluetoothGatt$1.onSearchComplete(BluetoothGatt.java:326)
        at android.bluetooth.IBluetoothGattCallback$Stub.onTransact(IBluetoothGattCallback.java:110)
        at android.os.Binder.execTransact(Binder.java:682)
2020-07-02 12:32:56.977 27471-27823/com.metricorr.app D/MasterLinkConnectionNRF$Commander: RX: android.bluetooth.BluetoothGattCharacteristic@152e745

    [          1593685976.979 27471:27823 E/MasterLinkConnectionNRF$MLApi$suspendCancellingIfNeeded$$inlined$suspendCancellableCorojava.lang.NullPointerException: Attempt to invoke interface method 'boolean java.util.Deque.add(java.lang.Object)' on a null object reference
        at no.nordicsemi.android.ble.BleManagerHandler.enqueue(BleManagerHandler.java:1193)
        at no.nordicsemi.android.ble.Request.enqueue(Request.java:1166)
        at dk.makeable.metricorr.domain.bluetooth.MasterLinkConnectionNRF$Commander.sendRaw(MasterLinkConnectionNRF.kt:365)
        at dk.makeable.metricorr.domain.bluetooth.MasterLinkConnectionNRF$MLApi$authenticate$2.invokeSuspend(MasterLinkConnectionNRF.kt:446)
        at dk.makeable.metricorr.domain.bluetooth.MasterLinkConnectionNRF$MLApi$authenticate$2.invoke(Unknown Source:10)
        at dk.makeable.metricorr.domain.bluetooth.MasterLinkConnectionNRF$MLApi$suspendCancellingIfNeeded$$inlined$suspendCancellableCoroutine$lambda$1.invokeSuspend(MasterLinkConnectionNRF.kt:677)
        at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
        at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:56)
        at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:571)
        at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:738)
        at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:678)
        at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:665)
2020-07-02 12:32:56.981 27471-27819/com.metricorr.app W/System.err:     at no.nordicsemi.android.ble.BleManagerHandler.enqueue(BleManagerHandler.java:1193)
2020-07-02 12:32:57.014 27471-27854/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)

LogCat from succesfull connect and subsequent write request (v2.2.0):

2020-07-02 12:27:10.634 26786-26877/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Connecting...
2020-07-02 12:27:10.635 26786-26877/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, LE 1M)
2020-07-02 12:27:11.587 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: [Callback] Connection state changed with status: 0 and new state: 2 (CONNECTED)
2020-07-02 12:27:11.590 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Connected to FB:CC:FD:FE:FD:70
2020-07-02 12:27:11.595 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: wait(300)
2020-07-02 12:27:11.900 26786-26786/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Discovering services...
2020-07-02 12:27:11.901 26786-26786/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.discoverServices()
2020-07-02 12:27:12.006 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
2020-07-02 12:27:12.159 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Services discovered
2020-07-02 12:27:12.167 26786-26799/com.metricorr.app D/[Koin]: | create instance for [type:Single,name:'RX_UUID', primary_type:'android.os.ParcelUuid']
2020-07-02 12:27:12.169 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Primary service found
2020-07-02 12:27:12.183 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
2020-07-02 12:27:12.186 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Enabling notifications for 6e400003-b5a3-f393-e0a9-e50e24dcca9e
2020-07-02 12:27:12.188 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
2020-07-02 12:27:12.232 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
2020-07-02 12:27:12.234 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notifications enabled
2020-07-02 12:27:12.240 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF$MasterLinkGattCallback: RX: android.bluetooth.BluetoothGattCharacteristic@fdb4690, TX: android.bluetooth.BluetoothGattCharacteristic@1e23942
2020-07-02 12:27:12.246 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
2020-07-02 12:27:12.255 26786-26877/com.metricorr.app D/MasterLinkConnectionNRF$Commander: RX: android.bluetooth.BluetoothGattCharacteristic@fdb4690
2020-07-02 12:27:12.257 26786-26877/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:12.257 26786-26877/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:12.329 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 5F-24-63-A5-5A
2020-07-02 12:27:12.525 26786-26786/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Reading remote RSSI...
2020-07-02 12:27:12.525 26786-26786/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.readRemoteRssi()
2020-07-02 12:27:12.536 26786-26884/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Remote RSSI received: -72 dBm

    [          1593685632.544 26786:26865 D/MasterLinkConnectionNRF$Commander$tryAwaitResponse$$inlined$suspendCancellableCoroutineRX: android.bluetooth.BluetoothGattCharacteristic@fdb4690
2020-07-02 12:27:12.588 26786-26865/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:12.588 26786-26865/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)

    [          1593685632.599 26786:26786 D/MasterLinkConnectionNRF$Commander$tryAwaitResponse$$inlined$suspendCancellableCoroutineCMD: {"cmd":"info"} was sent.
2020-07-02 12:27:12.621 4256-4256/? I/Layer: id=2341 onRemoved com.metricorr.app/dk.makeable.metricorr.ui.main.MainActivity#1 

    [          1593685632.631 26786:26866 D/MasterLinkConnectionNRF$Commander$tryAwaitResponse$$inlined$suspendCancellableCoroutineRX: android.bluetooth.BluetoothGattCharacteristic@fdb4690
2020-07-02 12:27:12.719 26786-26884/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 7B-22-63-6D-64-22-3A-22-69-6E-66-6F-22-7D
2020-07-02 12:27:13.364 26786-26884/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 7B-22-72-70-6C-22-3A-22-69-6E-66-6F-22-2C-22-69-6F-62-73-6E
2020-07-02 12:27:13.370 26786-26799/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 22-3A-22-41-4E-30-32-37-38-39-33-37-38-22-2C-22-69-6F-62-74
2020-07-02 12:27:13.374 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 70-22-3A-22-76-6C-31-30-30-22-2C-22-74-69-6D-65-22-3A-31-35
2020-07-02 12:27:13.382 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 39-33-36-38-35-36-33-33-2C-22-74-65-6D-70-22-3A-32-37-33-2C
2020-07-02 12:27:13.386 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 22-76-63-63-22-3A-33-32-38-38-2C-22-68-77-22-3A-22-33-2C-31
2020-07-02 12:27:13.390 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 22-2C-22-73-77-22-3A-22-31-31-32-39-38-2E-32-35-31-32-32-2E
2020-07-02 12:27:13.394 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 33-31-30-39-32-2C-38-37-36-32-2E-32-37-37-31-35-2E-32-39-35
2020-07-02 12:27:13.455 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 35-31-2C-32-38-35-31-38-2E-33-32-30-33-34-2E-33-31-35-33-32
2020-07-02 12:27:13.510 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 20-38-38-31-36-2E-38-37-36-32-2E-32-38-32-36-35-2C-32-38-32
2020-07-02 12:27:13.515 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 36-35-2E-38-32-39-35-2E-32-35-39-36-36-2C-32-39-37-33-30-2E
2020-07-02 12:27:13.520 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 32-39-38-30-31-2E-38-38-31-32-22-2C-22-70-74-63-6C-22-3A-22
2020-07-02 12:27:13.524 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 30-2E-31-2E-30-22-2C-22-6E-65-74-22-3A-22-4C-54-45-22-7D
2020-07-02 12:27:13.528 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)

    [          1593685633.528 26786:26786 D/MasterLinkConnectionNRF$Commander$tryAwaitResponse$$inlined$suspendCancellableCoroutineRead: received data: {"rpl":"info","iobsn":"AN02789378","iobtp":"vl100","time":1593685633,"temp":273,"vcc":3288,"hw":"3,1","sw":"11298.25122.31092,8762.27715.29551,28518.32034.31532 8816.8762.28265,28265.8295.25966,29730.29801.8812","ptcl":"0.1.0","net":"LTE"}
2020-07-02 12:27:13.529 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:13.648 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 7B-22-61-63-63-22-3A-31-32-2C-22-61-6C-74-22-3A-31-30-32-2C
2020-07-02 12:27:16.726 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Connection parameters updated (interval: 30.0ms, latency: 0, timeout: 4000ms)
2020-07-02 12:27:18.533 26786-26786/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:18.536 26786-26786/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)

    [          1593685638.543 26786:26786 D/MasterLinkConnectionNRF$Commander$tryAwaitResponse$$inlined$suspendCancellableCoroutineRead: Failed with status: -5
2020-07-02 12:27:18.560 26786-26866/com.metricorr.app D/[Koin]: +- got 'dk.makeable.metricorr.utils.ActivityCallbacks' in 0.737077 ms

    [          1593685638.575 26786:26874 D/MasterLinkConnectionNRF$Commander$tryAwaitResponse$$inlined$suspendCancellableCoroutineRX: android.bluetooth.BluetoothGattCharacteristic@fdb4690
2020-07-02 12:27:18.591 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 22-65-77-22-3A-22-45-22-2C-22-6C-61-74-22-3A-35-36-31-30-2E
2020-07-02 12:27:18.594 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:18.596 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:18.648 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 35-31-30-30-39-32-2C-22-6C-6F-6E-67-22-3A-31-30-30-35-2E-35
2020-07-02 12:27:18.649 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:18.650 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:18.708 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 31-37-33-37-38-2C-22-6E-73-22-3A-22-4E-22-2C-22-75-74-63-22
2020-07-02 12:27:18.709 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:18.710 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:18.767 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 3A-31-35-39-33-36-38-35-36-33-32-2C-22-63-6D-64-22-3A-22-67
2020-07-02 12:27:18.770 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:18.771 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:18.829 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 6E-73-73-22-7D
2020-07-02 12:27:18.832 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)

    [          1593685638.832 26786:26786 D/MasterLinkConnectionNRF$Commander$tryAwaitResponse$$inlined$suspendCancellableCoroutineCMD: {"acc":12,"alt":102,"ew":"E","lat":5610.510092,"long":1005.517378,"ns":"N","utc":1593685632,"cmd":"gnss"} was sent.
2020-07-02 12:27:18.834 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:18.859 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 7B-22-72-70-6C-22-3A-22-67-6E-73-73-22-2C-22-6C-6F-6E-67-22
2020-07-02 12:27:18.864 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 3A-31-30-30-35-2E-35-31-37-33-39-35-30-31-39-35-33-31-32-2C
2020-07-02 12:27:18.867 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 22-6C-61-74-22-3A-35-36-31-30-2E-35-31-30-32-35-33-39-30-36
2020-07-02 12:27:18.871 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 32-34-39-36-2C-22-6E-73-22-3A-22-4E-22-2C-22-65-77-22-3A-22
2020-07-02 12:27:18.874 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 45-22-2C-22-61-6C-74-22-3A-31-30-32-2C-22-61-63-63-22-3A-31
2020-07-02 12:27:18.876 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 31-2C-22-75-74-63-22-3A-31-35-39-33-36-38-35-36-33-32-7D

    [          1593685638.879 26786:26786 D/MasterLinkConnectionNRF$Commander$tryAwaitResponse$$inlined$suspendCancellableCoroutineRead: received data: {"rpl":"gnss","long":1005.5173950195312,"lat":5610.5102539062496,"ns":"N","ew":"E","alt":102,"acc":11,"utc":1593685632}
2020-07-02 12:27:18.888 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 7B-22-61-63-63-22-3A-31-32-2C-22-61-6C-74-22-3A-31-30-32-2C
2020-07-02 12:27:18.891 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:18.892 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:18.947 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 22-65-77-22-3A-22-45-22-2C-22-6C-61-74-22-3A-35-36-31-30-2E
2020-07-02 12:27:18.949 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:18.950 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:19.008 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 35-31-30-30-39-32-2C-22-6C-6F-6E-67-22-3A-31-30-30-35-2E-35
2020-07-02 12:27:19.009 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:19.010 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:19.067 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 31-37-33-37-38-2C-22-6E-73-22-3A-22-4E-22-2C-22-75-74-63-22
2020-07-02 12:27:19.071 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:19.073 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:19.130 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 3A-31-35-39-33-36-38-35-36-33-32-2C-22-63-6D-64-22-3A-22-67
2020-07-02 12:27:19.132 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Writing characteristic 6e400002-b5a3-f393-e0a9-e50e24dcca9e (WRITE REQUEST)
2020-07-02 12:27:19.134 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: gatt.writeCharacteristic(6e400002-b5a3-f393-e0a9-e50e24dcca9e)
2020-07-02 12:27:19.190 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Data written to 6e400002-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 6E-73-73-22-7D
2020-07-02 12:27:19.221 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 7B-22-72-70-6C-22-3A-22-67-6E-73-73-22-2C-22-6C-6F-6E-67-22
2020-07-02 12:27:19.224 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 3A-31-30-30-35-2E-35-31-37-33-39-35-30-31-39-35-33-31-32-2C
2020-07-02 12:27:19.236 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 22-6C-61-74-22-3A-35-36-31-30-2E-35-31-30-32-35-33-39-30-36
2020-07-02 12:27:19.240 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 32-34-39-36-2C-22-6E-73-22-3A-22-4E-22-2C-22-65-77-22-3A-22
2020-07-02 12:27:19.244 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 45-22-2C-22-61-6C-74-22-3A-31-30-32-2C-22-61-63-63-22-3A-31
2020-07-02 12:27:19.250 26786-26873/com.metricorr.app D/MasterLinkConnectionNRF: BLEMANAGER_LOG: Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 31-2C-22-75-74-63-22-3A-31-35-39-33-36-38-35-36-33-32-7D
2020-07-02 12:28:48.959 4754-4795/? D/BatteryStatsService: !@ mLastInfo WifiActivityEnergyInfo{ timestamp=607455546 mStackState=3 mControllerTxTimeMs=12009 mControllerTxTimePerLevelMs=[] mControllerRxTimeMs=506134 mControllerIdleTimeMs=6037267 mControllerEnergyUsed=151626103 }
2020-07-02 12:28:48.959 4754-4795/? D/BatteryStatsService: !@ latest WifiActivityEnergyInfo{ timestamp=607597980 mStackState=3 mControllerTxTimeMs=12030 mControllerTxTimePerLevelMs=[] mControllerRxTimeMs=508427 mControllerIdleTimeMs=6058287 mControllerEnergyUsed=152258371 }
2020-07-02 12:28:48.960 4754-4795/? D/BatteryStatsService: !@ delta timePeriodMs : 142434 txTimeMs : 21 rxTimeMs :2293 idleTimeMs : 21020
2020-07-02 12:30:39.181 4754-27116/? D/BatteryStatsService: !@ mLastInfo WifiActivityEnergyInfo{ timestamp=607597980 mStackState=3 mControllerTxTimeMs=12030 mControllerTxTimePerLevelMs=[] mControllerRxTimeMs=508427 mControllerIdleTimeMs=6058287 mControllerEnergyUsed=152258371 }
2020-07-02 12:30:39.182 4754-27116/? D/BatteryStatsService: !@ latest WifiActivityEnergyInfo{ timestamp=607708215 mStackState=3 mControllerTxTimeMs=12033 mControllerTxTimePerLevelMs=[] mControllerRxTimeMs=509998 mControllerIdleTimeMs=6067271 mControllerEnergyUsed=152661189 }
2020-07-02 12:30:39.182 4754-27116/? D/BatteryStatsService: !@ delta timePeriodMs : 110235 txTimeMs : 3 rxTimeMs :1571 idleTimeMs : 8984
philips77 commented 4 years ago

Thank you very much.

andybdahl commented 4 years ago

No problem @philips77 I Will have to revert to version 2.2.0, and therefore the split-write functionality from PR#209 again, I will do a workaround until you get to the bottom of this connection problem.

Just for info: I can consistently reproduce the issue on a Samsung Galaxy S8, S10, and on a OnePlus phone, Pixel devices seems to work fine with v2.2.1. Hope you can use that information for faster debugging.

I have a client waiting for their app, so any steps to fix this issue soon will be much appreciated!

philips77 commented 4 years ago

So I checked the logs and the code, and here're my findings. When service discovery is complete, you reach line:

[...]
at no.nordicsemi.android.ble.BleManagerHandler$3.onServicesDiscovered(BleManagerHandler.java:1888)
[...]

https://github.com/NordicSemiconductor/Android-BLE-Library/blob/e666df15f4a659242fd4f9629cec8b0aeeea8350/ble/src/main/java/no/nordicsemi/android/ble/BleManagerHandler.java#L1888 At this point initQueue is not null: https://github.com/NordicSemiconductor/Android-BLE-Library/blob/e666df15f4a659242fd4f9629cec8b0aeeea8350/ble/src/main/java/no/nordicsemi/android/ble/BleManagerHandler.java#L1852-L1853 and initInProgress is true: https://github.com/NordicSemiconductor/Android-BLE-Library/blob/e666df15f4a659242fd4f9629cec8b0aeeea8350/ble/src/main/java/no/nordicsemi/android/ble/BleManagerHandler.java#L1841

In the initialize() you enqueue a request, which calls: https://github.com/NordicSemiconductor/Android-BLE-Library/blob/e666df15f4a659242fd4f9629cec8b0aeeea8350/ble/src/main/java/no/nordicsemi/android/ble/BleManagerHandler.java#L1190-L1196 Looks, like initInProgress is in fact true, but the initQueue is null. This could happen if you called cancelQueue() or enqueued refreshCache() request.

philips77 commented 4 years ago

Could you put a breakpoint in line 1193 and in all places initQueue gets nullified? I wonder where and when it happens, and how does it work in 2.2.0. Did you try cleaning your build? For me this looks like an issue with Android Studio or caching...

andybdahl commented 4 years ago

I'll try it out, and update you with the results @philips77 Thanks for the quick responses

andybdahl commented 4 years ago

I found the source of the problem in: Line 2808

andybdahl commented 4 years ago

I can't say why it only happens on v2.2.1, but It consistently fails on my Galaxy s10 development device, and consistently succeeds as expected in v2.2.0

philips77 commented 4 years ago

I think the issue is a bit different. In my app I request MTU change and enable notifications in initialize(), but the second request begins before the MTU is set. That means at some point the second request gets fired when it shouldn't. So I think I might have replicated this on Samsung S8. Hope this is the root cause of your issue as well.

philips77 commented 4 years ago

Ok, I have a candidate for change. Could you check branch bugfix/210?

andybdahl commented 4 years ago

@philips77 I'll check it out

andybdahl commented 4 years ago

@philips77 I do requestMtu (+enqueue), and then in the next line enable notifications (+enqueue), so maybe the problem is the same as yours.

andybdahl commented 4 years ago

@philips77 Your fix is not working, now multiple requests are not performed, probably because the lines your changed in bugfix/210 causes the next request to not be run.

I can see when debugging that isInitInProgress is set to true multiple times AFTER initially being false, I suspect this causes the new bugfix you released to drop requests because of line #3188 here

philips77 commented 4 years ago

Ok, how about now?

philips77 commented 4 years ago

I created a PR. We can discuss your following findings there.

andybdahl commented 4 years ago

I'll try it out @philips77