assert failed: sys_timeout IDF (IDFGH-8580)

tn-97 commented 1 year ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v4.4.2

Operating System used.

Linux

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

No response

Development Kit.

ESP32-WROOM-Kit

Power Supply used.

USB

What is the expected behavior?

Pairing success

What is the actual behavior?

None

Steps to reproduce.

Build step to step : https://docs.espressif.com/projects/esp-matter/en/main/esp32/developing.html
When I use Chiptool connect with matter device
Scan QR
Input SSID and Password
Chiptool connected BLE and start pairing...

Debug Logs.

Rebooting...
ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (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:0x3fff0030,len:6608
load:0x40078000,len:14788
ho 0 tail 12 room 4
load:0x40080400,len:3792
0x40080400: _init at ??:?

entry 0x40080694
I (29) boot: ESP-IDF v4.4.1 2nd stage bootloader
I (29) boot: compile time 19:20:44
I (29) boot: chip revision: 1
I (32) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (39) boot.esp32: SPI Speed      : 40MHz
I (43) boot.esp32: SPI Mode       : DIO
I (48) boot.esp32: SPI Flash Size : 4MB
I (52) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (61) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 sec_cert         unknown          3f 06 0000d000 00003000
I (76) boot:  1 nvs              WiFi data        01 02 00010000 00006000
I (84) boot:  2 otadata          OTA data         01 00 00016000 00002000
I (91) boot:  3 phy_init         RF data          01 01 00018000 00001000
I (99) boot:  4 ota_0            OTA app          00 10 00020000 001e0000
I (106) boot:  5 ota_1            OTA app          00 11 00200000 001e0000
I (114) boot:  6 fctry            WiFi data        01 02 003e0000 00006000
I (121) boot: End of partition table
I (126) boot_comm: chip revision: 1, min. application chip revision: 0
I (133) esp_image: segment 0: paddr=00020020 vaddr=3f400020 size=2f794h (194452) map
I (212) esp_image: segment 1: paddr=0004f7bc vaddr=3ffbdb60 size=0085ch (  2140) load
I (213) esp_image: segment 2: paddr=00050020 vaddr=400d0020 size=e701ch (946204) map
I (560) esp_image: segment 3: paddr=00137044 vaddr=3ffbe3bc size=04eb4h ( 20148) load
I (568) esp_image: segment 4: paddr=0013bf00 vaddr=40080000 size=1c808h (116744) load
I (616) esp_image: segment 5: paddr=00158710 vaddr=50000000 size=00010h (    16) load
I (630) boot: Loaded app from partition at offset 0x20000
I (630) boot: Disabling RNG early entropy source...
I (642) cpu_start: Pro cpu up.
I (642) cpu_start: Starting app cpu, entry point is 0x400813b0
0x400813b0: call_start_cpu1 at /home/trungnghia/esp-idf/components/esp_system/port/cpu_start.c:160

I (628) cpu_start: App cpu up.
I (658) cpu_start: Pro cpu start user code
I (659) cpu_start: cpu freq: 160000000
I (659) cpu_start: Application information:
I (663) cpu_start: Project name:     light_switch
I (668) cpu_start: App version:      v1.0
I (673) cpu_start: Compile time:     Oct 22 2022 19:20:34
I (679) cpu_start: ELF file SHA256:  34a628890018d0cc...
I (685) cpu_start: ESP-IDF:          v4.4.1
I (690) heap_init: Initializing. RAM available for dynamic allocation:
I (697) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (703) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (709) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (716) heap_init: At 3FFD4248 len 0000BDB8 (47 KiB): DRAM
I (722) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (728) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (735) heap_init: At 4009C808 len 000037F8 (13 KiB): IRAM
I (742) spi_flash: detected chip: generic
I (745) spi_flash: flash io: dio
I (752) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (843) gpio: GPIO[0]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (863) esp_matter_cluster: Creating default binding cluster
E (863) esp_matter_core: Server Cluster 0x001e on endpoint 0x0001 already exists. Not creating again.
E (863) esp_matter_cluster: Could not create cluster
I (873) app_main: Switch created with endpoint_id 1
I (893) wifi:wifi driver task: 3ffdb5c4, prio:23, stack:6656, core=0
I (893) system_api: Base MAC address is not set
I (893) system_api: read default base MAC address from EFUSE
I (913) wifi:wifi firmware version: 63017e0
I (913) wifi:wifi certification version: v7.0
I (913) wifi:config NVS flash: enabled
I (913) wifi:config nano formating: disabled
I (913) wifi:Init data frame dynamic rx buffer num: 32
I (923) wifi:Init management frame dynamic rx buffer num: 32
I (923) wifi:Init management short buffer num: 32
I (933) wifi:Init dynamic tx buffer num: 32
I (933) wifi:Init static rx buffer size: 1600
I (943) wifi:Init static rx buffer num: 10
I (943) wifi:Init dynamic rx buffer num: 32
I (943) wifi_init: rx ba win: 6
I (953) wifi_init: tcpip mbox: 32
I (953) wifi_init: udp mbox: 6
I (953) wifi_init: tcp mbox: 6
I (963) wifi_init: tcp tx win: 5744
I (963) wifi_init: tcp rx win: 5744
I (973) wifi_init: tcp mss: 1440
I (973) wifi_init: WiFi IRAM OP enabled
I (973) wifi_init: WiFi RX IRAM OP enabled
I (1003) chip[DL]: NVS set: chip-counters/reboot-count = 249 (0xF9)
I (1003) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (1003) BTDM_INIT: BT controller compile version [5688ed5]
I (1013) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1413) CHIP[DL]: BLE host-controller synced
I (1923) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (1923) NimBLE: GAP procedure initiated: advertise; 
I (1933) NimBLE: disc_mode=2
I (1933) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1943) NimBLE: 

