search

esphome / issues

Issue Tracker for ESPHome
https://esphome.io/
291 stars 34 forks source link

OTA MD5 failure on second OTA upload #5157

Open fredericmorin opened 7 months ago

fredericmorin commented 7 months ago

The problem

The second OTA upload fails.

Starting with a fresh mains unplug/plug of the device, I can push a new esphome fw OTA upload. After that, every other OTA attempt fails with a MD5 Check Failed error.

Power cycling the device resolve the issue and allow for another OTA upload to complete sucessfully.

Same behavior is observed from both pip installed esphome and HA addon.

I was able to reproduce this issue without re-compiling the firmware. I ran esphome upload twice, without running esphome compile.

Which version of ESPHome has the issue?

2023.11.4

What type of installation are you using?

pip

Which version of Home Assistant has the issue?

No response

What platform are you using?

RTL87XX

Board

BEELITE smart switch

Component causing the issue

OTA

Example YAML snippet

esphome:
  name: plug21
  friendly_name: plug21
rtl87xx:
  board: generic-rtl8710bn-2mb-788k
logger:
ota: {"password": "1234567890"}
wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_password
captive_portal:
web_server:

Anything in the logs that might be useful for us?

RTL8710BN uart2 tx log output:

[...]
[C][lt.component:013]: LibreTiny:
[C][lt.component:014]:   Version: v1.4.1+sha.9b8e00c on generic-rtl8710bn-2mb-788k, compiled at Nov 26 2023 02:51:55, GCC 10.3.1 (-Os)
[C][lt.component:015]:   Loglevel: 3
[D][sensor:093]: 'WiFi Signal': Sending state -56.00000 dBm with 0 decimals of accuracy
[D][sensor:093]: 'WiFi Signal': Sending state -56.00000 dBm with 0 decimals of accuracy
[D][sensor:093]: 'WiFi Signal': Sending state -57.00000 dBm with 0 decimals of accuracy
[D][sensor:093]: 'WiFi Signal': Sending state -57.00000 dBm with 0 decimals of accuracy
[D][sensor:093]: 'WiFi Signal': Sending state -56.00000 dBm with 0 decimals of accuracy
[I][ota:117]: Boot seems successful, resetting boot loop counter.
[D][lt.preferences:104]: Saving 1 preferences to flash...
[D][lt.preferences:132]: Saving 1 preferences to flash: 0 cached, 1 written, 0 failed
[D][sensor:093]: 'WiFi Signal': Sending state -56.00000 dBm with 0 decimals of accuracy
[D][ota:151]: Starting OTA Update from 10.32.1.119...
[D][ota:320]: OTA in progress: 0.1%
[D][ota:320]: OTA in progress: 9.2%
[D][ota:320]: OTA in progress: 18.6%
[D][ota:320]: OTA in progress: 29.8%
[D][ota:320]: OTA in progress: 33.5%
[D][ota:320]: OTA in progress: 35.5%
[D][ota:320]: OTA in progress: 38.5%
[D][ota:320]: OTA in progress: 43.5%
[D][ota:320]: OTA in progress: 47.3%
[D][ota:320]: OTA in progress: 49.5%
[D][ota:320]: OTA in progress: 50.6%
[D][ota:320]: OTA in progress: 54.8%
[D][ota:320]: OTA in progress: 69.9%
[D][ota:320]: OTA in progress: 80.5%
[D][ota:320]: OTA in progress: 89.7%
[I][ota:353]: OTA update finished!
[I][app:134]: Rebooting safely...
ROM:[V0.1]
FLASHRATE:4
BOOT TYPE:0 XTAL:40000000
IMG1 DATA[1168:10002000]
IMG1 ENTRY[8000541:100021ef]
IMG1 ENTER
CHIPID[000000ff]
read_mode idx:3, flash_speed idx:0
calibration_result:[1:3:13][b:d]
calibration_result:[2:13:7][1:d]
calibration_result:[3:7:5][1:7]
calibration_ok:[2:13:7]
FLASH CALIB[NEW OK]
OTA2 ADDR[80d0000]
OTAx SELE[f0000000]
OTA1 USE
IMG2 DATA[0x8088c50:4064:0x10005000]
IMG2 SIGN[RTKWin(10005008)]
IMG2 ENTRY[0x10005000:0x803ac71]
System_Init1
System_Init2
I [      0.000] LibreTiny v1.4.1+sha.9b8e00c on generic-rtl8710bn-2mb-788k, compiled at Nov 26 2023 02:52:03, GCC 10.3.1 (-Os)
[I][logger:370]: Log initialized
[C][status_led:014]: Setting up Status LED...
[C][ota:473]: There have been 0 suspected unsuccessful boot attempts.
[D][lt.preferences:104]: Saving 1 preferences to flash...
[D][lt.preferences:132]: Saving 1 preferences to flash: 0 cached, 1 written, 0 failed
[I][app:029]: Running through setup()...
[D][binary_sensor:034]: 'Button': Sending initial state OFF
[C][switch.gpio:011]: Setting up GPIO Switch 'Relay'...
[D][switch:012]: 'Relay' Turning ON.
[D][switch:055]: 'Relay': Sending state ON
[D][switch:012]: 'Relay' Turning ON.
[C][wifi:038]: Setting up WiFi...
[C][wifi:051]: Starting WiFi...
[C][wifi:052]:   Local MAC: 10:5A:17:A9:7B:DB
interface 0 is initialized
                          interface 1 is initialized

