OTA timeout problem fixed by workaround

src/ota.cpp

@@ -26,6 +26,8 @@ const BintrayClient bintray(BINTRAY_USER, BINTRAY_REPO, BINTRAY_PACKAGE);
 // Connection port (HTTPS)
 const int port = 443;
 
+const unsigned long STREAM_TIMEOUT = 30000;
+
 // Variables to validate firmware content
 int volatile contentLength = 0;
 bool volatile isValidContentType = false;
@@ -145,13 +147,15 @@ bool do_ota_update() {
   WiFiClientSecure client;
 
   client.setCACert(bintray.getCertificate(currentHost));
+  //client.setTimeout(RESPONSE_TIMEOUT_MS);
+  // --> causing error [E][WiFiClient.cpp:236] setSocketOption(): 1006 : 9
+  // so we unfortunately need patched update.cpp which sets the stream timeout
 
   if (!client.connect(currentHost.c_str(), port)) {
     ESP_LOGI(TAG, "Cannot connect to %s", currentHost.c_str());
     display(3, " E", "connection lost");
     goto abort;
   }
-  // client.setTimeout(RESPONSE_TIMEOUT);
 
   while (redirect) {
     if (currentHost != prevHost) {
@@ -163,7 +167,6 @@ bool do_ota_update() {
         display(3, " E", "server error");
         goto abort;
       }
-      // client.setTimeout(RESPONSE_TIMEOUT);
     }
 
     ESP_LOGI(TAG, "Requesting %s", firmwarePath.c_str());
@@ -175,7 +178,7 @@ bool do_ota_update() {
 
     unsigned long timeout = millis();
     while (client.available() == 0) {
-      if ((millis() - timeout) > (RESPONSE_TIMEOUT * 1000)) {
+      if ((millis() - timeout) > (RESPONSE_TIMEOUT_MS)) {
         ESP_LOGI(TAG, "Client timeout");
         display(3, " E", "client timeout");
         goto abort;
@@ -233,8 +236,8 @@ bool do_ota_update() {
           isValidContentType = true;
         }
       }
-    }
-  } // while (redirect)
+    } // while (client.available())
+  }   // while (redirect)
 
   display(3, "OK", ""); // line download
 
@@ -257,8 +260,7 @@ bool do_ota_update() {
 #endif
 
   display(4, "**", "writing...");
-  written = Update.writeStream(client);
-  client.setTimeout(RESPONSE_TIMEOUT);
+  written = Update.writeStream(client); // this is a blocking call
 
   if (written == contentLength) {
     ESP_LOGI(TAG, "Written %u bytes successfully", written);

src/paxcounter.conf

@@ -70,7 +70,7 @@
 #define WIFI_MAX_TRY                    5       // maximum number of wifi connect attempts for OTA update [default = 20]
 #define OTA_MAX_TRY                     5       // maximum number of attempts for OTA download and write to flash [default = 3]
 #define OTA_MIN_BATT                    3700    // minimum battery level for OTA [millivolt]
-#define RESPONSE_TIMEOUT                60      // firmware binary server connection timeout [seconds]
+#define RESPONSE_TIMEOUT_MS             60000   // firmware binary server connection timeout [milliseconds]
 
 // LMIC settings
 // moved to src/lmic_config.h

src/update.cpp

@@ -0,0 +1,352 @@
+/*
+this file copied from esp32-arduino library and patched, see PR
+https://github.com/espressif/arduino-esp32/pull/1886
+*/
+
+#include "update.h"
+#include "Arduino.h"
+#include "esp_spi_flash.h"
+#include "esp_ota_ops.h"
+#include "esp_image_format.h"
+
+static const char * _err2str(uint8_t _error){
+    if(_error == UPDATE_ERROR_OK){
+        return ("No Error");
+    } else if(_error == UPDATE_ERROR_WRITE){
+        return ("Flash Write Failed");
+    } else if(_error == UPDATE_ERROR_ERASE){
+        return ("Flash Erase Failed");
+    } else if(_error == UPDATE_ERROR_READ){
+        return ("Flash Read Failed");
+    } else if(_error == UPDATE_ERROR_SPACE){
+        return ("Not Enough Space");
+    } else if(_error == UPDATE_ERROR_SIZE){
+        return ("Bad Size Given");
+    } else if(_error == UPDATE_ERROR_STREAM){
+        return ("Stream Read Timeout");
+    } else if(_error == UPDATE_ERROR_MD5){
+        return ("MD5 Check Failed");
+    } else if(_error == UPDATE_ERROR_MAGIC_BYTE){
+        return ("Wrong Magic Byte");
+    } else if(_error == UPDATE_ERROR_ACTIVATE){
+        return ("Could Not Activate The Firmware");
+    } else if(_error == UPDATE_ERROR_NO_PARTITION){
+        return ("Partition Could Not be Found");
+    } else if(_error == UPDATE_ERROR_BAD_ARGUMENT){
+        return ("Bad Argument");
+    } else if(_error == UPDATE_ERROR_ABORT){
+        return ("Aborted");
+    }
+    return ("UNKNOWN");
+}
+
+static bool _partitionIsBootable(const esp_partition_t* partition){
+    uint8_t buf[4];
+    if(!partition){
+        return false;
+    }
+    if(!ESP.flashRead(partition->address, (uint32_t*)buf, 4)) {
+        return false;
+    }
+
+    if(buf[0] != ESP_IMAGE_HEADER_MAGIC) {
+        return false;
+    }
+    return true;
+}
+
+static bool _enablePartition(const esp_partition_t* partition){
+    uint8_t buf[4];
+    if(!partition){
+        return false;
+    }
+    if(!ESP.flashRead(partition->address, (uint32_t*)buf, 4)) {
+        return false;
+    }
+    buf[0] = ESP_IMAGE_HEADER_MAGIC;
+
+    return ESP.flashWrite(partition->address, (uint32_t*)buf, 4);
+}
+
+UpdateClass::UpdateClass()
+: _error(0)
+, _buffer(0)
+, _bufferLen(0)
+, _size(0)
+, _progress_callback(NULL)
+, _progress(0)
+, _command(U_FLASH)
+, _partition(NULL)
+{
+}
+
+UpdateClass& UpdateClass::onProgress(THandlerFunction_Progress fn) {
+    _progress_callback = fn;
+    return *this;
+}
+
+void UpdateClass::_reset() {
+    if (_buffer)
+        delete[] _buffer;
+    _buffer = 0;
+    _bufferLen = 0;
+    _progress = 0;
+    _size = 0;
+    _command = U_FLASH;
+}
+
+bool UpdateClass::canRollBack(){
+    if(_buffer){ //Update is running
+        return false;
+    }
+    const esp_partition_t* partition = esp_ota_get_next_update_partition(NULL);
+    return _partitionIsBootable(partition);
+}
+
+bool UpdateClass::rollBack(){
+    if(_buffer){ //Update is running
+        return false;
+    }
+    const esp_partition_t* partition = esp_ota_get_next_update_partition(NULL);
+    return _partitionIsBootable(partition) && !esp_ota_set_boot_partition(partition);
+}
+
+bool UpdateClass::begin(size_t size, int command) {
+    if(_size > 0){
+        log_w("already running");
+        return false;
+    }
+
+    _reset();
+    _error = 0;
+
+    if(size == 0) {
+        _error = UPDATE_ERROR_SIZE;
+        return false;
+    }
+
+    if (command == U_FLASH) {
+        _partition = esp_ota_get_next_update_partition(NULL);
+        if(!_partition){
+            _error = UPDATE_ERROR_NO_PARTITION;
+            return false;
+        }
+        log_d("OTA Partition: %s", _partition->label);
+    }
+    else if (command == U_SPIFFS) {
+        _partition = esp_partition_find_first(ESP_PARTITION_TYPE_DATA, ESP_PARTITION_SUBTYPE_DATA_SPIFFS, NULL);
+        if(!_partition){
+            _error = UPDATE_ERROR_NO_PARTITION;
+            return false;
+        }
+    }
+    else {
+        _error = UPDATE_ERROR_BAD_ARGUMENT;
+        log_e("bad command %u", command);
+        return false;
+    }
+
+    if(size == UPDATE_SIZE_UNKNOWN){
+        size = _partition->size;
+    } else if(size > _partition->size){
+        _error = UPDATE_ERROR_SIZE;
+        log_e("too large %u > %u", size, _partition->size);
+        return false;
+    }
+
+    //initialize
+    _buffer = (uint8_t*)malloc(SPI_FLASH_SEC_SIZE);
+    if(!_buffer){
+        log_e("malloc failed");
+        return false;
+    }
+    _size = size;
+    _command = command;
+    _md5.begin();
+    return true;
+}
+
+void UpdateClass::_abort(uint8_t err){
+    _reset();
+    _error = err;
+}
+
+void UpdateClass::abort(){
+    _abort(UPDATE_ERROR_ABORT);
+}
+
+bool UpdateClass::_writeBuffer(){
+    //first bytes of new firmware
+    if(!_progress && _command == U_FLASH){
+        //check magic
+        if(_buffer[0] != ESP_IMAGE_HEADER_MAGIC){
+            _abort(UPDATE_ERROR_MAGIC_BYTE);
+            return false;
+        }
+        //remove magic byte from the firmware now and write it upon success
+        //this ensures that partially written firmware will not be bootable
+        _buffer[0] = 0xFF;
+    }
+    if(!ESP.flashEraseSector((_partition->address + _progress)/SPI_FLASH_SEC_SIZE)){
+        _abort(UPDATE_ERROR_ERASE);
+        return false;
+    }
+    if (!ESP.flashWrite(_partition->address + _progress, (uint32_t*)_buffer, _bufferLen)) {
+        _abort(UPDATE_ERROR_WRITE);
+        return false;
+    }
+    //restore magic or md5 will fail
+    if(!_progress && _command == U_FLASH){
+        _buffer[0] = ESP_IMAGE_HEADER_MAGIC;
+    }
+    _md5.add(_buffer, _bufferLen);
+    _progress += _bufferLen;
+    _bufferLen = 0;
+    return true;
+}
+
+bool UpdateClass::_verifyHeader(uint8_t data) {
+    if(_command == U_FLASH) {
+        if(data != ESP_IMAGE_HEADER_MAGIC) {
+            _abort(UPDATE_ERROR_MAGIC_BYTE);
+            return false;
+        }
+        return true;
+    } else if(_command == U_SPIFFS) {
+        return true;
+    }
+    return false;
+}
+
+bool UpdateClass::_verifyEnd() {
+    if(_command == U_FLASH) {
+        if(!_enablePartition(_partition) || !_partitionIsBootable(_partition)) {
+            _abort(UPDATE_ERROR_READ);
+            return false;
+        }
+
+        if(esp_ota_set_boot_partition(_partition)){
+            _abort(UPDATE_ERROR_ACTIVATE);
+            return false;
+        }
+        _reset();
+        return true;
+    } else if(_command == U_SPIFFS) {
+        _reset();
+        return true;
+    }
+    return false;
+}
+
+bool UpdateClass::setMD5(const char * expected_md5){
+    if(strlen(expected_md5) != 32)
+    {
+        return false;
+    }
+    _target_md5 = expected_md5;
+    return true;
+}
+
+bool UpdateClass::end(bool evenIfRemaining){
+    if(hasError() || _size == 0){
+        return false;
+    }
+
+    if(!isFinished() && !evenIfRemaining){
+        log_e("premature end: res:%u, pos:%u/%u\n", getError(), progress(), _size);
+        _abort(UPDATE_ERROR_ABORT);
+        return false;
+    }
+
+    if(evenIfRemaining) {
+        if(_bufferLen > 0) {
+            _writeBuffer();
+        }
+        _size = progress();
+    }
+
+    _md5.calculate();
+    if(_target_md5.length()) {
+        if(_target_md5 != _md5.toString()){
+            _abort(UPDATE_ERROR_MD5);
+            return false;
+        }
+    }
+
+    return _verifyEnd();
+}
+
+size_t UpdateClass::write(uint8_t *data, size_t len) {
+    if(hasError() || !isRunning()){
+        return 0;
+    }
+
+    if(len > remaining()){
+        _abort(UPDATE_ERROR_SPACE);
+        return 0;
+    }
+
+    size_t left = len;
+
+    while((_bufferLen + left) > SPI_FLASH_SEC_SIZE) {
+        size_t toBuff = SPI_FLASH_SEC_SIZE - _bufferLen;
+        memcpy(_buffer + _bufferLen, data + (len - left), toBuff);
+        _bufferLen += toBuff;
+        if(!_writeBuffer()){
+            return len - left;
+        }
+        left -= toBuff;
+    }
+    memcpy(_buffer + _bufferLen, data + (len - left), left);
+    _bufferLen += left;
+    if(_bufferLen == remaining()){
+        if(!_writeBuffer()){
+            return len - left;
+        }
+    }
+    return len;
+}
+
+size_t UpdateClass::writeStream(Stream &data) {
+    data.setTimeout(RESPONSE_TIMEOUT_MS);
+    size_t written = 0;
+    size_t toRead = 0;
+    if(hasError() || !isRunning())
+        return 0;
+
+    if(!_verifyHeader(data.peek())) {
+        _reset();
+        return 0;
+    }
+    if (_progress_callback) {
+        _progress_callback(0, _size);
+    }
+    while(remaining()) {
+        toRead = data.readBytes(_buffer + _bufferLen,  (SPI_FLASH_SEC_SIZE - _bufferLen));
+        if(toRead == 0) { //Timeout
+            delay(100);
+            toRead = data.readBytes(_buffer + _bufferLen, (SPI_FLASH_SEC_SIZE - _bufferLen));
+            if(toRead == 0) { //Timeout
+                _abort(UPDATE_ERROR_STREAM);
+                return written;
+            }
+        }
+        _bufferLen += toRead;
+        if((_bufferLen == remaining() || _bufferLen == SPI_FLASH_SEC_SIZE) && !_writeBuffer())
+            return written;
+        written += toRead;
+        if(_progress_callback) {
+            _progress_callback(_progress, _size);
+        }
+    }
+    if(_progress_callback) {
+        _progress_callback(_size, _size);
+    }
+    return written;
+}
+
+void UpdateClass::printError(Stream &out){
+    out.println(_err2str(_error));
+}
+
+UpdateClass Update;