I (1953) chip[DL]: CHIPoBLE advertising started
E (1953) chip[DL]: Long dispatch time: 949 ms, for event type 2
I (1963) chip[DL]: Starting ESP WiFi layer
I (1973) wifi:mode : sta (30:ae:a4:97:4c:08)
I (1973) wifi:enable tsf
W (1973) wifi:Haven't to connect to a suitable AP now!
I (1973) chip[DL]: Attempting to connect WiFi station interface
I (1983) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (1993) chip[DL]: Done driving station state, nothing else to do...
I (1993) wifi:new:<3,0>, old:<1,0>, ap:<255,255>, sta:<3,0>, prof:1
I (2003) chip[SVR]: Server initializing...
I (2003) wifi:state: init -> auth (b0)
I (2013) chip[TS]: Last Known Good Time: 2022-10-22T19:25:25
I (2023) chip[DMG]: AccessControl: initializing
I (2023) chip[DMG]: Examples::AccessControlDelegate::Init
I (2033) chip[DMG]: AccessControl: setting
I (2033) wifi:I (2033) chip[DMG]: DefaultAclStorage: initializing
state: auth -> assoc (0)
I (2043) chip[DMG]: DefaultAclStorage: 0 entries loaded
I (2073) chip[ZCL]: Using ZAP configuration...
I (2073) esp_matter_cluster: Cluster plugin init common callback
I (2073) chip[DMG]: AccessControlCluster: initializing
I (2083) wifi:state: assoc -> run (10)I (2083) chip[ZCL]: 0x3f40b244ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported

I (2093) chip[ZCL]: Initiating Admin Commissioning cluster.
E (2103) chip[ZCL]: Duplicate attribute override registration failed
I (2113) chip[DIS]: Updating services using commissioning mode 1
I (2113) chip[DIS]: CHIP minimal mDNS started advertising.
I (2123) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I (2133) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 6E4BE3C35D8F54DC.
I (2143) chip[DIS]: mDNS service published: _matterc._udp
I (2153) chip[IN]: CASE Server enabling CASE session setups
I (2153) chip[SVR]: Joining Multicast groups
I (2163) chip[SVR]: Server Listening...
I (2163) esp_matter_core: Dynamic endpoint 0 added
I (2173) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0003's Attribute 0x0001 is 0 **********
I (2183) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0004's Attribute 0x0000 is 128 **********
I (2193) wifi:I (2193) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0004's Attribute 0xFFFC is <invalid type: 0> **********
connected with Nha Tro L1, aid = 3, channel 3, BW20, bssid = d4:9a:a0:ba:d4:c0
I (2203) esp_matter_core: Dynamic endpoint 1 added
I (2213) wifi:security: WPA2-PSK, phy: bgn, rssi: -72
E (2223) chip[DL]: Long dispatch time: 223 ms, for event type 2
I (2223) wifi:pm start, type: 1
I (2233) chip[DL]: WIFI_EVENT_STA_START

I (2233) chip[DL]: Done driving station state, nothing else to do...
I (2243) wifi:AP's beacon interval = 102400 us, DTIM period = 1
 (2263) chip[DL]: Device already advertising, stop active advertisement and restart
I (2263) NimBLE: GAP procedure initiated: stop advertising.

I (2283) NimBLE: GAP procedure initiated: advertise; 
I (2283) NimBLE: disc_mode=2
I (2283) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (2293) NimBLE: 

I (2303) app_main: Commissioning window opened
I (2303) chip[SVR]: Cannot load binding table: a0
I (2313) chip[DL]: WIFI_EVENT_STA_CONNECTED
I (2313) chip[DL]: WiFi station state change: Connecting -> Connecting_Succeeded
I (2323) chip[DL]: WiFi station state change: Connecting_Succeeded -> Connected
I (2323) chip[DL]: WiFi station interface connected
I (2343) chip[ZCL]: WiFiDiagnosticsDelegate: OnConnectionStatusChanged
I (2343) chip[DL]: Done driving station state, nothing else to do...
I (2353) chip[DL]: Updating advertising data
I (2353) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (2363) chip[DL]: Device already advertising, stop active advertisement and restart
                                                                                                                                                     I (2383) NimBLE: GAP procedure initiated: stop advertising.

I (2383) NimBLE: GAP procedure initiated: advertise; 
I (2393) NimBLE: disc_mode=2
I (2393) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (2403) NimBLE: 

