Second characteristic write wont be received (From Android)

[sijohans]

Hello,

I am using an Android application to send data to a nRF52 board. The nRF52 board is the peripheral and the Android phone is the central. This is the link establishment process:

1. Connect
2. Negotiate MTU
3. Discover services
4. Enable notifications

Then we are using writeCharacteristics (and onCharacteristicWrite) and onCharacteristicChanged to send an receive data. This works quite well, but sometime i end up in an unrecoverable state where i have to restart Bluetooth on the phone to make it work again.

At this point, I am able to set up the connection, and send the first chunk of data. Then after this, i receive some data, but when sending the next chunk, this is never received on the nRF52 side. The gatt.writeCharacteristics return OK and i get the onCharacteristicWrite callback. I can however not see anything in the HCI snoop log file.

This is how it should be:

1. Central -> Peripheral 50 bytes
2. Peripheral -> Central 43 bytes
3. Peripheral -> Central 135 bytes
4. Central -> Peripheral 135 bytes

If (4) is not received within 5 seconds after (3) is sent, the peripheral will disconnect the central. This behavior i can identify. This is the log from the android phone:

05-29 09:40:04.125 2369-20902/test_ble_io I/BleClientChannel: handleMessage: MSG_CONNECT
05-29 09:40:04.126 2369-20902/test_ble_io D/BluetoothGatt: connect() - device: F6:C5:9D:24:12:0A, auto: false
05-29 09:40:04.126 2369-20902/test_ble_io D/BluetoothGatt: registerApp()
05-29 09:40:04.126 2369-20902/test_ble_io D/BluetoothGatt: registerApp() - UUID=24c021fc-7537-4867-8af3-2d6a45c3c7ac
05-29 09:40:04.127 2369-2380/test_ble_io D/BluetoothGatt: onClientRegistered() - status=0 clientIf=6
05-29 09:40:04.576 2369-2381/test_ble_io D/BluetoothGatt: onClientConnectionState() - status=0 clientIf=6 device=F6:C5:9D:24:12:0A
05-29 09:40:04.576 2369-2381/test_ble_io I/BleClientChannel: onConnectionStateChange, status 0, newState 2
05-29 09:40:04.576 2369-20902/test_ble_io I/BleClientChannel: handleMessage: MSG_NEGOTIATE_MTU
05-29 09:40:04.576 2369-20902/test_ble_io D/BluetoothGatt: configureMTU() - device: F6:C5:9D:24:12:0A mtu: 247
05-29 09:40:04.823 2369-2416/test_ble_io D/BluetoothGatt: onConfigureMTU() - Device=F6:C5:9D:24:12:0A mtu=247 status=0
05-29 09:40:04.823 2369-2416/test_ble_io I/BleClientChannel: onMtuChanged, status: 0, mtu: 247
05-29 09:40:04.823 2369-20902/test_ble_io I/BleClientChannel: handleMessage: MSG_DISCOVER_SERVICES
05-29 09:40:04.823 2369-20902/test_ble_io D/BluetoothGatt: discoverServices() - device: F6:C5:9D:24:12:0A
05-29 09:40:04.827 2369-2380/test_ble_io D/BluetoothGatt: onSearchComplete() = Device=F6:C5:9D:24:12:0A Status=0
05-29 09:40:04.827 2369-2380/test_ble_io I/onServicesDiscovered: status: 0
05-29 09:40:04.827 2369-20902/test_ble_io I/BleClientChannel: handleMessage: MSG_VERIFY_SERVICES
05-29 09:40:04.827 2369-20902/test_ble_io I/BleClientChannel: handleMessage: MSG_ENABLE_NOTIFICATIONS
05-29 09:40:04.827 2369-20902/test_ble_io D/BluetoothGatt: setCharacteristicNotification() - uuid: 48f058af-2d79-41af-be4f-722dee1ab571 enable: true
05-29 09:40:04.874 2369-2381/test_ble_io I/BleClientChannel: onDescriptorWrite, status: 0
05-29 09:40:04.874 2369-20902/test_ble_io I/BleClientChannel: handleMessage: MSG_NOTIFICATIONS_ENABLED
05-29 09:40:04.874 2369-20902/test_ble_io I/BleClientChannel: Notifications enabled
05-29 09:40:04.886 2369-20901/test_ble_io I/BleClientChannel: Writing
05-29 09:40:04.887 2369-20902/test_ble_io I/BleClientChannel: handleMessage: MSG_SEND_DATA
05-29 09:40:04.888 2369-2416/test_ble_io I/BleClientChannel: onCharacteristicWrite, status: 0
05-29 09:40:04.888 2369-2416/test_ble_io I/BleClientChannel: cha.getValue(): 2e000000401401651820f38dcc297599a50cfbf5a4c6dcae208c50cf7f0e65cbb8c62fb55722adef6d481401701402533141
05-29 09:40:04.889 2369-20902/test_ble_io I/BleClientChannel: handleMessage: MSG_DATA_SENT
05-29 09:40:04.889 2369-20902/test_ble_io I/BleClientChannel: Message sent
05-29 09:40:04.889 2369-20902/test_ble_io I/BleClientChannel: writeEvent == null => false
05-29 09:40:04.889 2369-20901/test_ble_io I/BleClientChannel: write done
05-29 09:40:04.889 2369-20901/test_ble_io I/BleClientChannel: reading
05-29 09:40:04.969 2369-2380/test_ble_io I/BleClientChannel: onCharacteristicChanged
05-29 09:40:04.970 2369-2380/test_ble_io I/BleClientChannel: cha.getValue(): 270000004014016518200fd62d176784478b0394677e240dba4062863dffef848b45c791576419d54c0641
05-29 09:40:04.972 2369-20901/test_ble_io I/BleClientChannel: reading
05-29 09:40:05.023 2369-2381/test_ble_io I/BleClientChannel: onCharacteristicChanged
05-29 09:40:05.023 2369-2381/test_ble_io I/BleClientChannel: cha.getValue(): 8300000040140162187c7fc176a481bcc71a14465b914f364cca6ae5d3102ba11326a7a98d0a5a7d145e0877a0efc978c64a39a1b86233bbdf2a38b774d212a2d256d0bce900f3755dfdfbd40ea594353897502590291c99331b228a32b5289383abb6a92dd37be6a35edbaf90f6b62aa766f22e78119327be338ff146846401e5f41dd7afaa41
05-29 09:40:05.027 2369-20901/test_ble_io I/BleClientChannel: Writing
05-29 09:40:05.027 2369-20902/test_ble_io I/BleClientChannel: handleMessage: MSG_SEND_DATA
05-29 09:40:05.028 2369-2416/test_ble_io I/BleClientChannel: onCharacteristicWrite, status: 0
05-29 09:40:05.028 2369-2416/test_ble_io I/BleClientChannel: cha.getValue(): 8300000040140162187c4505ac06dfb264f011e6160c0673abc60f61d8460eecc4bc92075bacdcf93727225a10a0915f0aeaf7e033ff67787d6a6922083b4d67a90fa8141360eb32072eb5010364d27d3b7f2fb85c2a4c9f67a1719879e65f6047cccd192631577bfce264cd1fa0efe44916c1424b018a36329f2541666e686c5917ae62619841
05-29 09:40:05.028 2369-20902/test_ble_io I/BleClientChannel: handleMessage: MSG_DATA_SENT
05-29 09:40:05.028 2369-20902/test_ble_io I/BleClientChannel: Message sent
05-29 09:40:05.029 2369-20902/test_ble_io I/BleClientChannel: writeEvent == null => false
05-29 09:40:05.029 2369-20901/test_ble_io I/BleClientChannel: write done
<--- Disconnected by peripheral here --->
05-29 09:40:10.020 2369-2380/test_ble_io D/BluetoothGatt: onClientConnectionState() - status=19 clientIf=6 device=F6:C5:9D:24:12:0A
05-29 09:40:10.020 2369-2380/test_ble_io I/BleClientChannel: onConnectionStateChange, status 19, newState 0
05-29 09:40:10.020 2369-20902/test_ble_io I/BleClientChannel: handleMessage: MSG_CLOSE
05-29 09:40:10.021 2369-20902/test_ble_io D/BluetoothGatt: cancelOpen() - device: F6:C5:9D:24:12:0A
05-29 09:40:10.021 2369-20902/test_ble_io D/BluetoothGatt: close()
05-29 09:40:10.021 2369-20902/test_ble_io D/BluetoothGatt: unregisterApp() - mClientIf=6
05-29 09:40:10.129 2369-20901/test_ble_io D/BluetoothGatt: cancelOpen() - device: F6:C5:9D:24:12:0A
05-29 09:40:10.130 2369-20901/test_ble_io D/BluetoothGatt: close()
05-29 09:40:10.130 2369-20901/test_ble_io D/BluetoothGatt: unregisterApp() - mClientIf=0

And the corresponding HCI snoop log is attached. When looking at the log file i can't see that the second write from the phone is present. Any suggestions?

[Petter Myhre]

I don't know what is unrecoverable state is, but do you have a sniffer log? To see what is happening on air? You can use nRF Sniffer. Have you been able to reproduce this with nRF Connect for Android?

[sijohans]

Hello, i have not used the nRF sniffer, will look into that. Will this one work for that: devzone.nordicsemi.com/.../ ?

I'm using a dev phone without google play, will see if i can install the nRF connect APK (found it on github now) or try it on another phone. I also notice this behavior when i end up in this state:

When i do gatt.disconnect() I receive the onConnectionStateChange callback with status GATT_SUCCESS and new connection state DISCONNECTED. However, when i receive this, i don't get the disconnected event on the nRF52 side. If i however restart bluetooth on the phone, it starts working again.

[sijohans]

Installed the nRF Connect, when the phone is in this strange state, the nrf connect also behaves strange. Seems like gatt operations are only queued on the phone and not actually performed.

[Petter Myhre]

Yes, you should be able to run nRF Sniffer on the nRF52 DK (if you use the unofficial firmware).