Initializing WIFI ...
WIFI initialized
                [D][wifi:441]: Starting scan...
[D][wifi:456]: Found networks:
[I][wifi:499]: - 'oxio-6B00' (6C:F3:7F:E7:2D:E2) ▂▄▆█
[D][wifi:501]:     Channel: 11
[D][wifi:502]:     RSSI: -54 dB
[D][wifi:504]: - 'RedMaJuVer4' (F8:79:0A:11:17:96) ▂▄▆█
[D][wifi:504]: - 'T.Fam' (90:AA:C3:C9:33:58) ▂▄▆█
[D][wifi:504]: - 'Helix 1175 2.4' (A0:FF:70:DC:62:9C) ▂▄▆█
[D][wifi:504]: - 'NETGEAR86' (B0:39:56:D8:0C:28) ▂▄▆█
[I][wifi:286]: WiFi Connecting to 'oxio-6B00'...

Interface 0 IP address : 10.32.1.111[I][wifi:573]: WiFi Connected!
[C][wifi:391]:   Local MAC: 10:5A:17:A9:7B:DB
[C][wifi:396]:   SSID: 'oxio-6B00'
[C][wifi:397]:   IP Address: 10.32.1.111
[C][wifi:398]:   BSSID: 6C:F3:7F:E7:2D:E2
[C][wifi:400]:   Hostname: 'plug21'
[C][wifi:402]:   Signal strength: -56 dB ▂▄▆█
[C][wifi:406]:   Channel: 11
[C][wifi:407]:   Subnet: 255.255.255.0
[C][wifi:408]:   Gateway: 10.32.1.1
[C][wifi:409]:   DNS1: 10.32.1.1
[C][wifi:410]:   DNS2: 10.32.1.1
[C][web_server:123]: Setting up web server...
[C][sntp:028]: Setting up SNTP...
[C][ota:097]: Over-The-Air Updates:
[C][ota:098]:   Address: 10.32.1.111:8892
[C][ota:101]:   Using Password.
[C][api:025]: Setting up Home Assistant API server...
[I][app:062]: setup() finished successfully!
[D][sensor:093]: 'WiFi Signal': Sending state -56.00000 dBm with 0 decimals of accuracy
[I][app:102]: ESPHome version 2023.11.4 compiled on Nov 26 2023, 02:51:58
[C][status_led:019]: Status LED:
[C][status_led:020]:   Pin: 23
[C][wifi:559]: WiFi:
[C][wifi:391]:   Local MAC: 10:5A:17:A9:7B:DB
[C][wifi:396]:   SSID: 'oxio-6B00'
[C][wifi:397]:   IP Address: 10.32.1.111
[C][wifi:398]:   BSSID: 6C:F3:7F:E7:2D:E2
[C][wifi:400]:   Hostname: 'plug21'
[C][wifi:402]:   Signal strength: -56 dB ▂▄▆█
[C][wifi:406]:   Channel: 11
[C][wifi:407]:   Subnet: 255.255.255.0
[C][wifi:408]:   Gateway: 10.32.1.1
[C][wifi:409]:   DNS1: 10.32.1.1
[C][wifi:410]:   DNS2: 10.32.1.1
[C][logger:416]: Logger:
[C][logger:417]:   Level: DEBUG
[C][logger:418]:   Log Baud Rate: 115200
[C][logger:420]:   Hardware UART: UART2
[C][gpio.output:010]: GPIO Binary Output:
[C][gpio.output:011]:   Pin: 29
[D][sntp:077]: Synchronized time: 2023-11-26 03:17:16
[C][gpio.binary_sensor:016]:   Pin: 5
[C][switch.gpio:068]: GPIO Switch 'Relay'
[C][switch.gpio:090]:   Restore Mode: always ON
[C][switch.gpio:031]:   Pin: 19
[C][restart:068]: Restart Switch 'Restart'
[C][restart:070]:   Icon: 'mdi:restart'
[C][restart:090]:   Restore Mode: always OFF
[C][captive_portal:088]: Captive Portal:
[C][web_server:168]: Web Server:
[C][web_server:169]:   Address: 10.32.1.111:80
[C][sntp:053]: SNTP Time:
[C][sntp:054]:   Server 1: '0.pool.ntp.org'
[C][sntp:055]:   Server 2: '1.pool.ntp.org'
[C][sntp:056]:   Server 3: '2.pool.ntp.org'
[C][sntp:057]:   Timezone: 'EST5EDT,M3.2.0,M11.1.0'
[C][mdns:115]: mDNS:
[C][mdns:116]:   Hostname: plug21
[C][ota:097]: Over-The-Air Updates:
[C][ota:098]:   Address: 10.32.1.111:8892
[C][ota:101]:   Using Password.
[C][api:139]: API Server:
[C][api:140]:   Address: 10.32.1.111:6053
[C][api:142]:   Using noise encryption: YES
[C][wifi_signal.sensor:009]: WiFi Signal 'WiFi Signal'
[C][wifi_signal.sensor:009]:   Device Class: 'signal_strength'
[C][wifi_signal.sensor:009]:   State Class: 'measurement'
[C][wifi_signal.sensor:009]:   Unit of Measurement: 'dBm'
[C][wifi_signal.sensor:009]:   Accuracy Decimals: 0
[C][lt.component:013]: LibreTiny:
[C][lt.component:014]:   Version: v1.4.1+sha.9b8e00c on generic-rtl8710bn-2mb-788k, compiled at Nov 26 2023 02:51:55, GCC 10.3.1 (-Os)
[C][lt.component:015]:   Loglevel: 3
[D][sensor:093]: 'WiFi Signal': Sending state -55.00000 dBm with 0 decimals of accuracy
[D][ota:151]: Starting OTA Update from 10.32.1.119...
[D][ota:320]: OTA in progress: 0.1%
[D][ota:320]: OTA in progress: 2.2%
[D][ota:320]: OTA in progress: 5.1%
[D][ota:320]: OTA in progress: 8.2%
[D][ota:320]: OTA in progress: 19.0%
[D][ota:320]: OTA in progress: 30.1%
[D][ota:320]: OTA in progress: 43.2%
[D][ota:320]: OTA in progress: 53.3%
[D][ota:320]: OTA in progress: 56.1%
[D][ota:320]: OTA in progress: 58.5%
[D][ota:320]: OTA in progress: 61.9%
[D][ota:320]: OTA in progress: 65.0%
[D][ota:320]: OTA in progress: 82.2%
[D][ota:320]: OTA in progress: 97.0%
E [    127.238] OTA: Error: MD5 Check Failed
E [    127.243] OTA: - written: 1039360 of 1039360
E [    127.248] OTA: - buf: size=2199023255552, left=1153656047362139272
E [    127.256] OTA: - ctx: seq=4294967295, part=(null)
E [    127.262] OTA: - buf: seq=2029/2030, addr=519168, len=44
[W][ota:336]: Error ending OTA!, error_code: 132
[W][component:214]: Component ota took a long time for an operation (14.61 s).
[W][component:215]: Components should block for at most 20-30ms.
[D][sensor:093]: 'WiFi Signal': Sending state -56.00000 dBm with 0 decimals of accuracy

