LWM2M Client fails to upgrade modem firmware

[RonanB96]

modem fw 1.3.0

ncs 1.5.0 and master

I am trying to test modem firmware upgrades using the lwm2m client sample and every time it is writing the 20% downloaded chunk, the modem throws an 

DFU_ERROR_INTERNAL_03 error. The modem firmware delta is attached

mfw_nrf9160_update_from_1.3.0_to_1.3.0-FOTA-TEST.bin

Log of downloading the firmware and error applying firmware

uart:~$ *** Booting Zephyr OS build v2.4.99-ncs1  ***
[00:00:00.207,794] <dbg> net_lwm2m_engine.lwm2m_engine_init: LWM2M engine socket receive thread started
[00:00:00.207,885] <dbg> net_lwm2m_obj_security.security_create: Create LWM2M security instance: 0
--- 20 messages dropped ---
[00:00:00.207,916] <dbg> net_lwm2m_obj_server.server_create: Create LWM2M server instance: 0
[00:00:00.208,007] <dbg> net_lwm2m_obj_device.device_create: Create LWM2M device instance: 0
[00:00:00.208,038] <dbg> net_lwm2m_obj_conn_mon.connmon_create: Create LWM2M connectivity monitoring instance: 0
[00:00:00.208,068] <dbg> net_lwm2m_obj_firmware.firmware_create: Create LWM2M firmware instance: 0
[00:00:00.208,099] <dbg> net_lwm2m_obj_location.location_create: Create Location instance: 0
[00:00:00.208,526] <inf> app_lwm2m_client: Run LWM2M client
[00:00:00.208,740] <dbg> app_lwm2m_client.main: Set DNS to custom address 8.8.8.8
[00:00:00.209,503] <inf> app_lwm2m_client: Initializing modem.
[00:00:00.233,459] <dbg> net_ipso_onoff_switch.switch_create: Create IPSO On/Off Switch instance: 1
[00:00:00.233,520] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:3342/1/5500, value:0x20025c27, len:1
[00:00:00.233,581] <dbg> net_lwm2m_engine.lwm2m_engine_create_obj_inst: path:3313/0
[00:00:00.233,642] <dbg> net_ipso_accel.accel_create: Create IPSO Accelerometer instance: 0
[00:00:00.233,734] <dbg> net_lwm2m_engine.lwm2m_engine_get: path:3/0/13, buf:0x20025c14, buflen:4
[00:00:00.233,764] <inf> app_lwm2m_accel: accelerometer normal
[00:00:00.233,795] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:3313/0/5702, value:0x20025c18, len:8
[00:00:00.233,856] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:3313/0/5703, value:0x20025c18, len:8
[00:00:00.233,917] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:3313/0/5704, value:0x20025c18, len:8
[00:00:00.233,978] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:3313/0/5518, value:0x20025c04, len:4
[00:00:00.234,039] <inf> app_lwm2m_firmware: Update Counter: current 0, update 0
[00:00:00.234,069] <inf> app_lwm2m_firmware: Image is not confirmed OK
[00:00:00.234,130] <inf> app_lwm2m_firmware: Marked image as OK
[00:00:00.234,313] <inf> app_lwm2m_firmware: Update Counter updated
[00:00:00.234,344] <inf> app_lwm2m_firmware: Firmware updated successfully
[00:00:00.234,375] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:5/0/5, value:0x20025c17, len:1
[00:00:01.896,240] <inf> app_lwm2m_client: Connecting to LTE network.
[00:00:01.896,270] <inf> app_lwm2m_client: This may take several minutes.
[00:00:01.896,331] <dbg> lte_lc.lte_lc_system_mode_set: Sending AT command to set system mode: AT%XSYSTEMMODE=0,1,1,0
[00:00:05.006,256] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 2,"2332","02592A20",9

[00:00:05.332,702] <dbg> lte_lc.at_handler: +CSCON notification
[00:00:06.644,134] <dbg> lte_lc.at_handler: +CEREG notification: +CEREG: 5,"2332","02592A20",9,,,"11100000","00101000"

[00:00:06.644,470] <dbg> lte_lc.parse_psm_cfg: TAU: 28800 sec, active time: -1 sec

