espressif / esp-zigbee-sdk

Espressif Zigbee SDK
Apache License 2.0
170 stars 29 forks source link

'Failed to initialize Zigbee stack' after light sleep (TZ-590) #225

Closed xmow49 closed 3 months ago

xmow49 commented 9 months ago

Answers checklist.

IDF version.

v5.2-beta1-263-ge49823f10c

esp-zigbee-lib version.

1.0.8

esp-zboss-lib version.

1.0.8

Espressif SoC revision.

ESP32-C6

What is the expected behavior?

I have a main loop in my code, who send/report attributes every minutes. Its working nice. Now after sending the data, I want a light sleep. So in my main loop, after 10s i do this

        esp_sleep_enable_timer_wakeup(main_sleep_time * 1000000); 
        esp_light_sleep_start();

I looked the light sleep example, but for now, I don't want to use the power manager (it breaks some part of my code)

So like in the sample I enable the sleep

    esp_zb_sleep_enable(true);
    esp_zb_sleep_set_threshold(1000);
    esp_zb_init(&zigbee_cfg);

What is the actual behavior?

Currently, this is how it works:

What's wrong with my setup? Is it required to use the power manager? What function calls after sleep to reconnect the device?

Steps to reproduce.

A lot of code of my project is needed to reproduce.

More Information.

Init logs:

I (23) boot: ESP-IDF v5.2-beta1-263-ge49823f10c 2nd stage bootloader
I (23) boot: compile time Jan 18 2024 18:40:04
I (24) boot: chip revision: v0.0
I (24) boot.esp32c6: SPI Speed      : 80MHz
I (25) boot.esp32c6: SPI Mode       : DIO
I (25) boot.esp32c6: SPI Flash Size : 4MB
I (26) boot: Enabling RNG early entropy source...
I (27) boot: Partition Table:
I (27) boot: ## Label            Usage          Type ST Offset   Length
I (28) boot:  0 ro_nvs           WiFi data        01 02 00009000 00002000
I (28) boot:  1 nvs              WiFi data        01 02 0000b000 00004000
I (29) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (30) boot:  3 otadata          OTA data         01 00 00010000 00002000
I (31) boot:  4 zb_storage       Unknown data     01 81 00012000 00004000
I (32) boot:  5 zb_fct           Unknown data     01 81 00016000 00000400
I (33) boot:  6 storage          Unknown data     01 82 00017000 00010000
I (34) boot:  7 nvs_key          NVS keys         01 04 00027000 00001000
I (34) boot:  8 ota_0            OTA app          00 10 00030000 002d5000
I (35) boot: End of partition table
I (36) boot: No factory image, trying OTA 0
I (36) esp_image: segment 0: paddr=00030020 vaddr=42190020 size=66280h (418432) map
I (122) esp_image: segment 1: paddr=000962a8 vaddr=40800000 size=09d70h ( 40304) load
I (137) esp_image: segment 2: paddr=000a0020 vaddr=42000020 size=1809d8h (1575384) map
I (458) esp_image: segment 3: paddr=00220a00 vaddr=40809d70 size=166f8h ( 91896) load
I (479) esp_image: segment 4: paddr=00237100 vaddr=50000000 size=00048h (    72) load
I (486) boot: Loaded app from partition at offset 0x30000
I (527) boot: Set actual ota_seq=1 in otadata[0]
I (528) boot: Disabling RNG early entropy source...
I (529) cpu_start: Unicore app
W (538) clk: esp_perip_clk_init() has not been implemented yet
I (538) cpu_start: Pro cpu start user code
I (539) cpu_start: cpu freq: 80000000 Hz
I (539) cpu_start: Application information:
I (539) cpu_start: Project name:     TICMeter
I (540) cpu_start: App version:      6c372e3-dirty
I (540) cpu_start: Compile time:     Jan 18 2024 21:41:33
I (541) cpu_start: ELF file SHA256:  87792cba0e852bbc...
I (541) cpu_start: ESP-IDF:          v5.2-beta1-263-ge49823f10c
I (542) cpu_start: Min chip rev:     v0.0
I (543) cpu_start: Max chip rev:     v0.99
I (543) cpu_start: Chip rev:         v0.0
I (544) heap_init: Initializing. RAM available for dynamic allocation:
I (545) heap_init: At 408311B0 len 0004B460 (301 KiB): RAM
I (545) heap_init: At 4087C610 len 00002F54 (11 KiB): RAM
I (546) heap_init: At 50000048 len 00003FA0 (15 KiB): RTCRAM
I (548) spi_flash: detected chip: generic
I (548) spi_flash: flash io: dio
I (549) sleep: Configure to isolate all GPIO pins in sleep state
I (550) sleep: Enable automatic switching of GPIO sleep configuration
I (551) coexist: coex firmware version: e41c5cb
I (551) coexist: coexist rom version 5b8dcfa
I (552) main_task: Started on CPU0
I (552) main_task: Calling app_main()
I (552) MAIN: Starting TICMeter...
I (552) gpio: GPIO[5]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (552) gpio: GPIO[1]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (552) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (3402) ZIGBEE: Initializing Zigbee stack
I (3452) ZBOSS: common/zb_init_default.c:181   ED build
I (3452) ZBOSS: common/zb_init_default.c:187   sizes: g_zb 25776 sched 1676 bpool 13140 nwk 2016 aps 5404 addr 660 zdo 868
I (3452) ZBOSS: common/zb_init_default.c:196   sec 2
I (3452) ZBOSS: common/zb_init_default.c:198   zcl 600
I (3462) ZBOSS: common/zb_init_default.c:201   zll 960
I (3462) ZBOSS: common/zb_init_default.c:207   nvram 140
I (3462) ZBOSS: common/zb_init_default.c:210   buttons 140
I (3462) ZBOSS: common/zb_init_default.c:212   err_ind 4
I (3462) ZBOSS: common/zb_init_default.c:218   scheduler q size 80
I (3462) ZBOSS: common/zb_init_default.c:221   g_mac 652 g_imac 28
I (3462) ZBOSS: common/zb_init_default.c:231   ZB_IOBUF_POOL_SIZE 80 ZB_NWK_IN_Q_SIZE 40 ZB_MAC_PENDING_QUEUE_SIZE 20 ZB_APS_DST_BINDING_TABLE_SIZE 64 ZB_APS_BIND_TRANS_TABLE_SIZE 20 ZB_N_APS_RETRANS_ENTRIES 26
I (3472) ZBOSS: common/zb_init_default.c:261   ZB_N_APS_KEY_PAIR_ARR_MAX_SIZE 5 ZB_IEEE_ADDR_TABLE_SIZE 32 ZB_NEIGHBOR_TABLE_SIZE 32 ZB_NWK_ROUTING_TABLE_SIZE 0 ZB_APS_DUPS_TABLE_SIZE 32
I (3472) ZIGBEE: Zigbee stack initialized
E (3472) ESP_ZIGBEE_ATTRIBUTE: The requested add attribute ID:0x300 is already existed
I (3492) ZBOSS: zdo/af_descriptor.c:357   ep_count 1
I (3492) ZIGBEE: Primary channel mask
I (3502) ZIGBEE: Secondary channel mask
I (3522) ZBOSS: common/zb_nvram.c:3189   ds_ver == 2
I (3522) ZBOSS: zdo/zdo_app_prod_conf.c:144   no production config block found
I (3522) ZBOSS: zdo/zdo_app_prod_conf.c:781   no valid production configuration found, signaling to application
I (3522) MAIN: Waiting for 50 seconds
I (3532) ZIGBEE: Zigbee stack started
I (3532) ZIGBEE: ZDO signal: ZDO Config Ready (0x17), status: UNKNOWN ERROR
I (3532) ZIGBEE: Zigbee stack initialized
I (3532) ZBOSS: commissioning/bdb/zdo_commissioning_bdb.c:349   dev type 2, joined 1, ext_pan_id 1, authenticated 1, tclk_valid 1
I (3522) main_task: Returned from app_main()
I (4172) ZBOSS: mac/mac.c:1022   Oops - error beacon payload is too small buf_sz 15 - drop it
I (4182) ZBOSS: mac/mac.c:1022   Oops - error beacon payload is too small buf_sz 15 - drop it
I (5852) ZBOSS: zdo/zdo_app_join.c:771   CONGRATULATIONS! joined status 0, addr 0x1a8c, iface_id 0, ch 20, rejoin 1
I (5852) ZBOSS: zdo/zdo_app_join.c:773   xpanid 67:ec:64:85:4b:3d:d1:70
I (5862) ZBOSS: commissioning/bdb/zdo_commissioning_bdb.c:549   COMMISSIONING_STOP: app signal 6 comm status 0
I (11052) ZBOSS: nwk/zb_nwk_ed_aging.c:227   ED aging is not supported

