OTA fails on ESP32

[guglielmino]

Expected Behavior

Running OTA update via HTTP RPC interface should download the firmware from the given URL and override running one.

Actual Behavior

The process fails, file is downloaded and update processing starts but, after a while, the process ends with a timeout. Error in console is:

[May  9 22:04:55.651] updater_abort        Update timed out
[May  9 22:04:55.657] updater_set_status   Update state 4 -> 9
[May  9 22:04:55.660] updater_finish       Finished: -5 Update failed

Steps to Reproduce the Problem

1. Expose a new firmware package (ie. fw.zip) from a URL
2. Issue the OTA.Update command
3. Run mos console to monitor device activity

Specifications

• Version: 2.1 (Build ID: 20180418-132622/2.1@d9490727+) release channel
• Platform: ESP32 (Olimex ESP32-EVB)
  • Console log dump mos_console.log

[rojer]

for various reasons it is not trivial to abort an update and start a new one at the same time. the timeout you see is the 5 minute default timeout, controlled by the update.timeout. i don't see anything out of ordinary in the log except taht download proceeds very slowly and you just need to increase the update.timeout setting. i will add a field to OTA.Update RPC so it can be specified per-request, but for now you'll need to change the configuration setting.

[guglielmino]

Download timeout was my first suspect, then I tried to run a web server on my PC connected to the same network. I implemented a small Python web server to be able to monitor the download. Download finished, I'm quite sure also because I tried to stop the web server after I saw that all data was dispatched. Stopped the web server I saw the device running the "processing" stage for some time and then giving up for timeout.

[rojer]

well, there's nothing to suspect here, really, in the log you provided the reason for update failure is quite clear:

[May  9 21:59:55.634] updater_context_crea starting, timeout 300
[May  9 21:59:55.637] mgos_event_trigger   ev MOS3 triggered 0 handlers
[May  9 21:59:55.643] mgos_ota_http_start  Update URL: http://192.168.0.18:8000/fw.zip, ct: 300, isv? 0
...
[May  9 22:00:26.129] mgos_upd_file_begin  Writing FS image @ 0x350000
[May  9 22:00:27.757] updater_set_status   Update state 3 -> 4
[May  9 22:00:27.760] updater_process_int  Processed 0, up to 0, 435 left in the buffer
[May  9 22:00:27.766] updater_process_int  fs.img 0 of 262144
...
[May  9 22:04:55.409] updater_process_int  fs.img 210432 of 262144
[May  9 22:04:55.412] mgos_event_trigger   ev MOS3 triggered 0 handlers
[May  9 22:04:55.651] updater_abort        Update timed out
[May  9 22:04:55.657] updater_set_status   Update state 4 -> 9
[May  9 22:04:55.660] updater_finish       Finished: -5 Update failed```

that's 5 minutes and it didn't finish downloading even the fs image. i'm not sure why download is so slow, but that's the reason, for sure.