SIGABRT when attempting to ACK secure channel StatusReport at completion of CASE

[msandstedt]

Problem

With a feature branch based off this rev:

commit 8ba47022b61c8dc1ba4f090d38f64a8eda6da47a
Author: Boris Zbarsky <[email protected]>
Date:   Mon Dec 20 19:16:31 2021 -0500

At completion of CASE handshake, the secure channel StatusReport message comes across. But when ACK for this is attempted, we have SIGABRT:

[1640274827.527551][4189025:4189030] CHIP:SC: Success status report received. Session was established
[1640274827.527604][4189025:4189030] CHIP:CTL: CertificateAuthenticatedSessionEstablishment -> CaseValidation
[1640274827.527634][4189025:4189030] CHIP:IN: New secure session created for device 0x00000000000004D2, key 2!!
[1640274827.527755][4189025:4189030] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1640274827.527813][4189025:4189030] CHIP:CTL: CaseValidation -> CaseComplete
[1640274827.527851][4189025:4189030] CHIP:CTL: CaseComplete -> InvokingCommissioningComplete
[1640274827.527917][4189025:4189030] CHIP:DMG: ICR moving to [AddingComm]
[1640274827.527951][4189025:4189030] CHIP:DMG: ICR moving to [AddedComma]
[1640274827.528039][4189025:4189030] CHIP:IN: Prepared encrypted message 0x5605afaca910 to 0x00000000000004D2 (0)  of type 0x8 and protocolId (0, 1) on exchange 23273i with MessageCounter:13899829.
[1640274827.528090][4189025:4189030] CHIP:IN: Sending encrypted msg 0x5605afaca910 with MessageCounter:13899829 to 0x00000000000004D2 (0) at monotonic time: 3721716118 msec
[1640274827.528229][4189025:4189030] CHIP:DMG: ICR moving to [CommandSen]
[1640274827.528313][4189025:4189030] CHIP:EM: Sending Standalone Ack for MessageCounter:2986371423 on exchange 23272i
pure virtual method called
terminate called without an active exception
Aborted (core dumped)

This is the M5Stack sending it:

I (23391) chip[EM]: Received message of type 0x32 with protocolId (0, 0) and MessageCounter:1742465611 on exchange 23272r
I (26661) chip[IN]: Prepared plaintext message 0x3ffc6fbc to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 23272r with MessageCounter:2986371423.
I (26681) chip[IN]: Sending plaintext msg 0x3ffc6fbc with MessageCounter:2986371423 to 0x0000000000000000 at monotonic time: 25930 msec
I (26701) chip[IN]: CASE Session established. Setting up the secure channel.
I (26701) chip[IN]: CASE secure channel is available now.
I (26701) chip[IN]: CASE Server enabling CASE session setups

Here is the stack trace:

#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:49
#1  0x00007f8da9145864 in __GI_abort () at abort.c:79
#2  0x00007f8da93a9911 in  () at /lib/x86_64-linux-gnu/libstdc++.so.6
#3  0x00007f8da93b538c in  () at /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x00007f8da93b53f7 in  () at /lib/x86_64-linux-gnu/libstdc++.so.6
#5  0x00007f8da93b6155 in  () at /lib/x86_64-linux-gnu/libstdc++.so.6
#6  0x00005605ae1579a8 in chip::Messaging::ExchangeMessageDispatch::SendMessage(chip::SessionHandle const&, unsigned short, bool, chip::Messaging::ReliableMessageContext*, bool, chip::Protocols::Id, unsigned char, chip::System::PacketBufferHandle&&) (this=0x7f8d9800cac8, session=..., exchangeId=23272, isInitiator=true, reliableMessageContext=0x5605afacaa60, isReliableTransmission=false, protocol=..., type=16 '\020', message=...) at ../src/messaging/ExchangeMessageDispatch.cpp:48
#7  0x00005605ae155ef0 in chip::Messaging::ExchangeContext::SendMessage(chip::Protocols::Id, unsigned char, chip::System::PacketBufferHandle&&, chip::BitFlags<chip::Messaging::SendMessageFlags, unsigned short> const&) (this=0x5605afacaa60, protocolId=..., msgType=16 '\020', msgBuf=..., sendFlags=...) at ../src/messaging/ExchangeContext.cpp:165
#8  0x00005605ae15ae80 in chip::Messaging::ExchangeContext::SendMessage<chip::Protocols::SecureChannel::MsgType, void>(chip::Protocols::SecureChannel::MsgType, chip::System::PacketBufferHandle&&, chip::BitFlags<chip::Messaging::SendMessageFlags, unsigned short> const&) (this=0x5605afacaa60, msgType=chip::Protocols::SecureChannel::MsgType::StandaloneAck, msgPayload=..., sendFlags=...) at ../src/messaging/ExchangeContext.h:118
#9  0x00005605ae15abad in chip::Messaging::ReliableMessageContext::SendStandaloneAckMessage() (this=0x5605afacaa60) at ../src/messaging/ReliableMessageContext.cpp:249
#10 0x00005605ae15a53b in chip::Messaging::ReliableMessageContext::FlushAcks() (this=0x5605afacaa60) at ../src/messaging/ReliableMessageContext.cpp:110
#11 0x00005605ae1560a7 in chip::Messaging::ExchangeContext::DoClose(bool) (this=0x5605afacaa60, clearRetransTable=false) at ../src/messaging/ExchangeContext.cpp:197
#12 0x00005605ae156178 in chip::Messaging::ExchangeContext::Close() (this=0x5605afacaa60) at ../src/messaging/ExchangeContext.cpp:225
#13 0x00005605ae156d69 in chip::Messaging::ExchangeContext::MessageHandled() (this=0x5605afacaa60) at ../src/messaging/ExchangeContext.cpp:507
#14 0x00005605ae15697c in operator()() const (__closure=0x7f8da27fb370) at ../src/messaging/ExchangeContext.cpp:447
#15 0x00005605ae15733c in Defer<chip::Messaging::ExchangeContext::HandleMessage(uint32_t, const chip::PayloadHeader&, const chip::Transport::PeerAddress&, chip::Messaging::MessageFlags, chip::System::PacketBufferHandle&&)::<lambda()> >::~Defer(void) (this=0x7f8da27fb370, __in_chrg=<optimized out>) at ../src/lib/support/Defer.h:28
#16 0x00005605ae156cdb in chip::Messaging::ExchangeContext::HandleMessage(unsigned int, chip::PayloadHeader const&, chip::Transport::PeerAddress const&, chip::BitFlags<chip::Messaging::MessageFlagValues, unsigned int>, chip::System::PacketBufferHandle&&) (this=0x5605afacaa60, messageCounter=2986371423, payloadHeader=..., peerAddress=..., msgFlags=..., msgBuf=...) at ../src/messaging/ExchangeContext.cpp:448
#17 0x00005605ae159d79 in operator()<chip::Messaging::ExchangeContext>(chip::Messaging::ExchangeContext*) const (__closure=0x7f8da27fb4f0, ec=0x5605afacaa60) at ../src/messaging/ExchangeMgr.cpp:228
#18 0x00005605ae15a135 in chip::internal::LambdaProxy<chip::Messaging::ExchangeContext, chip::Messaging::ExchangeManager::OnMessageReceived(const chip::PacketHeader&, const chip::PayloadHeader&, const chip::SessionHandle&, const chip::Transport::PeerAddress&, chip::SessionMessageDelegate::DuplicateMessage, chip::System::PacketBufferHandle&&)::<lambda(auto:5*)> >::Call(void *, void *) (context=0x7f8da27fb4f0, target=0x5605afacaa60) at ../src/lib/support/Pool.h:121
#19 0x00005605ae1547dc in chip::internal::StaticAllocatorBitmap::ForEachActiveObjectInner(void*, chip::Loop (*)(void*, void*)) (this=0x5605afacaa28, context=0x7f8da27fb4f0, lambda=0x5605ae15a10e <chip::internal::LambdaProxy<chip::Messaging::ExchangeContext, chip::Messaging::ExchangeManager::OnMessageReceived(const chip::PacketHeader&, const chip::PayloadHeader&, const chip::SessionHandle&, const chip::Transport::PeerAddress&, chip::SessionMessageDelegate::DuplicateMessage, chip::System::PacketBufferHandle&&)::<lambda(auto:5*)> >::Call(void *, void *)>) at ../src/lib/support/Pool.cpp:98
#20 0x00005605ae159e0d in chip::BitMapObjectPool<chip::Messaging::ExchangeContext, 8>::ForEachActiveObject<chip::Messaging::ExchangeManager::OnMessageReceived(const chip::PacketHeader&, const chip::PayloadHeader&, const chip::SessionHandle&, const chip::Transport::PeerAddress&, chip::SessionMessageDelegate::DuplicateMessage, chip::System::PacketBufferHandle&&)::<lambda(auto:5*)> >(struct {...} &&) (this=0x5605afacaa28, function=...) at ../src/lib/support/Pool.h:243
#21 0x00005605ae1593a1 in chip::Messaging::ExchangeManager::OnMessageReceived(chip::PacketHeader const&, chip::PayloadHeader const&, chip::SessionHandle const&, chip::Transport::PeerAddress const&, chip::SessionMessageDelegate::DuplicateMessage, chip::System::PacketBufferHandle&&) (this=0x5605afaca8a0, packetHeader=..., payloadHeader=..., session=..., source=..., isDuplicate=chip::SessionMessageDelegate::DuplicateMessage::No, msgBuf=...) at ../src/messaging/ExchangeMgr.cpp:214
#22 0x00005605ae16f93e in chip::SessionManager::MessageDispatch(chip::PacketHeader const&, chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) (this=0x5605afac9af0, packetHeader=..., peerAddress=..., msg=...) at ../src/transport/SessionManager.cpp:459
#23 0x00005605ae16f4d9 in chip::SessionManager::OnMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) (this=0x5605afac9af0, peerAddress=..., msg=...) at ../src/transport/SessionManager.cpp:383
#24 0x00005605ae171913 in chip::TransportMgrBase::HandleMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) (this=0x5605afac42e0, peerAddress=..., msg=...) at ../src/transport/TransportMgrBase.cpp:71
#25 0x00005605ae1fd6dd in chip::Transport::Base::HandleMessageReceived(chip::Transport::PeerAddress const&, chip::System::PacketBufferHandle&&) (this=0x5605afac4350, source=..., buffer=...) at ../src/transport/raw/Base.h:102
#26 0x00005605ae1fde18 in chip::Transport::UDP::OnUdpReceive(chip::Inet::UDPEndPoint*, chip::System::PacketBufferHandle&&, chip::Inet::IPPacketInfo const*) (endPoint=0x5605afabe6a0, buffer=..., pktInfo=0x7f8da27fba70) at ../src/transport/raw/UDP.cpp:120
#27 0x00005605ae228b96 in chip::Inet::UDPEndPointImplSockets::HandlePendingIO(chip::BitFlags<chip::System::SocketEventFlags, unsigned char>) (this=0x5605afabe6a0, events=...) at ../src/inet/UDPEndPointImplSockets.cpp:688
#28 0x00005605ae228404 in chip::Inet::UDPEndPointImplSockets::HandlePendingIO(chip::BitFlags<chip::System::SocketEventFlags, unsigned char>, long) (events=..., data=94582422103712) at ../src/inet/UDPEndPointImplSockets.cpp:569
#29 0x00005605ae168cb0 in chip::System::LayerImplSelect::HandleEvents() (this=0x5605ae2cb7c0 <chip::DeviceLayer::SystemLayerImpl()::gSystemLayerImpl>) at ../src/system/SystemLayerImplSelect.cpp:402
#30 0x00005605ae1b263e in chip::DeviceLayer::Internal::GenericPlatformManagerImpl_POSIX<chip::DeviceLayer::PlatformManagerImpl>::_RunEventLoop() (this=0x5605ae2cc370 <chip::DeviceLayer::PlatformManagerImpl::sInstance+16>) at ../src/include/platform/internal/GenericPlatformManagerImpl_POSIX.cpp:181
#31 0x00005605ae1b1778 in chip::DeviceLayer::PlatformManager::RunEventLoop() (this=0x5605ae2cc360 <chip::DeviceLayer::PlatformManagerImpl::sInstance>) at ../src/include/platform/PlatformManager.h:343
#32 0x00005605ae1b2bc5 in chip::DeviceLayer::Internal::GenericPlatformManagerImpl_POSIX<chip::DeviceLayer::PlatformManagerImpl>::EventLoopTaskMain(void*) (arg=0x5605ae2cc370 <chip::DeviceLayer::PlatformManagerImpl::sInstance+16>) at ../src/include/platform/internal/GenericPlatformManagerImpl_POSIX.cpp:207
#33 0x00007f8da9b47590 in start_thread (arg=0x7f8da27fc640) at pthread_create.c:463
#34 0x00007f8da9238223 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Proposed Solution

Unknown. Workaround is to close the exchange before an attempt is made to send the ACK.

[msandstedt]

Per #13146, the way to deal with this with current code is the following:

void OperationalDeviceProxy::DeferCloseCASESession()
{
    // Defer the release for the pending Ack to be sent
    mSystemLayer->ScheduleWork(CloseCASESessionTask, this);
}

Awkward or not, this does work.

[msandstedt]

This was resolved by #12794, which also now enables a real fix to #13146.