esphome upload logs:

# ./venv/bin/esphome upload esphome_copy/plug21.yaml 
INFO ESPHome 2023.11.4
INFO Reading configuration esphome_copy/plug21.yaml...
INFO Detected timezone 'America/Toronto'
Found multiple options for uploading, please choose one:
  [1] /dev/cu.usbserial-00008 (RFID ANTENNA)
  [2] Over The Air (10.32.1.111)
(number): 2
INFO Connecting to 10.32.1.111
INFO Uploading esphome_copy/.esphome/build/plug21/.pioenvs/plug21/firmware.uf2 (1039360 bytes)
Uploading: [============================================================] 100% Done...

INFO Waiting for result...
INFO OTA successful
INFO Successfully uploaded program.

# ./venv/bin/esphome upload esphome_copy/plug21.yaml
INFO ESPHome 2023.11.4
INFO Reading configuration esphome_copy/plug21.yaml...
INFO Detected timezone 'America/Toronto'
Found multiple options for uploading, please choose one:
  [1] /dev/cu.usbserial-00008 (RFID ANTENNA)
  [2] Over The Air (10.32.1.111)
(number): 2
INFO Connecting to 10.32.1.111
INFO Uploading esphome_copy/.esphome/build/plug21/.pioenvs/plug21/firmware.uf2 (1039360 bytes)
Uploading: [============================================================] 100% Done...

