Application service UUID gone after secure OTA DFU

[SK]

Hello, 

I am using nRF52832 on SES v4.12 with SDK v15.3 and SD v6.1.1 on a custom board.

Background: 

I want to perform OTA DFU and with that i have two services enabled (secure dfu buttonless and NUS). I was facing OTA DFU issue in which i was getting CRC does not match error. This has been resolved here - https://devzone.nordicsemi.com/f/nordic-q-a/55653/dfu-crc-does-not-match-error

So, i have been able to perform OTA update. 

The package that i created includes BL+SD+APP. 

Problem: 

Once i perform the update and connect again, i only see one service, which is Secure DFU service and the other which is the main application service ID (NUS) is gone. I looked in the forum and found this -https://devzone.nordicsemi.com/f/nordic-q-a/39982/after-ota-dfu-bootloader-application-gone

But i do not quite fully understand as to what is to be done here. Could you please highlight on what is required for a proper DFU process? From what i understand from the post and infocenter that it is still a single update, so BL+SD+APP merged together should work fine internally. 

EDIT:

Zip created has only application hex in it. BL+SD+APP is programmed directly using nrfjprog. 

Please let me know if you require more information. 

Thanks a lot!

-SK

[Aleksander Nowakowski]

After successful dfu the new application should be started. The services available after an update depend on what you have in it. If there's only Secure dfu service, than it's either the buttonless service (check characteristic name in nRF Connect for Android) which means that your have flashed an app without NUS, or you're still in bootloader mode, that is the app has been rejected by the new bootloader do for some reason. The old app has been removed, a specially if SD's major version has changed, to make space for dual bank.

In nRF Connect it may also be that another tab opened, with the bootloader address. Just close it and use the tab with your old device name. You may also clear cache, select Refresh services in the menu after connecting to your device.

[SK]

I migrated the SDK from 14.2 to 15.3. In v14.2, this DFU process worked fine. That means i have both the services running after DFU process and yes, there was another tab that opened with the bootloader address. 

But with 15.3, i donot see such a thing. SD major is still 132 that i am using with v6.1.1. 

