Matter: Cannot add an endpoint to more than two groups

[Josh_Johnston]

Hello!

Any and all guidance on the issue described below would be greatly appreciated! I am happy to provide any additional information.

Thank you for your time,

Josh

The System

• A Raspberry Pi 4 running the otbr-agent and chip-tool commands.
• nRF52840 USB dongle programmed with thread RCP firmware plugged into the Pi.
• An nRF5340-dk running the matter light_bulb sample using the nRF Connect SDK v2.5.1

The Problem

Attempting to add an endpoint to a third group results in Unable to listen to group on the light_bulb, but the command appears successful from chip-tool's perspective.

D: 54772 [IN]New secure session activated for device <000000000001B669, 1>, LSID:9109 PSID:55899!
I: 54781 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 54788 [IN]CASE Server enabling CASE session setups
D: 54796 [IN]SecureSession[0x200046f8]: Allocated Type:2 LSID:9110
I: 54806 [EM]>>> [E:293r S:9109 M:13683323] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 54829 [IN]Joining Multicast Group with address UDP:[ff35:40:fd00::100:5]:5540
E: 54836 [SVR]Unable to listen to group
I: 54844 [EM]<<< [E:293r S:9109 M:224548323 (Ack:13683323)] (S) Msg TX to 1:000000000001B669 [6DF1] --- Type 0001:09 (IM:InvokeCommandResponse)

The expected output is shown below, after adding the second group.

D: 53461 [IN]New secure session activated for device <000000000001B669, 1>, LSID:9108 PSID:42909!
I: 53470 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 53479 [IN]CASE Server enabling CASE session setups
D: 53487 [IN]SecureSession[0x20004640]: Allocated Type:2 LSID:9109
I: 53494 [EM]>>> [E:31925r S:9108 M:159503087] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 53516 [IN]Joining Multicast Group with address UDP:[ff35:40:fd00::100:4]:5540
I: 53530 [EM]<<< [E:31925r S:9108 M:251420196 (Ack:159503087)] (S) Msg TX to 1:000000000001B669 [6DF1] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 53545 [IN](S) Sending msg 251420196 on secure session with LSID: 9108
D: 53553 [DL]OpenThread State Changed (Flags: 0x00001000)

The full logs for both the Pi and the light_bulb are attached.

2671.pi.log

Fullscreen 3733.light_bulb.log Download

I: Factory Reset Triggered. Release button within 3000ms to cancel.
I: 97162 [TS]Pending Last Known Good Time: 2024-10-25T11:19:57
I: 97169 [TS]Previous Last Known Good Time: 2024-10-25T11:19:57
I: 97175 [TS]Reverted Last Known Good Time to previous value
I: 97185 [FP]Fabric (0x1) deleted.
I: 97189 [ZCL]OpCreds: Fabric index 0x1 was removed
I: 97193 [DIS]Updating services using commissioning mode 0
I: 97198 [DL]removing srp service: A105A369AB1A8E13-0000000000000002._matter._tcp
E: 97231 [SVR]Group added to nonexistent fabric?
E: 97240 [SVR]Group added to nonexistent fabric?
E: 97248 [SVR]Group added to nonexistent fabric?
E: 97274 [DL]Long dispatch time: 112 ms, for event type 2
I: 97279 [DL]Performing factory reset
E: 97970 [DL]SRP update error: domain name or RRset is duplicated


