DFU error: OPERATION NOT PERMITTED

[mdido]

Hello, I'm using softdevice 6.0, SDK 15.0, secure bootloader buttonless S132. On the phone with Android I'm using: nRF Toolbox 2.9.0 with DFU Library version 1.10.3.

I start the firmware update with firmware A and stop before it finishes by closing the app DFU. If I retry the update with the same firmware A, the app DFU resumes from the percentage from where it was interrupted, but the app DFU returns the error "OPERATION NOT PERMITTED and disconnects (I also attach the log). At this point I make an update with a frimware B. The update restarts from the beginning and, if I do not interrupt the app, it is successful.

What is the solution to this criticism in Android?

Best regards

Fullscreen Log 2020-06-22 10_13_42.txt Download

nRF Connect, 2020-06-22
SE-007-E000027 (FE:10:CD:01:21:29)
D	10:13:42.482	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
V	10:13:42.969	Connecting to FE:10:CD:01:21:29...
D	10:13:42.969	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D	10:13:43.104	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:13:43.104	Connected to FE:10:CD:01:21:29
V	10:13:43.106	Requesting new MTU...
D	10:13:43.106	gatt.requestMtu(517)
I	10:13:43.765	MTU changed to: 247
V	10:13:43.792	Discovering services...
D	10:13:43.793	gatt.discoverServices()
D	10:13:43.868	[Callback] Services discovered with status: 0
I	10:13:43.868	Services discovered
V	10:13:43.913	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)
Unknown Service (7f04f3f0-b665-11e3-a5e2-0800200c9a66)
- Unknown Characteristic [W WNR] (92b403f0-b665-11e3-a5e2-0800200c9a66)
- Unknown Characteristic [N R] (7d32c0f0-bef5-11e3-b1b6-0800200c9a66)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [N R] (2d417c80-b667-11e3-a5e2-0800200c9a66)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [N R] (f9f84152-b667-11e3-a5e2-0800200c9a66)
   Client Characteristic Configuration (0x2902)
Secure DFU Service (0xFE59)
- Buttonless DFU [I W] (8ec90003-f315-4f60-9fb8-838830daea50)
   Client Characteristic Configuration (0x2902)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
- Model Number String [R] (0x2A24)
- Serial Number String [R] (0x2A25)
- Hardware Revision String [R] (0x2A27)
- Firmware Revision String [R] (0x2A26)
- Software Revision String [R] (0x2A28)
D	10:13:43.913	gatt.setCharacteristicNotification(7d32c0f0-bef5-11e3-b1b6-0800200c9a66, true)
D	10:13:43.915	gatt.setCharacteristicNotification(2d417c80-b667-11e3-a5e2-0800200c9a66, true)
D	10:13:43.918	gatt.setCharacteristicNotification(f9f84152-b667-11e3-a5e2-0800200c9a66, true)
D	10:13:43.922	gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)
D	10:14:05.248	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	10:14:05.259	Error 8 (0x8): GATT CONN TIMEOUT
I	10:14:05.260	Disconnected
D	10:14:05.375	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	10:19:28.806	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	10:19:28.806	gatt.close()
D	10:19:28.844	wait(200)
V	10:19:29.047	Connecting to FE:10:CD:01:21:29...
D	10:19:29.047	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D	10:19:29.185	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:19:29.185	Connected to FE:10:CD:01:21:29
V	10:19:29.187	Requesting new MTU...
D	10:19:29.187	gatt.requestMtu(517)
I	10:19:29.515	MTU changed to: 247
V	10:19:29.542	Discovering services...
D	10:19:29.542	gatt.discoverServices()
D	10:19:29.700	[Callback] Services discovered with status: 0
I	10:19:29.700	Services discovered
V	10:19:29.746	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)
Unknown Service (7f04f3f0-b665-11e3-a5e2-0800200c9a66)
- Unknown Characteristic [W WNR] (92b403f0-b665-11e3-a5e2-0800200c9a66)
- Unknown Characteristic [N R] (7d32c0f0-bef5-11e3-b1b6-0800200c9a66)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [N R] (2d417c80-b667-11e3-a5e2-0800200c9a66)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [N R] (f9f84152-b667-11e3-a5e2-0800200c9a66)
   Client Characteristic Configuration (0x2902)
