gzReadSourceByte(): readSourceByte read error, available is 0. failed at retry --> infinite loop or halt

[scubachristopher]

Heya,

Thought we were good but I didn't test a failure case. Seems when the retry fails, although you return -1, you never bail back to the caller.

Caller snippet:

...
GzUnpacker *GZUnpacker = new GzUnpacker();

GZUnpacker->haltOnError( true ); // stop on fail (manual restart/reset required)
GZUnpacker->setupFSCallbacks( targzTotalBytesFn, targzFreeBytesFn ); // prevent the partition from exploding, recommended
GZUnpacker->setGzProgressCallback( BaseUnpacker::defaultProgressCallback ); // targzNullProgressCallback or defaultProgressCallback
GZUnpacker->setLoggerCallback( BaseUnpacker::targzPrintLoggerCallback  );    // gz log verbosity

//
// Read from the stream and decompress to the free OTA partition, then reset
//
if (!GZUnpacker->gzStreamUpdater(http.getStreamPtr(), UPDATE_SIZE_UNKNOWN) ) {
  Serial.printf("gzHTTPUpdater failed with return code #%d\n", GZUnpacker->tarGzGetError());
}

Never gets to GZUnpacker with the following log output:

Connected to Wifi: (Christopher) MAC: (40:F5:20:4A:0B:94) IP: (192.168.1.65) ESP hostname: (Box-5024-v2014), DNS server: (192.168.1.1)
Getting IP for URL: (digest.lagunaresearch.com)
Found IP for (digest.lagunaresearch.com): (54.153.65.87)
Attempting to connect to https://digest.lagunaresearch.com/chris.bin.gz
HTTP.begin successful for https://digest.lagunaresearch.com/chris.bin.gz
HTTP.get successful for https://digest.lagunaresearch.com/chris.bin.gz, size of file reported as 782953
[GZUpdater] Starting update with unknown binary size
[E][ESP32-targz-lib.cpp:1015] gzReadSourceByte(): readSourceByte read error, available is 0.  failed at retry
[E][ssl_client.cpp:33] _handle_error(): [data_to_read():270]: (-76) UNKNOWN ERROR CODE (004C)
[E][ESP32-targz-lib.cpp:1015] gzReadSourceByte(): readSourceByte read error, available is 0.  failed at retry
Wifi is disconnected, status is (6), attempting to reconnect
Attempting to connect to Wifi Station (Christopher) with password (6646664666)
[E][ESP32-targz-lib.cpp:1015] gzReadSourceByte(): readSourceByte read error, available is 0.  failed at retry
Connected to Wifi: (Christopher) MAC: (40:F5:20:4A:0B:94) IP: (192.168.1.65) ESP hostname: (Box-5024-v2014), DNS server: (192.168.1.1)
[E][ESP32-targz-lib.cpp:1015] gzReadSourceByte(): readSourceByte read error, available is 0.  failed at retry
[E][ESP32-targz-lib.cpp:1015] gzReadSourceByte(): readSourceByte read error, available is 0.  failed at retry
[E][ESP32-targz-lib.cpp:1015] gzReadSourceByte(): readSourceByte read error, available is 0.  failed at retry
[E][ESP32-targz-lib.cpp:1015] gzReadSourceByte(): readSourceByte read error, available is 0.  failed at retry
[E][ESP32-targz-lib.cpp:1015] gzReadSourceByte(): readSourceByte read error, available is 0.  failed at retry
[E][ESP32-targz-lib.cpp:1015] gzReadSourceByte(): readSourceByte read error, available is 0.  failed at retry
[E][ESP32-targz-lib.cpp:1015] gzReadSourceByte(): readSourceByte read error, available is 0.  failed at retry
... forever :(

So I modified GzUnpacker::gzReadSourceByte to just return -1 and got this:

Attempting to connect to https://digest.lagunaresearch.com/firmware.bin.gz
HTTP.begin successful for https://digest.lagunaresearch.com/firmware.bin.gz
HTTP.get successful for https://digest.lagunaresearch.com/firmware.bin.gz, size of file reported as 782942
[GZUpdater] Starting update with unknown binary size
bad id bytes
[E][ESP32-targz-lib.cpp:1091] gzUncompress(): [ERROR] in gzUncompress: uzlib_gzip_parse_header failed (response code -3!
[E][ESP32-targz-lib.cpp:1463] gzStreamUpdater(): gzHTTPUpdater returned error code -105
[E][ESP32-targz-lib.cpp:108] targz_system_halt(): System halted after error code #-105

My expectation (fair to say perhaps anyone's) is that it would return false.

Of course when it succeeds, it's beautiful.

I can revert back to my cloned repo with the retry before your refactor. Prefer to stay current. Let me know your thoughts...

[tobozo]

hey @scubachristopher thanks for your feedback

gzReadSourceByte hasn't changed much since that time you hinted at retrying after a fail, it still returns 0 if the read was successful or -1 after a second try failed.

However thanks to you I've found a way to replicate the error (turning off the wifi during transfer) so I'll be able to make a few tests and hopefully come back soon with a solution.

[edit] Spoil : https://github.com/tobozo/ESP32-targz/blob/master/src/uzlib/tinflate.c#L203

[edit2] Possible fix on this temporary branch

• added read errors count to uzlib
• added some logic to handle uzlib read errors in gzUncompress()

I turned off the WiFi in the middle of the transfer:

23:49:21.323 -> Connected as
23:49:21.323 -> 192.168.1.19
23:49:22.217 -> [TAR] firmware_example_esp32.spiffs.bin                                 1507328 bytes -  1507328 Total bytes
23:49:22.217 -> Progress: 0% ▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓▓ 25% ▓▓▓▓▓▓[W][WiFiGeneric.cpp:353] _eventCallback(): Reason: 2 - AUTH_EXPIRE
23:49:29.543 -> [E][ssl_client.cpp:33] _handle_error(): [data_to_read():270]: (-76) UNKNOWN ERROR CODE (004C)
23:49:31.465 -> [E][ESP32-targz-lib.cpp:1015] gzReadSourceByte(): readSourceByte read error, available is 0.  failed at retry
23:49:31.465 -> uzlib_get_byte/readSourceByte Errors: 1
23:49:31.498 -> [E][ESP32-targz-lib.cpp:1767] tarGzStreamUpdater(): tarGzStreamExpander returned error code -6
23:49:31.498 -> [E][ESP32-targz-lib.cpp:108] targz_system_halt(): System halted after error code #-6

[tobozo]

big thanks for fueling this library with your quality feedback, this is now fixed in the latest release, closing this as solved, feel free to reopen if necessary

[tobozo]

@scubachristopher I recently had retry failures when streaming from a SPI ethernet library.

In that situation, retrying right after the failure didn't work because the input buffer was still being filled by another task.

I came up with something different based on a timeout value, it gives more solid results in stressful situations, will publish a new release soon :-)

// consume and return a byte from the source stream into the argument 'out'.
// returns 0 on success, or -1 on error.
unsigned int GzUnpacker::gzReadSourceByte(CC_UNUSED struct GZ::TINF_DATA *data, unsigned char *out)
{
  _start: // using goto to avoid repeated code blocks
  if (tarGzIO.gz->readBytes( out, 1 ) != 1) {
    uint32_t now = millis();
    uint32_t timeout = now + targz_read_timeout;
    while( !tarGzIO.gz->available() ) {
      if( millis()>timeout ) {
        log_e("gz stream still unresponsive after %dms timeout, giving up", targz_read_timeout);
        return -1;
      }
      vTaskDelay(1); // let the app breathe
    }
    log_w("gz stream was unresponsive during %dms (timeout=%dms)", millis()-now, targz_read_timeout);
    goto _start;
  } else {
    //log_v("read 1 byte: 0x%02x", out[0] );
  }
  if( tarGzIO.gz_size > 0 ) {
    stream_bytesleft -= 1;
  }
  return 0;
}