[00:00:06.644,592] <inf> app_lwm2m_client: Connected to LTE network
[00:00:06.646,118] <inf> net_lwm2m_rd_client: Start LWM2M Client: nrf-352656106650180
[00:00:06.680,450] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:4/0/0, value:0x20026d7f, len:1
[00:00:06.680,603] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:4/0/8, value:0x20026d7c, len:4
[00:00:06.680,633] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:4/0/9, value:0x20026d7e, len:2
[00:00:06.680,664] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:4/0/10, value:0x20026d7e, len:2
[00:00:06.680,786] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:4/0/2, value:0x20026d77, len:1
[00:00:07.209,075] <dbg> net_lwm2m_engine.lwm2m_engine_get: path:0/0/1, buf:0x20023767, buflen:1
[00:00:07.209,167] <dbg> net_lwm2m_engine.lwm2m_engine_get: path:0/0/10, buf:0x20023792, buflen:2
[00:00:07.209,197] <inf> net_lwm2m_rd_client: RD Client started with endpoint 'nrf-352656106650180' with client lifetime 0
[00:00:07.209,259] <dbg> net_lwm2m_engine.lwm2m_parse_peerinfo: Parse url: coaps://leshan.eclipseprojects.io
[00:00:08.624,542] <dbg> net_lwm2m_engine.lwm2m_engine_get: path:1/0/1, buf:0x20023750, buflen:4
[00:00:08.626,220] <dbg> net_lwm2m_rd_client.sm_send_registration: registration sent [23.97.187.154]
[00:00:08.804,229] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:08.804,260] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:08.804,260] <dbg> net_lwm2m_rd_client.do_registration_reply_cb: Registration callback (code:2.1)
[00:00:08.804,290] <dbg> app_lwm2m_client.rd_client_event: Registration complete
[00:00:08.804,321] <inf> net_lwm2m_rd_client: Registration Done (EP='ItPzcT0F3x')
[00:00:08.804,351] <dbg> net_lwm2m_engine.lwm2m_udp_receive: reply 0x2001505c handled and removed
[00:00:15.982,482] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:15.982,513] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:22.163,604] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:22.163,635] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:22.163,696] <dbg> net_lwm2m_engine.handle_request: No accept option given. Assume OMA TLV.
[00:00:22.163,879] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:0 last:0
[00:00:22.163,909] <dbg> net_lwm2m_obj_firmware.lwm2m_firmware_set_update_state: Update state = 1
[00:00:22.164,642] <inf> dfu_target_modem_delta: Modem DFU Socket created
[00:00:22.164,947] <inf> dfu_target_modem_delta: Modem firmware version: e7f4d5d4-f607-43a6-b383-cfdb6d725c82
[00:00:22.165,710] <inf> dfu_target_modem_delta: Deleting firmware image, this can take several minutes
[00:00:32.318,206] <dbg> lte_lc.at_handler: +CSCON notification
[00:00:37.908,569] <inf> dfu_target_modem_delta: Modem FW delete complete
[00:00:37.908,599] <inf> app_lwm2m_firmware: Modem firmware download started.
[00:00:37.946,166] <inf> app_lwm2m_firmware: Downloaded 1%
[00:00:38.559,051] <dbg> lte_lc.at_handler: +CSCON notification
[00:00:38.794,372] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:38.794,372] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:38.794,372] <dbg> net_lwm2m_engine.lwm2m_udp_receive: No handler for response
[00:00:47.148,498] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:47.148,529] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:47.148,590] <dbg> net_lwm2m_engine.handle_request: No accept option given. Assume OMA TLV.
[00:00:47.148,773] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:0 last:0
[00:00:47.148,803] <inf> app_lwm2m_firmware: Downloaded 3%
[00:00:47.149,261] <inf> app_lwm2m_firmware: Downloaded 5%
[00:00:47.449,096] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:47.449,096] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:47.449,188] <dbg> net_lwm2m_engine.handle_request: No accept option given. Assume OMA TLV.
[00:00:47.449,310] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:512 last:0
[00:00:47.449,371] <inf> app_lwm2m_firmware: Downloaded 7%
[00:00:47.711,090] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:47.711,151] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:47.711,212] <dbg> net_lwm2m_engine.handle_request: No accept option given. Assume OMA TLV.
[00:00:47.711,334] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:768 last:0
[00:00:47.711,395] <inf> app_lwm2m_firmware: Downloaded 9%
[00:00:48.015,106] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:48.015,136] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:48.015,197] <dbg> net_lwm2m_engine.handle_request: No accept option given. Assume OMA TLV.
[00:00:48.015,350] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:1024 last:0
[00:00:48.015,380] <inf> app_lwm2m_firmware: Downloaded 11%
[00:00:48.346,099] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:48.346,130] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:48.346,191] <dbg> net_lwm2m_engine.handle_request: No accept option given. Assume OMA TLV.
[00:00:48.346,343] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:1280 last:0
[00:00:48.346,374] <inf> app_lwm2m_firmware: Downloaded 12%
[00:00:48.691,131] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:48.691,162] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:48.691,223] <dbg> net_lwm2m_engine.handle_request: No accept option given. Assume OMA TLV.
[00:00:48.691,375] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:1536 last:0
[00:00:48.691,406] <inf> app_lwm2m_firmware: Downloaded 14%
[00:00:49.003,143] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:49.003,173] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:49.003,234] <dbg> net_lwm2m_engine.handle_request: No accept option given. Assume OMA TLV.
[00:00:49.003,387] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:1792 last:0
[00:00:49.003,448] <inf> app_lwm2m_firmware: Downloaded 16%
[00:00:49.554,168] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:49.554,199] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:49.554,260] <dbg> net_lwm2m_engine.handle_request: No accept option given. Assume OMA TLV.
[00:00:49.554,412] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:2048 last:0
[00:00:49.554,443] <inf> app_lwm2m_firmware: Downloaded 18%
[00:00:49.850,189] <err> net_lwm2m_engine: Unknown IP address family:0
[00:00:49.850,219] <dbg> net_lwm2m_engine.lwm2m_udp_receive: checking for reply from [unk]
[00:00:49.850,280] <dbg> net_lwm2m_engine.handle_request: No accept option given. Assume OMA TLV.
[00:00:49.850,433] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:2304 last:0
[00:00:49.850,463] <inf> app_lwm2m_firmware: Downloaded 20%
[00:00:49.852,050] <err> dfu_target_modem_delta: send failed, modem errno 8, dfu err -5
[00:00:49.852,050] <err> app_lwm2m_firmware: dfu_target_write error, err -14
[00:00:49.852,050] <inf> dfu_target_modem_delta: Modem upgrade aborted.
[00:00:49.852,508] <dbg> net_lwm2m_obj_firmware.lwm2m_firmware_set_update_state: Update state = 0
[00:00:49.852,539] <dbg> net_lwm2m_obj_firmware.lwm2m_firmware_set_update_result: Update result = 5
uart:~$ 

