OTA failures with golioth_basics example

Golioth Device Help
1

Hi,
We’re testing out Golioth for a new ESP32-IDF based product, and trialling the OTA feature.
We’re using a ESP32-C3 devkit and running through the ````````golioth_basics example.

When performing a firmware update a number issues are occurring:

  1. The firmware downloading often fails and resets the CoAP client, starting the download from the first block
  2. If the download doesn’t fail, the device still boots from the old partition and the update process starts again after connecting to golioth cloud and receiving the OTA manifest.

Any tips on how to proceed from here?

Thanks

I (1001603) fw_block_processor: Downloading block index 1191 (1192/1195)
I (1002023) fw_block_processor: Downloading block index 1192 (1193/1195)
I (1002423) fw_block_processor: Downloading block index 1193 (1194/1195)
I (1002833) fw_block_processor: Downloading block index 1194 (1195/1195)
I (1003253) golioth_fw_update: Download took 678920 ms
I (1003253) fw_block_processor: Block Latency Stats:
I (1003253) fw_block_processor:    Min: 380 ms
I (1003253) fw_block_processor:    Ave: 636.373 ms
I (1003273) fw_block_processor:    Max: 8790 ms
I (1003273) fw_block_processor: Total bytes written: 1223136
I (1003283) esp_image: segment 0: paddr=00010020 vaddr=3c0f0020 size=31c38h (203832) map
I (1003313) esp_image: segment 1: paddr=00041c60 vaddr=3fc95c00 size=02ff4h ( 12276)
I (1003323) esp_image: segment 2: paddr=00044c5c vaddr=40380000 size=0b3bch ( 46012)
I (1003333) esp_image: segment 3: paddr=00050020 vaddr=42000020 size=e0238h (918072) map
I (1003453) esp_image: segment 4: paddr=00130260 vaddr=4038b3bc size=0a750h ( 42832)
I (1003463) golioth_fw_update: State = Downloaded
I (1004883) golioth_fw_update: State = Updating
I (1005293) fw_update_esp_idf: Setting boot partition
I (1005303) esp_image: segment 0: paddr=00010020 vaddr=3c0f0020 size=31c38h (203832) map
I (1005323) esp_image: segment 1: paddr=00041c60 vaddr=3fc95c00 size=02ff4h ( 12276)
I (1005323) esp_image: segment 2: paddr=00044c5c vaddr=40380000 size=0b3bch ( 46012)
I (1005343) esp_image: segment 3: paddr=00050020 vaddr=42000020 size=e0238h (918072) map
I (1005453) esp_image: segment 4: paddr=00130260 vaddr=4038b3bc size=0a750h ( 42832)
I (1005543) golioth_fw_update: Rebooting into new image in 5 seconds
I (1006053) golioth_basics: Sending hello! 99
I (1006543) golioth_fw_update: Rebooting into new image in 4 seconds
I (1007543) golioth_fw_update: Rebooting into new image in 3 seconds
I (1008543) golioth_fw_update: Rebooting into new image in 2 seconds
I (1009543) golioth_fw_update: Rebooting into new image in 1 seconds
I (1010543) example_wifi: retry to connect to the AP
I (1010543) example_wifi: connect to the AP fail
ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0x3 (RTC_SW_SYS_RST),boot:0xc (SPI_FAST_FLASH_BOOT)
Saved PC:0x403806c2
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fcd5820,len:0x16a0
load:0x403cc710,len:0x968
load:0x403ce710,len:0x2ee0
entry 0x403cc710
I (35) boot: ESP-IDF v5.0.2 2nd stage bootloader
I (35) boot: compile time 14:57:19
I (35) boot: chip revision: v0.3
I (37) boot.esp32c3: SPI Speed      : 80MHz
I (42) boot.esp32c3: SPI Mode       : DIO
I (46) boot.esp32c3: SPI Flash Size : 4MB
I (51) boot: Enabling RNG early entropy source...
I (57) boot: Partition Table:
I (60) boot: ## Label            Usage          Type ST Offset   Length
I (68) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (75) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (82) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (90) boot:  3 ota_0            OTA app          00 10 00010000 00190000
I (97) boot:  4 ota_1            OTA app          00 11 001a0000 00190000
I (105) boot: End of partition table
I (169) esp_image: segment 0: paddr=00010020 vaddr=3c0f0020 size=31c38h (203832) map
I (202) esp_image: segment 1: paddr=00041c60 vaddr=3fc95c00 size=02ff4h ( 12276) load
I (204) esp_image: segment 2: paddr=00044c5c vaddr=40380000 size=0b3bch ( 46012) load
I (216) esp_image: segment 3: paddr=00050020 vaddr=42000020 size=e0238h (918072) map
I (360) esp_image: segment 4: paddr=00130260 vaddr=4038b3bc size=0a750h ( 42832) load
I (374) boot: Loaded app from partition at offset 0x10000
I (374) boot: Disabling RNG early entropy source...
I (386) cpu_start: Pro cpu up.
I (394) cpu_start: Pro cpu start user code
I (394) cpu_start: cpu freq: 160000000 Hz
I (394) cpu_start: Application information:
I (397) cpu_start: Project name:     golioth_basics
I (403) cpu_start: App version:      v0.6.0-22-g763157e-dirty
I (409) cpu_start: Compile time:     May 15 2023 14:56:17
I (415) cpu_start: ELF file SHA256:  68b67b63976b2f5a...
I (421) cpu_start: ESP-IDF:          v5.0.2
I (426) cpu_start: Min chip rev:     v0.3
I (431) cpu_start: Max chip rev:     v0.99
I (436) cpu_start: Chip rev:         v0.3
I (441) heap_init: Initializing. RAM available for dynamic allocation:
I (448) heap_init: At 3FCA2D30 len 000399E0 (230 KiB): DRAM
I (454) heap_init: At 3FCDC710 len 00002950 (10 KiB): STACK/DRAM
I (461) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM
I (468) spi_flash: detected chip: generic
I (472) spi_flash: flash io: dio
I (476) coexist: coexist rom version 9387209
I (481) cpu_start: Starting scheduler.
I (489) BTDM_INIT: BT controller compile version [80abacd]
I (489) phy_init: phy_version 950,11a46e9,Oct 21 2022,08:56:12
I (529) system_api: Base MAC address is not set
I (529) system_api: read default base MAC address from EFUSE
I (529) BTDM_INIT: Bluetooth MAC: 68:67:25:4e:1d:9e

