search

maximkulkin / esp-homekit

Apple HomeKit accessory server library for ESP-OPEN-RTOS
MIT License
1.1k stars 169 forks source link

ESP32 hangs on wifi init after reset #89

Closed DietmarHoch closed 4 years ago

DietmarHoch commented 5 years ago

Hi Maxim,

your code works so far, but after a while (5-6days) it HomeKit-Apple says that the accessory is not responding. I know, this is hard to debug. the only thing that I noticed is that after a reset, the device is not connected to my wifi, please see the log, after the last line, no more messages came.

can I do something?

rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0018,len:4 load:0x3fff001c,len:6352 ho 0 tail 12 room 4 load:0x40078000,len:11304 ho 0 tail 12 room 4 load:0x40080400,len:6700 entry 0x40080764 I (32) boot: ESP-IDF v4.0-dev-540-g208e1ecc2-dirty 2nd stage bootloader I (32) boot: compile time 20:51:20 I (42) boot: Enabling RNG early entropy source... I (42) boot: SPI Speed : 40MHz I (43) boot: SPI Mode : DIO I (47) boot: SPI Flash Size : 4MB I (51) boot: Partition Table: I (55) boot: ## Label Usage Type ST Offset Length I (62) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (69) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (77) boot: 2 factory factory app 00 00 00010000 00100000 I (84) boot: End of partition table I (89) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x25fc4 (155588) map I (152) esp_image: segment 1: paddr=0x00035fec vaddr=0x3ffb0000 size=0x0354c ( 13644) load I (158) esp_image: segment 2: paddr=0x00039540 vaddr=0x40080000 size=0x00400 ( 1024) load 0x40080000: _WindowOverflow4 at /Users/dietmar/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

I (159) esp_image: segment 3: paddr=0x00039948 vaddr=0x40080400 size=0x066c8 ( 26312) load I (179) esp_image: segment 4: paddr=0x00040018 vaddr=0x400d0018 size=0x8cd3c (576828) map 0x400d0018: _stext at ??:?

I (381) esp_image: segment 5: paddr=0x000ccd5c vaddr=0x40086ac8 size=0x09220 ( 37408) load 0x40086ac8: ieee80211_output_process at ??:?

I (406) boot: Loaded app from partition at offset 0x10000 I (406) boot: Disabling RNG early entropy source... I (407) cpu_start: Pro cpu up. I (410) cpu_start: Application information: I (415) cpu_start: Project name: led I (420) cpu_start: App version: 397f73a-dirty I (425) cpu_start: Compile time: May 15 2019 20:51:23 I (431) cpu_start: ELF file SHA256: f8762f471eb00d80... I (437) cpu_start: ESP-IDF: v4.0-dev-540-g208e1ecc2-dirty I (444) cpu_start: Starting app cpu, entry point is 0x4008105c 0x4008105c: call_start_cpu1 at /Users/dietmar/esp/esp-idf/components/esp32/cpu_start.c:267

I (0) cpu_start: App cpu up. I (455) heap_init: Initializing. RAM available for dynamic allocation: I (461) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM I (467) heap_init: At 3FFB9B38 len 000264C8 (153 KiB): DRAM I (474) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (480) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (486) heap_init: At 4008FCE8 len 00010318 (64 KiB): IRAM I (493) cpu_start: Pro cpu start user code I (175) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (240) wifi: wifi driver task: 3ffc14a4, prio:23, stack:3584, core=0 I (240) wifi: wifi firmware version: 7c00966 I (240) wifi: config NVS flash: enabled I (240) wifi: config nano formating: disabled I (250) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (260) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (300) wifi: Init dynamic tx buffer num: 32 I (300) wifi: Init data frame dynamic rx buffer num: 32 I (300) wifi: Init management frame dynamic rx buffer num: 32 I (300) wifi: Init management short buffer num: 32 I (310) wifi: Init static rx buffer size: 1600 I (310) wifi: Init static rx buffer num: 10 I (320) wifi: Init dynamic rx buffer num: 32 I (420) phy: phy_version: 4100, 2a5dd04, Jan 23 2019, 21:00:07, 0, 0 I (420) wifi: mode : sta (30:ae:a4:fe:08:d8) STA start I (1030) wifi: new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1 I (2010) wifi: state: init -> auth (b0) I (2020) wifi: state: auth -> assoc (0) I (2030) wifi: state: assoc -> run (10) I (2070) wifi: connected with home-sweet-home, channel 6, bssid = 5c:49:79:1e:b7:7a I (2070) wifi: pm start, type: 1

I (3240) tcpip_adapter: sta ip: 192.168.178.29, mask: 255.255.255.0, gw: 192.168.178.1 WiFI ready

