CASE flow

[doru91]

I attach here results of the CASE flows between NXP devices and chip-device-ctrl when te5 branch is used.

Issue 1

See the attached issue_1_te5_device_logs, issue_1_te5_controller_logs.

On the device side, after SigmaR1 is received I see these ZCL messages:

[260343][P][ZCL]Unknown cluster ID: 0x0000_003E
[260348][P][ZCL]Unknown cluster ID: 0x0000_003E

Is it expected to have IM messages in the middle of CASE?

Then after the CASE session is established, I see the following error messages on the device side:

[271015][E][EM]OnMessageReceived failed, err = CHIP Error 0x0000002F: Invalid argument
[271023][P][EM]Received message of type 0x32 with vendorId 0x0000 and protocolId 0x0000 on exchange 39023
[271032][D][EM]ec id: 39023, Delegate: 0x0
[271037][E][EM]OnMessageReceived failed, err = CHIP Error 0x0000002F: Invalid argument
[271044][P][EM]Received message of type 0x32 with vendorId 0x0000 and protocolId 0x0000 on exchange 39023
[271054][D][EM]ec id: 39023, Delegate: 0x0
[271058][E][EM]OnMessageReceived failed, err = CHIP Error 0x0000002F: Invalid argument

IM commands are working fine after this flow.

Issue 2

See the attached issue_2_te5_device_logs, issue_2_te5_controller_logs.

While testing this PR #9449, I decreased the OPENTHREAD_CONFIG_NUM_MESSAGE_BUFFERS to 10 - insufficient for CASE.

The device logs are not very relevant for debugging this issue (I believe logging can be improved):

[121542][P][EM]Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 39023
[126419][E][SC]CASESession timed out while waiting for a response from the peer. Expected message type was hu
[126429][P][IN]CASE Session establishment failed: CHIP Error 0x00000032: Timeout
[126437][P][IN]CASE Server enabling CASE session setups

and also the controller logs are not very relevant:

chip-device-ctrl > resolve [1630842014.235623][1621816:1621824] CHIP:BLE: no endpoint for unsub complete
[1630842014.235991][1621816:1621820] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
0 1
[1630842016.764153][1621816:1621824] CHIP:DL: Avahi resolve found
[1630842016.764317][1621816:1621824] CHIP:DIS: Node ID resolved for 0x0000000000000001 to [fd11:22::8bf5:1c6e:1e8:b012]:5540
Node address has been updated
[1630842016.764633][1621816:1621824] CHIP:CTL: OperationalDiscoveryComplete for device ID 1
[1630842020.733574][1621816:1621824] CHIP:EM: Received message of type 0x31 with vendorId 0x0000 and protocolId 0x0000 on exchange 39023
Commissioning complete
Current address: fd11:22::8bf5:1c6e:1e8:b012:5540
chip-device-ctrl > [1630842025.680146][1621816:1621824] CHIP:EM: Received message of type 0x31 with vendorId 0x0000 and protocolId 0x0000 on exchange 39023
[1630842025.680529][1621816:1621824] CHIP:EM: Dropping unexpected message 00000000:49 986F MsgId:00000000

Issue 3

See the attached issue_3_te5_device_logs, issue_3_te5_controller_logs.

Here, I kept the reduced number of OPENTHREAD_CONFIG_NUM_MESSAGE_BUFFERS to 10 but I enabled openthread logging. Looking into the logs, we can deduce immediately that no more buffer messages are available after the SigmaR2 message is sent:

[69080][D][SC]Sent SigmaR2 msg
[69083][E][DL]Long dispatch time: 5660 ms, for event type 3
[69089][P][EM]Received message of type 0x30 with vendorId 0x0000 and protocolId 0x0000 on exchange 39023
[69098][P][IN]CASE Session establishment failed: CHIP Error 0x0000002A: Invalid message type
[69107][P][IN]CASE Server enabling CASE session setups
[69112][D][DL]Thread packet SENT: UDP, len 66
[69117][D][DL]    src  FD11:22::9CFE:4B55:46A6:C88E, port 5540
[69122][D][DL]    dest FD11:DB8:1::1, port 5541
[69127][P][EM]Received message of type 0x30 with vendorId 0x0000 and protocolId 0x0000 on exchange 39023
[69137][OT][INFO]-MEM-----: No available message buffer
[69142][E][EM]Non-crit err 3000001 sending solitary ack
[69147][E][EM]Dropping unexpected message 00000000:48 986F MsgId:00000000
[69154][P][EM]Received message of type 0x30 with vendorId 0x0000 and protocolId 0x0000 on exchange 39023

CASE.zip

[woody-apple]

Can you please reverify this on a more recent build? I believe these issues were solved :)