search

EverythingSmartHome / everything-presence-one

Official Repo for the Everything Presence One sensor!
411 stars 72 forks source link

Stops at cpu_start: Starting scheduler on APP CPU. #219

Closed dannytsang closed 2 months ago

dannytsang commented 2 months ago

I upgraded an EP1 to 1.2.6 from Home Assistant and the sensors are all showing as unavailable.

I have cleaned the build files and reinstalled the firmware from ESPHome and still the same.

The logs are showing the following the below and stays for for a long time (5+ minutes).

[21:16:27]I (13) boot: ESP-IDF 4.4.7 2nd stage bootloader
[21:16:27]I (13) boot: compile time 13:42:52
[21:16:27]I (13) boot: Multicore bootloader
[21:16:27]I (15) boot: chip revision: v3.0
[21:16:27]I (19) boot.esp32: SPI Speed      : 40MHz
[21:16:27]I (24) boot.esp32: SPI Mode       : DIO
[21:16:27]I (28) boot.esp32: SPI Flash Size : 4MB
[21:16:27]I (33) boot: Enabling RNG early entropy source...
[21:16:27]I (38) boot: Partition Table:
[21:16:27]I (42) boot: ## Label            Usage          Type ST Offset   Length
[21:16:27]I (49) boot:  0 otadata          OTA data         01 00 00009000 00002000
[21:16:27]I (56) boot:  1 phy_init         RF data          01 01 0000b000 00001000
[21:16:27]I (64) boot:  2 app0             OTA app          00 10 00010000 001c0000
[21:16:27]I (71) boot:  3 app1             OTA app          00 11 001d0000 001c0000
[21:16:27]I (79) boot:  4 nvs              WiFi data        01 02 00390000 0006d000
[21:16:27]I (86) boot: End of partition table
[21:16:27]I (91) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=44f2ch (282412) map
[21:16:27]I (201) esp_image: segment 1: paddr=00054f54 vaddr=3ffbdb60 size=050b4h ( 20660) load
[21:16:27]I (209) esp_image: segment 2: paddr=0005a010 vaddr=40080000 size=06008h ( 24584) load
[21:16:27]I (220) esp_image: segment 3: paddr=00060020 vaddr=400d0020 size=ff48ch (1045644) map
[21:16:27]I (598) esp_image: segment 4: paddr=0015f4b4 vaddr=40086008 size=18328h ( 99112) load
[21:16:27]I (654) boot: Loaded app from partition at offset 0x10000
[21:16:27]I (654) boot: Disabling RNG early entropy source...
[21:16:27]I (666) cpu_start: Multicore app
[21:16:27]I (666) cpu_start: Pro cpu up.
[21:16:27]I (666) cpu_start: Starting app cpu, entry point is 0x400826b0
[21:16:27]I (0) cpu_start: App cpu up.
[21:16:27]I (686) cpu_start: Pro cpu start user code
[21:16:27]I (686) cpu_start: cpu freq: 160000000
[21:16:27]I (686) cpu_start: Application information:
[21:16:27]I (691) cpu_start: Project name:     living_room-motion
[21:16:27]I (697) cpu_start: App version:      2024.7.3
[21:16:27]I (702) cpu_start: Compile time:     Aug  1 2024 13:42:20
[21:16:27]I (708) cpu_start: ELF file SHA256:  69d4142d6b067e08...
[21:16:27]I (714) cpu_start: ESP-IDF:          4.4.7
[21:16:27]I (718) cpu_start: Min chip rev:     v0.0
[21:16:27]I (723) cpu_start: Max chip rev:     v3.99 
[21:16:27]I (728) cpu_start: Chip rev:         v3.0
[21:16:27]I (733) heap_init: Initializing. RAM available for dynamic allocation:
[21:16:27]I (740) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
[21:16:27]I (746) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
[21:16:27]I (752) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
[21:16:27]I (758) heap_init: At 3FFCB938 len 000146C8 (81 KiB): DRAM
[21:16:27]I (764) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
[21:16:27]I (771) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
[21:16:27]I (777) heap_init: At 4009E330 len 00001CD0 (7 KiB): IRAM
[21:16:27]I (785) spi_flash: detected chip: generic
[21:16:27]I (788) spi_flash: flash io: dio
[21:16:27]I (795) cpu_start: Starting scheduler on PRO CPU.
[21:16:27]I (0) cpu_start: Starting scheduler on APP CPU.