> I (3373) esp_netif_handlers: sta ip: 192.168.1.14, mask: 255.255.255.0, gw: 192.168.1.1
I (3373) chip[DL]: IP_EVENT_STA_GOT_IP
I (3373) chip[DL]: IPv4 address changed on WiFi station interface: 192.168.1.14/255.255.255.0 gateway 192.168.1.1
I (3393) chip[DL]: IPv4 Internet connectivity ESTABLISHED
I (3403) app_main: Interface IP Address Changed
I (3403) chip[DIS]: Updating services using commissioning mode 1
I (3413) chip[DIS]: CHIP minimal mDNS started advertising.
I (3423) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I (3423) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 6E4BE3C35D8F54DC.
I (3443) chip[DIS]: mDNS service published: _matterc._udp
I (3873) chip[DL]: IP_EVENT_GOT_IP6
I (3873) chip[DL]: IPv6 addr available. Ready on WIFI_STA_DEF interface: fe80:0000:0000:0000:32ae:a4ff:fe97:4c08
I (3883) app_main: Interface IP Address Changed
I (3893) chip[DIS]: Updating services using commissioning mode 1
I (3903) chip[DIS]: CHIP minimal mDNS started advertising.
I (3913) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15 cm=1
I (3913) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 6E4BE3C35D8F54DC.
I (3933) chip[DIS]: mDNS service published: _matterc._udp
I (3933) ROUTE_HOOK: Hook already installed on netif, skip...
I (6033) ROUTE_HOOK: Received RIO
I (6033) ROUTE_HOOK: prefix 2001:EE0:4F0D:8100:: lifetime 2592000

assert failed: sys_timeout IDF/components/lwip/lwip/src/core/timeouts.c:316 (Timeout time too long, max is LWIP_UINT32_MAX/4 msecs)

Backtrace:0x40081cfa:0x3ffd7a400x40090c45:0x3ffd7a60 0x40096ee1:0x3ffd7a80 0x4016641c:0x3ffd7ba0 0x401548fd:0x3ffd7bc0 0x40154692:0x3ffd7bf0 0x40161ff3:0x3ffd7cc0 0x4016a8d0:0x3ffd7cf0 0x4016d755:0x3ffd7d30 0x401605a9:0x3ffd7d50 0x40093b35:0x3ffd7d80 
0x40081cfa: panic_abort at /home/trungnghia/esp-idf/components/esp_system/panic.c:402

0x40090c45: esp_system_abort at /home/trungnghia/esp-idf/components/esp_system/esp_system.c:128

0x40096ee1: __assert_func at /home/trungnghia/esp-idf/components/newlib/assert.c:85

0x4016641c: sys_timeout at /home/trungnghia/esp-idf/components/lwip/lwip/src/core/timeouts.c:316
 (inlined by) sys_timeout at /home/trungnghia/esp-idf/components/lwip/lwip/src/core/timeouts.c:309

0x401548fd: esp_route_table_add_route_entry at /home/trungnghia/esp-matter/components/route_hook/src/esp_route_table.c:81

0x40154692: ra_recv_handler at /home/trungnghia/esp-matter/components/route_hook/src/esp_route_hook.c:103
 (inlined by) icmp6_raw_recv_handler at /home/trungnghia/esp-matter/components/route_hook/src/esp_route_hook.c:147

0x40161ff3: raw_input at /home/trungnghia/esp-idf/components/lwip/lwip/src/core/raw.c:178

0x4016a8d0: ip6_input at /home/trungnghia/esp-idf/components/lwip/lwip/src/core/ipv6/ip6.c:1063

0x4016d755: ethernet_input at /home/trungnghia/esp-idf/components/lwip/lwip/src/netif/ethernet.c:229

0x401605a9: tcpip_thread_handle_msg at /home/trungnghia/esp-idf/components/lwip/lwip/src/api/tcpip.c:180
 (inlined by) tcpip_thread at /home/trungnghia/esp-idf/components/lwip/lwip/src/api/tcpip.c:154

0x40093b35: vPortTaskWrapper at /home/trungnghia/esp-idf/components/freertos/port/xtensa/port.c:131

More Information.

No response

tn-97 commented 1 year ago

I change my router => fixed

tn-97 commented 1 year ago

Fixed

HomeACcessoryKid commented 1 year ago

would you spare some details on which router was changed to which And maybe a hint of what you think made the difference?? TIA, HacK

HomeACcessoryKid commented 1 year ago

I have just found the real reason. see Incorrect call to sys_timeout for real-life IPv6 lifetime of 2 weeks #217 In your case the lifetime is 30 days... The good news is that it is possible to fix the code in case you don't want to change your router ;-)

tn-97 commented 1 year ago

@HomeACcessoryKid When you run GHA example => router must support and router standand not map IP address. If lauch with hub router it no problem

HomeACcessoryKid commented 1 year ago

The CHIP dev team has just applied the FIX needed to solve it. see #217 for a link to their fix. Changing the router is merely avoiding the problem.

espressif / esp-idf