Description
I recently ported my working app to Golioth SDK v0.19.0 to support the latest location services, and with the new SDK comes new issues and bugs. When triggering the OTA, I was getting the following Path too long error message. So to fix that, I added the following to the prj.conf file as stated in the Golioth template
CONFIG_COAP_EXTENDED_OPTIONS_LEN=y
CONFIG_COAP_EXTENDED_OPTIONS_LEN_VALUE=39
However, the issue persists, and although the device manages to download the image from the cloud, it gets stuck in a reset loop (see the full log),
[00:00:07.456,939] <inf> golioth_fw_update: Current version = 1.0.0, Target version = 1.1.1
[00:00:07.768,554] <inf> golioth_fw_update: Target component already downloaded. Attempting to update.
[00:00:07.768,554] <inf> golioth_fw_update: State = Updating
[00:00:08.096,893] <inf> golioth_fw_update: Rebooting into new image in 5 seconds
[00:00:09.097,045] <inf> golioth_fw_update: Rebooting into new image in 4 seconds
[00:00:10.097,198] <inf> golioth_fw_update: Rebooting into new image in 3 seconds
[00:00:11.097,351] <inf> golioth_fw_update: Rebooting into new image in 2 seconds
which seems to be related to this issue, as the OTA was working flawlessly in the previous SDK v0.18.0.
So, what should be the correct CoAP length value to prevent this?
39 does not seem to be working atm.
Expected Behavior
The device should be able to download without giving coap length error and boot in the downloaded image.
Actual Behavior
[00:00:07.728,027] <err> net_coap: 234 is > sizeof(coap_option->value)(39)!
[00:00:07.728,057] <inf> golioth_rpc: RPC observation established
[00:00:07.828,186] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:07.828,186] <inf> golioth_fw_update: State = Idle
[00:00:08.156,005] <inf> golioth_fw_update: Received OTA manifest
[00:00:08.156,066] <inf> golioth_fw_update: Current version = 1.0.0, Target version = 1.1.1
[00:00:08.468,231] <inf> golioth_fw_update: State = Downloading
[00:00:09.574,493] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:09.574,615] <inf> golioth_fw_update: Received block 0/368
Impact
Hampering the deployment and release of the firmware update to the fleet
Environment
NCS 3.0.2
Golioth SDK v0.19.0
Device nRF9151 SiP
Logs and Console Output
Booting TF-M v2.1.1-ncs4-2
[Sec Thread] Secure image initializing!
[00:00:00.256,866] <inf> lis2dh: fs=2, odr=0x4 lp_en=0x0 scale=9576
*** Booting My Application v1.0.0-a3bb163d1c60 ***
*** Using nRF Connect SDK v3.0.2-89ba1294ac9b ***
*** Using Zephyr OS v4.0.99-f791c49f492c ***
*** Golioth Firmware SDK v0.19.0 ***
[00:00:00.598,999] <dbg> battery: npm1300_fuel_gauge_init: Init and start nPM1300 PMIC
[00:00:00.599,212] <dbg> battery: fuel_gauge_init_params: nRF Fuel Gauge version: 1.0.1
[00:00:00.601,959] <inf> battery: Fuel gauge initialized successfully
[00:00:00.601,989] <inf> golioth_settings_autoload: Initializing settings subsystem
[00:00:00.608,337] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.608,337] <inf> fs_nvs: alloc wra: 0, fb8
[00:00:00.608,367] <inf> fs_nvs: data wra: 0, 74
[00:00:00.608,428] <inf> golioth_settings_autoload: Loading settings
[00:00:00.609,252] <inf> tracker: -------------------- MAIN APP --------------------
[00:00:00.609,283] <dbg> tracker: main: Starting application
[00:00:00.609,313] <inf> tracker: Firmware version: 1.0.0
[00:00:00.696,594] <inf> modem: Modem firmware version: mfw_nrf91x1_2.0.2
[00:00:00.796,020] <inf> modem: Reset reason: PIN reset | software (0x10001)
[00:00:02.609,680] <wrn> date_time: Valid time not currently available
[00:00:02.609,710] <err> vibe_monitor: Failed to obtain current time, error -61
[00:00:02.783,660] <inf> modem: Incoming RSRP status message, RSRP value is -88
[00:00:02.783,874] <inf> cellular_nrf91: LTE cell changed: Cell ID: 103705110, Tracking area: 41601
[00:00:02.783,905] <inf> cellular_nrf91: LTE mode: LTEM
[00:00:04.796,417] <inf> user_button: User button initialized on pin 31
[00:00:04.796,447] <inf> modem: Connecting to LTE, this may take some time...
[00:00:06.199,829] <wrn> at_monitor: No heap space for incoming notification: %XTIME: "0A","5280303013650A","01"
[00:00:06.202,606] <inf> modem: Network: Registered (roaming)
[00:00:06.203,063] <inf> golioth_mbox: Mbox created, bufsize: 1320, num_items: 10, item_size: 120
[00:00:06.203,765] <inf> golioth_fw_update: Current firmware version: main - 1.0.0
[00:00:06.205,718] <inf> modem: PSM parameter update: TAU: 3600 s, Active time: 0 s
[00:00:06.206,024] <inf> golioth_fw_update: State = Idle
[00:00:07.317,260] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:00:07.317,474] <inf> tracker: Golioth client connected
[00:00:07.317,596] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:07.728,027] <err> net_coap: 234 is > sizeof(coap_option->value)(39)!
[00:00:07.728,057] <inf> golioth_rpc: RPC observation established
[00:00:07.828,186] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:07.828,186] <inf> golioth_fw_update: State = Idle
[00:00:08.156,005] <inf> golioth_fw_update: Received OTA manifest
[00:00:08.156,066] <inf> golioth_fw_update: Current version = 1.0.0, Target version = 1.1.1
[00:00:08.468,231] <inf> golioth_fw_update: State = Downloading
[00:00:09.574,493] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:09.574,615] <inf> golioth_fw_update: Received block 0/368
[00:00:09.574,676] <inf> mcuboot_util: Image index: 0, Swap type: none
[00:00:09.574,707] <inf> golioth_fw_zephyr: swap type: none
[00:00:10.310,546] <inf> modem: Incoming RSRP status message, RSRP value is -93
[00:00:10.331,146] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:10.331,207] <inf> golioth_fw_update: Received block 1/368
[00:00:10.873,504] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:10.873,596] <inf> golioth_fw_update: Received block 2/368
[00:00:11.567,260] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:11.567,352] <inf> golioth_fw_update: Received block 3/368
[00:00:12.111,724] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:12.111,816] <inf> golioth_fw_update: Received block 4/368
[00:00:12.197,967] <inf> modem: Incoming RSRP status message, RSRP value is -91
[00:00:12.891,296] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:12.891,387] <inf> golioth_fw_update: Received block 5/368
[00:00:13.434,326] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:13.434,417] <inf> golioth_fw_update: Received block 6/368
[00:00:13.967,285] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:13.967,376] <inf> golioth_fw_update: Received block 7/368
[00:00:14.441,314] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:14.441,436] <inf> golioth_fw_update: Received block 8/368
[00:00:15.066,619] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:15.066,711] <inf> golioth_fw_update: Received block 9/368
[00:00:15.618,377] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:15.618,469] <inf> golioth_fw_update: Received block 10/368
[00:00:16.157,257] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:16.157,348] <inf> golioth_fw_update: Received block 11/368
[00:00:16.718,200] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:16.718,322] <inf> golioth_fw_update: Received block 12/368
[00:00:17.350,708] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:17.350,799] <inf> golioth_fw_update: Received block 13/368
[00:00:17.887,390] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
....
[00:03:44.854,187] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:03:44.854,278] <inf> golioth_fw_update: Received block 368/368
[00:03:44.949,554] <inf> golioth_fw_update: Successfully downloaded 377651 bytes in 216154 ms
[00:03:44.949,584] <inf> golioth_fw_update: State = Downloaded
[00:03:45.281,127] <inf> golioth_fw_update: State = Updating
[00:03:45.604,064] <inf> golioth_fw_update: Rebooting into new image in 5 seconds
[00:03:46.604,248] <inf> golioth_fw_update: Rebooting into new image in 4 seconds
[00:03:47.604,400] <inf> golioth_fw_update: Rebooting into new image in 3 seconds
[00:03:48.189,575] <inf> modem: Incoming RSRP status message, RSRP value is -85
[00:03:48.189,880] <inf> cellular_nrf91: LTE cell changed: Cell ID: 5370133, Tracking area: 41707
[00:03:48.189,910] <inf> modem: LTE cell changed: Cell ID: 5370133, Tracking area: 41707
[00:03:48.604,553] <inf> golioth_fw_update: Rebooting into new image in 2 seconds
uart:~$ All pins have been configured as non-secure
Booting TF-M v2.1.1-ncs4-2
[Sec Thread] Secure image initializing!
[00:00:00.256,835] <inf> lis2dh: fs=2, odr=0x4 lp_en=0x0 scale=9576
*** Booting My Application v1.0.0-a3bb163d1c60 ***
*** Using nRF Connect SDK v3.0.2-89ba1294ac9b ***
*** Using Zephyr OS v4.0.99-f791c49f492c ***
*** Golioth Firmware SDK v0.19.0 ***
[00:00:00.598,907] <dbg> battery: npm1300_fuel_gauge_init: Init and start nPM1300 PMIC
[00:00:00.599,121] <dbg> battery: fuel_gauge_init_params: nRF Fuel Gauge version: 1.0.1
[00:00:00.601,867] <inf> battery: Fuel gauge initialized successfully
[00:00:00.601,898] <inf> golioth_settings_autoload: Initializing settings subsystem
[00:00:00.608,245] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.608,245] <inf> fs_nvs: alloc wra: 0, fb8
[00:00:00.608,276] <inf> fs_nvs: data wra: 0, 74
[00:00:00.608,337] <inf> golioth_settings_autoload: Loading settings
[00:00:00.609,130] <inf> tracker: -------------------- MAIN APP --------------------
[00:00:00.609,191] <dbg> tracker: main: Starting application
[00:00:00.609,222] <inf> tracker: Firmware version: 1.0.0
[00:00:00.696,502] <inf> modem: Modem firmware version: mfw_nrf91x1_2.0.2
[00:00:00.795,928] <inf> modem: Reset reason: PIN reset | software (0x10001)
[00:00:04.405,029] <inf> modem: Incoming RSRP status message, RSRP value is -85
[00:00:04.405,242] <inf> cellular_nrf91: LTE cell changed: Cell ID: 5370133, Tracking area: 41707
[00:00:04.405,273] <inf> cellular_nrf91: LTE mode: LTEM
[00:00:04.796,325] <inf> user_button: User button initialized on pin 31
[00:00:04.796,325] <inf> modem: Connecting to LTE, this may take some time...
[00:00:05.821,807] <inf> modem: Incoming RSRP status message, RSRP value is -89
uart:~$
[00:00:09.586,517] <err> net_coap: 813 is > sizeof(coap_option->value)(39)!
[00:00:09.611,389] <err> net_coap: 234 is > sizeof(coap_option->value)(39)!
[00:00:09.611,419] <inf> golioth_rpc: RPC observation established
[00:00:09.666,564] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:09.666,564] <inf> golioth_fw_update: State = Idle
[00:00:09.960,662] <inf> golioth_fw_update: Received OTA manifest
[00:00:09.960,723] <inf> golioth_fw_update: Current version = 1.0.0, Target version = 1.1.1
[00:00:10.272,552] <inf> golioth_fw_update: Target component already downloaded. Attempting to update.
[00:00:10.272,552] <inf> golioth_fw_update: State = Updating
[00:00:10.571,746] <inf> golioth_fw_update: Rebooting into new image in 5 seconds
[00:00:11.571,899] <inf> golioth_fw_update: Rebooting into new image in 4 seconds
[00:00:12.572,052] <inf> golioth_fw_update: Rebooting into new image in 3 seconds
[00:00:13.572,204] <inf> golioth_fw_update: Rebooting into new image in 2 seconds
uart:~$ All pins have been configured as non-secure
Booting TF-M v2.1.1-ncs4-2
[Sec Thread] Secure image initializing!
[00:00:00.256,805] <inf> lis2dh: fs=2, odr=0x4 lp_en=0x0 scale=9576
*** Booting My Application v1.0.0-a3bb163d1c60 ***
*** Using nRF Connect SDK v3.0.2-89ba1294ac9b ***
*** Using Zephyr OS v4.0.99-f791c49f492c ***
*** Golioth Firmware SDK v0.19.0 ***
[00:00:00.598,602] <dbg> battery: npm1300_fuel_gauge_init: Init and start nPM1300 PMIC
[00:00:00.598,815] <dbg> battery: fuel_gauge_init_params: nRF Fuel Gauge version: 1.0.1
[00:00:00.601,562] <inf> battery: Fuel gauge initialized successfully
[00:00:00.601,593] <inf> golioth_settings_autoload: Initializing settings subsystem
[00:00:00.607,940] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.607,940] <inf> fs_nvs: alloc wra: 0, fb8
[00:00:00.607,971] <inf> fs_nvs: data wra: 0, 74
[00:00:00.608,001] <inf> golioth_settings_autoload: Loading settings
[00:00:00.608,825] <inf> tracker: -------------------- MAIN APP --------------------
[00:00:00.608,886] <dbg> tracker: main: Starting application
[00:00:00.608,886] <inf> tracker: Firmware version: 1.0.0
[00:00:00.696,197] <inf> modem: Modem firmware version: mfw_nrf91x1_2.0.2
[00:00:00.795,623] <inf> modem: Reset reason: PIN reset | software (0x10001)
[00:00:02.168,853] <inf> modem: Incoming RSRP status message, RSRP value is -81
[00:00:02.169,067] <inf> cellular_nrf91: LTE cell changed: Cell ID: 5370133, Tracking area: 41707
[00:00:02.169,097] <inf> cellular_nrf91: LTE mode: LTEM
[00:00:04.796,020] <inf> user_button: User button initialized on pin 31
[00:00:04.796,051] <inf> modem: Connecting to LTE, this may take some time...
[00:00:05.565,490] <wrn> at_monitor: No heap space for incoming notification: %XTIME: "0A","5280303063300A","01"
[00:00:05.668,182] <inf> modem: Network: Registered (roaming)
[00:00:05.668,670] <inf> golioth_mbox: Mbox created, bufsize: 1320, num_items: 10, item_size: 120
[00:00:05.669,372] <inf> golioth_fw_update: Current firmware version: main - 1.0.0
[00:00:05.671,325] <inf> modem: PSM parameter update: TAU: 3600 s, Active time: 0 s
[00:00:05.671,630] <inf> golioth_fw_update: State = Idle
[00:00:06.755,798] <inf> golioth_coap_client_zephyr: Golioth CoAP client connected
[00:00:06.756,011] <inf> tracker: Golioth client connected
[00:00:06.756,011] <inf> golioth_coap_client_zephyr: Entering CoAP I/O loop
[00:00:07.097,595] <err> net_coap: 27259 is > sizeof(coap_option->value)(39)!
[00:00:07.111,633] <err> net_coap: 234 is > sizeof(coap_option->value)(39)!
[00:00:07.111,694] <inf> golioth_rpc: RPC observation established
[00:00:07.143,737] <inf> golioth_fw_update: Waiting to receive OTA manifest
[00:00:07.143,768] <inf> golioth_fw_update: State = Idle
[00:00:07.456,878] <inf> golioth_fw_update: Received OTA manifest
[00:00:07.456,939] <inf> golioth_fw_update: Current version = 1.0.0, Target version = 1.1.1
[00:00:07.768,554] <inf> golioth_fw_update: Target component already downloaded. Attempting to update.
[00:00:07.768,554] <inf> golioth_fw_update: State = Updating
[00:00:08.096,893] <inf> golioth_fw_update: Rebooting into new image in 5 seconds
[00:00:09.097,045] <inf> golioth_fw_update: Rebooting into new image in 4 seconds
[00:00:10.097,198] <inf> golioth_fw_update: Rebooting into new image in 3 seconds
[00:00:11.097,351] <inf> golioth_fw_update: Rebooting into new image in 2 seconds