Pressing Reset Device goes through the same sequence as below. Is it hanging and not booting up properly?

[21:20:41][E][esp-idf:000]: I (94) gpio: GPIO[25]| InputEn: 1| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0 

[E][esp-idf:000]: I (95) gpio: GPIO[26]| InputEn: 1| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0 

[E][esp-idf:000]: I (132) uart: queue free spaces: 20

[E][esp-idf:000]: I (133) gpio: GPIO[32]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 

[E][esp-idf:000]: I (133) gpio: GPIO[15]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 

[E][shtcx:080]: sensor polling failed
[E][esp-idf:000]: I (164) gpio: GPIO[33]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0 

[E][esp-idf:000]: I (175) wifi:
[E][esp-idf:000]: wifi driver task: 3ffd8f68, prio:23, stack:6656, core=0
[E][esp-idf:000]: 

[E][esp-idf:000][wifi]: I (1150) system_api: Base MAC address is not set

[E][esp-idf:000][wifi]: I (1151) system_api: read default base MAC address from EFUSE

[E][esp-idf:000][wifi]: I (1186) wifi:
[E][esp-idf:000][wifi]: wifi firmware version: 1fd20f4
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1187) wifi:
[E][esp-idf:000][wifi]: wifi certification version: v7.0
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1191) wifi:
[E][esp-idf:000][wifi]: config NVS flash: enabled
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1212) wifi:
[E][esp-idf:000][wifi]: config nano formating: disabled
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1222) wifi:
[E][esp-idf:000][wifi]: Init data frame dynamic rx buffer num: 32
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1243) wifi:
[E][esp-idf:000][wifi]: Init static rx mgmt buffer num: 5
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1263) wifi:
[E][esp-idf:000][wifi]: Init management short buffer num: 32
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1283) wifi:
[E][esp-idf:000][wifi]: Init dynamic tx buffer num: 32
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1294) wifi:
[E][esp-idf:000][wifi]: Init static rx buffer size: 1600
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1314) wifi:
[E][esp-idf:000][wifi]: Init static rx buffer num: 10
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1335) wifi:
[E][esp-idf:000][wifi]: Init dynamic rx buffer num: 32
[E][esp-idf:000][wifi]: 

[E][esp-idf:000]: I (1346) wifi_init: rx ba win: 6

[E][esp-idf:000]: I (1355) wifi_init: tcpip mbox: 32

[E][esp-idf:000]: I (1365) wifi_init: udp mbox: 6

[E][esp-idf:000]: I (1365) wifi_init: tcp mbox: 6

[E][esp-idf:000]: I (1375) wifi_init: tcp tx win: 5760

[E][esp-idf:000]: I (1386) wifi_init: tcp rx win: 5760

[E][esp-idf:000]: I (1386) wifi_init: tcp mss: 1440

[E][esp-idf:000]: I (1396) wifi_init: WiFi IRAM OP enabled

[E][esp-idf:000]: I (1396) wifi_init: WiFi RX IRAM OP enabled

[E][esp-idf:000][wifi]: I (1408) phy_init: phy_version 4791,2c4672b,Dec 20 2023,16:06:06

[E][esp-idf:000][wifi]: I (1494) wifi:
[E][esp-idf:000][wifi]: mode : sta (c0:49:ef:6f:15:3c)
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1496) wifi:
[E][esp-idf:000][wifi]: enable tsf
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (1500) wifi:
[E][esp-idf:000][wifi]: Set ps type: 1

[E][esp-idf:000][wifi]: 

[E][shtcx:094]: sensor read failed
[E][esp-idf:000][wifi]: I (2531) wifi:
[E][esp-idf:000][wifi]: Set ps type: 1

[E][esp-idf:000][wifi]: 

[E][esp-idf:000]: I (2557) BTDM_INIT: BT controller compile version [0f0c5a2]

[E][esp-idf:000][btController]: I (2559) BTDM_INIT: Bluetooth MAC: c0:49:ef:6f:15:3e

