search

esphome / issues

Issue Tracker for ESPHome
https://esphome.io/
294 stars 37 forks source link

Captive Portal OTA does not complete #1891

Closed amoedo closed 3 years ago

amoedo commented 3 years ago

Operating environment/Installation (Hass.io/Docker/pip/etc.):

Hass.io core-2021.2.3 Home Assistant OS 5.12 oon Raspberry Pi ESP (ESP32/ESP8266, Board/Sonoff):

EDP8266 Wemos D1 Mini ESPHome version (latest production, beta, dev branch)

v1.16.2 Affected component:

https://esphome.io/components/captive_portal.html

Description of problem: I am trying to flash a new firmware from the captive portal, but the firmware upload never completes and there are no errors on the logs. The firmware upload starts fine, but looking at the logs seems like the WiFi scanning kills it. I've tried with Chome and Firefox on Windows 10. I can reproduce this with a minimal configuration as per below yaml.

Problem-relevant YAML-configuration entries:

esphome:
  name: testesp
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: "secret"
  password: "secret"

  # Enable fallback hotspot (captive portal) in case wifi connection fails
  ap:
    ssid: "Testesp Fallback Hotspot"
    password: "otapassword"

captive_portal:

# Enable logging
debug:
logger:
  level: VERY_VERBOSE
# Enable Home Assistant API
api:
  password: "pass"

ota:

status_led:
  pin:
    number: D4
    inverted: True

Logs (if applicable):