Secure DFU Service (0xFE59)
- Buttonless DFU [I W] (8ec90003-f315-4f60-9fb8-838830daea50)
   Client Characteristic Configuration (0x2902)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
- Model Number String [R] (0x2A24)
- Serial Number String [R] (0x2A25)
- Hardware Revision String [R] (0x2A27)
- Firmware Revision String [R] (0x2A26)
- Software Revision String [R] (0x2A28)
D	10:19:29.746	gatt.setCharacteristicNotification(7d32c0f0-bef5-11e3-b1b6-0800200c9a66, true)
D	10:19:29.749	gatt.setCharacteristicNotification(2d417c80-b667-11e3-a5e2-0800200c9a66, true)
D	10:19:29.751	gatt.setCharacteristicNotification(f9f84152-b667-11e3-a5e2-0800200c9a66, true)
D	10:19:29.756	gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)
D	10:19:51.867	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	10:19:51.868	Error 8 (0x8): GATT CONN TIMEOUT
I	10:19:51.868	Disconnected
D	10:19:51.922	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

[Aleksander Nowakowski]

Could you attach the logs showing this issue? In the attached logs there's no DFU operation.

Thank you

[mdido]

I generated the previous log by connecting the device with nrf connect and then I started the dfu with nrf toolbox which returned the error. Please let me know by enabling the log directly from the nrf toolbox

[Aleksander Nowakowski]

You may do dfu from nRF Connect.

[mdido]

Thanks for the advice. Here is the log:

Fullscreen Log 2020-06-23 16_30_40.txt Download

nRF Connect, 2020-06-23
SE-007-E000027 (FE:10:CD:01:21:29)
V 16:32:20.611 Connecting to FE:10:CD:01:21:29...
D 16:32:20.611 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D 16:32:21.057 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I 16:32:21.057 Connected to FE:10:CD:01:21:29
V 16:32:21.058 Requesting new MTU...
D 16:32:21.058 gatt.requestMtu(517)
D 16:32:21.059 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I 16:32:21.829 MTU changed to: 247
V 16:32:21.857 Discovering services...
D 16:32:21.857 gatt.discoverServices()
D 16:32:21.930 [Callback] Services discovered with status: 0
I 16:32:21.930 Services discovered
V 16:32:21.990 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)
Unknown Service (7f04f3f0-b665-11e3-a5e2-0800200c9a66)
- Unknown Characteristic [W WNR] (92b403f0-b665-11e3-a5e2-0800200c9a66)
- Unknown Characteristic [N R] (7d32c0f0-bef5-11e3-b1b6-0800200c9a66)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [N R] (2d417c80-b667-11e3-a5e2-0800200c9a66)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [N R] (f9f84152-b667-11e3-a5e2-0800200c9a66)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [N R] (f9f84150-b667-11e3-a5e2-0800200c9a66)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [N R] (f9f84151-b667-11e3-a5e2-0800200c9a66)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [N R] (f9f84153-b667-11e3-a5e2-0800200c9a66)
   Client Characteristic Configuration (0x2902)
- Unknown Characteristic [N R] (1dcec130-b668-11e3-a5e2-0800200c9a66)
   Client Characteristic Configuration (0x2902)
Secure DFU Service (0xFE59)
- Buttonless DFU [I W] (8ec90003-f315-4f60-9fb8-838830daea50)
   Client Characteristic Configuration (0x2902)
Battery Service (0x180F)
- Battery Level [N R] (0x2A19)
   Client Characteristic Configuration (0x2902)
