Problem doing full modem update on nrf9160 over the air

[Mark Heaps]

nordic_upgrade_with_zcbor_trace.txt

Hi

I am trying to perform a full modem update on my nrf9160 DK board.

I started at v1.3.4 and successfully used the partial update method to go to 1.3.5

I then used partial update again to go to 1.3.6

I then tried to do a full update to 1.3.7 and this failed.

I loaded file firmware.update.image.cbor from the 1.3.7 download archive

I loaded it onto my server and triggered the download.

The download started and recognised a full firmware update

The download completed but failed with the following errors

[00:20:43.351,623] <inf> app_lwm2m_fsm: FOTA Update request for instance 0
[00:20:43.351,654] <inf> fota_download_full_modem: Applying full modem firmware update from external flash
[00:20:43.384,582] <err> net_echo_server_sample: UDP: Connection error 110
[00:20:43.384,613] <inf> net_echo_server_sample: process_udp ret=-110
[00:20:43.384,735] <err> lte_lc: Failed to enable eDRX, reported error: -12
[00:20:43.387,725] <err> fmfu_fdev: Unable to decode wrapper
[00:20:43.387,756] <err> fota_download_full_modem: fmfu_fdev_load failed: -22

I've attached the full log showing current HW and FW versions of the modem, the start of the transfer and the end of the transfer.

Any ideas

Fullscreen 6153.nordic_example.txt Download

*** Using Zephyr OS v3.6.99-100befc70c74 ***
[00:00:01.147,827] <inf> operations: operations_init
[00:00:01.150,329] <inf> app_lwm2m_client: Run LWM2M client
[00:00:01.150,390] <inf> littlefs_handler: Area 0 at 0x0 on mx25r6435f@1 for 1048576 bytes
[00:00:01.150,421] <inf> littlefs_handler: /lfs1 automounted
[00:00:06.887,725] <inf> littlefs_handler: /lfs1: bsize = 16 ; frsize = 4096 ; blocks = 256 ; bfree = 59
[00:00:07.130,371] <inf> app_modem_mgmt: Initialised modem library
[00:00:07.130,401] <inf> app_modem_mgmt: Initialised modem info
[00:00:07.130,950] <inf> app_modem_mgmt: AT%HWVERSION ret=0 response=%HWVERSION: nRF9160 SICA B1A
OK

[00:00:07.131,652] <inf> app_modem_mgmt: AT%SHORTSWVER ret=0 response=%SHORTSWVER: nrf9160_1.3.6
OK

[00:00:07.132,324] <inf> app_modem_mgmt: AT%XMODEMUUID ret=0 response=%XMODEMUUID: 3e926f75-d31b-4852-b394-8c13f5a8bb6e
OK

[00:00:07.133,026] <inf> app_modem_mgmt: endpoint: urn:imei:351901930692193
[00:00:07.133,056] <inf> app_modem_mgmt: subscribing to signal quality metrics
[00:00:07.139,678] <inf> app_modem_mgmt: AT%CESQ=1 ret=0 response=OK

[00:00:07.140,319] <inf> app_modem_mgmt: AT%XSNRSQ=1 ret=0 response=OK

[00:00:07.352,203] <inf> lwm2m_lte_notification: Registering ncell notification handler
[00:00:07.352,325] <inf> lwm2m_firmware: Image is confirmed OK
[00:00:07.358,886] <err> pdn: Failed to read PDP contexts, err -77
[00:00:07.358,947] <inf> app_lwm2m_client: APN: (-77) ""
[00:00:07.358,947] <inf> app_comms_mgmt: comms_link_connect_startup: starting connection
[00:00:07.359,405] <wrn> app_lwm2m_fsm: PSM mode requested
[00:00:07.359,436] <inf> app_lwm2m_fsm: Connecting to network using async
[00:00:07.398,681] <inf> modbus_serial: RTU timeout 1002 us
[00:00:07.398,712] <inf> app_comms_mgmt: comms_link_start_udp: starting UDP
[00:00:07.398,712] <inf> net_echo_server_sample: Starting UDP
[00:00:07.398,773] <inf> net_echo_server_sample: start_udp_proto
[00:00:07.399,414] <inf> net_echo_server_sample: Waiting for UDP packets on port 4242...
[00:00:07.400,512] <inf> operations_sms: sms_register_listener returns 0
[00:00:07.400,543] <inf> app_gl_engine: GL Engine Init
[00:00:07.414,520] <err> fs: failed to create directory (-17)
[00:00:07.892,669] <err> fs: failed to create directory (-17)
[00:00:10.784,057] <inf> app_modem_mgmt: MON: rsrp=-109 dBm rsrq=-130 dB %CESQ: 31,1,13,1