15:10:59.039 -> [W][wifi:394]: No matching network found!
15:11:01.236 -> [VV][wifi_esp8266:485]: Event: AP receive Probe Request MAC=8E:FE:CE:9D:43:42 RSSI=-92
15:11:01.236 -> wifi evt: 7
15:11:04.033 -> [D][wifi:324]: Starting scan...
15:11:04.407 -> [VV][wifi_esp8266:485]: Event: AP receive Probe Request MAC=CE:38:BD:57:E6:92 RSSI=-90
15:11:04.407 -> wifi evt: 7
15:11:09.972 -> scandone
15:11:09.972 -> [D][wifi:339]: Found networks:
15:11:09.972 -> [D][wifi:389]: - 'Darpa' (3C:84:6A:AB:AF:CA) ▂▄▆█
15:11:10.018 -> [D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:AF:CA) ▂▄▆█
15:11:10.018 -> [D][wifi:389]: - '' (46:84:6A:AB:AF:CA) ▂▄▆█
15:11:10.018 -> [D][wifi:389]: - 'wificlientesR' (72:5A:9E:90:4D:7B) ▂▄▆█
15:11:10.018 -> [D][wifi:389]: - 'CELIA' (70:5A:9E:90:4D:7A) ▂▄▆█
15:11:10.018 -> [D][wifi:389]: - 'TP-Link_PEDRO' (0C:80:63:B9:E4:56) ▂▄▆█
15:11:10.065 -> [D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:22) ▂▄▆█
15:11:10.065 -> [D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:22) ▂▄▆█
15:11:10.065 -> [D][wifi:389]: - '' (46:84:6A:AB:B0:22) ▂▄▆█
15:11:10.065 -> [D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:46) ▂▄▆█
15:11:10.065 -> [D][wifi:389]: - '' (46:84:6A:AB:B0:46) ▂▄▆█
15:11:10.112 -> [D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:46) ▂▄▆█
15:11:10.112 -> [D][wifi:389]: - 'Tech_D0010144' (48:00:33:7A:23:EF) ▂▄▆█
15:11:10.112 -> [D][wifi:389]: - 'MOVISTAR_4F34' (CC:D4:A1:01:4F:36) ▂▄▆█
15:11:10.112 -> [D][wifi:389]: - 'MOVISTAR_E236' (CC:ED:DC:13:E2:37) ▂▄▆█
15:11:10.112 -> [D][wifi:389]: - 'wificlientesR' (72:5A:9E:35:F5:C1) ▂▄▆█
15:11:10.159 -> [D][wifi:389]: - 'vodafoneBA5110' (74:9D:79:B4:61:D0) ▂▄▆█
15:11:10.159 -> [D][wifi:389]: - 'PEDRO R_WIFI' (70:5A:9E:35:F5:C0) ▂▄▆█
15:11:10.159 -> [D][wifi:389]: - 'MOVISTAR_503E' (E8:D1:1B:A4:50:3F) ▂▄▆█
15:11:10.159 -> [D][wifi:389]: - 'MIWIFI_2G_03Ht' (4C:6E:6E:D0:85:B3) ▂▄▆█
15:11:10.159 -> [D][wifi:389]: - 'MOVISTAR_5E22' (98:97:D1:BD:5E:23) ▂▄▆█
15:11:10.207 -> [D][wifi:389]: - 'MiFibra-057B' (44:FE:3B:3E:05:7D) ▂▄▆█
15:11:10.207 -> [D][wifi:389]: - 'R-WLAN 3B' (80:29:94:F7:E7:AC) ▂▄▆█
15:11:10.207 -> [D][wifi:389]: - 'MOVISTAR_D049' (D4:7B:B0:10:D0:4A) ▂▄▆█
15:11:10.207 -> [W][wifi:394]: No matching network found!
15:11:12.773 -> [VV][wifi_esp8266:485]: Event: AP receive Probe Request MAC=3C:BD:3E:73:D5:F1 RSSI=-89
15:11:12.773 -> wifi evt: 7
15:11:13.565 -> [I][web_server_base:028]: OTA Update Start: testesp.bin
15:11:13.565 -> [begin] already running
15:11:13.565 -> [W][web_server_base:021]: OTA Update failed! Error: ERROR[0]: No Error
15:11:13.565 -> 
15:11:13.565 -> [D][web_server_base:059]: OTA in progress: 0.4%
15:11:14.638 -> [D][web_server_base:059]: OTA in progress: 14.4%
15:11:15.247 -> [D][wifi:324]: Starting scan...
15:11:15.667 -> [D][web_server_base:059]: OTA in progress: 26.7%
15:11:16.739 -> [D][web_server_base:059]: OTA in progress: 31.8%
15:11:21.364 -> scandone
15:11:21.364 -> [D][wifi:339]: Found networks:
15:11:21.364 -> [D][wifi:389]: - '' (46:84:6A:AB:AF:CA) ▂▄▆█
15:11:21.364 -> [D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:AF:CA) ▂▄▆█
15:11:21.364 -> [D][wifi:389]: - 'Darpa' (3C:84:6A:AB:AF:CA) ▂▄▆█
15:11:21.410 -> [D][wifi:389]: - 'CELIA' (70:5A:9E:90:4D:7A) ▂▄▆█
15:11:21.410 -> [D][wifi:389]: - 'wificlientesR' (72:5A:9E:90:4D:7B) ▂▄▆█
15:11:21.410 -> [D][wifi:389]: - 'TP-Link_PEDRO' (0C:80:63:B9:E4:56) ▂▄▆█
15:11:21.410 -> [D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:22) ▂▄▆█
15:11:21.410 -> [D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:22) ▂▄▆█
15:11:21.457 -> [D][wifi:389]: - '' (46:84:6A:AB:B0:22) ▂▄▆█
15:11:21.457 -> [D][wifi:389]: - '' (46:84:6A:AB:B0:46) ▂▄▆█
15:11:21.457 -> [D][wifi:389]: - 'MOVISTAR_4F34' (CC:D4:A1:01:4F:36) ▂▄▆█
15:11:21.457 -> [D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:46) ▂▄▆█
15:11:21.457 -> [D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:46) ▂▄▆█
15:11:21.503 -> [D][wifi:389]: - 'MOVISTAR_E236' (CC:ED:DC:13:E2:37) ▂▄▆█
15:11:21.503 -> [D][wifi:389]: - 'wificlientesR' (72:5A:9E:35:F5:C1) ▂▄▆█
15:11:21.503 -> [D][wifi:389]: - 'vodafoneBA5110' (74:9D:79:B4:61:D0) ▂▄▆█
15:11:21.503 -> [D][wifi:389]: - 'PEDRO R_WIFI' (70:5A:9E:35:F5:C0) ▂▄▆█
15:11:21.503 -> [D][wifi:389]: - 'MIWIFI_2G_03Ht' (4C:6E:6E:D0:85:B3) ▂▄▆█
15:11:21.550 -> [D][wifi:389]: - 'MiFibra-057B' (44:FE:3B:3E:05:7D) ▂▄▆█
15:11:21.550 -> [D][wifi:389]: - 'MOVISTAR_503E' (E8:D1:1B:A4:50:3F) ▂▄▆█
15:11:21.550 -> [D][wifi:389]: - 'MOVISTAR_5E22' (98:97:D1:BD:5E:23) ▂▄▆█
15:11:21.550 -> [D][wifi:389]: - 'MOAÑAMAR2.4' (80:3F:5D:D4:E6:01) ▂▄▆█
15:11:21.550 -> [D][wifi:389]: - 'R-WLAN 3B' (80:29:94:F7:E7:AC) ▂▄▆█
15:11:21.597 -> [D][wifi:389]: - 'vodafoneBA1911' (74:9D:79:BD:08:C0) ▂▄▆█
15:11:21.597 -> [D][wifi:389]: - 'MOVISTAR_D049' (D4:7B:B0:10:D0:4A) ▂▄▆█
15:11:21.597 -> [W][wifi:394]: No matching network found!
15:11:24.626 -> [VV][wifi_esp8266:485]: Event: AP receive Probe Request MAC=9E:65:31:4E:9B:79 RSSI=-92
15:11:24.626 -> wifi evt: 7
15:11:26.628 -> [D][wifi:324]: Starting scan...
15:11:32.523 -> scandone