Device Information (0x180A)
- Manufacturer Name String [R] (0x2A29)
- Model Number String [R] (0x2A24)
- Serial Number String [R] (0x2A25)
- Hardware Revision String [R] (0x2A27)
- Firmware Revision String [R] (0x2A26)
- Software Revision String [R] (0x2A28)
D 16:32:21.990 gatt.setCharacteristicNotification(7d32c0f0-bef5-11e3-b1b6-0800200c9a66, true)
D 16:32:21.992 gatt.setCharacteristicNotification(2d417c80-b667-11e3-a5e2-0800200c9a66, true)
D 16:32:21.994 gatt.setCharacteristicNotification(f9f84152-b667-11e3-a5e2-0800200c9a66, true)
D 16:32:21.996 gatt.setCharacteristicNotification(f9f84150-b667-11e3-a5e2-0800200c9a66, true)
D 16:32:21.998 gatt.setCharacteristicNotification(f9f84151-b667-11e3-a5e2-0800200c9a66, true)
D 16:32:21.999 gatt.setCharacteristicNotification(f9f84153-b667-11e3-a5e2-0800200c9a66, true)
D 16:32:22.001 gatt.setCharacteristicNotification(1dcec130-b668-11e3-a5e2-0800200c9a66, true)
D 16:32:22.004 gatt.setCharacteristicNotification(00002a19-0000-1000-8000-00805f9b34fb, true)
V 16:33:15.737 [DFU] DFU service started
V 16:33:15.737 [DFU] Opening file...
I 16:33:16.188 [DFU] Firmware file opened successfully
V 16:33:16.188 [DFU] Connecting to DFU target...
D 16:33:16.188 [DFU] gatt = device.connectGatt(autoConnect = false)
I 16:33:16.305 [DFU] Connected to FE:10:CD:01:21:29
V 16:33:16.305 [DFU] Discovering services...
D 16:33:16.305 [DFU] gatt.discoverServices()
I 16:33:16.842 [DFU] Services discovered
D 16:33:16.864 [DFU] wait(1000)
W 16:33:17.864 [DFU] Application with buttonless update found
V 16:33:17.864 [DFU] Jumping to the DFU Bootloader...
V 16:33:17.864 [DFU] Enabling indications for 8ec90003-f315-4f60-9fb8-838830daea50
D 16:33:17.864 [DFU] gatt.setCharacteristicNotification(8ec90003-f315-4f60-9fb8-838830daea50, true)
D 16:33:17.864 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x02-00)
I 16:33:17.882 [DFU] Data written to descr.8ec90003-f315-4f60-9fb8-838830daea50, value (0x): 02-00
V 16:33:17.882 [DFU] Notifications enabled for 8ec90003-f315-4f60-9fb8-838830daea50
A 16:33:17.882 [DFU] Indications enabled
D 16:33:17.882 [DFU] wait(1000)
V 16:33:18.908 [DFU] Writing to characteristic 8ec90003-f315-4f60-9fb8-838830daea50
D 16:33:18.908 [DFU] gatt.writeCharacteristic(8ec90003-f315-4f60-9fb8-838830daea50)
A 16:33:18.930 [DFU] Enter bootloader sent (Op Code = 1)
I 16:33:18.930 [DFU] Notification received from 8ec90003-f315-4f60-9fb8-838830daea50, value (0x): 20-01-01
A 16:33:18.930 [DFU] Response received (Op Code = 1, Status = 1)
D 16:33:22.931 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E 16:33:22.932 Error 8 (0x8): GATT CONN TIMEOUT
I 16:33:22.932 Disconnected
I 16:33:22.971 [DFU] Disconnected by the remote device
D 16:33:22.977 [DFU] gatt.refresh() (hidden)
D 16:33:22.977 [DFU] gatt.close()
V 16:33:22.977 [DFU] Scanning for the DFU Bootloader...
D 16:33:23.007 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D 16:33:23.059 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
I 16:33:23.302 [DFU] DFU Bootloader found with address FE:10:CD:01:21:2A
V 16:33:23.331 [DFU] DFU service started
I 16:33:23.331 [DFU] Firmware file opened successfully
D 16:33:23.331 [DFU] wait(1000)
D 16:33:24.349 [DFU] wait(1000)
V 16:33:25.340 [DFU] Connecting to DFU target...
D 16:33:25.401 [DFU] gatt = device.connectGatt(autoConnect = false)
I 16:33:25.792 [DFU] Connected to FE:10:CD:01:21:2A
V 16:33:25.792 [DFU] Discovering services...
D 16:33:25.792 [DFU] gatt.discoverServices()
D 16:33:25.973 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I 16:33:26.198 [DFU] Services discovered
D 16:33:26.251 [DFU] wait(1000)
V 16:33:27.213 [DFU] Requesting new MTU...
D 16:33:27.213 [DFU] gatt.requestMtu(517)
V 16:33:27.239 [DFU] Enabling notifications for 8ec90001-f315-4f60-9fb8-838830daea50
D 16:33:27.239 [DFU] gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
D 16:33:27.242 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I 16:33:27.268 [DFU] Data written to descr.8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 01-00
V 16:33:27.269 [DFU] Notifications enabled for 8ec90001-f315-4f60-9fb8-838830daea50
A 16:33:27.269 [DFU] Notifications enabled
D 16:33:27.269 [DFU] wait(1000)
V 16:33:28.299 [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D 16:33:28.299 [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I 16:33:28.304 [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 06-01
I 16:33:28.304 [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-06-01-00-01-00-00-87-00-00-00-AC-14-8F-56
A 16:33:28.306 [DFU] Command object info received (Max size = 256, Offset = 135, CRC = 568F14AC)
A 16:33:28.306 [DFU] Received CRC match Init packet
V 16:33:28.306 [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D 16:33:28.306 [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I 16:33:28.333 [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 04
I 16:33:28.333 [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-04-01
A 16:33:28.334 [DFU] Command object executed
V 16:33:28.334 [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D 16:33:28.334 [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I 16:33:28.363 [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 06-02
I 16:33:28.363 [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-06-01-00-10-00-00-00-A0-00-00-D1-44-18-B2
A 16:33:28.364 [DFU] Data object info received (Max size = 4096, Offset = 40960, CRC = B21844D1)
A 16:33:28.365 [DFU] 40960 bytes of data sent before, CRC match
V 16:33:28.398 [DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D 16:33:28.398 [DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
I 16:33:28.423 [DFU] Data written to 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 04
I 16:33:28.424 [DFU] Notification received from 8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 60-04-08
E 16:33:28.425 [DFU] Remote DFU error: OPERATION NOT PERMITTED
V 16:33:28.426 [DFU] Disconnecting...
D 16:33:28.427 [DFU] gatt.disconnect()
I 16:33:28.452 [DFU] Disconnected
D 16:33:28.452 [DFU] gatt.refresh() (hidden)
D 16:33:28.452 [DFU] gatt.close()
D 16:33:28.452 [DFU] wait(600)
D 16:33:29.046 gatt.close()
D 16:33:29.050 wait(200)
V 16:33:29.253 Connecting to FE:10:CD:01:21:29...
D 16:33:29.253 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE)
D 16:33:34.381 [Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E 16:33:34.381 Error 133 (0x85): GATT ERROR
I 16:33:34.381 Disconnected

[Aleksander Nowakowski]

Thank you. This looks like a bug in dfu from Sdk 15.3. 

When a phone reconnects to a device and tries dfu it first checks if upload can be resumed. It compares offset and CRC. It the init packet matches, it checks the same for the data. In your case, 40960 bytes has been saved before, which is 10 full data objects, 4096 bytes each. The CRC is ok. At this point the library should ensure that the last data object has been executed. It should be fine to execute an already executed object, but in your case it falls.

There are 2 solutions. You may migrate to Sdk 16 or 17, where this bug should be fixed, or I could try to implement a workaround in the Android and iOS library, but I don't know if it will work. I would just ignore the returned error assuming all went ok, and continue.

[mdido]

Thank you for your support.

Here are some comments to what you wrote:

you wrote: "this looks like a bug in dfu from Sdk 15.3

mdido: I'm using Sdk 15.0, not 15.3

you wrote: "you may migrate to Sdk 16 or 17, where this bug should be fixed"

mdido: Is there a release note or change log where I can find this bug fixed?

you wrote: "I could try to implement a workaround in the Android and iOS library"

mdido: It will be a workaround officially approved by Nordic?. Instead of ignoring the error, could you restart the update from the beginning? It seems that iOS does not return the error

[Aleksander Nowakowski]

Regarding the last request: If you're using DFU library in your app, you may call 

https://github.com/NordicSemiconductor/Android-DFU-Library/blob/2f61019d6da350ce3e577b5115e82b727b1c7112/dfu/src/main/java/no/nordicsemi/android/dfu/DfuServiceInitiator.java#L295

with value true. This will make the DFU always start from the beginning.

Also, I'm surprised the iOS DFU Library works. The issue should be independent from mobile OS. Do you also disable resume in iOS?

[mdido]

thank you for your suggestion.

About iOS we have to check with our developers. Is the function called the same way?

[Aleksander Nowakowski]

Also, I just checked this issue and it was missed and isn't fixed in SDK 16 nor 17. That means I need to do some kind of workaround.

[Aleksander Nowakowski]

Yes, there's similar flag in the initiator: github.com/.../DFUServiceInitiator.swift