INFO Waiting for result...
ERROR Error Update end: Error: Finishing update failed. See the MQTT/USB logs for more information.

Additional information

Version info:

# ./venv/bin/esphome compile esphome_copy/plug21.yaml
INFO ESPHome 2023.11.4
INFO Reading configuration esphome_copy/plug21.yaml...
INFO Detected timezone 'America/Toronto'
INFO Generating C++ source...
INFO Compiling app...
Processing plug21 (board: generic-rtl8710bn-2mb-788k; framework: arduino; platform: libretiny @ 1.4.1)
--------------------------------------------------------------------------------------------------------------------------
HARDWARE: RTL8710BN 125MHz, 256KB RAM, 788KB Flash
 - framework-arduino-api @ 2022.8.24+sha.237b10a 
 - framework-realtek-amb1 @ 0.0.0+v2022.06.21.sha.c4e44ef 
 - library-flashdb @ 1.2.0+sha.d5c892f 
 - library-freertos @ 8.1.2+sha.776ae6c 
 - library-freertos-port @ 2023.5.23+sha.a917d93 
 - library-lwip @ 2.1.3-amb1+sha.6297b80 
 - library-printf @ 6.1.0+sha.28a79bd 
 - library-uf2ota @ 5.0.0+sha.f955412 
PLATFORM VERSIONS:
 - libretiny @ 1.4.1+sha.9b8e00c
 - ltchiptool @ 4.8.0
CUSTOM OPTIONS:
 - fw_name = esphome
 - fw_version = 2023.11.4
Dependency Graph
|-- AsyncTCP-esphome @ 2.0.1
|-- ESPAsyncWebServer-esphome @ 3.1.0
|-- DNSServer @ 1.1.0
|-- noise-c @ 0.1.4
|-- ArduinoJson @ 6.18.5
RAM:   [==        ]  20.6% (used 53888 bytes from 262144 bytes)
Flash: [======    ]  64.3% (used 519124 bytes from 806912 bytes)
============================================== [SUCCESS] Took 2.24 seconds ==============================================
INFO Successfully compiled program.
Kaldek commented 6 months ago

I have the same issue. This is a Tuya WR4 using the generic-rtl8710bn-2mb-468k board type as per the LibreTiny website.

UART log shows the following: image

I can get one OTA through to the device, but subsequent OTAs all return the MD5 error. To repeat the test, I can reflash the unit via UART, then perform one successful OTA. After that, all subsequent OTAs have the MD5 error.

Jojo-A commented 6 months ago

Hi, I've got the same error over here. Tested with four devices and different board configurations, like generic, wr2, T102_V1.1,... Same behavior after ota update. The devices end up in a bootloop until the safety mode is triggered. Then I can transmit a new firmware ota and everything starts all over again...

Strange thing: if I wait really long time (sometimes several hours) the device manages to boot completely and works as intended.

magtimmermans commented 4 months ago

Also here same error