espressif / esp-matter

Espressif's SDK for Matter
Apache License 2.0
648 stars 151 forks source link

InteractionModelEngine abort() crash (CON-736) #607

Open law-ko opened 1 year ago

law-ko commented 1 year ago

Rebooting commissioned ESP32 and would result in the following crash:

I (26454) chip[SC]: SecureSession[0x3ffcbd48, LSID:41723]: State change 'kEstablishing' --> 'kActive'
I (26454) chip[IN]: CASE Session established to peer: <402194D0F5A42FDC, 1>
I (26464) chip[IN]: CASE Server enabling CASE session setups
I (26474) chip[EM]: <<< [E:20395r S:0 M:73727910 (Ack:103548553)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (26484) chip[IN]: (U) Sending msg 73727910 to IP address 'UDP:192.168.1.13%st1:60132'
I (26504) chip[EM]: >>> [E:20396r S:41723 M:250728408] (S) Msg RX from 1:402194D0F5A42FDC [3FB4] --- Type 0001:03 (IM:SubscribeRequest)

abort() was called at PC 0x400eb6b4 on core 0
0x400eb6b4: chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/lib/support/CodeUtils.h:508
 (inlined by) chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:1099

Backtrace: 0x4008226e:0x3ffb1b40 0x40093c5d:0x3ffb1b60 0x4009a0ea:0x3ffb1b80 0x400eb6b4:0x3ffb1bf0 0x400ebecc:0x3ffb1c90 0x400ec2ad:0x3ffb1e10 0x400ec36b:0x3ffb1e40 0x4013b03f:0x3ffb1e60 0x4013b74f:0x3ffb1eb0 0x4013e861:0x3ffb1f80 0x4013ebc8:0x3ffb2020 0x4013ec99:0x3ffb2090 0x401eb5a3:0x3ffb2100 0x4015946e:0x3ffb2150 0x401594ba:0x3ffb21a0 0x40145d85:0x3ffb21d0 0x40146082:0x3ffb21f0 0x401460b5:0x3ffb2260 0x40096cd9:0x3ffb2280
0x4008226e: panic_abort at /home/espuser/esp/esp-idf/components/esp_system/panic.c:423

0x40093c5d: esp_system_abort at /home/espuser/esp/esp-idf/components/esp_system/esp_system.c:153

0x4009a0ea: abort at /home/espuser/esp/esp-idf/components/newlib/abort.c:38

0x400eb6b4: chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/lib/support/CodeUtils.h:508
 (inlined by) chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:1099

0x400ebecc: chip::app::InteractionModelEngine::OnReadInitialRequest(chip::Messaging::ExchangeContext*, chip::PayloadHeader const&, chip::System::PacketBufferHandle&&, chip::app::ReadHandler::InteractionType) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:672

0x400ec2ad: chip::app::InteractionModelEngine::OnMessageReceived(chip::Messaging::ExchangeContext*, chip::PayloadHeader const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:870

0x400ec36b: non-virtual thunk to chip::app::InteractionModelEngine::OnMessageReceived(chip::Messaging::ExchangeContext*, chip::PayloadHeader const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.h:383

0x4013b03f: chip::Messaging::ExchangeContext::HandleMessage(unsigned long, chip::PayloadHeader const&, chip::BitFlags<chip::Messaging::MessageFlagValues, unsigned long>, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/messaging/ExchangeContext.cpp:625

0x4013b74f: chip::Messaging::ExchangeManager::OnMessageReceived(chip::PacketHeader const&, chip::PayloadHeader const&, chip::SessionHandle const&, chip::SessionMessageDelegate::DuplicateMessage, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/messaging/ExchangeMgr.cpp:351

0x4013e861: chip::SessionManager::SecureUnicastMessageDispatch(chip::PacketHeader const&, chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/SessionManager.cpp:778

0x4013ebc8: chip::SessionManager::OnMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/SessionManager.cpp:572

0x4013ec99: chip::TransportMgrBase::HandleMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/TransportMgrBase.cpp:76
 (inlined by) chip::TransportMgrBase::HandleMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/TransportMgrBase.cpp:59

0x401eb5a3: chip::Transport::Base::HandleMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/raw/Base.h:102
 (inlined by) chip::Transport::UDP::OnUdpReceive(chip::Inet::UDPEndPoint*, chip::System::PacketBufferHandle&&, chip::Inet::IPPacketInfo const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/raw/UDP.cpp:128

0x4015946e: chip::Inet::UDPEndPointImplLwIP::HandleDataReceived(chip::System::PacketBufferHandle&&, chip::Inet::IPPacketInfo*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/inet/UDPEndPointImplLwIP.cpp:291

0x401594ba: chip::LambdaBridge::Initialize<chip::Inet::UDPEndPointImplLwIP::LwIPReceiveUDPMessage(void*, udp_pcb*, pbuf*, ip_addr const*, unsigned short)::{lambda()#1}>(chip::Inet::UDPEndPointImplLwIP::LwIPReceiveUDPMessage(void*, udp_pcb*, pbuf*, ip_addr const*, unsigned short)::{lambda()#1} const&)::{lambda(std::aligned_storage<24u, 4u>::type const&)#1}::_FUN(std::aligned_storage<24u, 4u>::type const) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/inet/UDPEndPointImplLwIP.cpp:426
 (inlined by) operator() at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/LambdaBridge.h:39
 (inlined by) _FUN at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/LambdaBridge.h:39

0x40145d85: chip::DeviceLayer::Internal::GenericPlatformManagerImpl<chip::DeviceLayer::PlatformManagerImpl>::_DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl.ipp:290

0x40146082: chip::DeviceLayer::PlatformManager::DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:503
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::_RunEventLoop() at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:257

0x401460b5: chip::DeviceLayer::PlatformManager::RunEventLoop() at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:403
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::EventLoopTaskMain(void*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:280

0x40096cd9: vPortTaskWrapper at /home/espuser/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:154

Environment

shubhamdp commented 1 year ago

@law-ko Can you share more logs before the crash, want to understand the state of device before crashing.

law-ko commented 1 year ago

I did not have the log prior to the provided one, however, the crash occurs when the device is paired but rebooted. Happens after the device boots up.

On Sep 5, 2023, at 9:01 PM, Shubham Patil @.***> wrote:

 @law-ko Can you share more logs before the crash, want to understand the state of device before crashing.

— Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you were mentioned.

law-ko commented 1 year ago

@shubhamdp Here is the log:

I (26395) chip[EM]: >>> [E:20487r S:0 M:103548585] (U) Msg RX from 0:6726B742BD63D1AE [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (26405) chip[IN]: CASE Server received Sigma1 message . Starting handshake. EC 0x3ffcd6a0
I (26415) chip[EM]: <<< [E:20487r S:0 M:31402458 (Ack:103548585)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (26425) chip[IN]: (U) Sending msg 31402458 to IP address 'UDP:[FE80::1C27:F957:C9D7:1C98%st1]:62473'
I (26445) chip[SC]: Received Sigma1 msg
I (26455) chip[EM]: <<< [E:20487r S:0 M:31402459 (Ack:103548585)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume)
I (26475) chip[IN]: (U) Sending msg 31402459 to IP address 'UDP:[FE80::1C27:F957:C9D7:1C98%st1]:62473'

HEAP left: 2027840 of 304652 (320KB) 
I (26935) chip[IN]: (U) Sending msg 31402459 to IP address 'UDP:[FE80::1C27:F957:C9D7:1C98%st1]:62473'
I (27035) chip[EM]: >>> [E:20487r S:0 M:103548585] (U) Msg RX from 0:6726B742BD63D1AE [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (27045) chip[EM]: <<< [E:20487r S:0 M:31402460 (Ack:103548585)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (27055) chip[IN]: (U) Sending msg 31402460 to IP address 'UDP:[FE80::1C27:F957:C9D7:1C98%st1]:62473'
I (27095) chip[EM]: >>> [E:20487r S:0 M:103548586 (Ack:31402459)] (U) Msg RX from 0:6726B742BD63D1AE [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I (27175) chip[SC]: Success status report received. Session was established
I (27295) chip[SC]: SecureSession[0x3ffcbde8, LSID:51808]: State change 'kEstablishing' --> 'kActive'
I (27295) chip[IN]: CASE Session established to peer: <402194D0F5A42FDC, 1>
I (27305) chip[IN]: CASE Server enabling CASE session setups
I (27305) chip[EM]: <<< [E:20487r S:0 M:31402461 (Ack:103548586)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (27325) chip[IN]: (U) Sending msg 31402461 to IP address 'UDP:[FE80::1C27:F957:C9D7:1C98%st1]:62473'
I (27345) chip[EM]: >>> [E:20488r S:51808 M:3235534] (S) Msg RX from 1:402194D0F5A42FDC [3FB4] --- Type 0001:03 (IM:SubscribeRequest)

abort() was called at PC 0x400ebc0c on core 0
0x400ebc0c: chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/lib/support/CodeUtils.h:508
 (inlined by) chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:1099

Backtrace: 0x4008226e:0x3ffb1b40 0x40093c5d:0x3ffb1b60 0x4009a0ea:0x3ffb1b80 0x400ebc0c:0x3ffb1bf0 0x400ec424:0x3ffb1c90 0x400ec805:0x3ffb1e10 0x400ec8c3:0x3ffb1e40 0x4013b58f:0x3ffb1e60 0x4013bc9f:0x3ffb1eb0 0x4013edb1:0x3ffb1f80 0x4013f118:0x3ffb2020 0x4013f1e9:0x3ffb2090 0x401ebb0b:0x3ffb2100 0x401599d2:0x3ffb2150 0x40159a1e:0x3ffb21a0 0x401462d9:0x3ffb21d0 0x401465d6:0x3ffb21f0 0x40146609:0x3ffb2260 0x40096cd9:0x3ffb2280
0x4008226e: panic_abort at /home/espuser/esp/esp-idf/components/esp_system/panic.c:423

0x40093c5d: esp_system_abort at /home/espuser/esp/esp-idf/components/esp_system/esp_system.c:153

0x4009a0ea: abort at /home/espuser/esp/esp-idf/components/newlib/abort.c:38

0x400ebc0c: chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/lib/support/CodeUtils.h:508
 (inlined by) chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:1099

0x400ec424: chip::app::InteractionModelEngine::OnReadInitialRequest(chip::Messaging::ExchangeContext*, chip::PayloadHeader const&, chip::System::PacketBufferHandle&&, chip::app::ReadHandler::InteractionType) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:672

0x400ec805: chip::app::InteractionModelEngine::OnMessageReceived(chip::Messaging::ExchangeContext*, chip::PayloadHeader const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:870

0x400ec8c3: non-virtual thunk to chip::app::InteractionModelEngine::OnMessageReceived(chip::Messaging::ExchangeContext*, chip::PayloadHeader const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.h:383

0x4013b58f: chip::Messaging::ExchangeContext::HandleMessage(unsigned long, chip::PayloadHeader const&, chip::BitFlags<chip::Messaging::MessageFlagValues, unsigned long>, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/messaging/ExchangeContext.cpp:625

0x4013bc9f: chip::Messaging::ExchangeManager::OnMessageReceived(chip::PacketHeader const&, chip::PayloadHeader const&, chip::SessionHandle const&, chip::SessionMessageDelegate::DuplicateMessage, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/messaging/ExchangeMgr.cpp:351

0x4013edb1: chip::SessionManager::SecureUnicastMessageDispatch(chip::PacketHeader const&, chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/SessionManager.cpp:778

0x4013f118: chip::SessionManager::OnMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/SessionManager.cpp:572

0x4013f1e9: chip::TransportMgrBase::HandleMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/TransportMgrBase.cpp:76
 (inlined by) chip::TransportMgrBase::HandleMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/TransportMgrBase.cpp:59

0x401ebb0b: chip::Transport::Base::HandleMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/raw/Base.h:102
 (inlined by) chip::Transport::UDP::OnUdpReceive(chip::Inet::UDPEndPoint*, chip::System::PacketBufferHandle&&, chip::Inet::IPPacketInfo const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/raw/UDP.cpp:128

0x401599d2: chip::Inet::UDPEndPointImplLwIP::HandleDataReceived(chip::System::PacketBufferHandle&&, chip::Inet::IPPacketInfo*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/inet/UDPEndPointImplLwIP.cpp:291

0x40159a1e: chip::LambdaBridge::Initialize<chip::Inet::UDPEndPointImplLwIP::LwIPReceiveUDPMessage(void*, udp_pcb*, pbuf*, ip_addr const*, unsigned short)::{lambda()#1}>(chip::Inet::UDPEndPointImplLwIP::LwIPReceiveUDPMessage(void*, udp_pcb*, pbuf*, ip_addr const*, unsigned short)::{lambda()#1} const&)::{lambda(std::aligned_storage<24u, 4u>::type const&)#1}::_FUN(std::aligned_storage<24u, 4u>::type const) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/inet/UDPEndPointImplLwIP.cpp:426
 (inlined by) operator() at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/LambdaBridge.h:39
 (inlined by) _FUN at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/LambdaBridge.h:39

0x401462d9: chip::DeviceLayer::Internal::GenericPlatformManagerImpl<chip::DeviceLayer::PlatformManagerImpl>::_DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl.ipp:290

0x401465d6: chip::DeviceLayer::PlatformManager::DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:503
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::_RunEventLoop() at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:257

0x40146609: chip::DeviceLayer::PlatformManager::RunEventLoop() at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:403
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::EventLoopTaskMain(void*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:280

0x40096cd9: vPortTaskWrapper at /home/espuser/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:154
law-ko commented 1 year ago

@shubhamdp The device is attempting to resume previous subscription, but seems like allocating the resource failed. The matter stack is above External SPIRAM by ESP32-PICO-MINI.

    // The above loop cannot guarantee the resources for the new subscriptions when the resource usage from all fabrics are exactly
    // within the quota (which means we have exactly used all resources). Evict (from the large subscriptions first then from
    // oldest) subscriptions from the current fabric until we have enough resource for the new subscription.
    didEvictHandler = true;
    while ((usedAttributePaths + aRequestedAttributePathCount > attributePathCap ||
            usedEventPaths + aRequestedEventPathCount > eventPathCap || usedReadHandlers >= readHandlerCap) &&
           // Avoid infinity loop
           didEvictHandler)
    {
        didEvictHandler = evictAndUpdateResourceUsage(aFabricIndex, true);
    }

    // If didEvictHandler is false, means the loop above evicted all subscriptions from the current fabric but we still don't have
    // enough resources for the new subscription, this should never happen.
    // This is safe as long as we have rejected subscriptions without a fabric associated (with a PASE session) before.
    // Note: Spec#5141: should reject subscription requests on PASE sessions.
    VerifyOrDieWithMsg(didEvictHandler, DataManagement, "Failed to get required resources by evicting existing subscriptions.");
shubhamdp commented 1 year ago

@law-ko I see, not sure when this would happen, I will give it a try on ESP32 with PSRAM.

shubhamdp commented 1 year ago

Also, one more thing, I was backtracking the code on esp-matter commit 0cb1c14cd3072529880a5f17fb9708dec3c1744a and connectedhomeip submodule was at commit c95efa996d5c9a01a58b16060106127244fb1f5d. And I was unable to match the line numbers can you provide the exact connectedhomeip commit. I would also suggest to sync/update the submodules in esp-matter.

law-ko commented 11 months ago

@shubhamdp What is the correct way to update submodules? Are we supposed to update to their latest remote commits?

git submodule update --recursive --remote or git submodule update --recursive?

law-ko commented 11 months ago

@shubhamdp We have cloned the esp-matter repo into our own private repo, commit 0cb1c14cd3072529880a5f17fb9708dec3c1744a at release/v1.1 branch. How do we sync/update the submodules correctly?

law-ko commented 11 months ago

@shubhamdp Updating to the commit ID 3106fce gives us the same error but with different crash line number. VerifyOrDieWithMsg(didEvictHandler, DataManagement, "Failed to get required resources by evicting existing subscriptions.");

W (12871) app_main: Interface IP Address changed
I (12871) chip[DIS]: Updating services using commissioning mode 0
I (12881) chip[DIS]: Advertise operational node 083BEACDF09A3FB4-00000000468BB6A7
<ba-add>idx:1 (ifx:0, ce:9e:43:a1:33:61), tid:6, ssn:2, winSize:64
I (12891) chip[DIS]: Advertise operational node 0459C5EAC7ADA78D-00000000B00DD672
HEAP left: 2037752 of 304652 (320KB) 
HEAP left: 2015572 of 304652 (320KB) 
I (14281) chip[EM]: >>> [E:31758r S:0 M:125677024] (U) Msg RX from 0:1457538A5F623EA5 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I (14281) chip[IN]: CASE Server received Sigma1 message . Starting handshake. EC 0x3ffcd638
I (14291) chip[EM]: <<< [E:31758r S:0 M:28802124 (Ack:125677024)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (14311) chip[IN]: (U) Sending msg 28802124 to IP address 'UDP:[FE80::1C80:1062:A607:3535%st1]:60451'
I (14321) chip[SC]: Received Sigma1 msg
I (14351) chip[EM]: <<< [E:31758r S:0 M:28802125 (Ack:125677024)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume)
I (14361) chip[IN]: (U) Sending msg 28802125 to IP address 'UDP:[FE80::1C80:1062:A607:3535%st1]:60451'
HEAP left: 2018292 of 304652 (320KB) 
I (14601) chip[EM]: >>> [E:31758r S:0 M:125677025 (Ack:28802125)] (U) Msg RX from 0:1457538A5F623EA5 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I (14621) chip[SC]: Success status report received. Session was established
I (14661) chip[SC]: SecureSession[0x3ffcbd80]: Moving from state 'kEstablishing' --> 'kActive'
I (14661) chip[IN]: CASE Session established to peer: <402194D0F5A42FDC, 1>
I (14671) chip[IN]: CASE Server enabling CASE session setups
I (14671) chip[EM]: <<< [E:31758r S:0 M:28802126 (Ack:125677025)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I (14691) chip[IN]: (U) Sending msg 28802126 to IP address 'UDP:[FE80::1C80:1062:A607:3535%st1]:60451'
I (14711) chip[EM]: >>> [E:31759r S:19885 M:182873363] (S) Msg RX from 1:402194D0F5A42FDC [3FB4] --- Type 0001:03 (IM:SubscribeRequest)

abort() was called at PC 0x400f15d8 on core 0
0x400f15d8: chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/lib/support/CodeUtils.h:508
 (inlined by) chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:953

Backtrace: 0x4008226e:0x3ffb1b40 0x40093c5d:0x3ffb1b60 0x4009a0ea:0x3ffb1b80 0x400f15d8:0x3ffb1bf0 0x400f1d85:0x3ffb1c90 0x400f2149:0x3ffb1e10 0x400f2207:0x3ffb1e40 0x4013d56b:0x3ffb1e60 0x4013dc7b:0x3ffb1eb0 0x40140814:0x3ffb1f80 0x40140b58:0x3ffb2020 0x40140c29:0x3ffb2090 0x401ef343:0x3ffb2100 0x4015b692:0x3ffb2150 0x4015b6de:0x3ffb21a0 0x401476d1:0x3ffb21d0 0x401479ce:0x3ffb21f0 0x40147a01:0x3ffb2260 0x40096cd9:0x3ffb2280
0x4008226e: panic_abort at /home/espuser/esp/esp-idf/components/esp_system/panic.c:423

0x40093c5d: esp_system_abort at /home/espuser/esp/esp-idf/components/esp_system/esp_system.c:153

0x4009a0ea: abort at /home/espuser/esp/esp-idf/components/newlib/abort.c:38

0x400f15d8: chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/lib/support/CodeUtils.h:508
 (inlined by) chip::app::InteractionModelEngine::EnsureResourceForSubscription(unsigned char, unsigned int, unsigned int) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:953

0x400f1d85: chip::app::InteractionModelEngine::OnReadInitialRequest(chip::Messaging::ExchangeContext*, chip::PayloadHeader const&, chip::System::PacketBufferHandle&&, chip::app::ReadHandler::InteractionType) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:530

0x400f2149: chip::app::InteractionModelEngine::OnMessageReceived(chip::Messaging::ExchangeContext*, chip::PayloadHeader const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.cpp:724

0x400f2207: non-virtual thunk to chip::app::InteractionModelEngine::OnMessageReceived(chip::Messaging::ExchangeContext*, chip::PayloadHeader const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp/esp-matter/connectedhomeip/connectedhomeip/src/app/InteractionModelEngine.h:382

0x4013d56b: chip::Messaging::ExchangeContext::HandleMessage(unsigned long, chip::PayloadHeader const&, chip::BitFlags<chip::Messaging::MessageFlagValues, unsigned long>, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/messaging/ExchangeContext.cpp:612

0x4013dc7b: chip::Messaging::ExchangeManager::OnMessageReceived(chip::PacketHeader const&, chip::PayloadHeader const&, chip::SessionHandle const&, chip::SessionMessageDelegate::DuplicateMessage, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/messaging/ExchangeMgr.cpp:351

0x40140814: chip::SessionManager::SecureUnicastMessageDispatch(chip::PacketHeader const&, chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/SessionManager.cpp:758

0x40140b58: chip::SessionManager::OnMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/SessionManager.cpp:564

0x40140c29: chip::TransportMgrBase::HandleMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/TransportMgrBase.cpp:76
 (inlined by) chip::TransportMgrBase::HandleMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/TransportMgrBase.cpp:59

0x401ef343: chip::Transport::Base::HandleMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/raw/Base.h:102
 (inlined by) chip::Transport::UDP::OnUdpReceive(chip::Inet::UDPEndPoint*, chip::System::PacketBufferHandle&&, chip::Inet::IPPacketInfo const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/transport/raw/UDP.cpp:128

0x4015b692: chip::Inet::UDPEndPointImplLwIP::HandleDataReceived(chip::System::PacketBufferHandle&&, chip::Inet::IPPacketInfo*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/inet/UDPEndPointImplLwIP.cpp:291

0x4015b6de: chip::LambdaBridge::Initialize<chip::Inet::UDPEndPointImplLwIP::LwIPReceiveUDPMessage(void*, udp_pcb*, pbuf*, ip_addr const*, unsigned short)::{lambda()#1}>(chip::Inet::UDPEndPointImplLwIP::LwIPReceiveUDPMessage(void*, udp_pcb*, pbuf*, ip_addr const*, unsigned short)::{lambda()#1} const&)::{lambda(std::aligned_storage<24u, 4u>::type const&)#1}::_FUN(std::aligned_storage<24u, 4u>::type const) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/inet/UDPEndPointImplLwIP.cpp:426
 (inlined by) operator() at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/LambdaBridge.h:39
 (inlined by) _FUN at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/lib/support/LambdaBridge.h:39

0x401476d1: chip::DeviceLayer::Internal::GenericPlatformManagerImpl<chip::DeviceLayer::PlatformManagerImpl>::_DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl.ipp:290

0x401479ce: chip::DeviceLayer::PlatformManager::DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:505
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::_RunEventLoop() at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:257

0x40147a01: chip::DeviceLayer::PlatformManager::RunEventLoop() at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:405
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::EventLoopTaskMain(void*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../../../esp/esp-matter/connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:280

0x40096cd9: vPortTaskWrapper at /home/espuser/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:154
law-ko commented 11 months ago

Another crash log:

I (4601) chip[DIS]: Updating services using commissioning mode 0

abort() was called at PC 0x400f66c6 on core 1
0x400f66c6: chip::app::DnssdServer::AdvertiseOperational() at /home/espuser/esp-git/esp-matter/connectedhomeip/connectedhomeip/src/lib/support/CodeUtils.h:508
 (inlined by) chip::app::DnssdServer::AdvertiseOperational() at /home/espuser/esp-git/esp-matter/connectedhomeip/connectedhomeip/src/app/server/Dnssd.cpp:151

Backtrace: 0x4008226e:0x3ffb1f90 0x40093c5d:0x3ffb1fb0 0x4009a0ea:0x3ffb1fd0 0x400f66c6:0x3ffb2040 0x400f6c39:0x3ffb2150 0x400f6c9e:0x3ffb2170 0x400edce3:0x3ffb2190 0x401ee685:0x3ffb21b0 0x4014736d:0x3ffb21d0 0x4014764a:0x3ffb21f0 0x4014767d:0x3ffb2260 0x40096cd9:0x3ffb2280
0x4008226e: panic_abort at /home/espuser/esp/esp-idf/components/esp_system/panic.c:423

0x40093c5d: esp_system_abort at /home/espuser/esp/esp-idf/components/esp_system/esp_system.c:153

0x4009a0ea: abort at /home/espuser/esp/esp-idf/components/newlib/abort.c:38

0x400f66c6: chip::app::DnssdServer::AdvertiseOperational() at /home/espuser/esp-git/esp-matter/connectedhomeip/connectedhomeip/src/lib/support/CodeUtils.h:508
 (inlined by) chip::app::DnssdServer::AdvertiseOperational() at /home/espuser/esp-git/esp-matter/connectedhomeip/connectedhomeip/src/app/server/Dnssd.cpp:151

0x400f6c39: chip::app::DnssdServer::StartServer(chip::Dnssd::CommissioningMode) at /home/espuser/esp-git/esp-matter/connectedhomeip/connectedhomeip/src/app/server/Dnssd.cpp:388

0x400f6c9e: chip::app::DnssdServer::StartServer() at /home/espuser/esp-git/esp-matter/connectedhomeip/connectedhomeip/src/app/server/Dnssd.cpp:343

0x400edce3: esp_matter::device_callback_internal(chip::DeviceLayer::ChipDeviceEvent const*, int) at /home/espuser/esp-git/esp-matter/components/esp_matter/esp_matter_core.cpp:836

0x401ee685: chip::DeviceLayer::Internal::GenericPlatformManagerImpl<chip::DeviceLayer::PlatformManagerImpl>::DispatchEventToApplication(chip::DeviceLayer::ChipDeviceEvent const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl.ipp:336

0x4014736d: chip::DeviceLayer::Internal::GenericPlatformManagerImpl<chip::DeviceLayer::PlatformManagerImpl>::_DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl.ipp:301

0x4014764a: chip::DeviceLayer::PlatformManager::DispatchEvent(chip::DeviceLayer::ChipDeviceEvent const*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:505
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::_RunEventLoop() at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:257

0x4014767d: chip::DeviceLayer::PlatformManager::RunEventLoop() at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/PlatformManager.h:405
 (inlined by) chip::DeviceLayer::Internal::GenericPlatformManagerImpl_FreeRTOS<chip::DeviceLayer::PlatformManagerImpl>::EventLoopTaskMain(void*) at /home/espuser/esp-git/esp-matter/examples/im/outlet/build/esp-idf/chip/../../../../../../connectedhomeip/connectedhomeip/config/esp32/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_FreeRTOS.ipp:280

0x40096cd9: vPortTaskWrapper at /home/espuser/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:154

Note: the CHIP mDNS Use the minimal mDNS implementation shipped in the CHIP library is not being used.

law-ko commented 11 months ago

@shubhamdp This issue still exists, should we update the connectedhomeip to the latest commit on esp-matter main branch?

law-ko commented 10 months ago

@shubhamdp We are running 8 endpoints on the device, should we change any of these settings to ensure the resource is enough?

Screenshot 2023-10-23 at 2 42 43 PM

The crash line is here:

// If didEvictHandler is false, means the loop above evicted all subscriptions from the current fabric but we still don't have
    // enough resources for the new subscription, this should never happen.
    // This is safe as long as we have rejected subscriptions without a fabric associated (with a PASE session) before.
    // Note: Spec#5141: should reject subscription requests on PASE sessions.
    VerifyOrDieWithMsg(didEvictHandler, DataManagement, "Failed to get required resources by evicting existing subscriptions.");