I got the same result from using NCS v1.5.0 and on master.

I added in a custom DNS server as our SIM provider doesn't serve one from the network but otherwise, the sample is unchanged

[Albrecht Markus Schellenberger]

Hello Ronan,

I unfortunately do not have a straight forward answer to your problem. But I’ll try to dive into it a little an see if I can find a pattern. I’ll come back to you as soon as possible.

Just a quick question, though: Did firmware updates work with the previous modem firmware?

Regards,

Markus

[RonanB96]

Hi Markus,

I haven't tried with previous modem firmware but I have successfully used the fota_download lib for upgrading modem firmware deltas without any issues

Thanks

Ronan

[Albrecht Markus Schellenberger]

Hello Ronan,

After testing the LwM2M client application myself I can confirm that there is a FOTA issue, which might be related to mfw 1.3.0.

I have not really found a pattern yet, but I’ll cross-check this with our development department.

Could you just do me a favour and run the AT Command "AT+CGMR". It would be interesting for me to see which revision your currently have loaded on your modem. Thanks!

Regards,

Markus

[Albrecht Markus Schellenberger]

Hello Ronan,

my apologies for the late reply! It took me some time to analyse the issue.

What I can see in your log is that the first block of the FOTA image is send twice:

[00:00:22.163,879] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:0 last:0
[00:00:47.148,773] <dbg> net_lwm2m_engine.lwm2m_write_handler: BLOCK1: total:13772 current:0 last:0

This is the reason for modem errno 8 and DFU err -5.

Otherwise I wonder what kind of server it is you are connecting to since your log still says that you are connecting to the Leshian Server?

[00:00:07.209,259] <dbg> net_lwm2m_engine.lwm2m_parse_peerinfo: Parse url: coaps://leshan.eclipseprojects.io

Regards,

Markus

[RonanB96]

Hi Markus, 

Sorry for the delay, I was off most of last week. The response to AT+CGMR was mfw_nrf9160_1.3.0.

I am triggering the download from the Leshan Server by uploading the fota test file to "Package" Resource in the "Firmware Upgrade" Object.

My goal is just to prove that firmware upgrades triggered by an LWM2M server are possible and the underlying SDK is mature enough for our application. The Leshan server will not be used for our application