HomeKit: Starting server HomeKit: Using existing accessory ID: 59:46:69:7B:A7:3D HomeKit: Found admin pairing with 1A10F74C-B758-4348-BDE7-B5DAEE42B18A, disabling pair setup HomeKit: Configuring mDNS homekit_run_server: Staring HTTP server ets Jun 8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0018,len:4 load:0x3fff001c,len:6352 ho 0 tail 12 room 4 load:0x40078000,len:11304 ho 0 tail 12 room 4 load:0x40080400,len:6700 entry 0x40080764 I (32) boot: ESP-IDF v4.0-dev-540-g208e1ecc2-dirty 2nd stage bootloader I (32) boot: compile time 20:51:20 I (42) boot: Enabling RNG early entropy source... I (42) boot: SPI Speed : 40MHz I (43) boot: SPI Mode : DIO I (47) boot: SPI Flash Size : 4MB I (51) boot: Partition Table: I (55) boot: ## Label Usage Type ST Offset Length I (62) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (69) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (77) boot: 2 factory factory app 00 00 00010000 00100000 I (84) boot: End of partition table I (89) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x25fc4 (155588) map I (152) esp_image: segment 1: paddr=0x00035fec vaddr=0x3ffb0000 size=0x0354c ( 13644) load I (158) esp_image: segment 2: paddr=0x00039540 vaddr=0x40080000 size=0x00400 ( 1024) load 0x40080000: _WindowOverflow4 at /Users/dietmar/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

I (159) esp_image: segment 3: paddr=0x00039948 vaddr=0x40080400 size=0x066c8 ( 26312) load I (179) esp_image: segment 4: paddr=0x00040018 vaddr=0x400d0018 size=0x8cd3c (576828) map 0x400d0018: _stext at ??:?

I (381) esp_image: segment 5: paddr=0x000ccd5c vaddr=0x40086ac8 size=0x09220 ( 37408) load 0x40086ac8: ieee80211_output_process at ??:?

I (406) boot: Loaded app from partition at offset 0x10000 I (406) boot: Disabling RNG early entropy source... I (407) cpu_start: Pro cpu up. I (410) cpu_start: Application information: I (415) cpu_start: Project name: led I (420) cpu_start: App version: 397f73a-dirty I (425) cpu_start: Compile time: May 15 2019 20:51:23 I (431) cpu_start: ELF file SHA256: f8762f471eb00d80... I (437) cpu_start: ESP-IDF: v4.0-dev-540-g208e1ecc2-dirty I (444) cpu_start: Starting app cpu, entry point is 0x4008105c 0x4008105c: call_start_cpu1 at /Users/dietmar/esp/esp-idf/components/esp32/cpu_start.c:267

I (0) cpu_start: App cpu up. I (455) heap_init: Initializing. RAM available for dynamic allocation: I (462) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM I (468) heap_init: At 3FFB9B38 len 000264C8 (153 KiB): DRAM I (474) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (480) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (487) heap_init: At 4008FCE8 len 00010318 (64 KiB): IRAM I (493) cpu_start: Pro cpu start user code I (175) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (240) wifi: wifi driver task: 3ffc14a4, prio:23, stack:3584, core=0 I (240) wifi: wifi firmware version: 7c00966 I (240) wifi: config NVS flash: enabled I (240) wifi: config nano formating: disabled I (250) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (260) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE I (300) wifi: Init dynamic tx buffer num: 32 I (300) wifi: Init data frame dynamic rx buffer num: 32 I (300) wifi: Init management frame dynamic rx buffer num: 32 I (300) wifi: Init management short buffer num: 32 I (310) wifi: Init static rx buffer size: 1600 I (310) wifi: Init static rx buffer num: 10 I (320) wifi: Init dynamic rx buffer num: 32 I (430) phy: phy_version: 4100, 2a5dd04, Jan 23 2019, 21:00:07, 0, 0 I (430) wifi: mode : sta (30:ae:a4:fe:08:d8) STA start I (1160) wifi: new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1 I (2140) wifi: state: init -> auth (b0) I (2150) wifi: state: auth -> init (8a0) I (2150) wifi: new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1

maximkulkin commented 5 years ago

What firmware is that?

DietmarHoch commented 5 years ago

Hi Maxim,

it is an ESP32 Chip wit the latest Master ESP-IDF, with your LED example running in the Espressif ESP-IDF Git they have a similar problem issued: https://github.com/espressif/esp-idf/issues/3474 but they have more logs and maybe a connection manager, I copy a few log lines from there:

I (26520) Network Manager: Connection attempt: 16 I (27010) wifi: n:4 0, o:2 0, ap:255 255, sta:4 0, prof:1 I (27010) wifi: state: init -> auth (b0) I (28010) wifi: state: auth -> init (200) I (28010) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1 W (28010) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2) I (28010) Network Manager: Connection attempt: 17 W (30420) WIFI EVENT: Wi-Fi Reason: NO_AP_FOUND (201) I (30420) Network Manager: Connection attempt: 18 I (30540) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1

Could you please describe such a connection manager or implement in your code?

DietmarHoch commented 5 years ago

hey maxim, Espressif provided a fix for the problem, see the comments in: espressif/esp-idf#3474

maximkulkin commented 5 years ago

So, the fix in esp-idf, you just have to update to latest master?

DietmarHoch commented 5 years ago

for now it is only provided in the link. i will give you an update if they include it in the latest master.

Azmatron commented 5 years ago

Hello I’m having the same issue. Any advice on how I can apply this patch?