[00:00:10.884,216] <inf> app_modem_mgmt: MON: snr=3 dB srx=15 cd=0 %XSNRSQ: 27,2,142,0

[00:00:10.984,497] <dbg> app_lwm2m_fsm: lwm2m_lte_reg_handler_notify: LTE NW status: 2
[00:00:11.451,873] <inf> app_modem_mgmt: MON: rsrp=-109 dBm rsrq=-155 dB %CESQ: 31,1,8,1

[00:00:12.729,614] <inf> app_modem_mgmt: MON: Received +CGEV notification: +CGEV: ME PDN ACT 0,0

[00:00:12.729,644] <inf> app_modem_mgmt: MON: Default PDP context activated
[00:00:12.930,755] <inf> app_modem_mgmt: Modem response:+CGDCONT: 0,"IP","eseye1","10.178.88.128",0,0
OK


----

00:05:53.677,246] <inf> fota_download_util: Download Path 0164228b host coap://lwm2m.cumulocity.com:5783
[00:05:53.678,619] <inf> download_client: Downloading: 0164228b [0]
[00:05:54.015,625] <inf> download_client: Connecting to 3.123.199.199
[00:05:54.420,135] <inf> download_client: Downloaded 512/2089453 bytes (0%)
[00:05:54.421,142] <inf> lwm2m_firmware: FOTA download started, target 4
[00:05:54.767,150] <inf> download_client: Downloaded 1024/2089453 bytes (0%)
[00:05:54.926,116] <inf> download_client: Downloaded 1536/2089453 bytes (0%)
[00:05:55.090,209] <inf> download_client: Downloaded 2048/2089453 bytes (0%)
[00:05:55.235,198] <inf> download_client: Downloaded 2560/2089453 bytes (0%)
[00:05:55.438,293] <inf> download_client: Downloaded 3072/2089453 bytes (0%)
[00:05:55.635,375] <inf> download_client: Downloaded 3584/2089453 bytes (0%)
[00:05:55.795,227] <inf> download_client: Downloaded 4096/2089453 bytes (0%)
[00:05:56.115,386] <inf> download_client: Downloaded 4608/2089453 bytes (0%)
[00:05:56.275,207] <inf> download_client: Downloaded 5120/2089453 bytes (0%)
[00:05:56.766,235] <inf> download_client: Downloaded 5632/2089453 bytes (0%)
[00:05:56.967,437] <inf> download_client: Downloaded 6144/2089453 bytes (0%)
[00:05:57.175,445] <inf> download_client: Downloaded 6656/2089453 bytes (0%)
[00:05:57.333,282] <inf> download_client: Downloaded 7168/2089453 bytes (0%)
[00:05:57.481,262] <inf> download_client: Downloaded 7680/2089453 bytes (0%)
[00:05:57.641,448] <inf> download_client: Downloaded 8192/2089453 bytes (0%)
[00:05:57.961,456] <inf> download_client: Downloaded 8704/2089453 bytes (0%)
[00:05:58.163,452] <inf> download_client: Downloaded 9216/2089453 bytes (0%)
[00:05:58.379,455] <inf> download_client: Downloaded 9728/2089453 bytes (0%)
[00:05:58.542,449] <inf> download_client: Downloaded 10240/2089453 bytes (0%)
[00:05:58.708,282] <inf> download_client: Downloaded 10752/2089453 bytes (0%)
[00:05:58.854,919] <inf> download_client: Downloaded 11264/2089453 bytes (0%)
[00:05:58.996,276] <inf> download_client: Downloaded 11776/2089453 bytes (0%)
[00:05:59.155,303] <inf> download_client: Downloaded 12288/2089453 bytes (0%)
[00:05:59.476,287] <inf> download_client: Downloaded 12800/2089453 bytes (0%)
[00:05:59.678,497] <inf> download_client: Downloaded 13312/2089453 bytes (0%)
[00:05:59.885,406] <inf> download_client: Downloaded 13824/2089453 bytes (0%)
[00:06:00.056,304] <inf> download_client: Downloaded 14336/2089453 bytes (0%)
[00:06:00.212,310] <inf> download_client: Downloaded 14848/2089453 bytes (0%)
[00:06:00.356,292] <inf> download_client: Downloaded 15360/2089453 bytes (0%)
[00:06:00.526,367] <inf> download_client: Downloaded 15872/2089453 bytes (0%)
[00:06:00.691,589] <inf> download_client: Downloaded 16384/2089453 bytes (0%)
[00:06:01.005,523] <inf> download_client: Downloaded 16896/2089453 bytes (0%)
[00:06:01.183,532] <inf> download_client: Downloaded 17408/2089453 bytes (0%)
[00:06:01.395,385] <inf> download_client: Downloaded 17920/2089453 bytes (0%)
[00:06:01.555,389] <inf> download_client: Downloaded 18432/2089453 bytes (0%)
[00:06:01.715,545] <inf> download_client: Downloaded 18944/2089453 bytes (0%)
[00:06:01.907,562] <inf> download_client: Downloaded 19456/2089453 bytes (0%)
[00:06:02.130,401] <inf> download_client: Downloaded 19968/2089453 bytes (0%)
[00:06:02.297,454] <inf> download_client: Downloaded 20480/2089453 bytes (0%)
[00:06:02.606,994] <inf> download_client: Downloaded 20992/2089453 bytes (1%)
[00:06:02.787,384] <inf> download_client: Downloaded 21504/2089453 bytes (1%)
[00:06:02.915,588] <inf> download_client: Downloaded 22016/2089453 bytes (1%)
[00:06:03.075,592] <inf> download_client: Downloaded 22528/2089453 bytes (1%)
[00:06:03.278,564] <inf> download_client: Downloaded 23040/2089453 bytes (1%)
[00:06:03.475,463] <inf> download_client: Downloaded 23552/2089453 bytes (1%)
[00:06:03.647,460] <inf> download_client: Downloaded 24064/2089453 bytes (1%)
[00:06:03.796,447] <inf> download_client: Downloaded 24576/2089453 bytes (1%)
[00:06:


[00:20:36.631,530] <inf> download_client: Downloaded 2085888/2089453 bytes (99%)
[00:20:36.791,656] <inf> download_client: Downloaded 2086400/2089453 bytes (99%)
[00:20:36.967,559] <inf> download_client: Downloaded 2086912/2089453 bytes (99%)
[00:20:37.134,246] <inf> download_client: Downloaded 2087424/2089453 bytes (99%)
[00:20:37.362,762] <inf> download_client: Downloaded 2087936/2089453 bytes (99%)
[00:20:37.523,223] <inf> download_client: Downloaded 2088448/2089453 bytes (99%)
[00:20:37.672,210] <inf> download_client: Downloaded 2088960/2089453 bytes (99%)
[00:20:37.991,760] <inf> download_client: Downloaded 2089453/2089453 bytes (100%)
[00:20:37.991,851] <inf> download_client: Download complete
[00:20:37.991,851] <inf> dfu_target_full_modem: Modem firmware downloaded to flash device
[00:20:38.099,975] <inf> lwm2m_firmware: FOTA download finished
[00:20:38.299,194] <inf> app_lwm2m_fsm: FOTA download ready for instance 0, dfu_type 4
[00:20:38.391,418] <dbg> app_lwm2m_fsm: rd_client_event: Registration update started
[00:20:39.033,905] <inf> net_lwm2m_engine: Connected, sock id 2
[00:20:39.325,500] <inf> net_lwm2m_rd_client: Update callback (code:2.4)
[00:20:39.325,561] <dbg> app_lwm2m_fsm: rd_client_event: Registration update complete
[00:20:39.325,592] <inf> net_lwm2m_rd_client: Update Done
[00:20:41.351,470] <inf> app_lwm2m_fsm: FOTA Update request for instance 0
[00:20:41.351,501] <inf> lwm2m_firmware: Delay 2 s Update instance 0 
[00:20:41.351,776] <inf> app_lwm2m_fsm: lwm2m: client state UPDATE_FIRMWARE
[00:20:41.351,837] <inf> net_lwm2m_rd_client: Stop LWM2M Client: urn:imei:351901930692193
[00:20:41.551,452] <err> net_echo_server_sample: UDP: Connection error 115
[00:20:41.551,483] <inf> net_echo_server_sample: process_udp ret=-115
[00:20:41.552,368] <inf> app_modem_mgmt: MON: Received +CGEV notification: +CGEV: ME PDN DEACT 0

[00:20:41.552,429] <inf> app_lwm2m_client: PDN: cid=0 event=2 reason=0
[00:20:41.652,618] <dbg> app_lwm2m_fsm: lwm2m_lte_reg_handler_notify: LTE NW status: 0
[00:20:41.752,593] <inf> app_modem_mgmt: MON: Received +CGEV notification: +CGEV: ME DETACH

[00:20:41.752,655] <inf> app_lwm2m_client: PDN: cid=0 event=5 reason=0
[00:20:42.551,544] <inf> net_echo_server_sample: start_udp_proto
[00:20:42.560,943] <inf> net_echo_server_sample: Waiting for UDP packets on port 4242...
[00:20:42.984,008] <inf> app_modem_mgmt: MON: rsrp=115 dBm rsrq=1080 dB %CESQ: 255,0,255,0

[00:20:43.084,014] <inf> app_modem_mgmt: MON: snr=103 dB srx=32640 cd=255 %XSNRSQ: 127,0,32767,255

[00:20:43.351,623] <inf> app_lwm2m_fsm: FOTA Update request for instance 0
[00:20:43.351,654] <inf> fota_download_full_modem: Applying full modem firmware update from external flash
[00:20:43.384,582] <err> net_echo_server_sample: UDP: Connection error 110
[00:20:43.384,613] <inf> net_echo_server_sample: process_udp ret=-110
[00:20:43.384,735] <err> lte_lc: Failed to enable eDRX, reported error: -12
[00:20:43.387,725] <err> fmfu_fdev: Unable to decode wrapper
[00:20:43.387,756] <err> fota_download_full_modem: fmfu_fdev_load failed: -22
[00:20:43.707,214] <inf> app_lwm2m_fsm: FOTA failure 0 by status 8
[00:20:43.707,244] <wrn> app_lwm2m_fsm: FOTA unexpected new event type MODEM_RECONNECT
[00:20:44.384,674] <inf> net_echo_server_sample: start_udp_proto
[00:20:44.384,735] <err> net_echo_server_sample: Failed to create UDP socket: 105
[00:20:44.384,765] <wrn> net_echo_server_sample: start_udp_proto waiting 1s
[00:20:45.384,826] <inf> net_echo_server_sample: start_udp_proto
[00:20:45.384,918] <err> net_echo_server_sample: Failed to create UDP socket: 105
[00:20:45.384,918] <wrn> net_echo_server_sample: start_udp_proto waiting 1s
[00:20:46.385,009] <inf> net_echo_server_sample: start_udp_proto
[00:20:46.385,070] <err> net_echo_server_sample: Failed to create UDP socket: 105
[00:20:46.385,070] <wrn> net_echo_server_sample: start_udp_proto waiting 1s
[00:20:47.385,162] <inf> net_echo_server_sample: start_udp_proto
[00:20:47.385,223] <err> net_echo_server_sample: Failed to create UDP socket: 105
[00:20:47.385,253] <wrn> net_echo_server_sample: start_udp_proto waiting 1s
[00:20:48.385,345] <inf> net_echo_server_sample: start_udp_proto
[00:20:48.385,406] <err> net_echo_server_sample: Failed to create UDP socket: 105
[00:20:48.385,406] <wrn> net_echo_server_sample: start_udp_proto waiting 1s
[00:20:49.385,498] <inf> net_echo_server_sample: start_udp_proto
[00:20:49.385,559] <err> net_echo_server_sample: Failed to create UDP socket: 105
[00:20:49.385,589] <wrn> net_echo_server_sample: start_udp_proto waiting 1s
[00:20:50.385,681] <inf> net_echo_server_sample: start_udp_proto
[00:20:50.385,742] <err> net_echo_server_sample: Failed to create UDP socket: 105
[00:20:50.385,742] <wrn> net_echo_server_sample: start_udp_proto waiting 1s
[00:20:51.385,833] <inf> net_echo_server_sample: start_udp_proto
[00:20:51.385,894] <err> net_echo_server_sample: Failed to create UDP socket: 105
[00:20:51.385,925] <wrn> net_echo_server_sample: start_udp_proto waiting 1s
[00:20:52.386,016] <inf> net_echo_server_sample: start_udp_proto
[00:20:52.386,077] <err> net_echo_server_sample: Failed to create UDP socket: 105
[00:20:52.386,077] <wrn> net_echo_server_sample: start_udp_proto waiting 1s
[00:20:53.386,169] <inf> net_echo_server_sample: start_udp_proto
[00:20:53.386,260] <err> net_echo_server_sample: Failed to create UDP socket: 105
[00:20:53.386,260] <wrn> net_echo_server_sample: start_udp_proto waiting 1s
[00:20:54.386,352] <inf> net_echo_server_sample: start_udp_proto
[00:20:54.386,413] <err> net_echo_server_sample: Failed to create UDP socket: 105
[00:20:54.386,413] <wrn> net_echo_server_sample: start_udp_proto waiting 1s
uart:~$

[Mark Heaps]

Sorry I forgot some other detail.

I am using SDK 2.7.0

[Michal]

Hello,

So the first error is 115, which means "network is down". Looks like the modem is disconnecting for some reason. I wonder if there's some timeout.

Could you try to turn off PSM and eDRX and test again?

Best regards,

Michal

[Mark Heaps]

I've tried with edrx and PSM disabled. bith together and idependently.

The result is always the same.

The failure seems to be when it tries to decode the CBOR wrapper

[00:17:24.000,488] <err> fmfu_fdev: Unable to decode wrapper

So either the file I'm using isn't correct, or there has been some corruption.

Is it possible to use mcumgr to do the modem upgrade with the same file?

[Mark Heaps]

Further information: I enabled zcbor trace and repeated the download. The following is a fragment of the trace at the end.

[15:36:49.865,234] <inf> download_client: Downloaded 2085888/2089453 bytes (99%)
[15:36:50.110,839] <inf> download_client: Downloaded 2086400/2089453 bytes (99%)
[15:36:51.153,259] <inf> download_client: Downloaded 2086912/2089453 bytes (99%)
[15:36:51.444,702] <inf> download_client: Downloaded 2087424/2089453 bytes (99%)
[15:36:51.693,634] <inf> download_client: Downloaded 2087936/2089453 bytes (99%)
[15:36:51.922,454] <inf> download_client: Downloaded 2088448/2089453 bytes (99%)
uart:~$ encode_lwm2m_senml
New backup (level zu)
rem: zu, cur: 0x3ef, ec: 0xzx, err: 152, value_encode_len
encode_record
New backup (level zu)
rem: zu, cur: 0x3ed, ec: 0xzx, err: 165, value_encode_len
encode_repeated_record_bn
rem: zu, cur: 0x3ec, ec: 0xzx, err: 33, value_encode_len
rem: zu, cur: 0x3eb, ec: 0xzx, err: 101, value_encode_len
encode_repeated_record_bn success
encode_repeated_record_n
rem: zu, cur: 0x3e5, ec: 0xzx, err: 0, value_encode_len
rem: zu, cur: 0x3e4, ec: 0xzx, err: 97, value_encode_len
encode_repeated_record_n success
encode_repeated_record_union
rem: zu, cur: 0x3e2, ec: 0xzx, err: 2, value_encode_len
rem: zu, cur: 0x3e1, ec: 0xzx, err: 2, value_encode_len
encode_repeated_record_union success
Encoded zu elements.
Process backup (level zu, flags 0x1)
list_count: zu
rem: zu, cur: 0x3ed, ec: 0xzx, err: 163, value_encode_len
encode_record success
Encoded zu elements.
Process backup (level zu, flags 0x0)
list_count: zu
rem: zu, cur: 0x3ef, ec: 0xzx, err: 129, value_encode_len
encode_lwm2m_senml success
[15:36:52.179,290] <inf> download_client: Downloaded 2088960/2089453 bytes (99%)
[15:36:52.594,299] <inf> download_client: Downloaded 2089453/2089453 bytes (100%)
[15:36:52.594,390] <inf> download_client: Download complete
[15:36:52.594,390] <inf> dfu_target_full_modem: Modem firmware downloaded to flash device
[15:36:52.702,301] <inf> lwm2m_firmware: FOTA download finished
[15:36:52.888,458] <inf> app_lwm2m_fsm: FOTA download ready for instance 0, dfu_type 4
[15:36:53.015,014] <dbg> app_lwm2m_fsm: rd_client_event: Registration update started
[15:36:53.827,667] <inf> net_lwm2m_engine: Connected, sock id 0
[15:36:54.174,713] <inf> net_lwm2m_rd_client: Update callback (code:2.4)
[15:36:54.174,774] <dbg> app_lwm2m_fsm: rd_client_event: Registration update complete
[15:36:54.174,804] <inf> net_lwm2m_rd_client: Update Done
[15:36:55.317,169] <inf> app_lwm2m_fsm: FOTA Update request for instance 0
[15:36:55.317,230] <inf> lwm2m_firmware: Delay 2 s Update instance 0 
[15:36:55.317,474] <inf> app_lwm2m_fsm: lwm2m: client state UPDATE_FIRMWARE
[15:36:55.317,535] <inf> net_lwm2m_rd_client: Stop LWM2M Client: urn:imei:351901930692193
[15:36:55.463,470] <inf> app_modem_mgmt: MON: Received +CGEV notification: +CGEV: ME PDN DEACT 0

[15:36:55.463,500] <inf> app_lwm2m_client: PDN: cid=0 event=2 reason=0
[15:36:55.563,690] <dbg> app_lwm2m_fsm: lwm2m_lte_reg_handler_notify: LTE NW status: 0
[15:36:55.663,665] <inf> app_modem_mgmt: MON: Received +CGEV notification: +CGEV: ME DETACH

[15:36:55.663,696] <inf> app_lwm2m_client: PDN: cid=0 event=5 reason=0
[15:36:56.914,428] <inf> app_modem_mgmt: MON: rsrp=115 dBm rsrq=1080 dB %CESQ: 255,0,255,0

[15:36:57.014,434] <inf> app_modem_mgmt: MON: snr=103 dB srx=32640 cd=255 %XSNRSQ: 127,0,32767,255

[15:36:57.317,321] <inf> app_lwm2m_fsm: FOTA Update request for instance 0
[15:36:57.317,352] <inf> fota_download_full_modem: Applying full modem firmware update from external flash
[15:36:57.337,310] <err> lte_lc: Failed to enable eDRX, reported error: -12
uart:~$ decode_Wrapper
zcbor_tag_expect zcbor_tag_decode ZCBOR_ERR(10) ZCBOR_FAIL rem: zu, cur: 0x400, ec: 0xzx, err: 113, WEST_TOPDIR/modules/lib/zcbor/src/zcbor_decode.c:51
ZCBOR_FAIL rem: zu, cur: 0x400, ec: 0xzx, err: 113, WEST_TOPDIR/modules/lib/zcbor/src/zcbor_decode.c:1484
ZCBOR_FAIL rem: zu, cur: 0x400, ec: 0xzx, err: 113, WEST_TOPDIR/modules/lib/zcbor/src/zcbor_decode.c:1500
rem: zu, cur: 0x400, ec: 0xzx, err: 113, WEST_TOPDIR/nrf/subsys/dfu/fmfu_fdev/src/modem_update_decode.c:187
decode_Wrapper error: ZCBOR_ERR_WRONG_TYPE
[15:37:45.883,850] <err> fmfu_fdev: Unable to decode wrapper
[15:37:45.883,850] <err> fota_download_full_modem: fmfu_fdev_load failed: -22
[15:37:46.186,676] <inf> app_lwm2m_fsm: FOTA failure 0 by status 8
[15:37:46.186,706] <wrn> app_lwm2m_fsm: FOTA unexpected new event type MODEM_RECONNECT