I (539) golioth_ble: BLE Host Task Started
I (539) NimBLE: GAP procedure initiated: stop advertising.

I (549) NimBLE: GAP procedure initiated: advertise;
I (549) NimBLE: disc_mode=2
I (559) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (559) NimBLE:


Type 'help' to get the list of commands.
Use UP/DOWN arrows to navigate through command history.
Press TAB when typing command name to auto-complete.
I (619) pp: pp rom version: 9387209
I (629) net80211: net80211 rom version: 9387209
                                                                                                                                                                                                          I (639) wifi_init: rx ba win: 6
I (639) wifi_init: tcpip mbox: 32
I (639) wifi_init: udp mbox: 6
I (639) wifi_init: tcp mbox: 6
I (659) wifi_init: tcp tx win: 5744
I (659) wifi_init: tcp rx win: 5744
I (659) wifi_init: tcp mss: 1440
I (659) wifi_init: WiFi IRAM OP enabled
esp32> I (679) wifi_init: WiFi RX IRAM OP enabled
I (3979) esp_netif_handlers: sta ip: 192.168.1.37, mask: 255.255.255.0, gw: 192.168.1.254
I (3979) example_wifi: WiFi Connected. Got IP:192.168.1.37
I (3989) example_wifi: Connected to AP SSID: NewieVentures
I (3989) golioth_mbox: Mbox created, bufsize: 2184, num_items: 20, item_size: 104
I (3999) golioth_basics: Waiting for connection to Golioth...
I (4059) golioth_coap_client: Start CoAP session with host: coaps://coap.golioth.io
I (4069) golioth_coap_client: Session PSK-ID: c3-devkit-id@esp32devkit_test1
I (4079) libcoap: Setting PSK key

