Cannot update firmware with nRF Connect Device Manager

[Jakob123]

I am attempting to update our Android aplication to upload firmware with DFU. DFU works with nrf Connect, but when I attempt to upload a new version using Device Manager it just resets the device. Below i have attached a logcat output I get with Test and Confirm and another one I get if I do it in confirm only.

When attempting to upload firmware without test and confirmation the app claims it has been uploaded, but the device keeps old firmware.

Any help on how to beter debugg this problem or solve it would be greatly appriciated.

Chunk with offset 302308 has been lost (expected offset=302528, received=302088)
A notification for chunk with offset=299668 was lost, but the chunk was ack-ed by later chunk (confirmed offset=302748)
Chunk with offset 303188 has been lost (expected offset=303408, received=302968)
A notification for chunk with offset=302088 was lost, but the chunk was ack-ed by later chunk (confirmed offset=304948)
Chunk with offset 305608 has been lost (expected offset=305828, received=305388)
A notification for chunk with offset=302968 was lost, but the chunk was ack-ed by later chunk (confirmed offset=305828)
Chunk with offset 306488 has been lost (expected offset=306708, received=306268)
Image (307964 bytes) sent in 232352 ms (avg speed: 1,325420 kB/s)
A notification for chunk with offset=305388 was lost, but the chunk was ack-ed by later chunk (confirmed offset=307964)
A notification for chunk with offset=306268 was lost, but the chunk was ack-ed by later chunk (confirmed offset=307964)
Upload completed. 307964 bytes sent in 233393 ms with avg speed: 1.3195026 kBytes/s
Moving from state UPLOAD to state TEST
Sending (58 bytes) Header (Version: 1, Op: 2, Flags: 0, Len: 50, Group: 1, Seq: 231, Command: 0) CBOR {"confirm":false,"hash":"jXDk7aApQwqpOzFXCzBnuXtijn0ayVJfsJmuen+uQI4="}
Data written to da2e7828-fbce-4e01-ae9e-261174997c48
Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-F4-00-01-E7-00-BF-66-69-6D-61-67-65-73-9F-BF-64-73-6C-6F-74-00-67-76-65-72-73-69-6F-6E-65-30-2E-30-2E-30-64-68-61-73-68-58-20-AB-3C-E7-53-B6-EF-42-EE-AD-0B-20-78-54-C8-D2-54-6B-35-94-35-50-7F-
Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 73-00-FF
Received Header (Version: 0, Op: 3, Flags: 0, Len: 244, Group: 1, Seq: 231, Command: 0) CBOR {"images":[{"slot":0,"version":"0.0.0","hash":"qzznU7bvQu6tCyB4VMjSVGs1lDVQf6CDPRiAs/I6+6c=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,
Test response: {"images":[{"slot":0,"version":"0.0.0","hash":"qzznU7bvQu6tCyB4VMjSVGs1lDVQf6CDPRiAs/I6+6c=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"jXDk7aApQwqpOzFXCzBnuXtijn0ayVJfsJmuen+uQI4=","boota
Moving from state TEST to state RESET
Sending (10 bytes) Header (Version: 1, Op: 2, Flags: 0, Len: 2, Group: 0, Seq: 232, Command: 5) CBOR {}
Data written to da2e7828-fbce-4e01-ae9e-261174997c48
Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-02-00-00-E8-05-BF-FF
Received Header (Version: 0, Op: 3, Flags: 0, Len: 2, Group: 0, Seq: 232, Command: 5) CBOR {}
Reset request success. Waiting for disconnect...
onClientConnectionState() - status=8 clientIf=8 device=F5:28:47:BA:9B:1B
Error: (0x8): GATT CONN TIMEOUT
Disconnected
close()
unregisterApp() - mClientIf=8
Device disconnected
Moving from state RESET to state CONFIRM
STATE_ON
connect() - device: F5:28:47:BA:9B:1B, auto: false
isSecureModeEnabled
registerApp()
registerApp() - UUID=848b51f5-4b23-493f-a438-0458f9efaef6
onClientRegistered() - status=0 clientIf=8
onClientConnectionState() - status=0 clientIf=8 device=F5:28:47:BA:9B:1B
Connected to F5:28:47:BA:9B:1B
discoverServices() - device: F5:28:47:BA:9B:1B
onConnectionUpdated() - Device=F5:28:47:BA:9B:1B interval=6 latency=0 timeout=500 status=0
Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
onSearchComplete() = Device=F5:28:47:BA:9B:1B Status=0
Services discovered
configureMTU() - device: F5:28:47:BA:9B:1B mtu: 498
onConfigureMTU() - Device=F5:28:47:BA:9B:1B mtu=252 status=0
MTU changed to: 252
setCharacteristicNotification() - uuid: da2e7828-fbce-4e01-ae9e-261174997c48 enable: true
Data written to descr. 00002902-0000-1000-8000-00805f9b34fb
Notifications enabled
Data written to da2e7828-fbce-4e01-ae9e-261174997c48
onConnectionUpdated() - Device=F5:28:47:BA:9B:1B interval=39 latency=0 timeout=500 status=0
Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-06-00-00-FF-06-BF-62-72-63-08-FF
Wait for value changed complete
onPhyRead() - status=0 address=F5:28:47:BA:9B:1B txPhy=1 rxPhy=1
Received Header (Version: 0, Op: 1, Flags: 0, Len: 6, Group: 0, Seq: 255, Command: 6) CBOR {"rc":8}
PHY read (TX: LE 1M, RX: LE 1M)
Sending (58 bytes) Header (Version: 1, Op: 2, Flags: 0, Len: 50, Group: 1, Seq: 0, Command: 0) CBOR {"confirm":true,"hash":"jXDk7aApQwqpOzFXCzBnuXtijn0ayVJfsJmuen+uQI4="}
Data written to da2e7828-fbce-4e01-ae9e-261174997c48
Sending (10 bytes) Header (Version: 1, Op: 0, Flags: 0, Len: 2, Group: 0, Seq: 1, Command: 6) CBOR {}
Data written to da2e7828-fbce-4e01-ae9e-261174997c48
Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-06-00-01-00-00-BF-62-72-63-03-FF
Received Header (Version: 0, Op: 3, Flags: 0, Len: 6, Group: 1, Seq: 0, Command: 0) CBOR {"rc":3}
Upgrade failed
Mcu Mgr Error: 3
	at io.runtime.mcumgr.ble.McuMgrBleTransport$2.onResponse(McuMgrBleTransport.java:417)
	at io.runtime.mcumgr.ble.callback.SmpProtocolSessionKt.onResponse$lambda$1(SmpProtocolSession.kt:156)
	at io.runtime.mcumgr.ble.callback.SmpProtocolSessionKt.$r8$lambda$y5OWzRv1IbLlvC7QCOqni68WVyI(Unknown Source:0)
	at io.runtime.mcumgr.ble.callback.SmpProtocolSessionKt$$ExternalSyntheticLambda2.run(Unknown Source:4)
	at android.os.Handler.handleCallback(Handler.java:873)
	at android.os.Handler.dispatchMessage(Handler.java:99)
	at android.os.Looper.loop(Looper.java:214)
	at android.os.HandlerThread.run(HandlerThread.java:65)
Sending (20 bytes) Header (Version: 1, Op: 0, Flags: 0, Len: 12, Group: 0, Seq: 2, Command: 7) CBOR {"format":"sv"}
Data written to da2e7828-fbce-4e01-ae9e-261174997c48
Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-06-00-00-02-07-BF-62-72-63-08-FF
Received Header (Version: 0, Op: 1, Flags: 0, Len: 6, Group: 0, Seq: 2, Command: 7) CBOR {"rc":8}
Sending (10 bytes) Header (Version: 1, Op: 0, Flags: 0, Len: 2, Group: 0, Seq: 3, Command: 8) CBOR {}
Data written to da2e7828-fbce-4e01-ae9e-261174997c48
Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-06-00-00-03-08-BF-62-72-63-08-FF
Received Header (Version: 0, Op: 1, Flags: 0, Len: 6, Group: 0, Seq: 3, Command: 8) CBOR {"rc":8}
onConnectionUpdated() - Device=F5:28:47:BA:9B:1B interval=39 latency=0 timeout=42 status=0
Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 420ms)

Chunk with offset 267988 has been lost (expected offset=268208, received=267768)
Chunk with offset 268208 has been lost (expected offset=268428, received=267768)
A notification for chunk with offset=267768 was lost, but the chunk was ack-ed by later chunk (confirmed offset=274808)
Chunk with offset 290868 has been lost (expected offset=291088, received=290648)
Chunk with offset 291088 has been lost (expected offset=291308, received=290648)
A notification for chunk with offset=290648 was lost, but the chunk was ack-ed by later chunk (confirmed offset=297688)
Chunk with offset 307368 has been lost (expected offset=307588, received=307148)
Chunk with offset 307588 has been lost (expected offset=307808, received=307148)
Image (307964 bytes) sent in 96156 ms (avg speed: 3,202754 kB/s)
A notification for chunk with offset=307148 was lost, but the chunk was ack-ed by later chunk (confirmed offset=307964)
Upload completed. 307964 bytes sent in 97933 ms with avg speed: 3.1446075 kBytes/s
Moving from state UPLOAD to state CONFIRM
Sending (58 bytes) Header (Version: 1, Op: 2, Flags: 0, Len: 50, Group: 1, Seq: 203, Command: 0) CBOR {"confirm":true,"hash":"jXDk7aApQwqpOzFXCzBnuXtijn0ayVJfsJmuen+uQI4="}
Data written to da2e7828-fbce-4e01-ae9e-261174997c48
Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-F4-00-01-CB-00-BF-66-69-6D-61-67-65-73-9F-BF-64-73-6C-6F-74-00-67-76-65-72-73-69-6F-6E-65-30-2E-30-2E-30-64-68-61-73-68-58-20-AB-3C-E7-53-B6-EF-42-EE-AD-0B-20-78-54-C8-D2-54-6B-35-94-35-50-7F-A0-83-3D-18-80-B3-F2-3A-F
Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 73-00-FF
Received Header (Version: 0, Op: 3, Flags: 0, Len: 244, Group: 1, Seq: 203, Command: 0) CBOR {"images":[{"slot":0,"version":"0.0.0","hash":"qzznU7bvQu6tCyB4VMjSVGs1lDVQf6CDPRiAs/I6+6c=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":
Confirm response: {"images":[{"slot":0,"version":"0.0.0","hash":"qzznU7bvQu6tCyB4VMjSVGs1lDVQf6CDPRiAs/I6+6c=","bootable":true,"pending":false,"confirmed":true,"active":true,"permanent":false},{"slot":1,"version":"0.0.0","hash":"jXDk7aApQwqpOzFXCzBnuXtijn0ayVJfsJmuen+uQI4=","bootable":true,"pending":tr
Moving from state CONFIRM to state RESET
Sending (10 bytes) Header (Version: 1, Op: 2, Flags: 0, Len: 2, Group: 0, Seq: 204, Command: 5) CBOR {}
Data written to da2e7828-fbce-4e01-ae9e-261174997c48
Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 03-00-00-02-00-00-CC-05-BF-FF
Received Header (Version: 0, Op: 3, Flags: 0, Len: 2, Group: 0, Seq: 204, Command: 5) CBOR {}
Reset request success. Waiting for disconnect...
onClientConnectionState() - status=8 clientIf=9 device=F5:28:47:BA:9B:1B
Error: (0x8): GATT CONN TIMEOUT
Disconnected
close()
unregisterApp() - mClientIf=9
Device disconnected
Upgrade complete
MSG_WINDOW_FOCUS_CHANGED 0 1
prepareNavigationBarInfo() DecorView@d4b9b93[MainActivity]
getNavigationBarColor() -16777216
setWindowStopped(true) old=false
Input channel destroyed: fd=73
EGLNativeWindowType 0x7e44dcf010 disconnect failed
eglDestroySurface = 0x7e1d860000, 0x7e44dcf000
Relayout returned: old=[0,0][1080,2220] new=[0,0][1080,2220] result=0x5 surface={valid=false 0} changed=true
Surface release. android.view.ViewRootImpl$ViewRootHandler.handleMessage:4822 android.os.Handler.dispatchMessage:106 
Relayout returned: old=[0,0][1080,2220] new=[0,0][1080,2220] result=0x1 surface={valid=false 0} changed=false
Relayout returned: old=[0,0][1080,2220] new=[0,0][1080,2220] result=0x1 surface={valid=false 0} changed=false
setWindowStopped(false) old=true
setWindowStopped(false) old=false
Relayout returned: old=[0,0][1080,2220] new=[0,0][1080,2220] result=0x7 surface={valid=true 542321209344} changed=true
EGLint new_window_surface(egl_winsys_display *, void *, EGLSurface, EGLConfig, egl_winsys_surface **, EGLBoolean) returns 0x3000
eglCreateWindowSurface = 0x7e1d860000, 0x7e44dcf010
MSG_WINDOW_FOCUS_CHANGED 1 1
prepareNavigationBarInfo() DecorView@d4b9b93[MainActivity]
getNavigationBarColor() -16777216
prepareNavigationBarInfo() DecorView@d4b9b93[MainActivity]
getNavigationBarColor() -16777216
Starting input: tba=no.nordicsemi.android.nrfconnectdevicemanager ic=null mNaviBarColor -16777216 mIsGetNaviBarColorSuccess true , NavVisible : true , NavTrans : false
startInputInner - Id : 0
startInputInner - mService.startInputOrWindowGainedFocus
Input channel constructed: fd=73

[Menon]

Hello,

I am letting you know that I have been assigned to this case and have started looking into it. Could you share which SDK version and Nordic chip/DK you are using here? Are you working with a custom board here?

If I understood correctly, OTA firmware updating is working properly with the nRF Connect mobile app, but it fails with the Device Manager app. Is this correct?

 

Kind Regards,

Abhijith

[Jakob123]

SDK version - v2.2.0
Chips used:
We are using a custom board with a nrf9160 and nrf52811. The nrf52811 acts as a bluetooth controller - the code is a copy of zephyr/samples/bluetooth/hci_uart
nrf9160 and nrf52811 communicate using lp_uart
I am also attaching our configuration file. 
Yes, update works using nRF Connect mobile but fails with Device Manager.

common.conf

[Menon]

Hello,

Sorry for the delay. This is a bit strange. Is there anyway I can get a minimal project for reproducing this here? Is there any error message from the nRF side while doing DFU? If so, could you also share those logs? Since it is a custom board, I am not sure if I can reproduce this, but I will try it on our DK.

 

Kind Regards,

Abhijith

[Jakob123]

I am attempting to upload firmware using https://github.com/NordicSemiconductor/Android-nRF-Connect-Device-Manager. I cannot get logs from the nRF side. Do you know of any difference between those two applications that might be causing a difference? Is there any configuration i could attempt to change wich might have a difference?

[Menon]

Hello,

I don't think you need to configure anything separately for the nRF Connect device manager app to collect the logs. Do the logs from the nRF device remain visible while using nRF-connect mobile apps? Is there anyway I can try this here and reproduce the issue? I am not sure if this is something related to the nRF device manager app. Since you are able to do the DFU via the nRF Connect app, I guess your application might be okay.

Kind Regards,

Abhijith