[E][shtcx:094]: sensor read failed
[E][esp-idf:000][wifi]: I (4149) wifi:
[E][esp-idf:000][wifi]: new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (4375) wifi:
[E][esp-idf:000][wifi]: state: init -> auth (b0)
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (4381) wifi:
[E][esp-idf:000][wifi]: state: auth -> assoc (0)
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (4393) wifi:
[E][esp-idf:000][wifi]: state: assoc -> run (10)
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (4414) wifi:
[E][esp-idf:000][wifi]: connected with danter2, aid = 28, channel 11, BW20, bssid = 48:2f:6b:29:8d:c1
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (4421) wifi:
[E][esp-idf:000][wifi]: security: WPA2-PSK, phy: bgn, rssi: -31
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (4442) wifi:
[E][esp-idf:000][wifi]: pm start, type: 1

[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (4459) wifi:
[E][esp-idf:000][wifi]: <ba-add>idx:0 (ifx:0, 48:2f:6b:29:8d:c1), tid:6, ssn:1, winSize:64
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][wifi]: I (4493) wifi:
[E][esp-idf:000][wifi]: AP's beacon interval = 102400 us, DTIM period = 1
[E][esp-idf:000][wifi]: 

[E][esp-idf:000][sys_evt]: I (5458) esp_netif_handlers: sta ip: 192.168.20.35, mask: 255.255.255.0, gw: 192.168.20.1

[E][esp-idf:000][wifi]: I (5531) wifi:
[E][esp-idf:000][wifi]: <ba-add>idx:1 (ifx:0, 48:2f:6b:29:8d:c1), tid:0, ssn:1, winSize:64
[E][esp-idf:000][wifi]: 

[E][esp-idf:000]: I (5716) esp-x509-crt-bundle: Certificate validated

[E][esp-idf:000][BTU_TASK]: W (64689) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e

[E][esp-idf:000][BTU_TASK]: W (83361) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13

[E][esp-idf:000][BTU_TASK]: W (83362) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16

[E][esp-idf:000][BTU_TASK]: W (83363) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x16

[E][esp-idf:000][BTU_TASK]: W (83363) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x16

[E][esp-idf:000][BTU_TASK]: W (83400) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16