I (4079) golioth_coap_client: Entering CoAP I/O loop
I (4969) golioth_coap_client: Golioth CoAP client connected
I (4969) golioth_basics: Golioth client connected
I (4969) golioth_basics: Hello, Golioth!
I (4969) golioth_fw_update: Current firmware version: main - 1.2.5
I (4989) golioth_fw_update: Waiting for golioth client to connect before cancelling rollback
I (4999) golioth_fw_update: Firmware updated successfully!
I (5069) golioth_fw_update: State = Idle
W (7849) golioth_coap_client: CoAP message retransmitted
E (9989) golioth_basics: Error setting string: GOLIOTH_ERR_TIMEOUT
W (11489) golioth_coap_client: CoAP message retransmitted
W (13849) golioth_coap_client: CoAP message retransmitted
W (14079) golioth_coap_client: Ignoring request that has aged out, type 3, path my_string
E (14989) golioth_basics: Synchronous get my_int failed: GOLIOTH_ERR_TIMEOUT
I (14989) golioth_basics: Entering endless loop
I (14989) golioth_basics: Sending hello! 0
W (15309) golioth_coap_client: Ignoring request that has aged out, type 1, path my_int
I (16229) golioth_fw_update: Waiting to receive OTA manifest
I (16639) golioth_basics: Callback got my_int = 42
I (18589) golioth_fw_update: Received OTA manifest
I (18589) golioth_fw_update: Current version = 1.2.5, Target version = 1.2.6
I (18609) golioth_fw_update: State = Downloading
W (19299) golioth_coap_client: 4.00 (req type: 3, path: .c/status), len 59
I (20119) golioth_fw_update: Image size = 1223136
I (20119) fw_block_processor: Downloading block index 0 (1/1195)
I (21049) fw_update_esp_idf: Writing to partition subtype 17 at offset 0x1a0000
I (21049) fw_update_esp_idf: Erasing flash
I (25099) golioth_basics: Sending hello! 1
1 Like
2

Hi Joshua, thanks for trying out Golioth!

I looked through your logs and I think I see the issue causing the binary to be continually downloaded. Did you change the hardcoded firmware version, recompile, and upload that new binary as the artifact/release? This number needs to be updated, and must match the number provided when you upload the new binary to Golioth.

For the Golioth Basics example, there is a repo-root/examples/common/golioth_basics.c file which is where you set the firmware version number: golioth-firmware-sdk/golioth_basics.c at 763157e23b01d28f039f7e772c40d1617766b836 · golioth/golioth-firmware-sdk · GitHub

I see from your terminal output that the downloaded firmware is still reporting v1.2.5 when it boots, but it should be reporting v1.2.6 (which is what the server says is available). Right now it is up to you to make sure the compiled-in version matches the version you enter when you upload. But we do have an issue on our backlog to improve this.

On the topic of block downloads that fail and restart from the beginning. This is the expected behavior for right now. But we are currently developing an enhancement that lets the device restart a partial download from the last successful block. I don’t know for sure when this will be released, but it is a priority for us.

Please let me know if you this gets you unstuck :smiley:

1 Like
3

Thanks for the info Mike.
Yes, I was changing the firmware version in the line you mentioned, and following the flow you outlined.

Since writing this I re-read the docs and saw that the latest supported ESP-IDF version is 4.x, and I was using 5.x. I switched to v4.4.4 and I did have a successful OTA update after several downloading attempts. Not sure if the IDF version change is related, but it succeeded at least that once. I’ll have a few more tries to confirm for myself.

This has satisfied my evaluation for now I think. Thanks for the help!