nRFConnect DFU not working from Android 8 devices but does work to Android 7.1 and Android 7.1.1 devices

[Mark P. Mendelsohn]

Scan of services after connecting to DFUTarg does not return

the new services on the device. Instead the old services that existed

on the device before going into DFU mode are returned.

Device side trace shows it was actually in DFU mode. 

Same device with nRFConnect works from Android 7.1 and 7.1.1

Device side trace

0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> SD: BLE_GATTS_EVT_WRITE
0> PM: PM_EVT_STORAGE_FULL
0> DFU:BLE_GATTS_EVT_WRITE
0> DFU: on_write
0> DFU:Received indication state 1
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> SD: BLE_GATTS_EVT_RW_AUTHORIZE_REQUEST
0> DFU:BLE_GATTS_EVT_RW_AUTHORIZE_REQUEST
0> DFU: on_rw_authorize_req
0> DFU: type=2,w.op=1
0> DFU: req.handle=0x10, ctrl.handle=0x10
0> DFU: on_ctrlpt_write
0> DFU: DFU_RSP_BUSY NOT Programming or Engineering Mode
0> DFU: forward
0> DFU:Writing peer data to the bootloaderDFU:---------------system attribute table: 8--------------SD: BLE_GATTS_EVT_HVC
0> DFU:BLE_GATTS_EVT_HVC
0> Device is preparing to enter bootloader mode.
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> Device will enter bootloader mode.
0> PMM: prepare_dfu_mode() id=65535
0> PMM: delete_peer_id_history
0> PWR: wants to reset to DFU mode.
0> PWD: power-off detect enabled
0>
0> DFU BOOT (145)
0>
0> Bluetooth Name NM04-000008
0> Board Type D048 (INCOMPATIBLE)
0> Model Type ETS (INCOMPATIBLE)
0> FPGA Ver Model 4 Version 4 (INCOMPATIBLE)
0> Firmware Ver 1.2.262
0> Firmware Type DEVELOP_BLE_UART
0> SoftDevice Ver 5.0.0
0> BootLoader Ver 2 (INSTALLED)
0> Mfg Data Ver 3
0> Sys Config Ver 6
0> Bluetooth Enabled
0> Stimulation Enabled
0>
0> 3V supply enabled
0> Vrf (3000 mV) enabled
0> BLE: local BDADDR EFF00F3689C3
0> PWR: Normal Power State entered
0> 3V supply enabled
0> Stim State SEARCHING
0> ADV: Sys=31F0736D Bat=4009 Amp=0 Err=00 Prg=F Ins=0 Post=0 Stim=0 LowP=0 LowB=0 Sess=1 Buzz=1
0> BLE: Starting advertising upon reset
0> BLE: Fast advertising in progress
0> SD: BLE_GAP_EVT_TIMEOUT
0> BLE: Slow advertising in progress

Host side trace 

nRF Connect, 2018-06-29
NM04-000008 (EF:F0:0F:36:89:C3)
V	11:19:34.115	Connecting to EF:F0:0F:36:89:C3...
D	11:19:34.115	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	11:19:37.443	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	11:19:37.443	Connected to EF:F0:0F:36:89:C3
D	11:19:37.447	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	11:19:37.449	wait(1600ms)
V	11:19:39.050	Discovering services...
D	11:19:39.050	gatt.discoverServices()
D	11:19:39.086	[Callback] Services discovered with status: 0
I	11:19:39.086	Services discovered
V	11:19:39.125	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
   Client Characteristic Configuration (0x2902)
