Closed tomatensaus closed 11 months ago
Can you check:
M8.bin
file came from .esphome/build/xxxx/.pioenvs/xxx/firmware.bin
(for esphome CLI) or downloaded as Legacy format
(for esphome HA addon) (see README)Thank you! I will try the suggestions above and report back by editing this comment
[23:10:27][ 70463][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'HTTP/1.1 200 OK'
[23:10:27][ 70464][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Date: Wed, 18 Oct 2023 21:10:12 GMT'
[23:10:27][ 70468][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Server: Apache'
[23:10:27][ 70475][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Last-Modified: Wed, 18 Oct 2023 21:06:22 GMT'
[23:10:27][ 70485][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Accept-Ranges: bytes'
[23:10:27][ 70492][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Content-Length: 1267984'
[23:10:27][ 70500][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Keep-Alive: timeout=5, max=100'
[23:10:27][ 70508][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Connection: Keep-Alive'
[23:10:27][ 70515][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Content-Type: application/octet-stream'
[23:10:27][ 70524][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: ''
[23:10:27][ 70530][D][HTTPClient.cpp:1307] handleHeaderResponse(): code: 200
[23:10:27][ 70536][D][HTTPClient.cpp:1310] handleHeaderResponse(): size: 1267984
[23:10:27][ 70542][D][HTTPClient.cpp:628] sendRequest(): sendRequest code=200
[23:10:27][ 70524][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: ''
[23:10:27][ 70530][D][HTTPClient.cpp:1307] handleHeaderResponse(): code: 200
[23:10:27][ 70536][D][HTTPClient.cpp:1310] handleHeaderResponse(): size: 1267984
[23:10:27][ 70542][D][HTTPClient.cpp:628] sendRequest(): sendRequest code=200
[23:10:27]
[23:10:27][V][ota_http:131]: http GET finished.
[23:10:27][D][ota_http:144]: firmware is 1267984 bytes length.
[23:10:27][D][ota_http:042]: Using ArduinoESP32OTABackend
[23:10:27][ 70576][D][Updater.cpp:133] begin(): OTA Partition: app1
[23:10:30]E (76604) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
[23:10:30]E (76604) task_wdt: - loopTask (CPU 1)
[23:10:30]E (76604) task_wdt: Tasks currently running:
[23:10:30]E (76604) task_wdt: CPU 0: IDLE
[23:10:30]E (76604) task_wdt: CPU 1: IDLE
[23:10:30]E (76604) task_wdt: Aborting.
[23:10:30]
[23:10:30]abort() was called at PC 0x401032cc on core 0
[23:10:30]
[23:10:30]
[23:10:30]Backtrace:0x40083915:0x3ffbeaec |<-CORRUPTED
I can also confirm that I am using the firmware.bin file as the flash above will confirm the filesize
-rw-r--r-- 1 y yo 1267984 Oct 18 22:52 firmware.bin
-rw-r--r-- 1 y yo 1333520 Oct 18 22:52 firmware-factory.bin
I will see if I can setup an insecure http server tomorrow. From the logs I suspect the watchdog timer is triggering the reboot
I can reproduce this bug on an https
server.
Yes, the watchdog timer is triggering the reboot, for an unknown reason, the https stream hangs after sending 16064 bytes, whatever the buffsize is.
The way http request are handled will change with #4, so it might solve the problem.
I've tried several fixes, but none worked.
I setup the code to debug and found that getStream() object never has any data available (causing the loop to get stuck waiting for data, and the WDT triggering the reboot)
[17:36:09][D][ota_http:146]: firmware is 1267984 bytes length.
[17:36:09][D][ota_http:043]: Using ArduinoESP32OTABackend
[17:36:09][ 46347][D][Updater.cpp:133] begin(): OTA Partition: app1
[17:36:09][V][ota_http:167]: going to 1024 bytes at 0/1267984
[17:36:09][V][ota_http:169]: waiting for 1024 bytes available..
[17:36:09][V][ota_http:172]: data available: 0
[17:36:09][V][ota_http:172]: data available: 0
[17:36:09][V][ota_http:172]: data available: 0
[17:36:09][V][ota_http:172]: data available: 0
[17:36:09][V][ota_http:172]: data available: 0
[17:36:09][V][ota_http:172]: data available: 0
[17:36:09][V][ota_http:172]: data available: 0
[17:36:09][V][ota_http:172]: data available: 0
[17:36:09][V][ota_http:172]: data available: 0
[17:36:09][V][ota_http:172]: data available: 0
I think the bug is related to this thread https://forum.arduino.cc/t/writing-a-stream-to-a-file/1099001/2
I was able to get more data by using HTTPClient::getStreamPtr
instead of HTTPClient::getStream
. But data stream stops after sending ~16k of data. Found related problem here: https://www.esp32.com/viewtopic.php?f=13&t=32299
I've open PR #10 so you can try my changes and see if you can go further. Here are my logs with the PR:
[10:35:20][D][button:010]: 'Firmware update' Pressed.
[10:35:20][D][ota_http:098]: Trying to connect to https://penkear.home/firmware.bin
[10:35:20][ 36297][V][HTTPClient.cpp:252] beginInternal(): url: https://penkear.home/firmware.bin
[10:35:20][ 36297][D][HTTPClient.cpp:263] beginInternal(): unexpected protocol: https, expected http
[10:35:20][ 36303][V][HTTPClient.cpp:252] beginInternal(): url: https://penkear.home/firmware.bin
[10:35:20][ 36311][D][HTTPClient.cpp:303] beginInternal(): protocol: https, host: penkear.home port: 443 url: /firmware.bin
[10:35:20][V][ota_http:112]: http begin successfull.
[10:35:20][VV][ota_http:116]: http client setReuse.
[10:35:20][V][ota_http:121]: md5sum from received data initialized.
[10:35:21][V][ota_http:125]: http headers collected.
[10:35:21][ 36353][D][HTTPClient.cpp:598] sendRequest(): request type: 'GET' redirCount: 0
[10:35:21]
[10:35:21][ 36354][V][ssl_client.cpp:62] start_ssl_client(): Free internal heap before TLS 225548
[10:35:21][ 36358][V][ssl_client.cpp:68] start_ssl_client(): Starting socket
[10:35:21][ 36386][V][ssl_client.cpp:149] start_ssl_client(): Seeding the random number generator
[10:35:21][ 36387][V][ssl_client.cpp:158] start_ssl_client(): Setting up the SSL/TLS structure...
[10:35:21][ 36392][D][ssl_client.cpp:179] start_ssl_client(): WARNING: Skipping SSL Verification. INSECURE!
[10:35:21][ 36399][V][ssl_client.cpp:257] start_ssl_client(): Setting hostname for TLS session...
[10:35:21][ 36407][V][ssl_client.cpp:272] start_ssl_client(): Performing the SSL/TLS handshake...
[10:35:21][ 36968][V][ssl_client.cpp:293] start_ssl_client(): Verifying peer X.509 certificate...
[10:35:21][ 36969][V][ssl_client.cpp:301] start_ssl_client(): Certificate verified.
[10:35:21][ 36972][V][ssl_client.cpp:316] start_ssl_client(): Free internal heap after TLS 189116
[10:35:21][ 36980][D][HTTPClient.cpp:1156] connect(): connected to penkear.home:443
[10:35:21][ 36987][V][ssl_client.cpp:369] send_ssl_data(): Writing HTTP request with 154 bytes...
[10:35:21][ 37053][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'HTTP/1.1 200 OK'
[10:35:21][ 37053][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Server: nginx/1.22.0 (Ubuntu)'
[10:35:21][ 37057][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Date: Fri, 20 Oct 2023 08:35:21 GMT'
[10:35:21][ 37066][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Content-Type: application/octet-stream'
[10:35:21][ 37075][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Content-Length: 1067456'
[10:35:21][ 37082][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Last-Modified: Fri, 15 Sep 2023 21:47:12 GMT'
[10:35:21][ 37092][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Connection: keep-alive'
[10:35:21][ 37099][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'ETag: "6504d0e0-1049c0"'
[10:35:21][ 37107][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: 'Accept-Ranges: bytes'
[10:35:21][ 37114][V][HTTPClient.cpp:1250] handleHeaderResponse(): RX: ''
[10:35:21][ 37120][D][HTTPClient.cpp:1307] handleHeaderResponse(): code: 200
[10:35:21][ 37126][D][HTTPClient.cpp:1310] handleHeaderResponse(): size: 1067456
[10:35:21][ 37132][D][HTTPClient.cpp:628] sendRequest(): sendRequest code=200
[10:35:21]
[10:35:21][V][ota_http:131]: http GET finished.
[10:35:21][D][ota_http:140]: firmware is 1067456 bytes length.
[10:35:21][D][ota_http:042]: Using ArduinoESP32OTABackend
[10:35:21][ 37161][D][Updater.cpp:133] begin(): OTA Partition: app0
[10:35:21][VV][ota_http:153]: Got esp32 stream
[10:35:21][VV][ota_http:161]: waiting for 1024 bytes available..
[10:35:21][VV][ota_http:168]: data available: 16115
[10:35:21][VV][ota_http:175]: md5 added
[10:35:21][VV][ota_http:179]: wrote to backend
[10:35:21][D][ota_http:192]: Progress: 0.1%
[10:35:21][VV][ota_http:161]: waiting for 1024 bytes available..
[10:35:21][VV][ota_http:168]: data available: 15091
[10:35:21][VV][ota_http:175]: md5 added
[10:35:21][VV][ota_http:179]: wrote to backend
[...]
[10:35:22][VV][ota_http:161]: waiting for 1024 bytes available..
[10:35:22][VV][ota_http:168]: data available: 1779
[10:35:22][VV][ota_http:175]: md5 added
[10:35:22][VV][ota_http:179]: wrote to backend
[10:35:22][VV][ota_http:161]: waiting for 1024 bytes available..
[10:35:22][VV][ota_http:164]: not enougth data available: 755 (total read: 15360)
[10:35:22][VV][ota_http:164]: not enougth data available: 755 (total read: 15360)
[... infinite loop until watchdog triggered...]
[10:35:26][VV][ota_http:164]: not enougth data available: 755 (total read: 15360)
[10:35:26][VV][ota_http:164]: not enougth data available: 755 (total read: 15360)
[10:35:26][VV][ota_http:164]: not enougth data available: 755 (total read: 15360)
[10:35:26]E (48883) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
[10:35:26]E (48883) task_wdt: - loopTask (CPU 1)
[10:35:26]E (48883) task_wdt: Tasks currently running:
[10:35:26]E (48883) task_wdt: CPU 0: IDLE
[10:35:26]E (48883) task_wdt: CPU 1: IDLE
[10:35:26]E (48883) task_wdt: Aborting.
[10:35:26]
[10:35:26]abort() was called at PC 0x400f2f09 on core 0
[10:35:26]
[10:35:26]
[10:35:26]Backtrace:0x40083791:0x3ffbeacc |<-CORRUPTED
[11:35:00][V][ota_http:131]: http GET finished.
[11:35:00][D][ota_http:140]: firmware is 1267984 bytes length.
[11:35:00][D][ota_http:042]: Using ArduinoESP32OTABackend
[11:35:00][ 24447][D][Updater.cpp:133] begin(): OTA Partition: app1
[11:35:00][V][ota_http:153]: Got esp32 stream
[11:35:00][V][ota_http:161]: waiting for 1024 bytes available..
[11:35:00][V][ota_http:168]: data available: 7931
[11:35:00][V][ota_http:175]: md5 added
[11:35:00][V][ota_http:179]: wrote to backend
[11:35:00][D][ota_http:192]: Progress: 0.1%
[11:35:00][V][ota_http:161]: waiting for 1024 bytes available..
[11:35:00][V][ota_http:168]: data available: 6907
[11:35:00][V][ota_http:175]: md5 added
[11:35:00][V][ota_http:179]: wrote to backend
[11:35:00][V][ota_http:161]: waiting for 1024 bytes available..
[11:35:00][V][ota_http:168]: data available: 5883
[11:35:00][V][ota_http:175]: md5 added
[11:35:00][V][ota_http:179]: wrote to backend
[11:35:00][V][ota_http:161]: waiting for 1024 bytes available..
[11:35:00][V][ota_http:168]: data available: 4859
[11:35:00][V][ota_http:175]: md5 added
[11:35:00][V][ota_http:179]: wrote to backend
[11:35:00][V][ota_http:161]: waiting for 1024 bytes available..
[11:35:00][V][ota_http:168]: data available: 3835
[11:35:00][V][ota_http:175]: md5 added
[11:35:00][V][ota_http:179]: wrote to backend
[11:35:00][V][ota_http:161]: waiting for 1024 bytes available..
[11:35:00][V][ota_http:168]: data available: 2811
[11:35:00][V][ota_http:175]: md5 added
[11:35:00][V][ota_http:179]: wrote to backend
[11:35:00][V][ota_http:161]: waiting for 1024 bytes available..
[11:35:00][V][ota_http:168]: data available: 1787
[11:35:00][V][ota_http:175]: md5 added
[11:35:00][V][ota_http:179]: wrote to backend
[11:35:00][V][ota_http:161]: waiting for 1024 bytes available..
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
[11:35:00][V][ota_http:164]: not enougth data available: 763 (total read: 7168)
I am also getting more output from the stream pointer, similar to your debug log.
by changing the logic in the read loop I was able to read the whole file and write it to the OTA backend
If the available is less than the buffer size, simply read what is available. As long as it is > 0. Once you read the last couple of bytes then the stream will fetch more. I will create a PR shortly
while (bytes_read != body_length) {
ESP_LOGV(TAG, "data available: %zu", streamPtr->available());
//ESP_LOGV(TAG, "waiting for %zu bytes available..", bufsize);
while (streamPtr->available() == 0) {
// give other tasks a chance to run while waiting for some data:
ESP_LOGV(TAG, "not enougth data available: %zu (total read: %zu)", streamPtr->available(), bytes_read);
yield();
delay(1);
}
size_t bufsize = std::min(chunk_size, body_length - bytes_read);
size_t availableData = streamPtr->available();
bufsize = std::min(bufsize, availableData);
ESP_LOGV(TAG, "going to %d bytes at %zu/%zu", bufsize, bytes_read, body_length);
streamPtr->readBytes(buf, bufsize);
bytes_read += bufsize;
buf[bufsize] = '\0'; // not fed to ota
[13:04:29][D][ota_http:098]: Trying to connect to https://example.com/M8.bin
[13:04:31][D][ota_http:140]: firmware is 1267984 bytes length.
[13:04:31][D][ota_http:042]: Using ArduinoESP32OTABackend
[13:04:31][D][ota_http:193]: Progress: 0.1%
[13:04:32][D][ota_http:193]: Progress: 5.5%
[13:04:33][D][ota_http:193]: Progress: 12.1%
[13:04:34][D][ota_http:193]: Progress: 18.8%
[13:04:35][D][ota_http:193]: Progress: 25.2%
[13:04:36][D][ota_http:193]: Progress: 31.4%
[13:04:37][D][ota_http:193]: Progress: 37.7%
[13:04:38][D][ota_http:193]: Progress: 44.2%
[13:04:39][D][ota_http:193]: Progress: 50.5%
[13:04:40][D][ota_http:193]: Progress: 56.9%
[13:04:41][D][ota_http:193]: Progress: 62.4%
[13:04:42][D][ota_http:193]: Progress: 68.8%
[13:04:43][D][ota_http:193]: Progress: 75.0%
[13:04:44][D][ota_http:193]: Progress: 81.2%
[13:04:45][D][ota_http:193]: Progress: 87.5%
[13:04:46][D][ota_http:193]: Progress: 93.4%
[13:04:47][D][ota_http:193]: Progress: 100.0%
[13:04:47][I][ota_http:201]: Done in 19 secs
[13:04:47][D][ota_http:206]: md5sum recieved: 06caed9c61c09496d5927f766bc2d378 (size 1267984)
[13:04:48][I][ota_http:225]: OTA update finished! Rebooting...
[13:04:48][I][app:134]: Rebooting safely...
[13:04:48][D][esp32.preferences:114]: Saving 1 preferences to flash...
[13:04:48][D][esp32.preferences:143]: Saving 1 preferences to flash: 0 cached, 1 written, 0 failed
Nice! So what I understand about the differences between http and https streams is that in https the stream is only populated if its size is zero.
Waiting for your PR. Do not forget to comment logs messages in while (bytes_read != body_length)
loop, because even if the log level is low, they fill the log buffer.
Pull request added #11
And thank you for building this awesome esp component!
Many thanks for the PR, @tomatensaus !
I replaced the URL of my server with example.com and also the filename to hide the contents on my server