I (54022) LINKY: Read 0 bytes, remaning:4500
I (55042) LINKY: Read 120 bytes, remaning:3480
I (56062) LINKY: Read 240 bytes, remaning:2460
I (56162) ZBOSS: zcl/zcl_main.c:357   zb_zcl_get_cluster_check_value: cluster_id 1794 cluster_role 1
I (56162) ZBOSS: zcl/zcl_main.c:382   zb_zcl_get_cluster_write_attr_hook: cluster_id 1794 cluster_role 1
I (56162) ZBOSS: zcl/zcl_main.c:357   zb_zcl_get_cluster_check_value: cluster_id 65346 cluster_role 1
I (56172) ZBOSS: zcl/zcl_main.c:382   zb_zcl_get_cluster_write_attr_hook: cluster_id 65346 cluster_role 1
I (56192) ZBOSS: zcl/zcl_main.c:357   zb_zcl_get_cluster_check_value: cluster_id 2820 cluster_role 1
I (56192) ZBOSS: zcl/zcl_main.c:382   zb_zcl_get_cluster_write_attr_hook: cluster_id 2820 cluster_role 1
I (56202) ZBOSS: zcl/zcl_main.c:357   zb_zcl_get_cluster_check_value: cluster_id 65346 cluster_role 1
I (56202) ZBOSS: zcl/zcl_main.c:382   zb_zcl_get_cluster_write_attr_hook: cluster_id 65346 cluster_role 1
I (56212) ZBOSS: zcl/zcl_main.c:357   zb_zcl_get_cluster_check_value: cluster_id 65346 cluster_role 1
I (56212) ZBOSS: zcl/zcl_main.c:382   zb_zcl_get_cluster_write_attr_hook: cluster_id 65346 cluster_role 1
W (56272) ZIGBEE: Receive Zigbee action(0x1005) callback, message:
W (56292) ZIGBEE: Receive Zigbee action(0x1005) callback, message:
W (56322) ZIGBEE: Receive Zigbee action(0x1005) callback, message:
W (56352) ZIGBEE: Receive Zigbee action(0x1005) callback, message:
W (56382) ZIGBEE: Receive Zigbee action(0x1005) callback, message:
I (66222) MAIN: Waiting for 50 seconds

After sleep:

I (54217) MAIN: -----------------------------------------------------------------
I (54217) MAIN: Waking up, VCondo: 4.914000
I (54717) LINKY: Read 0 bytes, remaning:4500
I (55737) LINKY: Read 120 bytes, remaning:3480
I (56767) LINKY: Read 240 bytes, remaning:2450
I (56867) ZBOSS: zcl/zcl_main.c:357   zb_zcl_get_cluster_check_value: cluster_id 1794 cluster_role 1
I (56867) ZBOSS: zcl/zcl_main.c:382   zb_zcl_get_cluster_write_attr_hook: cluster_id 1794 cluster_role 1
I (56867) ZBOSS: zcl/zcl_main.c:357   zb_zcl_get_cluster_check_value: cluster_id 65346 cluster_role 1
I (56877) ZBOSS: zcl/zcl_main.c:382   zb_zcl_get_cluster_write_attr_hook: cluster_id 65346 cluster_role 1
I (56897) ZBOSS: zcl/zcl_main.c:357   zb_zcl_get_cluster_check_value: cluster_id 2820 cluster_role 1
I (56897) ZBOSS: zcl/zcl_main.c:382   zb_zcl_get_cluster_write_attr_hook: cluster_id 2820 cluster_role 1
I (56907) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (56907) ZBOSS: zcl/zcl_main.c:357   zb_zcl_get_cluster_check_value: cluster_id 65346 cluster_role 1
I (56917) ZBOSS: zcl/zcl_main.c:382   zb_zcl_get_cluster_write_attr_hook: cluster_id 65346 cluster_role 1
I (56917) ZBOSS: zcl/zcl_main.c:357   zb_zcl_get_cluster_check_value: cluster_id 65346 cluster_role 1
I (56917) ZBOSS: zcl/zcl_main.c:382   zb_zcl_get_cluster_write_attr_hook: cluster_id 65346 cluster_role 1
I (56927) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (56947) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (56967) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (56987) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (59947) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (59967) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (59987) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (60007) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (60027) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (62987) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (63007) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (63027) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (63057) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (63077) ZIGBEE: ZDO signal: NLME Status Indication (0x32), status: UNKNOWN ERROR
I (63077) ZBOSS: commissioning/bdb/zdo_commissioning_bdb.c:349   dev type 2, joined 1, ext_pan_id 1, authenticated 1, tclk_valid 1
I (65377) ZBOSS: nwk/nwk_join.c:629   Rejoin failure: no dev with xpanid 67:ec:64:85:4b:3d:d1:70 or can't choose best parent
I (65377) ZBOSS: commissioning/bdb/zdo_commissioning_bdb.c:549   COMMISSIONING_STOP: app signal 6 comm status 3
W (65377) ZIGBEE: Failed to initialize Zigbee stack (status: -1)
W (66927) MAIN: Free heap memory: 214416
W (66927) MAIN: Heap diff: 0
I (66927) MAIN: Waiting for 50 seconds
kelin6 commented 8 months ago

@xmow49

Based on your requirements, if you only want to send a Zigbee command or report an attribute every 10 seconds after successful network formation, while keeping the device in sleep mode the rest of the time, you can consider the following approach:

It's important to note that you should avoid usingesp_light_sleep_start directly in the Zigbee Light Sleep example because the esp-zigbee-sdk internally calls this interface. The example is designed to utilize system sleep, and it will only enter sleep when FreeRTOS enters the idle task.