Secure DFU Service (0xFE59)
- Secure Buttonless DFU [I W] (8ec90004-f315-4f60-9fb8-838830daea50)
   Client Characteristic Configuration (0x2902)
Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
- RX Characteristic [W WNR] (6e400002-b5a3-f393-e0a9-e50e24dcca9e)
- TX Characteristic [N] (6e400003-b5a3-f393-e0a9-e50e24dcca9e)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [R] (6e400010-b5a3-f393-e0a9-e50e24dcca9e)
- Unknown Characteristic [R] (6e400020-b5a3-f393-e0a9-e50e24dcca9e)
- Unknown Characteristic [R] (6e400030-b5a3-f393-e0a9-e50e24dcca9e)
- Unknown Characteristic [W] (6e400040-b5a3-f393-e0a9-e50e24dcca9e)
D	11:19:39.125	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D	11:19:39.129	gatt.setCharacteristicNotification(8ec90004-f315-4f60-9fb8-838830daea50, true)
D	11:19:39.131	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
V	11:19:44.975	Reading characteristic 6e400030-b5a3-f393-e0a9-e50e24dcca9e
D	11:19:44.975	gatt.readCharacteristic(6e400030-b5a3-f393-e0a9-e50e24dcca9e)
I	11:19:45.043	Read Response received from 6e400030-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 34-56-C9-BE-64-01-B3-F9-06-DC-D5-FF-13-DC-52-E3
A	11:19:45.044	"(0x) 34-56-C9-BE-64-01-B3-F9-06-DC-D5-FF-13-DC-52-E3" received
V	11:20:01.878	[DFU] DFU service started
V	11:20:01.878	[DFU] Opening file...
I	11:20:01.958	[DFU] Firmware file opened successfully
V	11:20:01.958	[DFU] Connecting to DFU target...
D	11:20:01.958	[DFU] gatt = device.connectGatt(autoConnect = false)
I	11:20:02.122	[DFU] Connected to EF:F0:0F:36:89:C3
D	11:20:02.126	[DFU] wait(1600)
V	11:20:03.726	[DFU] Discovering services...
D	11:20:03.726	[DFU] gatt.discoverServices()
I	11:20:03.732	[DFU] Services discovered
D	11:20:03.759	[DFU] wait(1000)
W	11:20:04.738	[DFU] Application with buttonless update found
V	11:20:04.738	[DFU] Jumping to the DFU Bootloader...
V	11:20:04.738	[DFU] Enabling indications for 8ec90004-f315-4f60-9fb8-838830daea50
D	11:20:04.738	[DFU] gatt.setCharacteristicNotification(8ec90004-f315-4f60-9fb8-838830daea50, true)
D	11:20:04.740	[DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x02-00)
I	11:20:04.792	[DFU] Data written to descr.8ec90004-f315-4f60-9fb8-838830daea50, value (0x): 02-00
V	11:20:04.792	[DFU] Notifications enabled for 8ec90004-f315-4f60-9fb8-838830daea50
A	11:20:04.792	[DFU] Indications enabled
D	11:20:04.792	[DFU] wait(1000)
V	11:20:05.806	[DFU] Writing to characteristic 8ec90004-f315-4f60-9fb8-838830daea50
D	11:20:05.806	[DFU] gatt.writeCharacteristic(8ec90004-f315-4f60-9fb8-838830daea50)
I	11:20:05.876	[DFU] Notification received from 8ec90004-f315-4f60-9fb8-838830daea50, value (0x): 20-01-01
I	11:20:05.876	Indication received from 8ec90004-f315-4f60-9fb8-838830daea50, value: (0x) 20-01-01
A	11:20:05.876	"(0x) 20-01-01" received
A	11:20:05.883	[DFU] Enter bootloader sent (Op Code = 1)
A	11:20:05.883	[DFU] Response received (Op Code = 1, Status = 1)
D	11:20:10.926	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	11:20:10.926	Error 8 (0x8): GATT CONN TIMEOUT
I	11:20:10.926	[DFU] Disconnected by the remote device
I	11:20:10.926	Disconnected
D	11:20:10.963	[DFU] gatt.close()
D	11:20:10.964	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	11:20:10.965	[DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
V	11:20:10.976	[DFU] DFU service started
I	11:20:10.976	[DFU] Firmware file opened successfully
D	11:20:10.976	[DFU] wait(1000)
D	11:20:11.976	[DFU] wait(1000)
V	11:20:12.977	[DFU] Connecting to DFU target...
D	11:20:13.023	[DFU] gatt = device.connectGatt(autoConnect = false)
I	11:20:13.302	[DFU] Connected to EF:F0:0F:36:89:C3
D	11:20:13.303	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	11:20:13.304	[DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	11:20:13.305	[DFU] wait(1600)
V	11:20:14.906	[DFU] Discovering services...
D	11:20:14.906	[DFU] gatt.discoverServices()
I	11:20:14.911	[DFU] Services discovered
D	11:20:14.937	[DFU] wait(1000)
W	11:20:15.920	[DFU] Application with buttonless update found
V	11:20:15.920	[DFU] Jumping to the DFU Bootloader...
V	11:20:15.920	[DFU] Enabling indications for 8ec90004-f315-4f60-9fb8-838830daea50
D	11:20:15.920	[DFU] gatt.setCharacteristicNotification(8ec90004-f315-4f60-9fb8-838830daea50, true)
D	11:20:15.921	[DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x02-00)
E	11:20:15.998	[DFU] Error (0x03): GATT WRITE NOT PERMIT
V	11:20:15.998	[DFU] Disconnecting...
D	11:20:16.026	[DFU] gatt.disconnect()
I	11:20:16.026	[DFU] Disconnected
D	11:20:16.026	[DFU] gatt.close()
D	11:20:16.026	[DFU] wait(600)
D	11:20:16.615	gatt.close()
D	11:20:16.618	wait(200)
V	11:20:16.819	Connecting to EF:F0:0F:36:89:C3...
D	11:20:16.819	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	11:20:16.826	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	11:20:16.826	Connected to EF:F0:0F:36:89:C3
D	11:20:16.827	wait(1600ms)
D	11:20:17.038	[Callback] Connection state changed with status: 22 and new state: DISCONNECTED (0)
E	11:20:17.038	Error 22 (0x16): GATT CONN TERMINATE LOCAL HOST
I	11:20:17.038	Disconnected
D	11:20:17.089	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	11:20:20.416	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	11:20:20.417	gatt.close()
D	11:20:20.422	wait(200)
V	11:20:20.624	Connecting to EF:F0:0F:36:89:C3...
D	11:20:20.625	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	11:20:20.636	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	11:20:20.636	Connected to EF:F0:0F:36:89:C3
D	11:20:20.638	wait(1600ms)
V	11:20:22.238	Discovering services...
D	11:20:22.238	gatt.discoverServices()
D	11:20:22.242	[Callback] Services discovered with status: 0
I	11:20:22.242	Services discovered
V	11:20:22.275	Generic Access (0x1800)
- Device Name [R W] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
- Central Address Resolution [R] (0x2AA6)
Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
   Client Characteristic Configuration (0x2902)
Secure DFU Service (0xFE59)
- Secure Buttonless DFU [I W] (8ec90004-f315-4f60-9fb8-838830daea50)
   Client Characteristic Configuration (0x2902)
Nordic UART Service (6e400001-b5a3-f393-e0a9-e50e24dcca9e)
- RX Characteristic [W WNR] (6e400002-b5a3-f393-e0a9-e50e24dcca9e)
- TX Characteristic [N] (6e400003-b5a3-f393-e0a9-e50e24dcca9e)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [R] (6e400010-b5a3-f393-e0a9-e50e24dcca9e)
- Unknown Characteristic [R] (6e400020-b5a3-f393-e0a9-e50e24dcca9e)
- Unknown Characteristic [R] (6e400030-b5a3-f393-e0a9-e50e24dcca9e)
- Unknown Characteristic [W] (6e400040-b5a3-f393-e0a9-e50e24dcca9e)
D	11:20:22.275	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D	11:20:22.277	gatt.setCharacteristicNotification(8ec90004-f315-4f60-9fb8-838830daea50, true)
D	11:20:22.279	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)

[Kenneth]

From my understanding if you call discoverServices() immediately inside the onConnectionStateChanged callback you will get the old set from cache, but if you wait a bit, and call discoverServices() then, you’ll have to wait until the discovery is done as cache has invalidated. Could you give that a try?

Best regards,
Kenneth

[Mark P. Mendelsohn]

Ken,

Thanks for the response. The nRF Connect utility is distributed on iOS and Android from Nordic as a binary.

There is no source code available to the general public to add a timer and recompile. It is working on older versions of Android but not newer ones. 

[Aleksander Nowakowski]

Hi Mark, I'm on it. But first, here's the story:

When your device is bonded, and it seems yours is as you are using the Buttonless Service with Bond support (UUID 8ec90004-f315-4f60-9fb8-838830daea50),  it should send an indication to the phone just after reconnection. The lib gives 1600 ms to ensure that the indication was sent and the phone cleared the cache.

I	11:20:13.302	[DFU] Connected to EF:F0:0F:36:89:C3
D	11:20:13.303	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	11:20:13.304	[DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	11:20:13.305	[DFU] wait(1600)
V	11:20:14.906	[DFU] Discovering services...
D	11:20:14.906	[DFU] gatt.discoverServices()

The service discovery performed after that should return new services, but for some reason it doesn't and the DFU service again gets the buttonless service which is invalid (write fails). That means, that either the Service Changed indication wasn't sent, the SC CCCD wasn't enabled, or Android 8 ignored it, or didn't clear the cache properly like it used to do before. As older Android versions seems to work, it looks like an issue with Android 8, or with your phone.

Let me do some tests.

[Aleksander Nowakowski]

I'm able to reproduce your issue using Pixel 2 with Android 8.1.0.

[Aleksander Nowakowski]

github.com/.../112

[Aleksander Nowakowski]

I've just released version 1.7.0 on jcenter/Maven Central. Could you verify the fix has helped?