I ran nrfjprog --eraseall before programming the module with merged hex (BL+SD+APP) and then did a reset. Till here, application runs fine. I can see both the services on the nRF Connect. It is only when i try to update the application (creating a package) via OTA DFU, that i see the problem. When i try to connect, i see only Secure DFU service and not the other one. Not sure whats going on :(  

[Aleksander Nowakowski]

Doesn't matter, it's still "new", as it was updated. After exiting bootloader it should notify client that services have been have changed.

[SK]

oh alright, in that sense, yes.

BTW, i tried again and this time i got 133 error. Attached. 

Fullscreen Log 2019-12-18 17_32_29.txt Download

nRF Connect, 2019-12-18
HELIOS_1 (FB:30:2F:3A:7F:01)
V	17:30:44.401	Connecting to FB:30:2F:3A:7F:01...
D	17:30:44.401	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	17:30:45.147	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	17:30:45.190	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	17:30:45.190	Connected to FB:30:2F:3A:7F:01
V	17:30:45.228	Discovering services...
D	17:30:45.228	gatt.discoverServices()
I	17:30:45.856	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
D	17:30:45.959	[Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDING (11)
D	17:30:45.987	[Broadcast] Action received: android.bluetooth.device.action.PAIRING_REQUEST, pairing variant: PAIRING_VARIANT_CONSENT (3)
D	17:30:46.047	[Callback] Services discovered with status: 0
I	17:30:46.047	Services discovered
V	17:30:46.075	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)
D	17:30:46.076	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D	17:30:46.077	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
I	17:30:46.134	Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
D	17:30:47.258	[Broadcast] Action received: android.bluetooth.device.action.PAIRING_REQUEST, pairing variant: PAIRING_VARIANT_PIN (0)
I	17:30:47.456	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
V	17:30:51.921	Enabling notifications for 6e400003-b5a3-f393-e0a9-e50e24dcca9e
D	17:30:51.921	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
D	17:30:51.922	gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x0100)
D	17:30:54.033	[Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_BONDED (12)
I	17:30:54.033	Device bonded
I	17:30:55.009	Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
A	17:30:55.009	"Notifications enabled" sent
V	17:30:55.014	Notifications enabled for 6e400003-b5a3-f393-e0a9-e50e24dcca9e
I	17:30:55.023	Connection parameters updated (interval: 75.0ms, latency: 0, timeout: 4000ms)
I	17:30:55.023	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:30:55.023	"l,�,/" received
I	17:30:55.976	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:30:55.976	"l,�,/" received
I	17:30:56.951	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:30:56.951	"l,�,/" received
I	17:30:57.925	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:30:57.925	"l,�,/" received
I	17:30:58.901	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:30:58.901	"l,�,/" received
I	17:30:59.950	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:30:59.950	"l,�,/" received
I	17:31:00.926	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:31:00.926	"l,�,/" received
I	17:31:01.902	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:31:01.903	"l,�,/" received
I	17:31:02.878	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:31:02.878	"l,�,/" received
I	17:31:03.852	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:31:03.852	"l,�,/" received
I	17:31:04.828	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:31:04.828	"l,�,/" received
I	17:31:05.799	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:31:05.799	"l,�,/" received
I	17:31:06.850	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:31:06.850	"l,�,/" received
I	17:31:07.824	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:31:07.824	"k,�,/" received
I	17:31:08.802	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:31:08.802	"k,�,/" received
I	17:31:09.853	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:31:09.854	"k,�,/" received
V	17:31:10.394	[DFU] DFU service started
V	17:31:10.394	[DFU] Opening file...
I	17:31:10.413	[DFU] Firmware file opened successfully
V	17:31:10.413	[DFU] Connecting to DFU target...
D	17:31:10.413	[DFU] gatt = device.connectGatt(autoConnect = false)
I	17:31:10.422	[DFU] Connected to FB:30:2F:3A:7F:01
D	17:31:10.422	[DFU] wait(1600)
I	17:31:10.750	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:31:10.750	"k,�,/" received
I	17:31:11.730	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:31:11.730	"k,�,/" received
V	17:31:12.024	[DFU] Discovering services...
D	17:31:12.024	[DFU] gatt.discoverServices()
I	17:31:12.035	[DFU] Services discovered
V	17:31:12.037	[DFU] Reading Service Changed CCCD value...
D	17:31:12.037	[DFU] gatt.readDescriptor(00002902-0000-1000-8000-00805f9b34fb)
I	17:31:12.183	[DFU] Read Response received from descr.00002a05-0000-1000-8000-00805f9b34fb, value (0x): 00-00
V	17:31:12.185	[DFU] Enabling indications for 00002a05-0000-1000-8000-00805f9b34fb
D	17:31:12.186	[DFU] gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D	17:31:12.194	[DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x02-00)
I	17:31:12.326	[DFU] Data written to descr.00002a05-0000-1000-8000-00805f9b34fb, value (0x): 02-00
V	17:31:12.326	[DFU] Indications enabled for 00002a05-0000-1000-8000-00805f9b34fb
A	17:31:12.328	[DFU] Service Changed indications enabled
D	17:31:12.371	[DFU] wait(1000)
I	17:31:12.777	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:31:12.777	"k,�,/" received
W	17:31:13.354	[DFU] Application with buttonless update found
V	17:31:13.354	[DFU] Jumping to the DFU Bootloader...
V	17:31:13.354	[DFU] Enabling indications for 8ec90004-f315-4f60-9fb8-838830daea50
D	17:31:13.354	[DFU] gatt.setCharacteristicNotification(8ec90004-f315-4f60-9fb8-838830daea50, true)
D	17:31:13.357	[DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x02-00)
I	17:31:13.457	[DFU] Data written to descr.8ec90004-f315-4f60-9fb8-838830daea50, value (0x): 02-00
V	17:31:13.457	[DFU] Notifications enabled for 8ec90004-f315-4f60-9fb8-838830daea50
A	17:31:13.457	[DFU] Indications enabled
D	17:31:13.457	[DFU] wait(1000)
I	17:31:13.752	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:31:13.752	"k,�,/" received
V	17:31:14.483	[DFU] Writing to characteristic 8ec90004-f315-4f60-9fb8-838830daea50
D	17:31:14.483	[DFU] gatt.writeCharacteristic(8ec90004-f315-4f60-9fb8-838830daea50)
A	17:31:14.652	[DFU] Enter bootloader sent (Op Code = 1)
I	17:31:14.655	[DFU] Notification received from 8ec90004-f315-4f60-9fb8-838830daea50, value (0x): 20-01-01
A	17:31:14.656	[DFU] Response received (Op Code = 1, Status = 1)
I	17:31:14.728	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:31:14.728	"k,�,/" received
D	17:31:18.788	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	17:31:18.788	Error 8 (0x8): GATT CONN TIMEOUT
I	17:31:18.788	Disconnected
D	17:31:18.821	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
I	17:31:18.836	[DFU] Disconnected by the remote device
D	17:31:18.836	[DFU] gatt.close()
D	17:31:18.836	[DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
V	17:31:18.846	[DFU] DFU service started
I	17:31:18.846	[DFU] Firmware file opened successfully
D	17:31:18.846	[DFU] wait(1000)
D	17:31:19.855	[DFU] wait(1000)
V	17:31:20.846	[DFU] Connecting to DFU target...
D	17:31:20.892	[DFU] gatt = device.connectGatt(autoConnect = false)
E	17:31:25.917	[DFU] Connection failed (0x85): GATT ERROR
W	17:31:25.917	[DFU] Retrying...
D	17:31:25.917	[DFU] gatt.refresh() (hidden)
D	17:31:25.921	[DFU] gatt.close()
V	17:31:25.966	[DFU] DFU service started
I	17:31:25.966	[DFU] Firmware file opened successfully
D	17:31:25.966	[DFU] wait(1000)
D	17:31:27.034	[DFU] wait(1000)
V	17:31:27.967	[DFU] Connecting to DFU target...
D	17:31:27.969	[DFU] gatt = device.connectGatt(autoConnect = false)
E	17:31:33.002	[DFU] Connection failed (0x85): GATT ERROR
W	17:31:33.002	[DFU] Retrying...
D	17:31:33.004	[DFU] gatt.refresh() (hidden)
D	17:31:33.008	[DFU] gatt.close()
V	17:31:33.049	[DFU] DFU service started
I	17:31:33.049	[DFU] Firmware file opened successfully
D	17:31:33.049	[DFU] wait(1000)
D	17:31:34.096	[DFU] wait(1000)
V	17:31:35.054	[DFU] Connecting to DFU target...
D	17:31:35.056	[DFU] gatt = device.connectGatt(autoConnect = false)
E	17:31:40.090	[DFU] Connection failed (0x85): GATT ERROR
D	17:31:40.091	[DFU] gatt.close()
D	17:31:40.094	[DFU] wait(600)
D	17:31:40.698	gatt.close()
D	17:31:40.730	wait(200)
V	17:31:40.932	Connecting to FB:30:2F:3A:7F:01...
D	17:31:40.932	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	17:31:45.969	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	17:31:45.969	Error 133 (0x85): GATT ERROR
I	17:31:45.969	Disconnected

One more 

Fullscreen Log 2019-12-18 17_37_21.txt Download

nRF Connect, 2019-12-18
HELIOS_1 (FB:30:2F:3A:7F:01)
V	17:35:26.747	Connecting to FB:30:2F:3A:7F:01...
D	17:35:26.747	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	17:35:26.828	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	17:35:26.841	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	17:35:26.841	Connected to FB:30:2F:3A:7F:01
D	17:35:26.842	wait(1600ms)
I	17:35:27.652	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	17:35:27.971	Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
V	17:35:28.443	Discovering services...
D	17:35:28.443	gatt.discoverServices()
D	17:35:28.466	[Callback] Services discovered with status: 0
I	17:35:28.466	Services discovered
V	17:35:28.516	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)
D	17:35:28.516	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D	17:35:28.524	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
I	17:35:32.970	Connection parameters updated (interval: 75.0ms, latency: 0, timeout: 4000ms)
V	17:35:39.073	Disabling notifications for 6e400003-b5a3-f393-e0a9-e50e24dcca9e
D	17:35:39.073	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, false)
D	17:35:39.074	gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x0000)
I	17:35:39.196	Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 00-00
A	17:35:39.196	"Notifications and indications disabled" sent
V	17:35:39.199	Notifications and indications disabled for 6e400003-b5a3-f393-e0a9-e50e24dcca9e
V	17:35:39.774	Enabling notifications for 6e400003-b5a3-f393-e0a9-e50e24dcca9e
D	17:35:39.774	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
D	17:35:39.775	gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x0100)
I	17:35:39.871	Data written to descr. 00002902-0000-1000-8000-00805f9b34fb, value: (0x) 01-00
A	17:35:39.871	"Notifications enabled" sent
V	17:35:39.874	Notifications enabled for 6e400003-b5a3-f393-e0a9-e50e24dcca9e
V	17:35:43.549	Disconnecting...
D	17:35:43.549	gatt.disconnect()
D	17:35:43.563	[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	17:35:43.563	Disconnected
D	17:35:44.535	gatt.close()
D	17:35:44.541	wait(200)
V	17:35:44.742	Connecting to FB:30:2F:3A:7F:01...
D	17:35:44.742	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	17:35:44.761	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
I	17:35:44.775	Disconnected
D	17:35:46.732	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	17:35:46.732	gatt.close()
D	17:35:46.745	wait(200)
V	17:35:46.946	Connecting to FB:30:2F:3A:7F:01...
D	17:35:46.946	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	17:35:46.962	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	17:35:46.962	Connected to FB:30:2F:3A:7F:01
D	17:35:46.963	wait(1600ms)
D	17:35:47.792	[Callback] Connection state changed with status: 22 and new state: DISCONNECTED (0)
E	17:35:47.792	Error 22 (0x16): GATT CONN TERMINATE LOCAL HOST
I	17:35:47.792	Disconnected
D	17:35:47.868	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	17:35:59.796	gatt.close()
D	17:35:59.799	wait(200)
V	17:36:00.000	Connecting to FB:30:2F:3A:7F:01...
D	17:36:00.000	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	17:36:00.072	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	17:36:00.079	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	17:36:00.079	Connected to FB:30:2F:3A:7F:01
D	17:36:00.080	wait(1600ms)
V	17:36:01.682	Discovering services...
D	17:36:01.682	gatt.discoverServices()
D	17:36:01.750	[Callback] Services discovered with status: 0
I	17:36:01.750	Services discovered
V	17:36:01.783	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)
D	17:36:01.784	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D	17:36:01.788	gatt.setCharacteristicNotification(6e400003-b5a3-f393-e0a9-e50e24dcca9e, true)
I	17:36:02.697	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:36:02.697	"k,�,/" received
I	17:36:04.051	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:04.051	"l,�,/" received
I	17:36:04.694	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:36:04.694	"k,�,/" received
I	17:36:05.671	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:36:05.671	"k,�,/" received
I	17:36:06.648	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:06.648	"l,�,/" received
I	17:36:07.669	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:07.669	"l,�,/" received
I	17:36:08.644	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:08.644	"l,�,/" received
I	17:36:09.672	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:09.672	"l,�,/" received
I	17:36:10.593	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:10.593	"l,�,/" received
I	17:36:11.616	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:11.616	"l,�,/" received
I	17:36:12.693	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6B-2C-00-FA-2C-03-00-2F
A	17:36:12.693	"k,�,/" received
I	17:36:13.566	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:13.566	"l,�,/" received
I	17:36:14.542	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:14.542	"l,�,/" received
I	17:36:15.567	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:15.567	"l,�,/" received
I	17:36:16.540	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:16.540	"l,�,/" received
I	17:36:17.516	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:17.516	"l,�,/" received
I	17:36:18.540	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:18.540	"l,�,/" received
V	17:36:19.469	[DFU] DFU service started
V	17:36:19.469	[DFU] Opening file...
I	17:36:19.469	[DFU] Firmware file opened successfully
V	17:36:19.469	[DFU] Connecting to DFU target...
D	17:36:19.469	[DFU] gatt = device.connectGatt(autoConnect = false)
I	17:36:19.479	[DFU] Connected to FB:30:2F:3A:7F:01
D	17:36:19.480	[DFU] wait(1600)
I	17:36:19.514	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:19.514	"l,�,/" received
I	17:36:20.491	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:20.491	"l,�,/" received
V	17:36:21.083	[DFU] Discovering services...
D	17:36:21.084	[DFU] gatt.discoverServices()
I	17:36:21.093	[DFU] Services discovered
V	17:36:21.096	[DFU] Reading Service Changed CCCD value...
D	17:36:21.096	[DFU] gatt.readDescriptor(00002902-0000-1000-8000-00805f9b34fb)
I	17:36:21.180	[DFU] Read Response received from descr.00002a05-0000-1000-8000-00805f9b34fb, value (0x): 02-00
A	17:36:21.181	[DFU] Service Changed indications enabled
D	17:36:21.209	[DFU] wait(1000)
I	17:36:21.465	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:21.465	"l,�,/" received
W	17:36:22.203	[DFU] Application with buttonless update found
V	17:36:22.204	[DFU] Jumping to the DFU Bootloader...
V	17:36:22.204	[DFU] Enabling indications for 8ec90004-f315-4f60-9fb8-838830daea50
D	17:36:22.204	[DFU] gatt.setCharacteristicNotification(8ec90004-f315-4f60-9fb8-838830daea50, true)
D	17:36:22.209	[DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x02-00)
I	17:36:22.297	[DFU] Data written to descr.8ec90004-f315-4f60-9fb8-838830daea50, value (0x): 02-00
V	17:36:22.297	[DFU] Notifications enabled for 8ec90004-f315-4f60-9fb8-838830daea50
A	17:36:22.298	[DFU] Indications enabled
D	17:36:22.298	[DFU] wait(1000)
I	17:36:22.490	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:22.490	"l,�,/" received
V	17:36:23.343	[DFU] Writing to characteristic 8ec90004-f315-4f60-9fb8-838830daea50
D	17:36:23.343	[DFU] gatt.writeCharacteristic(8ec90004-f315-4f60-9fb8-838830daea50)
A	17:36:23.417	[DFU] Enter bootloader sent (Op Code = 1)
I	17:36:23.417	[DFU] Notification received from 8ec90004-f315-4f60-9fb8-838830daea50, value (0x): 20-01-01
A	17:36:23.417	[DFU] Response received (Op Code = 1, Status = 1)
I	17:36:23.469	Notification received from 6e400003-b5a3-f393-e0a9-e50e24dcca9e, value: (0x) 11-07-6C-2C-00-FA-2C-03-00-2F
A	17:36:23.469	"l,�,/" received
D	17:36:28.498	[Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)
E	17:36:28.498	Error 8 (0x8): GATT CONN TIMEOUT
I	17:36:28.498	Disconnected
I	17:36:28.534	[DFU] Disconnected by the remote device
D	17:36:28.534	[DFU] gatt.close()
D	17:36:28.551	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	17:36:28.590	[DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
V	17:36:28.590	[DFU] DFU service started
I	17:36:28.590	[DFU] Firmware file opened successfully
D	17:36:28.590	[DFU] wait(1000)
D	17:36:29.585	[DFU] wait(1000)
V	17:36:30.586	[DFU] Connecting to DFU target...
D	17:36:30.626	[DFU] gatt = device.connectGatt(autoConnect = false)
D	17:36:30.736	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	17:36:30.752	[DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I	17:36:30.758	[DFU] Connected to FB:30:2F:3A:7F:01
D	17:36:30.760	[DFU] wait(1600)
V	17:36:32.363	[DFU] Discovering services...
D	17:36:32.363	[DFU] gatt.discoverServices()
I	17:36:32.374	[DFU] Services discovered
V	17:36:32.385	[DFU] Reading Service Changed CCCD value...
D	17:36:32.386	[DFU] gatt.readDescriptor(00002902-0000-1000-8000-00805f9b34fb)
I	17:36:32.424	[DFU] Read Response received from descr.00002a05-0000-1000-8000-00805f9b34fb, value (0x): 02-00
A	17:36:32.424	[DFU] Service Changed indications enabled
D	17:36:32.472	[DFU] wait(1000)
V	17:36:33.473	[DFU] Requesting new MTU...
D	17:36:33.473	[DFU] gatt.requestMtu(517)
I	17:36:33.524	[DFU] MTU changed to: 247
V	17:36:33.524	[DFU] Enabling notifications for 8ec90001-f315-4f60-9fb8-838830daea50
D	17:36:33.525	[DFU] gatt.setCharacteristicNotification(8ec90001-f315-4f60-9fb8-838830daea50, true)
D	17:36:33.527	[DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)
I	17:36:33.578	[DFU] Data written to descr.8ec90001-f315-4f60-9fb8-838830daea50, value (0x): 01-00
V	17:36:33.578	[DFU] Notifications enabled for 8ec90001-f315-4f60-9fb8-838830daea50
A	17:36:33.579	[DFU] Notifications enabled
D	17:36:33.579	[DFU] wait(1000)
V	17:36:34.579	[DFU] Writing to characteristic 8ec90001-f315-4f60-9fb8-838830daea50
D	17:36:34.580	[DFU] gatt.writeCharacteristic(8ec90001-f315-4f60-9fb8-838830daea50)
E	17:36:39.804	[DFU] Error (0x85): GATT ERROR
V	17:36:39.804	[DFU] Disconnecting...
D	17:36:39.841	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	17:36:39.904	[DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
D	17:36:39.904	[DFU] gatt.disconnect()
I	17:36:39.904	[DFU] Disconnected
D	17:36:39.907	[DFU] gatt.close()
D	17:36:39.956	[DFU] wait(600)
D	17:36:40.525	gatt.close()
D	17:36:40.541	wait(200)
V	17:36:40.743	Connecting to FB:30:2F:3A:7F:01...
D	17:36:40.743	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	17:36:45.777	[Callback] Connection state changed with status: 133 and new state: DISCONNECTED (0)
E	17:36:45.777	Error 133 (0x85): GATT ERROR
I	17:36:45.777	Disconnected

[SK]

Aleksander Nowakowski said:

You need to select "Refresh services" in the top menu to clear the cache and do service discovery again

This worked! so we will have to do everytime we try to do OTA DFU, then? 

[SK]

and it seems, sometimes i get that 133 error and other times ( which is 2/10) i get DFU done successfully. 

[Aleksander Nowakowski]

Ideally, the app, after started after successful DFU, should send SC indication, just like the bootloader is sending when switched from app to bootloader mode. On Android you may force clear the cache, like nRF Connect does, but if you want to support iOS as well, there's no such API, not even hidden, so working SC is a must when working with bonded DFU.

The errors 133 happen often, yes. The DFU lib does what it can to try to avoid them, tries many times sometimes, but, a specially on older Android devices and when the device is bonded, the 133 error is common. What phone are you testing on?

If you have sniffer (for example this one: https://www.nordicsemi.com/Software-and-tools/Development-Tools/nRF-Sniffer-for-Bluetooth-LE) you may try to find out what's causing this 133 error. Usually it means that there was a packet lost, packet collision, some packets came too early or too late, or, when device is bonded, perhaps something with the encryption. Try putting phone and device close to each other to avoid interference, sometimes disabling wi-fi also helps, as I read in the Internet. 133 is a generic error when "something else" happens, so it may be almost anything.

The 133 around 5 sec after connection attempt seems like the Connect Request was missed by the device and it continued to advertise instead. Retries should increase the chance of success.

[SK]

Aleksander Nowakowski said:

What phone are you testing on?

I am testing on samsung S9+ currently.

Aleksander Nowakowski said:

133 is a generic error when "something else" happens, so it may be almost anything

That's comforting to know :D 

Yes, i will try it out by sniffing the packets and see if i can get somewhere with this error. 

SK said:

Would you know anything about this issue? https://devzone.nordicsemi.com/f/nordic-q-a/36346/a-problem-on-buttonless-dfu-bonding-valid

This is what Hung said in the link i shared above

"I think we found the root cause of the issue. When you set the MTU to something else not the default that the iPhone set when connected, the nrf_ble_gatt.c will try to request sd_ble_gattc_exchange_mtu_request() immediately right after CONNECTED event."

. Would you know if it is corrected in v15.3? or is it still an issue? 

[Hung Bui]

@SK: The issue regarding the MTU request is fixed in SDK v16.0 but not on SDK v15.3 you may want to follow my suggestion in the case. 

[SK]

Okay sure, will do. In that case, you say putting in a timer to delay the MTU exchange? When should the timer expire? Could you tell me more on the details, please.  

[Hung Bui]

The main reason to delay MTU exchange was to wait for the phone to do that. (so that we have larger MTU ATT). I would say give it 1-2 second. 

Regarding the issue of having sd_ble_gatts_service_changed() and sd_ble_gattc_exchange_mtu_request() at the same time, you can check if the error is NRF_ERROR_INVALID_STATE the application can retry after a certain time (let's say 1 second) . 

[SK]

Hi Hung Bui

Sorry, i had to move to some other tasks. I tried to do as you suggested, but i am getting error on the sd_ble_gattc_exchange_mtu_request() --> unknown error code 

Would you know why would that be? I have added timer as below.

    if (p_link->att_mtu_desired > p_link->att_mtu_effective)
    {
        NRF_LOG_DEBUG("Requesting to update ATT MTU to %u bytes on connection 0x%x.",
                      p_link->att_mtu_desired, conn_handle);
        create_mtu_request_timer();
        app_timer_start(mtu_request_delay_timer, APP_TIMER_TICKS(1000), NULL);
    }

Rest of the code i have moved in the handler:

static void request_delay_handler(void *p_context)
{
  ret_code_t err_code;
  nrf_ble_gatt_t * p_gatt = (nrf_ble_gatt_t *)p_context;
  ble_evt_t const * p_ble_evt;
  uint16_t  conn_handle = p_ble_evt->evt.common_evt.conn_handle;
  nrf_ble_gatt_link_t * p_link      = &p_gatt->links[conn_handle];
    err_code = sd_ble_gattc_exchange_mtu_request(conn_handle, p_link->att_mtu_desired);

    if (err_code == NRF_SUCCESS)
    {
        p_link->att_mtu_exchange_requested = true;
    }
    else if (err_code == NRF_ERROR_BUSY)
    {
        p_link->att_mtu_exchange_pending = true;
        NRF_LOG_DEBUG("sd_ble_gattc_exchange_mtu_request()"
                      " on connection 0x%x returned busy, will retry.", conn_handle);
    }
    else
    {
        NRF_LOG_ERROR("sd_ble_gattc_exchange_mtu_request() returned %s.",
                      nrf_strerror_get(err_code));
    }  
}

Once i connect, i get this error: 

<error> nrf_ble_gatt: sd_ble_gattc_exchange_mtu_request() returned Unknown error code.