uart:~$ *** Booting nRF Connect SDK v2.5.1 ***
I: Init CHIP stack
I: 157 [DL]BLE address: F4:FB:DB:E1:94:A7
I: 178 [DL]OpenThread started: OK
I: 181 [DL]Setting OpenThread device type to ROUTER
Configuring button #0: gpio@842500, 23, 17
Configuring button #1: gpio@842500, 24, 17
Configuring button #2: gpio@842500, 8, 17
Configuring button #3: gpio@842500, 9, 17
I: 201 [SVR]Subscription persistence not supported
I: 205 [SVR]Server initializing...
I: 209 [TS]Last Known Good Time: [unknown]
I: 212 [TS]Setting Last Known Good Time to firmware build time 2024-10-25T11:19:57
I: 221 [DMG]AccessControl: initializing
I: 224 [DMG]Examples::AccessControlDelegate::Init
I: 229 [DMG]AccessControl: setting
I: 232 [DMG]DefaultAclStorage: initializing
I: 235 [DMG]DefaultAclStorage: 0 entries loaded
D: 240 [IN]UDP::Init bind&listen port=5540
E: 244 [IN]SO_REUSEPORT failed: 109
D: 247 [IN]UDP::Init bound to port=5540
D: 250 [IN]BLEBase::Init - setting/overriding transport
D: 255 [IN]TransportMgr initialized
D: 261 [DL]Using Thread extended MAC for hostname.
I: 266 [ZCL]Using ZAP configuration...
I: 272 [DMG]AccessControlCluster: initializing
D: 276 [DL]Boot reason: 6
I: 279 [ZCL]Initiating Admin Commissioning cluster.
I: 283 [ZCL]Endpoint 1 On/off already set to new value
I: 289 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
D: 296 [IN]SecureSession[0x200041f0]: Allocated Type:1 LSID:9102
D: 301 [DL]CHIPoBLE advertising set to on
I: 305 [DIS]Updating services using commissioning mode 1
E: 310 [DIS]Failed to remove advertised services: 3
D: 315 [DL]Using Thread extended MAC for hostname.
I: 319 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 328 [DIS]Failed to advertise commissionable node: 3
E: 333 [DIS]Failed to finalize service update: 3
I: 337 [DIS]Updating services using commissioning mode 1
E: 342 [DIS]Failed to remove advertised services: 3
D: 347 [DL]Using Thread extended MAC for hostname.
I: 351 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 360 [DIS]Failed to advertise commissionable node: 3
E: 365 [DIS]Failed to finalize service update: 3
I: 369 [DIS]Delaying proxy of operational discovery: missing delegate
I: 375 [IN]CASE Server enabling CASE session setups
D: 380 [IN]SecureSession[0x200042a8]: Allocated Type:2 LSID:9103
I: 386 [SVR]Joining Multicast groups
I: 389 [SVR]Server Listening...
I: 392 [DL]Device Configuration:
I: 395 [DL]  Serial Number: 11223344556677889900
I: 399 [DL]  Vendor Id: 65521 (0xFFF1)
I: 403 [DL]  Product Id: 32773 (0x8005)
I: 406 [DL]  Product Name: not-specified
I: 410 [DL]  Hardware Version: 0
I: 413 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 418 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 425 [DL]  Manufacturing Date: 2022-01-01
I: 428 [DL]  Device Type: 65535 (0xFFFF)
I: 432 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 436 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 443 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 451 [SVR]Manual pairing code: [34970112332]
I: 456 [DL]CHIP task running
I: 462 [DL]CHIPoBLE advertising started
I: 466 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: 471 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 477 [DL]NFC Tag emulation started
I: 15894 [DL]BLE connection established (ConnId: 0x00)
I: 15899 [DL]Current number of connections: 1/1
I: 15903 [DL]CHIPoBLE advertising stopped
I: 15907 [DL]NFC Tag emulation stopped
D: 17357 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17364 [BLE]local and remote recv window sizes = 5
I: 17368 [BLE]selected BTP version 4
I: 17372 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 17447 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 17451 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 17459 [IN]BLE EndPoint 0x20012208 Connection Complete
I: 17464 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 17536 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17545 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17552 [EM]>>> [E:7513r S:0 M:186942528] (U) Msg RX from 0:38290223567E860A [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I: 17565 [EM]<<< [E:7513r S:0 M:104315748] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 17577 [IN](U) Sending msg 104315748 to IP address 'BLE'
D: 17582 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140)
D: 17671 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17680 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17687 [EM]>>> [E:7513r S:0 M:186942529] (U) Msg RX from 0:38290223567E860A [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I: 19036 [EM]<<< [E:7513r S:0 M:104315749] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 19048 [IN](U) Sending msg 104315749 to IP address 'BLE'
D: 19053 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132)
E: 19060 [DL]Long dispatch time: 1381 ms, for event type 16388
D: 19111 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19120 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 19127 [EM]>>> [E:7513r S:0 M:186942530] (U) Msg RX from 0:38290223567E860A [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I: 19139 [EM]<<< [E:7513r S:0 M:104315750] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 19150 [IN](U) Sending msg 104315750 to IP address 'BLE'
D: 19155 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 19164 [SC]SecureSession[0x200041f0]: Moving from state 'kEstablishing' --> 'kActive'
D: 19171 [IN]SecureSession[0x200041f0]: Activated - Type:1 LSID:9102
D: 19177 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:9102 PSID:53633!
I: 19186 [SVR]Commissioning completed session establishment step
I: 19192 [DIS]Updating services using commissioning mode 0
E: 19197 [DIS]Failed to remove advertised services: 3
E: 19202 [DIS]Failed to finalize service update: 3
D: 19207 [DL]CHIPoBLE advertising set to off
I: 19210 [SVR]Device completed Rendezvous process
D: 19247 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19255 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 19263 [EM]>>> [E:7514r S:9102 M:112946105] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 19273 [IM]Received Read request
I: 19283 [EM]<<< [E:7514r S:9102 M:75546762] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 19293 [IN](S) Sending msg 75546762 on secure session with LSID: 9102
D: 19299 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 19427 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19434 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 21)
D: 19517 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19525 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 19533 [EM]>>> [E:7515r S:9102 M:112946106] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 19543 [IM]Received Read request
I: 19550 [EM]<<< [E:7515r S:9102 M:75546763] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 19561 [IN](S) Sending msg 75546763 on secure session with LSID: 9102
D: 19567 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 185)
D: 19652 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19660 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 19667 [EM]>>> [E:7516r S:9102 M:112946107] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 19679 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 19686 [EM]<<< [E:7516r S:9102 M:75546764] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 19697 [IN](S) Sending msg 75546764 on secure session with LSID: 9102
D: 19703 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 19787 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19795 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 19803 [EM]>>> [E:7517r S:9102 M:112946108] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 19816 [EM]<<< [E:7517r S:9102 M:75546765] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 19828 [IN](S) Sending msg 75546765 on secure session with LSID: 9102
D: 19834 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 19967 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20012 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 20020 [EM]>>> [E:7518r S:9102 M:112946109] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 20032 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 20041 [EM]<<< [E:7518r S:9102 M:75546766] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 20052 [IN](S) Sending msg 75546766 on secure session with LSID: 9102
D: 20058 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 20147 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20154 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 20237 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20244 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48)
D: 20327 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20335 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 20343 [EM]>>> [E:7519r S:9102 M:112946110] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 20354 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 20364 [EM]<<< [E:7519r S:9102 M:75546767] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 20375 [IN](S) Sending msg 75546767 on secure session with LSID: 9102
D: 20381 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 20462 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20469 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 20552 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20559 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 77)
D: 20642 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20650 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 20658 [EM]>>> [E:7520r S:9102 M:112946111] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 20669 [ZCL]OpCreds: Received an AttestationRequest command
I: 20704 [ZCL]OpCreds: AttestationRequest successful.
I: 20713 [EM]<<< [E:7520r S:9102 M:75546768] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 20724 [IN](S) Sending msg 75546768 on secure session with LSID: 9102
D: 20731 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 20822 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20829 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 20912 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20919 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 237)
D: 21002 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21047 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 21055 [EM]>>> [E:7521r S:9102 M:112946112] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 21067 [ZCL]OpCreds: Received a CSRRequest command
I: 21212 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 21246 [ZCL]OpCreds: CSRRequest successful.
I: 21253 [EM]<<< [E:7521r S:9102 M:75546769] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 21264 [IN](S) Sending msg 75546769 on secure session with LSID: 9102
D: 21270 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
E: 21278 [DL]Long dispatch time: 231 ms, for event type 16388
D: 21362 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21369 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 138)
D: 21452 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21460 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 21542 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 21551 [EM]>>> [E:7522r S:9102 M:112946113] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 21563 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 21622 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 21628 [EM]<<< [E:7522r S:9102 M:75546770] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 21640 [IN](S) Sending msg 75546770 on secure session with LSID: 9102
D: 21646 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68)
E: 21654 [DL]Long dispatch time: 111 ms, for event type 16388
D: 21812 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21820 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 21904 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 21993 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 22003 [EM]>>> [E:7523r S:9102 M:112946114] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 22015 [ZCL]OpCreds: Received an AddNOC command
I: 22021 [FP]Validating NOC chain
I: 22130 [FP]NOC chain validation successful
I: 22134 [FP]Added new fabric at index: 0x1
I: 22138 [FP]Assigned compressed fabric ID: 0x33E88E3B87C86DF1, node ID: 0x0000000000000002
I: 22146 [TS]Last Known Good Time: 2024-10-25T11:19:57
I: 22151 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
I: 22157 [TS]Retaining current Last Known Good Time
I: 22170 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
D: 22178 [DL]Using Thread extended MAC for hostname.
I: 22183 [DIS]Advertise operational node 33E88E3B87C86DF1-0000000000000002
I: 22190 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 22197 [EM]<<< [E:7523r S:9102 M:75546771] (S) Msg TX to 1:FFFFFFFB00000000 [6DF1] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 22208 [IN](S) Sending msg 75546771 on secure session with LSID: 9102
D: 22214 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
E: 22222 [DL]Long dispatch time: 230 ms, for event type 16388
D: 22307 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 22315 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 22323 [EM]>>> [E:7524r S:9102 M:112946115] (S) Msg RX from 1:FFFFFFFB00000000 [6DF1] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 22337 [EM]<<< [E:7524r S:9102 M:75546772] (S) Msg TX to 1:FFFFFFFB00000000 [6DF1] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 22348 [IN](S) Sending msg 75546772 on secure session with LSID: 9102
D: 22355 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 22442 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 22450 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 22458 [EM]>>> [E:7525r S:9102 M:112946116] (S) Msg RX from 1:FFFFFFFB00000000 [6DF1] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 22469 [FS]GeneralCommissioning: Received ArmFailSafe (65s)
I: 22476 [EM]<<< [E:7525r S:9102 M:75546773] (S) Msg TX to 1:FFFFFFFB00000000 [6DF1] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 22487 [IN](S) Sending msg 75546773 on secure session with LSID: 9102
D: 22493 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 22622 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 22630 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 22638 [EM]>>> [E:7526r S:9102 M:112946117] (S) Msg RX from 1:FFFFFFFB00000000 [6DF1] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 22659 [DL]OpenThread State Changed (Flags: 0x101fc100)
D: 22664 [DL]   Network Name: TestNet
D: 22668 [DL]   PAN Id: 0x976E
D: 22671 [DL]   Extended PAN Id: 0xF581065E27EB4A59
D: 22675 [DL]   Channel: 11
D: 22678 [DL]   Mesh Prefix: fd00:c0ce:7ac8:4a81::/64
D: 22683 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 22688 [DL]   Device Role: DETACHED
D: 22691 [DL]   Thread Unicast Addresses:
D: 22695 [DL]        fd00:c0ce:7ac8:4a81:43e3:1ee4:7ab8:f51f/64 valid
D: 22701 [DL]        fe80::3856:f144:bcc3:6af7/64 valid preferred
D: 23547 [DL]OpenThread State Changed (Flags: 0x200012a4)
D: 23552 [DL]   Device Role: CHILD
D: 23555 [DL]   Partition Id: 0xBD3375C
D: 23559 [DL]OpenThread State Changed (Flags: 0x00000001)
D: 23565 [DL]   Thread Unicast Addresses:
D: 23568 [DL]        fd08:b89:78:f372:e6b7:a3aa:434e:8787/64 valid preferred
D: 23575 [DL]        fd00:c0ce:7ac8:4a81:0:ff:fe00:5001/64 valid rloc
D: 23581 [DL]        fd00:c0ce:7ac8:4a81:43e3:1ee4:7ab8:f51f/64 valid
D: 23587 [DL]        fe80::3856:f144:bcc3:6af7/64 valid preferred
I: 23595 [EM]<<< [E:7526r S:9102 M:75546774] (S) Msg TX to 1:FFFFFFFB00000000 [6DF1] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 23606 [IN](S) Sending msg 75546774 on secure session with LSID: 9102
D: 23612 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 70)
D: 23620 [DL]Using Thread extended MAC for hostname.
I: 23625 [DIS]Advertise operational node 33E88E3B87C86DF1-0000000000000002
I: 23631 [SVR]Operational advertising enabled
D: 23747 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 26222 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 28729 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 28787 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 29653 [DL]OpenThread State Changed (Flags: 0x00000200)
D: 31262 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 33769 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 33827 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 35533 [DL]SRP Client was started, detected server: fd00:c0ce:7ac8:4a81:ca34:3c9c:4f64:2a2b
D: 35541 [DL]OpenThread State Changed (Flags: 0x00000200)
D: 36227 [DL]SRP update succeeded
I: 36230 [DIS]Setting operational delegate post init
I: 36238 [SWU]Stopping the watchdog timer
I: 36241 [SWU]Starting the periodic query timer, timeout: 86400 seconds
E: 36248 [SVR]Server initialization complete
I: 36252 [DIS]Updating services using commissioning mode 0
D: 36257 [DL]Using Thread extended MAC for hostname.
I: 36261 [DIS]Advertise operational node 33E88E3B87C86DF1-0000000000000002
I: 36268 [DL]advertising srp service: 33E88E3B87C86DF1-0000000000000002._matter._tcp
D: 36302 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 37537 [DL]SRP update succeeded
I: 37818 [EM]>>> [E:7527r S:0 M:186942531] (U) Msg RX from 0:91BDC9466F783843 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 37830 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20005bb0
I: 37837 [IN]CASE Server disabling CASE session setups
I: 37842 [EM]<<< [E:7527r S:0 M:104315751 (Ack:186942531)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 37855 [IN](U) Sending msg 104315751 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:37745'
I: 37865 [SC]Received Sigma1 msg
I: 37871 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000002
I: 38046 [EM]<<< [E:7527r S:0 M:104315752 (Ack:186942531)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 38059 [IN](U) Sending msg 104315752 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:37745'
I: 38070 [SC]Sent Sigma2 msg
I: 38266 [EM]>>> [E:7527r S:0 M:186942532 (Ack:104315752)] (U) Msg RX from 0:91BDC9466F783843 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 38279 [EM]<<< [E:7527r S:0 M:104315753 (Ack:186942532)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 38292 [IN](U) Sending msg 104315753 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:37745'
I: 38302 [SC]Received Sigma3 msg
E: 38310 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 38480 [DL]Long dispatch time: 158 ms, for event type 2
I: 38490 [EM]<<< [E:7527r S:0 M:104315754 (Ack:186942532)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 38503 [IN](U) Sending msg 104315754 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:37745'
I: 38514 [SC]SecureSession[0x200042a8]: Moving from state 'kEstablishing' --> 'kActive'
D: 38522 [IN]SecureSession[0x200042a8]: Activated - Type:2 LSID:9103
D: 38529 [IN]New secure session activated for device <000000000001B669, 1>, LSID:9103 PSID:53634!
I: 38540 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 38549 [IN]CASE Server enabling CASE session setups
D: 38554 [IN]SecureSession[0x20004360]: Allocated Type:2 LSID:9104
I: 38561 [EM]>>> [E:7528r S:9103 M:201472173] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 38573 [FS]GeneralCommissioning: Received CommissioningComplete
I: 38581 [FP]Metadata for Fabric 0x1 persisted to storage.
I: 38599 [TS]Committing Last Known Good Time to storage: 2024-10-25T11:19:57
I: 38607 [ZCL]OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x33E88E3B87C86DF1, FabricId 0000000000000001, NodeId 0000000000000002, VendorId 0xFFF1
I: 38623 [FS]GeneralCommissioning: Successfully commited pending fabric data
I: 38629 [FS]Fail-safe cleanly disarmed
I: 38634 [EM]<<< [E:7528r S:9103 M:144370371 (Ack:201472173)] (S) Msg TX to 1:000000000001B669 [6DF1] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 38647 [IN](S) Sending msg 144370371 on secure session with LSID: 9103
I: 38655 [SWU]Device commissioned, schedule a default provider query
I: 38661 [SVR]Commissioning completed successfully
I: 38666 [DIS]Updating services using commissioning mode 0
D: 38672 [DL]Using Thread extended MAC for hostname.
I: 38677 [DIS]Advertise operational node 33E88E3B87C86DF1-0000000000000002
D: 38685 [IN]Expiring all PASE sessions
D: 38689 [IN]SecureSession[0x200041f0]: MarkForEviction Type:1 LSID:9102
I: 38696 [SC]SecureSession[0x200041f0]: Moving from state 'kActive' --> 'kPendingEviction'
D: 38705 [IN]SecureSession[0x200041f0]: Released - Type:1 LSID:9102
D: 38711 [IN]Clearing BLE pending packets.
I: 38714 [BLE]Releasing end point's BLE connection back to application.
I: 38721 [DL]Closing BLE GATT connection (ConnId 00)
I: 38727 [EM]>>> [E:7527r S:0 M:186942533 (Ack:104315754)] (U) Msg RX from 0:91BDC9466F783843 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
E: not connected!
D: 38742 [DL]ConnId: 0x00, New CCCD value: 0x0000
E: 38746 [BLE]no endpoint for unsub recvd
I: 38777 [DL]BLE GAP connection terminated (reason 0x16)
I: 38782 [DL]Current number of connections: 0/1
I: 38969 [EM]>>> [E:7528r S:9103 M:201472174 (Ack:144370371)] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 44744 [EM]>>> [E:24806r S:0 M:96832576] (U) Msg RX from 0:874CD040C22C4025 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 44756 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20005bb0
I: 44763 [IN]CASE Server disabling CASE session setups
I: 44768 [EM]<<< [E:24806r S:0 M:104315755 (Ack:96832576)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 44781 [IN](U) Sending msg 104315755 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:45405'
I: 44791 [SC]Received Sigma1 msg
I: 44798 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000002
I: 44977 [EM]<<< [E:24806r S:0 M:104315756 (Ack:96832576)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 44990 [IN](U) Sending msg 104315756 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:45405'
I: 45001 [SC]Sent Sigma2 msg
I: 45553 [EM]>>> [E:24806r S:0 M:96832577 (Ack:104315756)] (U) Msg RX from 0:874CD040C22C4025 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 45566 [EM]<<< [E:24806r S:0 M:104315757 (Ack:96832577)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 45579 [IN](U) Sending msg 104315757 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:45405'
I: 45588 [SC]Received Sigma3 msg
E: 45598 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 45766 [DL]Long dispatch time: 158 ms, for event type 2
I: 45776 [EM]<<< [E:24806r S:0 M:104315758 (Ack:96832577)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 45788 [IN](U) Sending msg 104315758 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:45405'
I: 45800 [SC]SecureSession[0x20004360]: Moving from state 'kEstablishing' --> 'kActive'
D: 45808 [IN]SecureSession[0x20004360]: Activated - Type:2 LSID:9104
D: 45815 [IN]New secure session activated for device <000000000001B669, 1>, LSID:9104 PSID:17040!
I: 45823 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 45831 [IN]CASE Server enabling CASE session setups
D: 45839 [IN]SecureSession[0x200041f0]: Allocated Type:2 LSID:9105
I: 45849 [EM]>>> [E:24807r S:9104 M:144708553] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 45874 [EM]<<< [E:24807r S:9104 M:22522419 (Ack:144708553)] (S) Msg TX to 1:000000000001B669 [6DF1] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 45887 [IN](S) Sending msg 22522419 on secure session with LSID: 9104
I: 45895 [EM]>>> [E:24806r S:0 M:96832578 (Ack:104315758)] (U) Msg RX from 0:874CD040C22C4025 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 45912 [EM]>>> [E:24807r S:9104 M:144708554 (Ack:22522419)] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 47882 [EM]>>> [E:43737r S:0 M:131468757] (U) Msg RX from 0:D45EA1C0ED911ADA [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 47894 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20005bb0
I: 47901 [IN]CASE Server disabling CASE session setups
I: 47906 [EM]<<< [E:43737r S:0 M:104315759 (Ack:131468757)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 47919 [IN](U) Sending msg 104315759 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:40931'
I: 47929 [SC]Received Sigma1 msg
I: 47939 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000002
I: 48113 [EM]<<< [E:43737r S:0 M:104315760 (Ack:131468757)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 48126 [IN](U) Sending msg 104315760 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:40931'
I: 48137 [SC]Sent Sigma2 msg
I: 48320 [EM]>>> [E:43737r S:0 M:131468758 (Ack:104315760)] (U) Msg RX from 0:D45EA1C0ED911ADA [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 48333 [EM]<<< [E:43737r S:0 M:104315761 (Ack:131468758)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 48346 [IN](U) Sending msg 104315761 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:40931'
I: 48356 [SC]Received Sigma3 msg
E: 48365 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 48534 [DL]Long dispatch time: 159 ms, for event type 2
I: 48543 [EM]<<< [E:43737r S:0 M:104315762 (Ack:131468758)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 48556 [IN](U) Sending msg 104315762 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:40931'
I: 48568 [SC]SecureSession[0x200041f0]: Moving from state 'kEstablishing' --> 'kActive'
D: 48576 [IN]SecureSession[0x200041f0]: Activated - Type:2 LSID:9105
D: 48583 [IN]New secure session activated for device <000000000001B669, 1>, LSID:9105 PSID:21875!
I: 48593 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 48600 [IN]CASE Server enabling CASE session setups
D: 48609 [IN]SecureSession[0x20004418]: Allocated Type:2 LSID:9106
I: 48617 [EM]>>> [E:43738r S:9105 M:18085730] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0001:06 (IM:WriteRequest)
D: 48628 [IM]Received Write request
I: 48651 [EM]<<< [E:43738r S:9105 M:94780723 (Ack:18085730)] (S) Msg TX to 1:000000000001B669 [6DF1] --- Type 0001:07 (IM:WriteResponse)
I: 48662 [IN](S) Sending msg 94780723 on secure session with LSID: 9105
I: 48671 [EM]>>> [E:43737r S:0 M:131468759 (Ack:104315762)] (U) Msg RX from 0:D45EA1C0ED911ADA [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 48717 [EM]>>> [E:43738r S:9105 M:18085731 (Ack:94780723)] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 49183 [EM]>>> [E:13694r S:0 M:10934429] (U) Msg RX from 0:ADE94DC61A2855C1 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 49195 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20005bb0
I: 49202 [IN]CASE Server disabling CASE session setups
I: 49207 [EM]<<< [E:13694r S:0 M:104315763 (Ack:10934429)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 49220 [IN](U) Sending msg 104315763 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:41559'
I: 49230 [SC]Received Sigma1 msg
I: 49241 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000002
I: 49416 [EM]<<< [E:13694r S:0 M:104315764 (Ack:10934429)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 49428 [IN](U) Sending msg 104315764 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:41559'
I: 49439 [SC]Sent Sigma2 msg
I: 50348 [IN](U) Sending msg 104315764 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:41559'
I: 50546 [EM]>>> [E:13694r S:0 M:10934430 (Ack:104315764)] (U) Msg RX from 0:ADE94DC61A2855C1 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 50559 [EM]<<< [E:13694r S:0 M:104315765 (Ack:10934430)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 50572 [IN](U) Sending msg 104315765 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:41559'
I: 50581 [SC]Received Sigma3 msg
E: 50590 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 50759 [DL]Long dispatch time: 159 ms, for event type 2
I: 50769 [EM]<<< [E:13694r S:0 M:104315766 (Ack:10934430)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 50782 [IN](U) Sending msg 104315766 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:41559'
I: 50793 [SC]SecureSession[0x20004418]: Moving from state 'kEstablishing' --> 'kActive'
D: 50802 [IN]SecureSession[0x20004418]: Activated - Type:2 LSID:9106
D: 50808 [IN]New secure session activated for device <000000000001B669, 1>, LSID:9106 PSID:43125!
I: 50817 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 50825 [IN]CASE Server enabling CASE session setups
D: 50833 [IN]SecureSession[0x200044d0]: Allocated Type:2 LSID:9107
I: 50843 [EM]>>> [E:13695r S:9106 M:144439525] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0001:06 (IM:WriteRequest)
D: 50854 [IM]Received Write request
I: 50866 [EM]<<< [E:13695r S:9106 M:168675876 (Ack:144439525)] (S) Msg TX to 1:000000000001B669 [6DF1] --- Type 0001:07 (IM:WriteResponse)
I: 50878 [IN](S) Sending msg 168675876 on secure session with LSID: 9106
I: 50887 [EM]>>> [E:13694r S:0 M:10934431 (Ack:104315766)] (U) Msg RX from 0:ADE94DC61A2855C1 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 50920 [EM]>>> [E:13695r S:9106 M:144439526 (Ack:168675876)] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 51457 [EM]>>> [E:35018r S:0 M:25195827] (U) Msg RX from 0:E94EDC7C067D0417 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 51468 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20005bb0
I: 51475 [IN]CASE Server disabling CASE session setups
I: 51481 [EM]<<< [E:35018r S:0 M:104315767 (Ack:25195827)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 51493 [IN](U) Sending msg 104315767 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:50328'
I: 51503 [SC]Received Sigma1 msg
I: 51514 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000002
I: 51689 [EM]<<< [E:35018r S:0 M:104315768 (Ack:25195827)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 51702 [IN](U) Sending msg 104315768 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:50328'
I: 51713 [SC]Sent Sigma2 msg
I: 51858 [EM]>>> [E:35018r S:0 M:25195828 (Ack:104315768)] (U) Msg RX from 0:E94EDC7C067D0417 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 51871 [EM]<<< [E:35018r S:0 M:104315769 (Ack:25195828)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 51884 [IN](U) Sending msg 104315769 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:50328'
I: 51894 [SC]Received Sigma3 msg
E: 51903 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 52071 [DL]Long dispatch time: 158 ms, for event type 2
I: 52081 [EM]<<< [E:35018r S:0 M:104315770 (Ack:25195828)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 52094 [IN](U) Sending msg 104315770 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:50328'
I: 52106 [SC]SecureSession[0x200044d0]: Moving from state 'kEstablishing' --> 'kActive'
D: 52114 [IN]SecureSession[0x200044d0]: Activated - Type:2 LSID:9107
D: 52120 [IN]New secure session activated for device <000000000001B669, 1>, LSID:9107 PSID:45636!
I: 52129 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 52136 [IN]CASE Server enabling CASE session setups
D: 52145 [IN]SecureSession[0x20004588]: Allocated Type:2 LSID:9108
I: 52152 [EM]>>> [E:35019r S:9107 M:131641130] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 52260 [IN]Joining Multicast Group with address UDP:[ff35:40:fd00::100:3]:5540
I: 52273 [EM]<<< [E:35019r S:9107 M:61795445 (Ack:131641130)] (S) Msg TX to 1:000000000001B669 [6DF1] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 52287 [IN](S) Sending msg 61795445 on secure session with LSID: 9107
D: 52296 [DL]OpenThread State Changed (Flags: 0x00001000)
I: 52305 [EM]>>> [E:35018r S:0 M:25195829 (Ack:104315770)] (U) Msg RX from 0:E94EDC7C067D0417 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 52322 [EM]>>> [E:35019r S:9107 M:131641131 (Ack:61795445)] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 52801 [EM]>>> [E:31924r S:0 M:90630522] (U) Msg RX from 0:B13ABCE9099778FA [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 52813 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20005bb0
I: 52820 [IN]CASE Server disabling CASE session setups
I: 52825 [EM]<<< [E:31924r S:0 M:104315771 (Ack:90630522)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 52838 [IN](U) Sending msg 104315771 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:43307'
I: 52848 [SC]Received Sigma1 msg
I: 52859 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000002
I: 53036 [EM]<<< [E:31924r S:0 M:104315772 (Ack:90630522)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 53048 [IN](U) Sending msg 104315772 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:43307'
I: 53059 [SC]Sent Sigma2 msg
I: 53198 [EM]>>> [E:31924r S:0 M:90630523 (Ack:104315772)] (U) Msg RX from 0:B13ABCE9099778FA [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 53212 [EM]<<< [E:31924r S:0 M:104315773 (Ack:90630523)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 53224 [IN](U) Sending msg 104315773 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:43307'
I: 53234 [SC]Received Sigma3 msg
E: 53242 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 53412 [DL]Long dispatch time: 159 ms, for event type 2
I: 53422 [EM]<<< [E:31924r S:0 M:104315774 (Ack:90630523)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 53435 [IN](U) Sending msg 104315774 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:43307'
I: 53447 [SC]SecureSession[0x20004588]: Moving from state 'kEstablishing' --> 'kActive'
D: 53455 [IN]SecureSession[0x20004588]: Activated - Type:2 LSID:9108
D: 53461 [IN]New secure session activated for device <000000000001B669, 1>, LSID:9108 PSID:42909!
I: 53470 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 53479 [IN]CASE Server enabling CASE session setups
D: 53487 [IN]SecureSession[0x20004640]: Allocated Type:2 LSID:9109
I: 53494 [EM]>>> [E:31925r S:9108 M:159503087] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 53516 [IN]Joining Multicast Group with address UDP:[ff35:40:fd00::100:4]:5540
I: 53530 [EM]<<< [E:31925r S:9108 M:251420196 (Ack:159503087)] (S) Msg TX to 1:000000000001B669 [6DF1] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 53545 [IN](S) Sending msg 251420196 on secure session with LSID: 9108
D: 53553 [DL]OpenThread State Changed (Flags: 0x00001000)
I: 53562 [EM]>>> [E:31924r S:0 M:90630524 (Ack:104315774)] (U) Msg RX from 0:B13ABCE9099778FA [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 53579 [EM]>>> [E:31925r S:9108 M:159503088 (Ack:251420196)] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 54055 [EM]>>> [E:292r S:0 M:197602012] (U) Msg RX from 0:6CB14E2CCDE22560 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
I: 54066 [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20005bb0
I: 54074 [IN]CASE Server disabling CASE session setups
I: 54079 [EM]<<< [E:292r S:0 M:104315775 (Ack:197602012)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 54091 [IN](U) Sending msg 104315775 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:55917'
I: 54101 [SC]Received Sigma1 msg
I: 54113 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x0000000000000002
I: 54301 [EM]<<< [E:292r S:0 M:104315776 (Ack:197602012)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 54313 [IN](U) Sending msg 104315776 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:55917'
I: 54324 [SC]Sent Sigma2 msg
D: 54327 [DL]OpenThread State Changed (Flags: 0x00000064)
D: 54332 [DL]   Device Role: ROUTER
I: 54509 [EM]>>> [E:292r S:0 M:197602013 (Ack:104315776)] (U) Msg RX from 0:6CB14E2CCDE22560 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
I: 54522 [EM]<<< [E:292r S:0 M:104315777 (Ack:197602013)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 54534 [IN](U) Sending msg 104315777 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:55917'
I: 54544 [SC]Received Sigma3 msg
E: 54553 [SC]The device does not support GetClock_RealTimeMS() API: 3.  Falling back to Last Known Good UTC Time
E: 54722 [DL]Long dispatch time: 159 ms, for event type 2
I: 54733 [EM]<<< [E:292r S:0 M:104315778 (Ack:197602013)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 54745 [IN](U) Sending msg 104315778 to IP address 'UDP:[fd08:b89:78:f372:c9ac:a3c:a537:f497]:55917'
I: 54757 [SC]SecureSession[0x20004640]: Moving from state 'kEstablishing' --> 'kActive'
D: 54765 [IN]SecureSession[0x20004640]: Activated - Type:2 LSID:9109
D: 54772 [IN]New secure session activated for device <000000000001B669, 1>, LSID:9109 PSID:55899!
I: 54781 [IN]CASE Session established to peer: <000000000001B669, 1>
I: 54788 [IN]CASE Server enabling CASE session setups
D: 54796 [IN]SecureSession[0x200046f8]: Allocated Type:2 LSID:9110
I: 54806 [EM]>>> [E:293r S:9109 M:13683323] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 54829 [IN]Joining Multicast Group with address UDP:[ff35:40:fd00::100:5]:5540
E: 54836 [SVR]Unable to listen to group
I: 54844 [EM]<<< [E:293r S:9109 M:224548323 (Ack:13683323)] (S) Msg TX to 1:000000000001B669 [6DF1] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 54856 [IN](S) Sending msg 224548323 on secure session with LSID: 9109
I: 54865 [EM]>>> [E:292r S:0 M:197602014 (Ack:104315778)] (U) Msg RX from 0:6CB14E2CCDE22560 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 54902 [EM]>>> [E:293r S:9109 M:13683324 (Ack:224548323)] (S) Msg RX from 1:000000000001B669 [6DF1] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 55164 [EM]>>> [E:28831r S:3 M:220765547] (G) Msg RX from 1:000000000001B669 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 55179 [EM]Received Groupcast Message with GroupId 0x0003 (3)
I: 55187 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 55192 [ZCL]On Command - OffWaitTime :  0
I: 55196 [ZCL]On/Toggle Command - Stop Timer
I: 55202 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 55214 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 55231 [ZCL]Event: move from 1
I: 55234 [ZCL] to 254
I: 55236 [ZCL](diff +1)
I: 55238 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 57480 [EM]>>> [E:25461r S:3 M:220766547] (G) Msg RX from 1:000000000001B669 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 57491 [EM]Received Groupcast Message with GroupId 0x0003 (3)
I: 57500 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 57508 [ZCL]Event: move from 254
I: 57511 [ZCL] to 1
I: 57514 [ZCL](diff -1)
I: 57516 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 57531 [ZCL]Setting on/off to OFF due to level change
I: 57536 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 57541 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 57553 [ZCL]Off completed. reset OnTime to  0
I: 57557 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 59780 [EM]>>> [E:9389r S:4 M:220767547] (G) Msg RX from 1:000000000001B669 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 59792 [EM]Received Groupcast Message with GroupId 0x0004 (4)
I: 59801 [ZCL]Toggle ep1 on/off from state 0 to 1
I: 59806 [ZCL]On Command - OffWaitTime :  0
I: 59810 [ZCL]On/Toggle Command - Stop Timer
I: 59816 [ZCL]Cluster OnOff: attribute OnOff set to 1
I: Turn On Action has been initiated
I: Turn On Action has been completed
I: 59828 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: 59835 [ZCL]Event: move from 1
I: 59838 [ZCL] to 254
I: 59840 [ZCL](diff +1)
I: 59842 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: Level Action has been initiated
I: Setting brightness level to 254
I: Level Action has been completed
I: 61988 [EM]>>> [E:18369r S:4 M:220768547] (G) Msg RX from 1:000000000001B669 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 62001 [EM]Received Groupcast Message with GroupId 0x0004 (4)
I: 62011 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 62017 [ZCL]Event: move from 254
I: 62020 [ZCL] to 1
I: 62022 [ZCL](diff -1)
I: 62025 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
I: Level Action has been initiated
I: Setting brightness level to 1
I: Level Action has been completed
I: 62040 [ZCL]Setting on/off to OFF due to level change
I: 62045 [ZCL]Toggle ep1 on/off from state 1 to 0
I: 62050 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: Turn Off Action has been initiated
I: Turn Off Action has been completed
I: 62061 [ZCL]Off completed. reset OnTime to  0
I: 62065 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
E: 68661 [SWU]No suitable OTA Provider candidate found
I: 68666 [SWU]No provider available

Bash script for testing

The following script:

1. Wipes any existing fabric info and sets up a new fabric
2. Commissions the light_bulb
3. Creates three groups and adds the light_bulb to each one.
4. Toggles the LED using each of the three created groups.

The output of me running this script is found in the attached pi.log for the Pi's perspective, and light_bulb.log for the nRF5340's perspective.

1185.test_bench.sh

#!/bin/bash -x

# Thread network setup
## Create a clean slate
ot-ctl thread stop
ot-ctl ifconfig down
ot-ctl factoryreset
rm /var/lib/thread/*
rm /var/chip-tool/*

sleep 5

## Setup a new thread network
ot-ctl dataset init new
ot-ctl dataset channel 11
ot-ctl dataset panid 0x976e
ot-ctl dataset extpanid f581065e27eb4a59
ot-ctl dataset networkname TestNet
ot-ctl dataset networkkey d645efebea99fd80fc10addc20bcdd93
ot-ctl dataset pskc f254a33b452bf277b1329750f2922e3a
ot-ctl dataset commit active
ot-ctl prefix add fd08:b89:78:f372::/64 paos med
ot-ctl ifconfig up
ot-ctl thread start
ot-ctl dataset active -x

# Commissioning
## Save the active datset to be used in commissioning
DATASET=$(ot-ctl dataset active -x | head -n1 | tr -d '\r')

## Commission the light bulb
chip-tool pairing code-thread 2 hex:$DATASET MT:6FCJ142C00KA0648G00 --bypass-attestation-verifier true

sleep 5

# Configure 3 groups
chip-tool groupsettings add-keysets 0xaaaa 0 0x21dfe0 hex:281b29592d521ea8a8d57a4a7639511b
chip-tool groupkeymanagement key-set-write '{"groupKeySetID":42,"groupKeySecurityPolicy":0,"epochKey0":"281b29592d521ea8a8d57a4a7639511b","epochStartTime0":2220000,"epochKey1":"c7cb12d00355e03c942a0b7447d05c1b","epochStartTime1":2220001,"epochKey2":"ba5aaef06db2a60920fd54166e734018","epochStartTime2":2220002}' 2 0

chip-tool groupsettings add-group grp3 3
chip-tool groupsettings bind-keyset 3 43690

chip-tool groupsettings add-group grp4 4
chip-tool groupsettings bind-keyset 4 43690

chip-tool groupsettings add-group grp5 5
chip-tool groupsettings bind-keyset 5 43690

chip-tool groupkeymanagement write group-key-map '[{"groupId":3,"groupKeySetID":42},{"groupId":4,"groupKeySetID":42},{"groupId":5,"groupKeySetID":42}]' 2 0
chip-tool accesscontrol write acl '[{"fabricIndex":1,"privilege":5,"authMode":2,"subjects":[112233],"targets":null},{"fabricIndex":1,"privilege":3,"authMode":3,"subjects":[3,4,5],"targets":[{"cluster":null,"endpoint":1,"deviceType":null},{"cluster":null,"endpoint":1,"deviceType":null},{"cluster":null,"endpoint":1,"deviceType":null}]}]' 2 0

chip-tool groups add-group 3 grp3 2 1 # Success
chip-tool groups add-group 4 grp4 2 1 # Success
chip-tool groups add-group 5 grp5 2 1 # Fail: "Unable to listen to group" on edge device, even though it appears successful from chip-tool's perspective

# Control the light bulb using each group
## First group works
chip-tool onoff on 0xFFFFFFFFFFFF0003 0
sleep 2
chip-tool onoff off 0xFFFFFFFFFFFF0003 0
sleep 2

## Second group works
chip-tool onoff on 0xFFFFFFFFFFFF0004 0
sleep 2
chip-tool onoff off 0xFFFFFFFFFFFF0004 0
sleep 2

## Third group fails, no traffic comes through on the light bulb
chip-tool onoff on 0xFFFFFFFFFFFF0005 0
sleep 2
chip-tool onoff off 0xFFFFFFFFFFFF0005 0

Attempts to fix the issue

I made the following changes to the light_bulb, which seems to have no affect. Just for kicks I tried setting CONFIG_OPENTHREAD_IP6_MAX_EXT_MCAST_ADDRS to 1, but I was still able to add 2 groups. I do a pristine build between attempts.

# prj.conf
CONFIG_OPENTHREAD_IP6_MAX_EXT_MCAST_ADDRS=10
CONFIG_NET_IF_MCAST_IPV6_ADDR_COUNT=10

// src/chip_project_config.h
#define CHIP_CONFIG_MAX_GROUP_CONCURRENT_ITERATORS 10

Note that there is also a MaxGroupsPerFabric field in src/light_bulb.zap that may be relevant, but I was unable to make it have any affect. Maybe I need some guidance here.

Efforts to isolate the issue

I tried commissioning a second light_bulb running on another nRF5340-dk and was able to add it to two groups, but the third gives Unable to listen to group just like the before.

I tried running connectedhomeip/examples/lighting-app for Linux on the Pi to test a non-Nordic device and interestingly I was able to add three groups, and receive the group cast messages for those three groups (one more than the light_bulb), but then adding a fourth group gave a new failure: CHIP:EVL: Dropped 1 event from buffer with priority 1 and event number 0x0000000000000002 due to overflow: event priority_level: 1 . So this leads me to believe the group limit of 2 is not an issue with the Pi’s setup, but rather the light_bulb .

I made a small patch to the SDK to print the error resulting in Unable to listen to group and it was 4000003 which I can’t seem to find where this is defined.

diff --git a/src/app/server/Server.h b/src/app/server/Server.h
index eee11b0bc6..82731cc2e4 100644
--- a/src/app/server/Server.h
+++ b/src/app/server/Server.h
@@ -385,10 +385,11 @@ private:
                 return;
             }
 
-            if (mServer->GetTransportManager().MulticastGroupJoinLeave(
-                    Transport::PeerAddress::Multicast(fabric->GetFabricId(), new_group.group_id), true) != CHIP_NO_ERROR)
+            CHIP_ERROR ret = mServer->GetTransportManager().MulticastGroupJoinLeave(
+                    Transport::PeerAddress::Multicast(fabric->GetFabricId(), new_group.group_id), true);
+            if (ret != CHIP_NO_ERROR)
             {
-                ChipLogError(AppServer, "Unable to listen to group");
+                ChipLogError(AppServer, "Unable to listen to group. Err = %" CHIP_ERROR_FORMAT, ret.Format());
             }
         };

I found this potentially related issue in the connectedhomeip GitHub.

[AHaug]

Hi,

Could you attach the generated .config file? Or look for CONFIG_NET_IF_MCAST_IPV6_ADDR_COUNT and see what this is set to by default? Could you try increasing this parameter and see if the behavior persists?

Kind regards,
Andreas

[Josh_Johnston]

Hi Andreas,

Thanks for the reply. I had increased both CONFIG_NET_IF_MCAST_IPV6_ADDR_COUNT and CONFIG_OPENTHREAD_IP6_MAX_EXT_MCAST_ADDRS to 10 and saw no effect. See the attached .conf. Let me know if you see anything that is misconfigured.

Regards,

Josh

3386..config.txt

[AHaug]

Thank you for verifying, I'll have a second look

If possible while waiting for me to have a closer look, do you see the same behaviour in NCS 2.7.0 and/or 2.8.0-rc1? Quite a few features have been improved in both Matter and Wifi since 2.5.x

Kind regards,
Andreas

[Josh_Johnston]

Thanks. I have tested using NCS 2.7.0 and saw the same behavior.

[Josh_Johnston]

One of my colleagues figured it out. By default NCS uses a pre-compiled OpenThread lib. One must set CONFIG_OPENTHREAD_SOURCES=y in order for any OpenThread KCONFIGS to take effect.

# prj.conf
CONFIG_OPENTHREAD_SOURCES=y
CONFIG_NET_IF_MCAST_IPV6_ADDR_COUNT=14
CONFIG_OPENTHREAD_IP6_MAX_EXT_MCAST_ADDRS=14
CONFIG_OPENTHREAD_IP6_MAX_EXT_UCAST_ADDRS=14

// src/chip_project_config.h

#define CHIP_CONFIG_MAX_GROUP_ENDPOINTS_PER_FABRIC (4)

[Josh_Johnston]

As some feedback, it would have been super valuable to have a KCONFIG warning/error when trying to set CONFIG_OPENTHREAD_IP6_MAX_EXT_MCAST_ADDRS without having CONFIG_OPENTHREAD_SOURCES set.