Additional information and things you've tried:

I've tried the upload multiple times. It never completes. It always seems to be killed off as soon as the device starts wifi scanning.

I've tried using a random file with just 125kb size and it does complete the upload before the next wifi scan and it proceeded to flash the firmware (even if not a valid firmware).

I've tried enabling the Web Server component and use the OTA from the webserver. It works as expected. Completes the upload of the firmware and restarts.

[22:37:07][VV][scheduler:152]: Running interval '' with interval=10000 last_execution=9600 (now=19605)
[22:37:17][VV][scheduler:152]: Running interval '' with interval=10000 last_execution=19600 (now=29607)
[22:37:18][VV][api.service:220]: on_ping_request: PingRequest {}
[22:37:18][VV][api.service:032]: send_ping_response: PingResponse {}
[22:37:27][VV][scheduler:152]: Running interval '' with interval=10000 last_execution=29600 (now=39605)
[22:37:29][I][web_server_base:028]: OTA Update Start: testesp.bin
[22:37:29]sleep disable
[22:37:29][begin] roundedSize:       0x00393000 (3747840)
[22:37:29][begin] updateEndAddress:  0x003FB000 (4173824)
[22:37:29][begin] currentSketchSize: 0x00067000 (421888)
[22:37:29][begin] _startAddress:     0x00068000 (425984)
[22:37:29][begin] _currentAddress:   0x00068000 (425984)
[22:37:29][begin] _size:             0x00393000 (3747840)
[22:37:29][D][web_server_base:059]: OTA in progress: 0.3%
[22:37:29]Header: 0xE9 1 3 40
[22:37:30][D][web_server_base:059]: OTA in progress: 8.8%
[22:37:31][D][web_server_base:059]: OTA in progress: 24.0%
[22:37:32][D][web_server_base:059]: OTA in progress: 39.6%
[22:37:33][D][web_server_base:059]: OTA in progress: 48.8%
[22:37:33][VV][api.service:220]: on_ping_request: PingRequest {}
[22:37:33][VV][api.service:032]: send_ping_response: PingResponse {}
[22:37:34][D][web_server_base:059]: OTA in progress: 63.6%
[22:37:35][D][web_server_base:059]: OTA in progress: 79.2%
[22:37:36][D][web_server_base:059]: OTA in progress: 92.5%
[22:37:37]Staged: address:0x00068000, size:0x000603A0
[22:37:37][I][web_server_base:068]: OTA update successful!
[22:37:37][VV][scheduler:026]: set_timeout(name='', timeout=100)
[22:37:37][VV][scheduler:152]: Running timeout '' with interval=100 last_execution=48682 (now=48783)
[22:37:37][I][app:142]: Rebooting safely...
[22:37:37][VV][preferences:051]: SAVE 32: 0=0x00000000 1=0x0DEFE4E3 (Type=233825507, CRC=0x0DEFE4E3)
[22:37:37][VV][api.service:020]: send_disconnect_request: DisconnectRequest {}
[22:37:37]state: 5 -> 0 (0)
[22:37:37]rm 0
[22:37:37]pm close 7
[22:37:37]del if0
[22:37:37]usl
[22:37:37][W][wifi_esp8266:444]: Event: Disconnected ssid='Darpa' bssid=3C:84:6A:AB:AF:CA reason='Association Leave'
[22:37:37]wifi evt: 1
[22:37:37]STA disconnect: 8
[22:37:37]
[22:37:37] ets Jan  8 2013,rst cause:2, boot mode:(3,6)
[22:37:37]
[22:37:37]load 0x4010f000, len 3584, room 16 
[22:37:37]tail 0
[22:37:37]chksum 0xb0
[22:37:37]csum 0xb0
[22:37:37]v2843a5ac
[22:37:43]@cp:0
[22:37:43]ld
[22:37:43][I][logger:166]: Log initialized
[22:37:43][C][status_led:014]: Setting up Status LED...
[22:37:43][C][ota:366]: There have been 0 suspected unsuccessful boot attempts.
[22:37:43][I][app:029]: Running through setup()...
amoedo commented 3 years ago