ets Jul 29 2019 12:21:46
[21:20:41]
[21:20:41]rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[21:20:41]configsip: 0, SPIWP:0xee
[21:20:41]clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[21:20:41]mode:DIO, clock div:2
[21:20:41]load:0x3fff0030,len:6652
[21:20:41]ho 0 tail 12 room 4
[21:20:41]load:0x40078000,len:15052
[21:20:41]load:0x40080400,len:3836
[21:20:41]entry 0x4008069c
[21:20:41]I (29) boot: ESP-IDF 4.4.7 2nd stage bootloader
[21:20:41]I (29) boot: compile time 13:42:52
[21:20:41]I (29) boot: Multicore bootloader
[21:20:41]I (32) boot: chip revision: v3.0
[21:20:41]I (36) boot.esp32: SPI Speed      : 40MHz
[21:20:41]I (41) boot.esp32: SPI Mode       : DIO
[21:20:41]I (45) boot.esp32: SPI Flash Size : 4MB
[21:20:41]I (50) boot: Enabling RNG early entropy source...
[21:20:41]I (55) boot: Partition Table:
[21:20:41]I (59) boot: ## Label            Usage          Type ST Offset   Length
[21:20:41]I (66) boot:  0 otadata          OTA data         01 00 00009000 00002000
[21:20:41]I (74) boot:  1 phy_init         RF data          01 01 0000b000 00001000
[21:20:41]I (81) boot:  2 app0             OTA app          00 10 00010000 001c0000
[21:20:41]I (89) boot:  3 app1             OTA app          00 11 001d0000 001c0000
[21:20:41]I (96) boot:  4 nvs              WiFi data        01 02 00390000 0006d000
[21:20:41]I (104) boot: End of partition table
[21:20:41]I (108) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=44f2ch (282412) map
[21:20:41]I (219) esp_image: segment 1: paddr=00054f54 vaddr=3ffbdb60 size=050b4h ( 20660) load
[21:20:41]I (227) esp_image: segment 2: paddr=0005a010 vaddr=40080000 size=06008h ( 24584) load
[21:20:41]I (237) esp_image: segment 3: paddr=00060020 vaddr=400d0020 size=ff48ch (1045644) map
[21:20:41]I (616) esp_image: segment 4: paddr=0015f4b4 vaddr=40086008 size=18328h ( 99112) load
[21:20:41]I (671) boot: Loaded app from partition at offset 0x10000
[21:20:41]I (672) boot: Disabling RNG early entropy source...
[21:20:41]I (683) cpu_start: Multicore app
[21:20:41]I (683) cpu_start: Pro cpu up.
[21:20:41]I (683) cpu_start: Starting app cpu, entry point is 0x400826b0
[21:20:41]I (0) cpu_start: App cpu up.
[21:20:41]I (703) cpu_start: Pro cpu start user code
[21:20:41]I (704) cpu_start: cpu freq: 160000000
[21:20:41]I (704) cpu_start: Application information:
[21:20:41]I (708) cpu_start: Project name:     living_room-motion
[21:20:41]I (714) cpu_start: App version:      2024.7.3
[21:20:41]I (719) cpu_start: Compile time:     Aug  1 2024 13:42:20
[21:20:41]I (725) cpu_start: ELF file SHA256:  69d4142d6b067e08...
[21:20:41]I (731) cpu_start: ESP-IDF:          4.4.7
[21:20:41]I (736) cpu_start: Min chip rev:     v0.0
[21:20:41]I (740) cpu_start: Max chip rev:     v3.99 
[21:20:41]I (745) cpu_start: Chip rev:         v3.0
[21:20:41]I (750) heap_init: Initializing. RAM available for dynamic allocation:
[21:20:41]I (757) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
[21:20:41]I (763) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
[21:20:41]I (769) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
[21:20:41]I (776) heap_init: At 3FFCB938 len 000146C8 (81 KiB): DRAM
[21:20:41]I (782) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
[21:20:41]I (788) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
[21:20:41]I (795) heap_init: At 4009E330 len 00001CD0 (7 KiB): IRAM
[21:20:41]I (802) spi_flash: detected chip: generic
[21:20:41]I (805) spi_flash: flash io: dio
[21:20:41]I (812) cpu_start: Starting scheduler on PRO CPU.
[21:20:41]I (0) cpu_start: Starting scheduler on APP CPU.

I cleaned the build files and reinstalled again but still the same issue. Any ideas? The sensors that are on 1.2.5 are up and running.

dannytsang commented 2 months ago

I forgot, this is the YAML config:

substitutions:
  name: "living-room-motion"
packages:
  Everything_Smart_Technology.Everything_Presence_One: github://everythingsmarthome/presence-one/everything-presence-one.yaml@main
esphome:
  name: ${name}
  name_add_mac_suffix: false
esp32:
  board: esp32dev
  framework:
    type: esp-idf

esp32_ble_tracker:
  scan_parameters:
    active: true  # Whether to send scan-request packets to devices to gather more info (like devicename)
    interval: 211ms  # suggested 211ms # default 320ms
    window: 120ms  # suggested 120ms # default 30ms

bluetooth_proxy:
  active: true

switch:
  - platform: restart
    name: "Living Room Motion Restart"

wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_password
dannytsang commented 2 months ago

ok maybe not 1.2.6 issue because I changed the below line and still get the same output stopping at Starting CPU scheduler as per above.

packages:
  Everything_Smart_Technology.Everything_Presence_One: github://everythingsmarthome/presence-one/everything-presence-one.yaml@1.2.5

Is my EP1 dying 😢

dannytsang commented 2 months ago

I tried again with @main and HA is reporting data now so maybe the output is as expected. I'll put it down my own wifi issue but all is good again.

EverythingSmartHome commented 2 months ago

The log output is normal, no issues there. I'm guessing the issue you had with the update is the same as before, where you applied the GitHub update which overwrote your encryption key.

The 1.2.6 update disables the GitHub updates again as many users were applying it without realising this would happen if they had it added to ESPHome addon. Hopefully it can be re-enabled again once ESPHome handles this better

dannytsang commented 2 months ago

I thought I sorted the encryption key out last time. If you do enable it again, stick in the release notes.

On another note, how has it picked up 1.2.6 in Home Assistant when GitHub release is at 1.2.5? I didn't see a release note link to go with 1.2.6 either.