I've tested a similar situation with another board ESP8266 NodeMCuv2. You can see two attempts for OTA from the Captive Portal on the log below. The first one fails. I assume because the upload didn't finish before the wifi scan interval. The second one I've timed it to hit just after the scan finished and it completed uploading before the next one. The OTA was successful but the firmware was corrupted and the device didn't start. Flashing it via USB worked fine.

[22:53:02][W][wifi:394]: No matching network found!
[22:53:07][D][wifi:324]: Starting scan...
[22:53:08][I][web_server_base:028]: OTA Update Start: esp1 (1).bin
[22:53:08][D][web_server_base:059]: OTA in progress: 0.3%
[22:53:09][D][dht:048]: Got Temperature=22.3°C Humidity=40.6%
[22:53:09][D][sensor:092]: 'Living Room Temperature': Sending state 22.30000 °C with 1 decimals of accuracy
[22:53:09][D][sensor:092]: 'Living Room Humidity': Sending state 40.60000 % with 0 decimals of accuracy
[22:53:13][D][wifi:339]: Found networks:
[22:53:13][D][wifi:389]: - '' (46:84:6A:AB:AF:CA) ▂▄▆█
[22:53:13][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:AF:CA) ▂▄▆█
[22:53:13][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:AF:CA) ▂▄▆█
[22:53:13][D][wifi:389]: - 'CELIA' (70:5A:9E:90:4D:7A) ▂▄▆█
[22:53:13][D][wifi:389]: - 'wificlientesR' (72:5A:9E:90:4D:7B) ▂▄▆█
[22:53:13][D][wifi:389]: - 'TP-Link_PEDRO' (0C:80:63:B9:E4:56) ▂▄▆█
[22:53:13][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:22) ▂▄▆█
[22:53:13][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:22) ▂▄▆█
[22:53:13][D][wifi:389]: - '' (46:84:6A:AB:B0:22) ▂▄▆█
[22:53:13][D][wifi:389]: - 'Tech_D0010144' (48:00:33:7A:23:EF) ▂▄▆█
[22:53:13][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:46) ▂▄▆█
[22:53:13][D][wifi:389]: - '' (46:84:6A:AB:B0:46) ▂▄▆█
[22:53:13][D][wifi:389]: - 'MOVISTAR_4F34' (CC:D4:A1:01:4F:36) ▂▄▆█
[22:53:13][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:46) ▂▄▆█
[22:53:13][D][wifi:389]: - 'vodafoneBA5110' (74:9D:79:B4:61:D0) ▂▄▆█
[22:53:13][D][wifi:389]: - 'MOVISTAR_E236' (CC:ED:DC:13:E2:37) ▂▄▆█
[22:53:13][D][wifi:389]: - 'MOVISTAR_5E22' (98:97:D1:BD:5E:23) ▂▄▆█
[22:53:13][D][wifi:389]: - 'Cudy-E5A2' (B4:4B:D6:25:E5:A2) ▂▄▆█
[22:53:13][D][wifi:389]: - 'MOVISTAR_503E' (E8:D1:1B:A4:50:3F) ▂▄▆█
[22:53:13][D][wifi:389]: - 'wificlientesR' (72:5A:9E:35:F5:C1) ▂▄▆█
[22:53:13][D][wifi:389]: - 'MOVISTAR_79F8' (84:AA:9C:21:79:F9) ▂▄▆█
[22:53:13][D][wifi:389]: - 'David' (88:F7:C7:2B:0A:92) ▂▄▆█
[22:53:13][D][wifi:389]: - 'MOVISTAR_D049' (D4:7B:B0:10:D0:4A) ▂▄▆█
[22:53:13][D][wifi:389]: - 'vodafoneBA1911' (74:9D:79:BD:08:C0) ▂▄▆█
[22:53:13][D][wifi:389]: - 'wificlientesR' (8A:F7:C7:2B:0A:93) ▂▄▆█
[22:53:13][D][wifi:389]: - 'MOVISTAR_36B5' (E4:AB:89:A5:36:B6) ▂▄▆█
[22:53:13][W][wifi:394]: No matching network found!
[22:53:18][D][wifi:324]: Starting scan...
[22:53:19][D][dht:048]: Got Temperature=22.3°C Humidity=40.5%
[22:53:19][D][sensor:092]: 'Living Room Temperature': Sending state 22.30000 °C with 1 decimals of accuracy
[22:53:19][D][sensor:092]: 'Living Room Humidity': Sending state 40.50000 % with 0 decimals of accuracy
[22:53:24][D][wifi:339]: Found networks:
[22:53:24][D][wifi:389]: - '' (46:84:6A:AB:AF:CA) ▂▄▆█
[22:53:24][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:AF:CA) ▂▄▆█
[22:53:24][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:AF:CA) ▂▄▆█
[22:53:24][D][wifi:389]: - 'CELIA' (70:5A:9E:90:4D:7A) ▂▄▆█
[22:53:24][D][wifi:389]: - 'wificlientesR' (72:5A:9E:90:4D:7B) ▂▄▆█
[22:53:24][D][wifi:389]: - 'TP-Link_PEDRO' (0C:80:63:B9:E4:56) ▂▄▆█
[22:53:24][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:22) ▂▄▆█
[22:53:24][D][wifi:389]: - 'Tech_D0010144' (48:00:33:7A:23:EF) ▂▄▆█
[22:53:24][D][wifi:389]: - '' (46:84:6A:AB:B0:22) ▂▄▆█
[22:53:24][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:22) ▂▄▆█
[22:53:24][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:46) ▂▄▆█
[22:53:24][D][wifi:389]: - '' (46:84:6A:AB:B0:46) ▂▄▆█
[22:53:24][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:46) ▂▄▆█
[22:53:24][D][wifi:389]: - 'MOVISTAR_4F34' (CC:D4:A1:01:4F:36) ▂▄▆█
[22:53:24][D][wifi:389]: - 'MOVISTAR_E236' (CC:ED:DC:13:E2:37) ▂▄▆█
[22:53:24][D][wifi:389]: - 'vodafoneBA5110' (74:9D:79:B4:61:D0) ▂▄▆█
[22:53:24][D][wifi:389]: - 'MIWIFI_2G_03Ht' (4C:6E:6E:D0:85:B3) ▂▄▆█
[22:53:24][D][wifi:389]: - 'MOVISTAR_6E0E' (CC:ED:DC:5A:6E:0F) ▂▄▆█
[22:53:24][D][wifi:389]: - 'MOVISTAR_D049' (D4:7B:B0:10:D0:4A) ▂▄▆█
[22:53:24][D][wifi:389]: - 'PEDRO R_WIFI' (70:5A:9E:35:F5:C0) ▂▄▆█
[22:53:24][D][wifi:389]: - 'wificlientesR' (72:5A:9E:35:F5:C1) ▂▄▆█
[22:53:24][D][wifi:389]: - 'vodafoneBA1911' (74:9D:79:BD:08:C0) ▂▄▆█
[22:53:24][D][wifi:389]: - 'MOVISTAR_5E22' (98:97:D1:BD:5E:23) ▂▄▆█
[22:53:24][D][wifi:389]: - 'MOVISTAR_79F8' (84:AA:9C:21:79:F9) ▂▄▆█
[22:53:24][D][wifi:389]: - 'MiFibra-057B' (44:FE:3B:3E:05:7D) ▂▄▆█
[22:53:24][D][wifi:389]: - 'Cudy-E5A2' (B4:4B:D6:25:E5:A2) ▂▄▆█
[22:53:24][D][wifi:389]: - 'Orange-0839' (A8:D3:F7:14:08:3B) ▂▄▆█
[22:53:24][D][wifi:389]: - 'MIWIFI_6669' (1C:64:99:7D:66:6C) ▂▄▆█
[22:53:24][W][wifi:394]: No matching network found!
[22:53:29][D][dht:048]: Got Temperature=22.3°C Humidity=40.7%
[22:53:29][D][sensor:092]: 'Living Room Temperature': Sending state 22.30000 °C with 1 decimals of accuracy
[22:53:29][D][sensor:092]: 'Living Room Humidity': Sending state 40.70000 % with 0 decimals of accuracy
[22:53:29][D][wifi:324]: Starting scan...
[22:53:35][D][wifi:339]: Found networks:
[22:53:35][D][wifi:389]: - '' (46:84:6A:AB:AF:CA) ▂▄▆█
[22:53:35][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:AF:CA) ▂▄▆█
[22:53:35][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:AF:CA) ▂▄▆█
[22:53:35][D][wifi:389]: - 'CELIA' (70:5A:9E:90:4D:7A) ▂▄▆█
[22:53:35][D][wifi:389]: - 'wificlientesR' (72:5A:9E:90:4D:7B) ▂▄▆█
[22:53:35][D][wifi:389]: - 'TP-Link_PEDRO' (0C:80:63:B9:E4:56) ▂▄▆█
[22:53:35][D][wifi:389]: - 'Tech_D0010144' (48:00:33:7A:23:EF) ▂▄▆█
[22:53:35][D][wifi:389]: - '' (46:84:6A:AB:B0:22) ▂▄▆█
[22:53:35][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:22) ▂▄▆█
[22:53:35][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:22) ▂▄▆█
[22:53:35][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:46) ▂▄▆█
[22:53:35][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:46) ▂▄▆█
[22:53:35][D][wifi:389]: - 'MOVISTAR_4F34' (CC:D4:A1:01:4F:36) ▂▄▆█
[22:53:35][D][wifi:389]: - '' (46:84:6A:AB:B0:46) ▂▄▆█
[22:53:35][D][wifi:389]: - 'MOVISTAR_E236' (CC:ED:DC:13:E2:37) ▂▄▆█
[22:53:35][D][wifi:389]: - 'vodafoneBA5110' (74:9D:79:B4:61:D0) ▂▄▆█
[22:53:35][D][wifi:389]: - 'vodafoneBA1911' (74:9D:79:BD:08:C0) ▂▄▆█
[22:53:35][D][wifi:389]: - 'MOVISTAR_6E0E' (CC:ED:DC:5A:6E:0F) ▂▄▆█
[22:53:35][D][wifi:389]: - 'MOVISTAR_5E22' (98:97:D1:BD:5E:23) ▂▄▆█
[22:53:35][D][wifi:389]: - 'MOVISTAR_D049' (D4:7B:B0:10:D0:4A) ▂▄▆█
[22:53:35][D][wifi:389]: - 'wificlientesR' (72:5A:9E:35:F5:C1) ▂▄▆█
[22:53:35][D][wifi:389]: - 'MOVISTAR_36B5' (E4:AB:89:A5:36:B6) ▂▄▆█
[22:53:35][D][wifi:389]: - 'MOVISTAR_A53D' (E4:AB:89:37:A5:3E) ▂▄▆█
[22:53:35][D][wifi:389]: - 'MOVISTAR_503E' (E8:D1:1B:A4:50:3F) ▂▄▆█
[22:53:35][D][wifi:389]: - 'Orange-0839' (A8:D3:F7:14:08:3B) ▂▄▆█
[22:53:36][D][wifi:389]: - 'MOVISTAR_79F8' (84:AA:9C:21:79:F9) ▂▄▆█
[22:53:36][D][wifi:389]: - 'MundoR-8B8A' (38:70:0C:35:8B:88) ▂▄▆█
[22:53:36][D][wifi:389]: - 'Cudy-E5A2' (B4:4B:D6:25:E5:A2) ▂▄▆█
[22:53:36][W][wifi:394]: No matching network found!
[22:53:39][D][dht:048]: Got Temperature=22.3°C Humidity=40.5%
[22:53:39][D][sensor:092]: 'Living Room Temperature': Sending state 22.30000 °C with 1 decimals of accuracy
[22:53:39][D][sensor:092]: 'Living Room Humidity': Sending state 40.50000 % with 0 decimals of accuracy
[22:53:41][D][wifi:324]: Starting scan...
[22:53:46][D][wifi:339]: Found networks:
[22:53:46][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:AF:CA) ▂▄▆█
[22:53:46][D][wifi:389]: - '' (46:84:6A:AB:AF:CA) ▂▄▆█
[22:53:46][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:AF:CA) ▂▄▆█
[22:53:46][D][wifi:389]: - 'CELIA' (70:5A:9E:90:4D:7A) ▂▄▆█
[22:53:47][D][wifi:389]: - 'wificlientesR' (72:5A:9E:90:4D:7B) ▂▄▆█
[22:53:47][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:22) ▂▄▆█
[22:53:47][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:22) ▂▄▆█
[22:53:47][D][wifi:389]: - '' (46:84:6A:AB:B0:22) ▂▄▆█
[22:53:47][D][wifi:389]: - 'TP-Link_PEDRO' (0C:80:63:B9:E4:56) ▂▄▆█
[22:53:47][D][wifi:389]: - 'Darpa_Guest' (42:84:6A:AB:B0:46) ▂▄▆█
[22:53:47][D][wifi:389]: - 'Darpa' (3C:84:6A:AB:B0:46) ▂▄▆█
[22:53:47][D][wifi:389]: - '' (46:84:6A:AB:B0:46) ▂▄▆█
[22:53:47][D][wifi:389]: - 'Tech_D0010144' (48:00:33:7A:23:EF) ▂▄▆█
[22:53:47][D][wifi:389]: - 'MOVISTAR_E236' (CC:ED:DC:13:E2:37) ▂▄▆█
[22:53:47][D][wifi:389]: - 'MOVISTAR_4F34' (CC:D4:A1:01:4F:36) ▂▄▆█
[22:53:47][D][wifi:389]: - 'vodafoneBA5110' (74:9D:79:B4:61:D0) ▂▄▆█
[22:53:47][D][wifi:389]: - 'MOVISTAR_6E0E' (CC:ED:DC:5A:6E:0F) ▂▄▆█
[22:53:47][D][wifi:389]: - 'MOVISTAR_D049' (D4:7B:B0:10:D0:4A) ▂▄▆█
[22:53:47][D][wifi:389]: - 'MOVISTAR_5E22' (98:97:D1:BD:5E:23) ▂▄▆█
[22:53:47][D][wifi:389]: - 'wificlientesR' (72:5A:9E:35:F5:C1) ▂▄▆█
[22:53:47][D][wifi:389]: - 'MOVISTAR_503E' (E8:D1:1B:A4:50:3F) ▂▄▆█
[22:53:47][D][wifi:389]: - 'vodafoneBA1911' (74:9D:79:BD:08:C0) ▂▄▆█
[22:53:47][D][wifi:389]: - 'MOVISTAR_A53D' (E4:AB:89:37:A5:3E) ▂▄▆█
[22:53:47][D][wifi:389]: - 'Orange-0839' (A8:D3:F7:14:08:3B) ▂▄▆█
[22:53:47][D][wifi:389]: - 'MOVISTAR_BC20' (D4:7B:B0:08:BC:21) ▂▄▆█
[22:53:47][D][wifi:389]: - 'MOVISTAR_79F8' (84:AA:9C:21:79:F9) ▂▄▆█
[22:53:47][D][wifi:389]: - 'David' (88:F7:C7:2B:0A:92) ▂▄▆█
[22:53:47][W][wifi:394]: No matching network found!
[22:53:47][I][web_server_base:028]: OTA Update Start: esp1 (1).bin
[22:53:47][W][web_server_base:021]: OTA Update failed! Error: ERROR[0]: No Error
[22:53:47]
[22:53:47][D][web_server_base:059]: OTA in progress: 0.3%
[22:53:48][D][web_server_base:059]: OTA in progress: 48.7%
[22:53:49][D][dht:048]: Got Temperature=22.4°C Humidity=41.1%
[22:53:49][D][sensor:092]: 'Living Room Temperature': Sending state 22.40000 °C with 1 decimals of accuracy
[22:53:49][D][sensor:092]: 'Living Room Humidity': Sending state 41.10000 % with 0 decimals of accuracy
[22:53:49][D][web_server_base:059]: OTA in progress: 92.4%
[22:53:49][I][web_server_base:068]: OTA update successful!
[22:53:49][I][app:142]: Rebooting safely...
[22:53:50]
[22:53:50] ets Jan  8 2013,rst cause:2, boot mode:(3,6)
[22:53:50]
[22:53:50]load 0x4010f000, len 3584, room 16 
[22:53:50]tail 0
[22:53:50]chksum 0xb0
[22:53:50]csum 0xb0
[22:53:50]v2843a5ac
[22:53:56]@cp:0
[22:53:56]ld
[22:53:56]e:
[22:53:56] ets Jan  8 2013,rst cause:3, boot mode:(3,6)
[22:53:56]
bjornstevens commented 3 years ago

I might be completely wrong, but will adding this under wifi do anything? fast_connect: true

amoedo commented 3 years ago

Thanks for the suggestion. I gave it a try, but it doesn't help. The behaviour is similar. As soon as it starts trying to connect to the wifi without scan (fast connect), the OTA stops. Nothing relevant that I can see in the logs. It's like the file upload fails.

23:33:53.327 -> wifi evt: 7
23:33:53.327 -> [I][wifi:194]: WiFi Connecting to 'secret'...
23:33:53.327 -> [V][wifi:196]: Connection Params:
23:33:53.327 -> [V][wifi:197]:   SSID: 'secret'
23:33:53.373 -> [V][wifi:202]:   BSSID: Not Set
23:33:53.373 -> [V][wifi:220]:   Password: 'secret1234'
23:33:53.373 -> [V][wifi:227]:   Channel: Not Set
23:33:53.373 -> [V][wifi:235]:   Using DHCP IP
23:33:53.373 -> [V][wifi:237]:   Hidden: NO
23:33:56.231 -> scandone
23:33:56.231 -> [W][wifi_esp8266:441]: Event: Disconnected ssid='secret' reason='Probe Request Unsuccessful'
23:33:56.231 -> wifi evt: 1
23:33:56.231 -> STA disconnect: 201
23:33:56.231 -> [W][wifi:485]: Error while connecting to network.
23:33:57.500 -> [I][web_server_base:028]: OTA Update Start: testesp (4).bin
23:33:57.500 -> sleep disable
23:33:57.500 -> [begin] roundedSize:       0x00396000 (3760128)
23:33:57.500 -> [begin] updateEndAddress:  0x003FB000 (4173824)
23:33:57.547 -> [begin] currentSketchSize: 0x00064000 (409600)
23:33:57.547 -> [begin] _startAddress:     0x00065000 (413696)
23:33:57.547 -> [begin] _currentAddress:   0x00065000 (413696)
23:33:57.547 -> [begin] _size:             0x00396000 (3760128)
23:33:57.547 -> [D][web_server_base:059]: OTA in progress: 0.3%
23:33:57.593 -> Header: 0xE9 1 3 40
23:33:58.299 -> [VV][wifi_esp8266:485]: Event: AP receive Probe Request MAC=04:79:70:B6:1D:77 RSSI=-28
23:33:58.344 -> wifi evt: 7
23:33:58.344 -> [VV][wifi_esp8266:485]: Event: AP receive Probe Request MAC=04:79:70:B6:1D:77 RSSI=-35
23:33:58.344 -> wifi evt: 7
23:33:58.344 -> [VV][wifi_esp8266:485]: Event: AP receive Probe Request MAC=04:79:70:B6:1D:77 RSSI=-32
23:33:58.344 -> wifi evt: 7
23:33:58.344 -> [VV][wifi_esp8266:485]: Event: AP receive Probe Request MAC=04:79:70:B6:1D:77 RSSI=-31
23:33:58.344 -> wifi evt: 7
23:33:58.576 -> [D][web_server_base:059]: OTA in progress: 14.3%
23:33:58.668 -> [VV][wifi_esp8266:485]: Event: AP receive Probe Request MAC=04:79:70:B6:1D:77 RSSI=-70
23:33:58.668 -> wifi evt: 7
23:33:59.647 -> [D][web_server_base:059]: OTA in progress: 23.2%
23:34:00.626 -> [D][web_server_base:059]: OTA in progress: 36.4%
23:34:01.515 -> [I][wifi:194]: WiFi Connecting to 'secret'...
23:34:01.515 -> [V][wifi:196]: Connection Params:
23:34:01.515 -> [V][wifi:197]:   SSID: 'secret'
23:34:01.515 -> [V][wifi:202]:   BSSID: Not Set
23:34:01.515 -> [V][wifi:220]:   Password: 'secret1234'
23:34:01.515 -> [V][wifi:227]:   Channel: Not Set
23:34:01.515 -> [V][wifi:235]:   Using DHCP IP
23:34:01.562 -> [V][wifi:237]:   Hidden: NO
23:34:01.656 -> [D][web_server_base:059]: OTA in progress: 50.3%
23:34:03.293 -> [VV][wifi_esp8266:485]: Event: AP receive Probe Request MAC=04:79:70:B6:1D:77 RSSI=-27
23:34:03.293 -> wifi evt: 7
23:34:03.903 -> [VV][wifi_esp8266:485]: Event: AP receive Probe Request MAC=04:79:70:B6:1D:77 RSSI=-71
23:34:03.903 -> wifi evt: 7
23:34:04.469 -> scandone
23:34:04.469 -> [W][wifi_esp8266:441]: Event: Disconnected ssid='secret' reason='Probe Request Unsuccessful'
23:34:04.469 -> wifi evt: 1
23:34:04.469 -> STA disconnect: 201
23:34:04.516 -> [W][wifi:485]: Error while connecting to network.
stale[bot] commented 3 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.