Matter Commissioning Failure After NCS v3.1.0 Update

[Patrick]

Hi,

I am having an issue with matter device commissioning after updating from NCS v3.0.2 to v3.1.0. Prior to the update, the device was able to join a matter network running under Home Assistant and SmartThings. After updating from NCS v3.0.2 to v3.1.0, device commissioning into a Matter network running on Home Assistant fails consistently (have not yet tested SmartThings). The commissioning process begins normally, but the device ultimately fails to join the network. 

Based on a quick look through the commissioning logs, the significant divergence occurs at:

• NCS v3.0.2: Line 273 - device continues normal communication with Matter server
• NCS v3.1.0: Line 280 - device appears to stop communicating with server

The v3.0.2 log shows continued server communication and ultimately successful network joining, while the v3.1.0 log shows the process hanging with no clear error.

Logs:

NCS v3.0.2 (Working) Commissioning Log
4812.matter commissioning - ncs 302.txt

NCS v3.1.0 (Failing) Commissioning Log

Fullscreen 5078.matter commissioning - ncs 310.txt Download

00> *** Booting nRF Connect SDK v3.1.0-6c6e5b32496e ***
00> *** Using Zephyr OS v4.1.99-1612683d4010 ***
00> I: 16 [DL]BLE address: CE:47:7F:36:97:2D
00> I: Initializing all sensor services.
00> I: 20 [DL]CHIP task running
00> I: Init CHIP stack
00> I: 20 [DL]OpenThread started: OK
00> I: 21 [DL]Setting OpenThread device type to SLEEPY END DEVICE
00> I: 23 [DL]Found DAC Private Key in factory data set. Copying to secure storage...
00> I: 27 [DL]The device does not support hardware protection against write.
00> D: Registered new test event: 0xffffffff00000000
00> D: Registered new test event: 0xffffffff10000000
00> I: Successfully registered ICDManager as test event trigger handler
00> I: 28 [SVR]Initializing subscription resumption storage...
00> I: 29 [SVR]Server initializing...
00> I: 29 [TS]Last Known Good Time: [unknown]
00> I: 29 [TS]Setting Last Known Good Time to firmware build time 2023-10-14T01:16:48
00> I: 31 [DMG]AccessControl: initializing
00> I: 31 [DMG]Examples::AccessControlDelegate::Init
00> I: 31 [DMG]AccessControl: setting
00> I: 31 [DMG]DefaultAclStorage: initializing
00> I: I: 23476 [DL]Current number of connections: 1/1
00> I: 23476 [DL]BLE connection established (ConnId: 0x00)
00> I: 23476 [DL]CHIPoBLE advertising stopped
00> D: 24298 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 24298 [BLE]local and remote recv window sizes = 5
00> I: 24299 [BLE]selected BTP version 4
00> I: 24299 [BLE]using BTP fragment sizes rx 182 / tx 182.
00> D: 24418 [DL]ConnId: 0x00, New CCCD value: 0x0002
00> D: 24418 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
00> D: 24419 [IN]BLE EndPoint 0x2000b9a0 Connection Complete
00> I: 24419 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 185)
00> D: 24478 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 24481 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 24482 [EM]>>> [E:4864r S:0 M:75511551] (U) Msg RX from 0:18B5C5E5EEBC0E08 [0000] to 0000000000000000 --- Type 0000:20 (SecureChannel:PBKDFParamRequest) (B:98)
00> I: 24483 [EM]<<< [E:4864r S:0 M:165987213] (U) Msg TX from 0000000000000000 to 0:18B5C5E5EEBC0E08 [0000] [BLE] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) (B:153)
00> D: 24483 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 158)
00> I: 24484 [SVR]Commissioning session establishment step started
00> D: 24598 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 24601 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 24601 [EM]>>> [E:4864r S:0 M:75511552] (U) Msg RX from 0:18B5C5E5EEBC0E08 [0000] to 0000000000000000 --- Type 0000:22 (SecureChannel:PASE_Pake1) (B:92)
00> I: 24608 [EM]<<< [E:4864r S:0 M:165987214] (U) Msg TX from 0000000000000000 to 0:18B5C5E5EEBC0E08 [0000] [BLE] --- Type 0000:23 (SecureChannel:PASE_Pake2) (B:127)
00> D: 24609 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132)
00> D: 24658 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 24660 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 24660 [EM]>>> [E:4864r S:0 M:75511553] (U) Msg RX from 0:18B5C5E5EEBC0E08 [0000] to 0000000000000000 --- Type 0000:24 (SecureChannel:PASE_Pake3) (B:59)
00> I: 24661 [EM]<<< [E:4864r S:0 M:165987215] (U) Msg TX from 0000000000000000 to 0:18B5C5E5EEBC0E08 [0000] [BLE] --- Type 0000:40 (SecureChannel:StatusReport) (B:30)
00> D: 24662 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
00> I: 24663 [SC]SecureSession[0x2000c070, LSID:62051]: State change 'kEstablishing' --> 'kActive'
00> D: 24663 [IN]SecureSession[0x2000c070]: Activated - Type:1 LSID:62051
00> D: 24663 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:62051 PSID:52577!
00> I: 24664 [SVR]Commissioning completed session establishment step
00> I: 24664 [DIS]Updating services using commissioning mode 0
00> E: 24664 [DIS]Failed to remove advertised services: 3
00> E: 24664 [DIS]Failed to finalize service update: 3
00> D: 24664 [DL]CHIPoBLE advertising set to off
00> I: 24664 [SVR]Device completed Rendezvous process
00> D: 24718 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 24720 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 24721 [EM]>>> [E:4865r S:62051 M:266886722] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
00> D: 24721 [IM]Received Read request
00> I: 24723 [EM]<<< [E:4865r S:62051 M:89986249] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:68)
00> D: 24723 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 73)
00> D: 24838 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 24840 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 24841 [EM]>>> [E:4866r S:62051 M:266886723] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
00> D: 24841 [IM]Received Read request
00> I: 24843 [EM]<<< [E:4866r S:62051 M:89986250] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:90)
00> D: 24843 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 95)
00> D: 24958 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 24960 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 24961 [EM]>>> [E:4867r S:62051 M:266886724] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:52)
00> D: 24961 [IM]Received Read request
00> I: 24963 [EM]<<< [E:4867r S:62051 M:89986251] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:67)
00> D: 24963 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
00> D: 25078 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 25080 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 25081 [EM]>>> [E:4868r S:62051 M:266886725] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:51)
00> D: 25081 [IM]Received Read request
00> I: 25083 [EM]<<< [E:4868r S:62051 M:89986252] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:66)
00> D: 25083 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
00> D: 25198 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 25200 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 25201 [EM]>>> [E:4869r S:62051 M:266886726] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
00> D: 25203 [DL]OpenThread State Changed (Flags: 0x01009009)
00> D: 25203 [DL]   Network Name: OpenThread
00> D: 25203 [DL]   PAN Id: 0x66D5
00> D: 25203 [DL]   Extended PAN Id: 0xDEAD00BEEF00CAFE
00> D: 25203 [DL]   Channel: 11
00> D: 25203 [DL]   Mesh Prefix: fdde:ad00:beef:0:0:0:0:0/64
00> D: 25203 [DL]   Thread Unicast Addresses:
00> D: 25204 [DL]        fe80:0:0:0:4c65:af11:a7ec:b451/64 valid preferred
00> I: 26427 [DL]Thread Network: ha-thread-5a53 Panid 0x5a53 Channel 15 RSSI -69 LQI 108 Version 4
00> I: 26532 [DL]Thread Network: NEST-PAN-2E03 Panid 0x2e03 Channel 15 RSSI -91 LQI 20 Version 4
00> I: 26540 [DL]Thread Network: NEST-PAN-2E03 Panid 0x2e03 Channel 15 RSSI -91 LQI 20 Version 4
00> I: 26564 [DL]Thread Network: ha-thread-5a53 Panid 0x5a53 Channel 15 RSSI -38 LQI 232 Version 4
00> I: 26591 [DL]Thread Network: NEST-PAN-2E03 Panid 0x2e03 Channel 15 RSSI -90 LQI 24 Version 4
00> I: 26601 [DL]Thread Network: NEST-PAN-2E03 Panid 0x2e03 Channel 15 RSSI -89 LQI 24 Version 4
00> D: 27700 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
00> D: 27779 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> I: 29611 [DL]Thread Network: MyHome36 Panid 0xbc1c Channel 25 RSSI -88 LQI 32 Version 4
00> D: 30054 [DL]OpenThread State Changed (Flags: 0x00008000)
00> D: 30055 [DL]   Network Name: OpenThread
00> D: 30055 [DL]   PAN Id: 0xFFFF
00> D: 30055 [DL]   Extended PAN Id: 0xDEAD00BEEF00CAFE
00> D: 30055 [DL]   Channel: 11
00> D: 30055 [DL]   Mesh Prefix: fdde:ad00:beef:0:0:0:0:0/64
00> I: 30057 [EM]<<< [E:4869r S:62051 M:89986253] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:227)
00> D: 30057 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 30058 [DL]OpenThread State Changed (Flags: 0x01002002)
00> D: 30058 [DL]   Thread Unicast Addresses:
00> D: 30119 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 30119 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 51)
00> D: 30239 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 30239 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 30422 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 30423 [EM]>>> [E:4870r S:62051 M:266886727] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:134)
00> D: 30423 [IM]Received Read request
00> I: 30433 [EM]<<< [E:4870r S:62051 M:89986254] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:257)
00> D: 30434 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 30539 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 30539 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 82)
00> D: 30659 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 30662 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 30663 [EM]>>> [E:4871r S:62051 M:266886728] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:103)
00> D: 30663 [IM]Received Read request
00> E: 30665 [DMG]Read request on unknown cluster - no data version available
00> E: 30665 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0002err = 5c3
00> E: 30666 [DMG]Read request on unknown cluster - no data version available
00> E: 30666 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0001err = 5c3
00> E: 30666 [DMG]Read request on unknown cluster - no data version available
00> E: 30667 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0000err = 5c3
00> E: 30667 [DMG]Read request on unknown cluster - no data version available
00> E: 30668 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0007err = 5c3
00> E: 30668 [DMG]Read request on unknown cluster - no data version available
00> E: 30668 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0006err = 5c3
00> I: 30670 [EM]<<< [E:4871r S:62051 M:89986255] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:181)
00> D: 30670 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 30839 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 30839 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
00> D: 30959 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 30961 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 30961 [EM]>>> [E:4872r S:62051 M:266886729] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
00> I: 30962 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
00> I: 30963 [EM]<<< [E:4872r S:62051 M:89986256] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> D: 30963 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
00> D: 31079 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 31081 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 31082 [EM]>>> [E:4873r S:62051 M:266886730] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
00> I: 31086 [EM]<<< [E:4873r S:62051 M:89986257] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> D: 31086 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
00> D: 31319 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 31321 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 31321 [EM]>>> [E:4874r S:62051 M:266886731] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
00> I: 31322 [ZCL]OpCreds: Certificate Chain request received for PAI
00> I: 31323 [EM]<<< [E:4874r S:62051 M:89986258] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:527)
00> D: 31324 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 31499 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 31499 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 31619 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 31619 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 172)
00> D: 31739 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 31799 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 31800 [EM]>>> [E:4875r S:62051 M:266886732] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
00> I: 31801 [ZCL]OpCreds: Certificate Chain request received for DAC
00> I: 31802 [EM]<<< [E:4875r S:62051 M:89986259] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:555)
00> D: 31802 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 31979 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 31979 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 32099 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 32099 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 32219 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 32219 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 20)
00> D: 32339 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 32340 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 32519 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 32520 [EM]>>> [E:4876r S:62051 M:266886733] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
00> I: 32521 [ZCL]OpCreds: Received an AttestationRequest command
00> I: 32522 [ZCL]OpCreds: AttestationRequest successful.
00> I: 32523 [EM]<<< [E:4876r S:62051 M:89986260] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:716)
00> D: 32523 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 32699 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 32699 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 32819 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 32819 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 32939 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 32939 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 181)
00> D: 33059 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 33060 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 33241 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 33241 [EM]>>> [E:4877r S:62051 M:266886734] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
00> I: 33242 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
00> I: 33243 [EM]<<< [E:4877r S:62051 M:89986261] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> D: 33243 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
00> D: 33359 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 35160 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 35160 [EM]>>> [E:4878r S:62051 M:266886735] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
00> I: 35161 [ZCL]OpCreds: Received a CSRRequest command
00> I: 35169 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
00> I: 35170 [ZCL]OpCreds: CSRRequest successful.
00> I: 35171 [EM]<<< [E:4878r S:62051 M:89986262] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:391)
00> D: 35171 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 35279 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 35280 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 182)
00> D: 35459 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 35460 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 36)
00> D: 35579 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 35584 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 35703 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 35703 [EM]>>> [E:4879r S:62051 M:266886736] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:316)
00> I: 35704 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
00> I: 35706 [ZCL]OpCreds: AddTrustedRootCertificate successful.
00> I: 35707 [EM]<<< [E:4879r S:62051 M:89986263] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:63)
00> D: 35707 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68)
00> D: 35819 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 35882 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 36062 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 36062 [EM]>>> [E:4880r S:62051 M:266886737] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:352)
00> I: 36063 [ZCL]OpCreds: Received an AddNOC command
00> I: 36064 [FP]Validating NOC chain
00> I: 36067 [FP]NOC chain validation successful
00> I: 36067 [FP]Added new fabric at index: 0x1
00> I: 36067 [FP]Assigned compressed fabric ID: 0xEBF1D717072701DF, node ID: 0x00000000311B32F6
00> I: 36068 [TS]Last Known Good Time: 2023-10-14T01:16:48
00> I: 36068 [TS]New proposed Last Known Good Time: 2025-08-21T00:40:40
00> I: 36068 [TS]Updating pending Last Known Good Time to 2025-08-21T00:40:40
00> I: 36078 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x0000000042461682
00> D: 36078 [DL]Using Thread extended MAC for hostname.
00> I: 36078 [DIS]Advertise operational node EBF1D717072701DF-00000000311B32F6
00> E: 36078 [SVR]Operational advertising failed: 3
00> I: 36079 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
00> I: 36079 [EM]<<< [E:4880r S:62051 M:89986264] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [01DF] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> D: 36080 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
00> D: 36239 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 36244 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 36245 [EM]>>> [E:4881r S:62051 M:266886738] (S) Msg RX from 1:FFFFFFFB00000000 [01DF] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:175)
00> I: 36248 [EM]<<< [E:4881r S:62051 M:89986265] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [01DF] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> D: 36248 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
00> D: 36359 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 36420 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 36420 [EM]>>> [E:4882r S:62051 M:266886739] (S) Msg RX from 1:FFFFFFFB00000000 [01DF] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
00> I: 36421 [FS]GeneralCommissioning: Received ArmFailSafe (129s)
00> I: 36422 [EM]<<< [E:4882r S:62051 M:89986266] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [01DF] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> D: 36422 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
00> D: 36539 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 36542 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 36543 [EM]>>> [E:4883r S:62051 M:266886740] (S) Msg RX from 1:FFFFFFFB00000000 [01DF] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:73)
00> D: 36573 [DL]OpenThread State Changed (Flags: 0x1017c110)
00> D: 36574 [DL]   Network Name: ha-thread-5a53
00> D: 36574 [DL]   PAN Id: 0x5A53
00> D: 36574 [DL]   Extended PAN Id: 0x8383B9C50F008897
00> D: 36574 [DL]   Channel: 15
00> D: 36574 [DL]   Mesh Prefix: fd66:bf80:8221:1f54:0:0:0:0/64
00> D: 36579 [DL]OpenThread State Changed (Flags: 0x1100100d)
00> D: 36579 [DL]   Device Role: DETACHED
00> D: 36579 [DL]   Thread Unicast Addresses:
00> D: 36579 [DL]        fd66:bf80:8221:1f54:7c7d:b926:4dd5:5b4/64 valid preferred
00> D: 36579 [DL]        fe80:0:0:0:4c65:af11:a7ec:b451/64 valid preferred
00> I: 37782 [DL]SRP Client was started, detected server: fd66:bf80:8221:1f54:5a91:ed03:c4ba:51ed
00> D: 37783 [DL]OpenThread State Changed (Flags: 0x200002a4)
00> D: 37783 [DL]   Device Role: CHILD
00> D: 37783 [DL]   Partition Id: 0x17A5AE38
00> D: 37787 [DL]Thread Attached updating Multicast address
00> I: 37787 [SVR]Joining Multicast groups
00> I: 37788 [EM]<<< [E:4883r S:62051 M:89986267] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [01DF] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:65)
00> D: 37788 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 70)
00> D: 37788 [DL]Using Thread extended MAC for hostname.
00> I: 37789 [DIS]Advertise operational node EBF1D717072701DF-00000000311B32F6
00> E: 37789 [SVR]Operational advertising failed: 3
00> D: 37860 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 38477 [DL]SRP update succeeded
00> I: 38477 [SVR]Server initialization complete
00> I: 38477 [DIS]Updating services using commissioning mode 0
00> D: 38477 [DL]Using Thread extended MAC for hostname.
00> I: 38477 [DIS]Advertise operational node EBF1D717072701DF-00000000311B32F6
00> I: 38478 [DL]advertising srp service: EBF1D717072701DF-00000000311B32F6._matter._tcp
00> I: 38481 [IM]No subscriptions to resume
00> I: 38481 [SWU]Stopping the watchdog timer
00> I: 38481 [SWU]Starting the periodic query timer, timeout: 86400 seconds
00> D: 39422 [DL]SRP update succeeded
00> D: 40320 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 42820 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
00> D: 42900 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 45361 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 47861 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
00> D: 47941 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 50401 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 52901 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
00> D: 52981 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 55442 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 57942 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
00> D: 58022 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 60482 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 62983 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
00> D: 63062 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 65523 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 68023 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
00> D: 68103 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 70563 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 73064 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
00> D: 73143 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 75604 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 78104 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
00> D: 78184 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 80644 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 82866 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> I: 82867 [EM]>>> [E:4884r S:62051 M:266886741] (S) Msg RX from 1:FFFFFFFB00000000 [01DF] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
00> I: 82868 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
00> I: 82868 [EM]<<< [E:4884r S:62051 M:89986268] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [01DF] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> D: 82869 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
00> D: 82984 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
00> D: 85445 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
00> D: 87945 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
00> D: 88025 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)

Questions:

• Does the Matter server (Home Assistant) need to match the specific Matter version in the NCS v3.1.0 SDK? Matter 1.4 is currently supported. 
• What debugging steps would you recommend to identify why communication stops at line 280 in the v3.1.0 log?

Thanks in advance,

Patrick

[AHaug]

Hello,

Does the Matter server (Home Assistant) need to match the specific Matter version in the NCS v3.1.0 SDK? Matter 1.4 is currently supported. 

This is a bit ambigious w.r.t whats running what version of the app. If I understand you correct, your Home Assistant Matter server does not run Matter v1.4, or does also the Matter integration run v1.4? I see that the integration should support v1.4 but I'm curious if your server is set up to do so. A v1.4.2 Matter device (which NCS 3.1.0 uses) is compatible with a server running v1.4 but not with a server running v1.3 due to cluster changes that may have been introduced.

Kind regards,
Andreas

[Patrick]

Apologies for the confusion. The Matter server / Home Assistant integration should be Matter 1.4. 

[Emanuel Costa]

having the same problem as you. After the update I am not able to commission the device using TH and Apple Homekit.

00> rtt:~$ [00:00:00.080,383] <inf> app: BLE is Advertising
00> rtt:~$ rtt:~$ [00:00:05.034,667] <inf> FR_handler: reset_counter_cb called
00> rtt:~$ [00:00:05.034,729] <inf> FR_handler: Reset Counter set to Zero
00> rtt:~$ [00:00:05.036,071] <inf> FR_handler: frc stored: 0
00> rtt:~$ rtt:~$ [00:00:30.080,627] <inf> chip: [DL]CHIPoBLE advertising mode changed to slow
00> rtt:~$ [00:00:30.082,855] <inf> chip: [DL]CHIPoBLE advertising started
00> rtt:~$ rtt:~$ [00:06:05.972,869] <inf> app: Ping
00> rtt:~$ rtt:~$ [00:07:15.338,470] <inf> chip: [DL]Current number of connections: 1/2
00> rtt:~$ [00:07:15.338,958] <inf> chip: [DL]BLE connection established (ConnId: 0x00)
00> rtt:~$ [00:07:15.339,080] <inf> chip: [DL]CHIPoBLE advertising stopped
00> rtt:~$ [00:07:15.339,141] <inf> app: BLE is Connected
00> rtt:~$ rtt:~$ [00:07:16.977,081] <inf> chip: [BLE]local and remote recv window sizes = 5
00> rtt:~$ [00:07:16.977,172] <inf> chip: [BLE]selected BTP version 4
00> rtt:~$ [00:07:16.977,355] <inf> chip: [BLE]using BTP fragment sizes rx 244 / tx 244.
00> rtt:~$ rtt:~$ [00:07:17.067,474] <inf> chip: [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 498)
00> rtt:~$ [00:07:17.067,535] <inf> app: BLE is Connected
00> rtt:~$ rtt:~$ [00:07:17.158,752] <inf> chip: [EM]>>> [E:46617r S:0 M:69251320] (U) Msg RX from 0:D8E80D21E8DAADC1 [0000] to 0000000000000000 --- Type 0000:20 (SecureChannel:PBKDFParamRequest) (B:98)
00> rtt:~$ rtt:~$ --- 1 messages dropped ---
00> [00:07:17.160,736] <inf> chip: [SVR]Commissioning session establishment step started
00> rtt:~$ rtt:~$ [00:07:17.293,182] <inf> chip: [EM]>>> [E:46617r S:0 M:69251321] (U) Msg RX from 0:D8E80D21E8DAADC1 [0000] to 0000000000000000 --- Type 0000:22 (SecureChannel:PASE_Pake1) (B:92)
00> rtt:~$ rtt:~$ [00:07:17.431,610] <inf> chip: [EM]<<< [E:46617r S:0 M:106844064] (U) Msg TX from 0000000000000000 to 0:D8E80D21E8DAADC1 [0000] [BLE] --- Type 0000:23 (SecureChannel:PASE_Pake2) (B:127)
00> rtt:~$ [00:07:17.432,159] <err> chip: [DL]Long dispatch time: 140 ms, for event type 16388
00> rtt:~$ rtt:~$ [00:07:17.562,927] <inf> chip: [EM]>>> [E:46617r S:0 M:69251322] (U) Msg RX from 0:D8E80D21E8DAADC1 [0000] to 0000000000000000 --- Type 0000:24 (SecureChannel:PASE_Pake3) (B:59)
00> rtt:~$ rtt:~$ --- 1 messages dropped ---
00> [00:07:17.566,375] <inf> chip: [SC]SecureSession[0x20004590, LSID:64145]: State change 'kEstablishing' --> 'kActive'
00> rtt:~$ rtt:~$ [00:07:17.566,467] <inf> chip: [SVR]Commissioning completed session establishment step
00> rtt:~$ [00:07:17.566,772] <inf> chip: [DIS]Updating services using commissioning mode 0
00> rtt:~$ [00:07:17.566,864] <err> chip: [DIS]Failed to remove advertised services: 3
00> rtt:~$ rtt:~$ [00:07:17.566,955] <err> chip: [DIS]Failed to finalize service update: 3
00> rtt:~$ [00:07:17.567,077] <inf> chip: [SVR]Device completed Rendezvous process
00> rtt:~$ [00:07:17.567,169] <inf> app: BLE is Connected
00> rtt:~$ rtt:~$ [00:07:17.744,415] <inf> chip: [EM]>>> [E:46618r S:64145 M:71682220] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:134)
00> rtt:~$ rtt:~$ [00:07:17.769,256] <inf> chip: [EM]<<< [E:46618r S:64145 M:169201959] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) (B:257)
00> rtt:~$ rtt:~$ [00:07:18.059,082] <inf> chip: [EM]>>> [E:46619r S:64145 M:71682221] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:02 (IM:ReadRequest) (B:103)
00> rtt:~$ rtt:~$ [00:07:18.063,171] <err> chip: [DMG]Read request on unknown cluster - no data version available
00> rtt:~$ [00:07:18.063,476] <err> chip: [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0002err = 5c3
00> rtt:~$ rtt:~$ [00:07:18.064,605] <err> chip: [DMG]Read request on unknown cluster - no data version available
00> rtt:~$ [00:07:18.064,910] <err> chip: [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0001err = 5c3
00> rtt:~$ rtt:~$ [00:07:18.065,948] <err> chip: [DMG]Read request on unknown cluster - no data version available
00> rtt:~$ [00:07:18.066,253] <err> chip: [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0000err = 5c3
00> rtt:~$ rtt:~$ [00:07:18.067,291] <err> chip: [DMG]Read request on unknown cluster - no data version available
00> rtt:~$ [00:07:18.067,565] <err> chip: [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0007err = 5c3
00> rtt:~$ rtt:~$ [00:07:18.068,695] <err> chip: [DMG]Read request on unknown cluster - no data version available
00> rtt:~$ [00:07:18.068,969] <err> chip: [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0046, attributeId: 0x0000_0006err = 5c3
00> rtt:~$ rtt:~$ --- 2 messages dropped ---
00> [00:07:18.240,142] <inf> chip: [FS]GeneralCommissioning: Received ArmFailSafe (60s)
00> rtt:~$ rtt:~$ [00:07:18.241,729] <inf> chip: [EM]<<< [E:46620r S:64145 M:169201961] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> rtt:~$ rtt:~$ [00:07:18.373,596] <inf> chip: [EM]>>> [E:46621r S:64145 M:71682223] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:70)
00> rtt:~$ rtt:~$ [00:07:18.381,286] <inf> chip: [EM]<<< [E:46621r S:64145 M:169201962] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> rtt:~$ rtt:~$ [00:07:18.508,575] <inf> chip: [EM]>>> [E:46622r S:64145 M:71682224] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
00> rtt:~$ rtt:~$ [00:07:18.510,162] <inf> chip: [ZCL]OpCreds: Certificate Chain request received for PAI
00> rtt:~$ rtt:~$ [00:07:18.513,946] <inf> chip: [EM]<<< [E:46622r S:64145 M:169201963] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:599)
00> rtt:~$ rtt:~$ [00:07:18.823,547] <inf> chip: [EM]>>> [E:46623r S:64145 M:71682225] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:62)
00> rtt:~$ rtt:~$ [00:07:18.825,073] <inf> chip: [ZCL]OpCreds: Certificate Chain request received for DAC
00> rtt:~$ rtt:~$ [00:07:18.828,918] <inf> chip: [EM]<<< [E:46623r S:64145 M:169201964] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:606)
00> rtt:~$ rtt:~$ [00:07:19.138,946] <inf> chip: [EM]>>> [E:46624r S:64145 M:71682226] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
00> rtt:~$ rtt:~$ [00:07:19.140,563] <inf> chip: [ZCL]OpCreds: Received an AttestationRequest command
00> rtt:~$ [00:07:19.174,896] <inf> chip: [ZCL]OpCreds: AttestationRequest successful.
00> rtt:~$ rtt:~$ [00:07:19.177,917] <inf> chip: [EM]<<< [E:46624r S:64145 M:169201965] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:408)
00> rtt:~$ rtt:~$ [00:07:19.453,979] <inf> chip: [EM]>>> [E:46625r S:64145 M:71682227] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:94)
00> rtt:~$ [00:07:19.455,505] <inf> chip: [ZCL]OpCreds: Received a CSRRequest command
00> rtt:~$ rtt:~$ [00:07:19.649,810] <inf> chip: [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
00> rtt:~$ [00:07:19.683,013] <inf> chip: [ZCL]OpCreds: CSRRequest successful.
00> rtt:~$ rtt:~$ --- 1 messages dropped ---
00> [00:07:19.686,523] <err> chip: [DL]Long dispatch time: 234 ms, for event type 16388
00> rtt:~$ rtt:~$ [00:07:20.041,656] <inf> chip: [EM]>>> [E:46626r S:64145 M:71682228] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:463)
00> rtt:~$ rtt:~$ [00:07:20.043,212] <inf> chip: [ZCL]OpCreds: Received an AddTrustedRootCertificate command
00> rtt:~$ [00:07:20.105,407] <inf> chip: [ZCL]OpCreds: AddTrustedRootCertificate successful.
00> rtt:~$ rtt:~$ [00:07:20.106,903] <inf> chip: [EM]<<< [E:46626r S:64145 M:169201967] (S) Msg TX from 0000000000000000 to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:63)
00> rtt:~$ rtt:~$ [00:07:20.492,980] <inf> chip: [EM]>>> [E:46627r S:64145 M:71682229] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:865)
00> rtt:~$ rtt:~$ [00:07:20.494,842] <inf> chip: [ZCL]OpCreds: Received an AddNOC command
00> rtt:~$ [00:07:20.497,436] <inf> chip: [FP]Validating NOC chain
00> rtt:~$ [00:07:20.623,992] <inf> chip: [FP]NOC chain validation successful
00> rtt:~$ [00:07:20.624,145] <inf> chip: [FP]Added new fabric at index: 0x1
00> rtt:~$ rtt:~$ [00:07:20.624,359] <inf> chip: [FP]Assigned compressed fabric ID: 0x4F4940A7F99F386C, node ID: 0x0000000012344321
00> rtt:~$ [00:07:20.624,572] <inf> chip: [TS]Last Known Good Time: 2023-10-14T01:16:48
00> rtt:~$ rtt:~$ [00:07:20.624,786] <inf> chip: [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
00> rtt:~$ [00:07:20.624,847] <inf> chip: [TS]Retaining current Last Known Good Time
00> rtt:~$ rtt:~$ [00:07:20.650,726] <inf> chip: [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
00> rtt:~$ [00:07:20.651,000] <inf> chip: [DIS]Advertise operational node 4F4940A7F99F386C-0000000012344321
00> rtt:~$ rtt:~$ [00:07:20.651,092] <err> chip: [SVR]Operational advertising failed: 3
00> rtt:~$ [00:07:20.651,367] <inf> chip: [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
00> rtt:~$ rtt:~$ [00:07:20.652,832] <inf> chip: [EM]<<< [E:46627r S:64145 M:169201968] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [386C] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> rtt:~$ [00:07:20.653,015] <err> chip: [DL]Long dispatch time: 164 ms, for event type 16388
00> rtt:~$ rtt:~$ [00:07:20.759,796] <inf> chip: [EM]>>> [E:46628r S:64145 M:71682230] (S) Msg RX from 1:FFFFFFFB00000000 [386C] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:160)
00> rtt:~$ rtt:~$ [00:07:20.768,524] <inf> chip: [EM]<<< [E:46628r S:64145 M:169201969] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [386C] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> rtt:~$ rtt:~$ [00:07:20.893,615] <inf> chip: [EM]>>> [E:46629r S:64145 M:71682231] (S) Msg RX from 1:FFFFFFFB00000000 [386C] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
00> rtt:~$ rtt:~$ [00:07:20.895,141] <inf> chip: [FS]GeneralCommissioning: Received ArmFailSafe (94s)
00> rtt:~$ rtt:~$ [00:07:20.896,759] <inf> chip: [EM]<<< [E:46629r S:64145 M:169201970] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [386C] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> rtt:~$ rtt:~$ [00:07:21.028,747] <inf> chip: [EM]>>> [E:46630r S:64145 M:71682232] (S) Msg RX from 1:FFFFFFFB00000000 [386C] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:73)
00> rtt:~$ rtt:~$ [00:07:21.086,303] <inf> app: Network is Provisioned
00> rtt:~$ [00:07:21.087,036] <inf> app: Network is Provisioned
00> rtt:~$ [00:07:21.087,402] <inf> app: Network is Provisioned
00> rtt:~$ rtt:~$ [00:07:22.398,864] <inf> chip: [DL]SRP Client was started, detected server: fd6b:36d4:8273:67a8:4731:553b:7c17:e1b5
00> rtt:~$ [00:07:22.399,078] <inf> chip: [ZCL]ThreadDiagnosticsDelegate: OnConnectionStatusChanged
00> rtt:~$ [00:07:22.399,719] <inf> app: Network is Provisioned
00> rtt:~$ rtt:~$ [00:07:22.400,634] <inf> chip: [SVR]Joining Multicast groups
00> rtt:~$ [00:07:22.401,123] <inf> app: Network is Provisioned
00> rtt:~$ [00:07:22.402,496] <inf> chip: [EM]<<< [E:46630r S:64145 M:169201971] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [386C] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:65)
00> rtt:~$ rtt:~$ [00:07:22.403,259] <inf> chip: [DIS]Advertise operational node 4F4940A7F99F386C-0000000012344321
00> rtt:~$ [00:07:22.403,350] <err> chip: [SVR]Operational advertising failed: 3
00> rtt:~$ [00:07:22.403,350] <inf> app: Network is Provisioned
00> rtt:~$ rtt:~$ [00:07:22.944,244] <inf> chip: [SVR]Server initialization complete
00> rtt:~$ [00:07:22.944,335] <inf> chip: [DIS]Updating services using commissioning mode 0
00> rtt:~$ [00:07:22.944,580] <inf> chip: [DIS]Advertise operational node 4F4940A7F99F386C-0000000012344321
00> rtt:~$ rtt:~$ [00:07:22.945,098] <inf> chip: [DL]advertising srp service: 4F4940A7F99F386C-0000000012344321._matter._tcp
00> rtt:~$ [00:07:22.945,190] <inf> app: Network is Provisioned
00> rtt:~$ [00:07:22.963,409] <inf> chip: [IM]No subscriptions to resume
00> rtt:~$ [00:07:22.967,559] <inf> chip: [SWU]Stopping the watchdog timer
00> rtt:~$ rtt:~$ [00:07:22.967,681] <inf> chip: [SWU]Starting the periodic query timer, timeout: 86400 seconds
00> rtt:~$ [00:07:22.967,712] <inf> app: Network is Provisioned
00> rtt:~$ rtt:~$ [00:07:31.006,469] <inf> app: Network is Provisioned
00> rtt:~$ rtt:~$ [00:08:07.514,556] <inf> chip: [EM]>>> [E:46631r S:64145 M:71682233] (S) Msg RX from 1:FFFFFFFB00000000 [386C] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
00> rtt:~$ rtt:~$ [00:08:07.516,082] <inf> chip: [FS]GeneralCommissioning: Received ArmFailSafe (120s)
00> rtt:~$ rtt:~$ [00:08:07.517,761] <inf> chip: [EM]<<< [E:46631r S:64145 M:169201972] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [386C] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> rtt:~$ rtt:~$ [00:08:52.560,333] <inf> chip: [EM]>>> [E:46632r S:64145 M:71682234] (S) Msg RX from 1:FFFFFFFB00000000 [386C] to 0000000000000000 --- Type 0001:08 (IM:InvokeCommandRequest) (B:65)
00> rtt:~$ rtt:~$ [00:08:52.561,920] <inf> chip: [FS]GeneralCommissioning: Received ArmFailSafe (120s)
00> rtt:~$ rtt:~$ [00:08:52.563,507] <inf> chip: [EM]<<< [E:46632r S:64145 M:169201973] (S) Msg TX from 0000000000000000 to 1:FFFFFFFB00000000 [386C] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) (B:66)
00> rtt:~$ rtt:~$ [00:09:37.604,553] <inf> chip: [BLE]Releasing end point's BLE connection back to application.
00> rtt:~$ [00:09:37.604,675] <inf> chip: [DL]Closing BLE GATT connection (ConnId 00)
00> rtt:~$ rtt:~$ [00:09:37.739,196] <inf> chip: [DL]Current number of connections: 0/2
00> rtt:~$ [00:09:37.739,379] <inf> chip: [DL]BLE GAP connection terminated (reason 0x16)
00> rtt:~$ [00:09:37.739,593] <inf> app: Network is Provisioned
00> rtt:~$ rtt:~$ [00:10:52.561,828] <inf> chip: [FS]Fail-safe timer expired
00> rtt:~$ [00:10:52.561,981] <err> chip: [SVR]Failsafe timer expired
00> rtt:~$ [00:10:52.562,164] <inf> chip: [SC]SecureSession[0x20004590, LSID:64145]: State change 'kActive' --> 'kPendingEviction'
00> rtt:~$ [00:10:52.562,377] <err> chip: [SVR]Commissioning failed (attempt 1): 32
00> rtt:~$ rtt:~$ [00:10:52.581,207] <inf> chip: [DIS]Updating services using commissioning mode 1
00> rtt:~$ [00:10:52.581,420] <inf> chip: [DIS]Advertise operational node 4F4940A7F99F386C-0000000012344321
00> rtt:~$ rtt:~$ [00:10:52.582,305] <inf> chip: [DIS]Advertise commission parameter vendorID=4977 productID=257 discriminator=0684/02 cm=1 cp=0
00> rtt:~$ [00:10:52.582,916] <inf> chip: [DL]advertising srp service: 42C835F23719CEDD._matterc._udp
00> rtt:~$ [00:10:52.583,190] <err> chip: [ZCL]OpCreds: Got FailSafeTimerExpired
00> rtt:~$ rtt:~$ [00:10:52.583,282] <err> chip: [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
00> rtt:~$ [00:10:52.583,404] <err> chip: [FP]Reverting pending fabric data for fabric 0x1
00> rtt:~$ rtt:~$ [00:10:52.584,686] <err> chip: [FP]Warning: metadata not found during delete of fabric 0x1
00> rtt:~$ rtt:~$ [00:10:52.667,205] <inf> chip: [FP]Fabric (0x1) deleted.
00> rtt:~$ [00:10:52.667,266] <inf> chip: [SVR]Closing pairing window
00> rtt:~$ [00:10:52.667,541] <inf> chip: [DIS]Updating services using commissioning mode 0
00> rtt:~$ rtt:~$ [00:10:52.667,663] <inf> chip: [DL]removing srp service: 4F4940A7F99F386C-0000000012344321._matter._tcp
00> rtt:~$ [00:10:52.667,816] <inf> chip: [DL]removing srp service: 42C835F23719CEDD._matterc._udp
00> rtt:~$ [00:10:52.668,029] <inf> chip: [ZCL]UserLabel: Last Fabric index 0x1 was removed
00> rtt:~$ rtt:~$ [00:10:52.677,001] <inf> chip: [ZCL]OpCreds: Fabric index 0x1 was removed
00> rtt:~$ [00:10:52.677,124] <inf> chip: [DIS]Updating services using commissioning mode 0
00> rtt:~$ rtt:~$ [00:10:52.677,246] <inf> chip: [DL]removing srp service: 4F4940A7F99F386C-0000000012344321._matter._tcp
00> rtt:~$ [00:10:52.677,368] <inf> chip: [DL]removing srp service: 42C835F23719CEDD._matterc._udp
00> rtt:~$ rtt:~$ [00:10:52.839,752] <inf> chip: [TS]Pending Last Known Good Time: 2023-10-14T01:16:48
00> rtt:~$ [00:10:52.840,606] <inf> chip: [TS]Previous Last Known Good Time: 2023-10-14T01:16:48
00> rtt:~$ [00:10:52.840,698] <inf> chip: [TS]Reverted Last Known Good Time to previous value
00> rtt:~$ rtt:~$ [00:10:52.841,918] <err> chip: [FP]Warning: metadata not found during delete of fabric 0x1
00> rtt:~$ [00:10:52.845,428] <inf> chip: [ZCL]UserLabel: Last Fabric index 0x1 was removed
00> rtt:~$ [00:10:52.854,095] <inf> chip: [ZCL]OpCreds: Fabric index 0x1 was removed
00> rtt:~$ rtt:~$ [00:10:52.854,187] <inf> chip: [DIS]Updating services using commissioning mode 0
00> rtt:~$ [00:10:52.854,339] <inf> chip: [DL]removing srp service: 4F4940A7F99F386C-0000000012344321._matter._tcp
00> rtt:~$ rtt:~$ [00:10:52.854,461] <inf> chip: [DL]removing srp service: 42C835F23719CEDD._matterc._udp
00> rtt:~$ [00:10:52.876,312] <err> chip: [SVR]Warning, failed to delete GroupDataProvider state for fabric index 0x1: d8
00> rtt:~$ [00:10:52.877,288] <err> chip: [ZCL]OpCreds: failed to delete fabric at index 1: d8
00> rtt:~$ rtt:~$ [00:10:54.878,631] <inf> chip: [NP]Reverting Thread operational dataset
00> rtt:~$ [00:10:54.893,249] <inf> app: Network is Provisioned
00> rtt:~$ [00:10:54.893,402] <err> chip: [DL]Long dispatch time: 2332 ms, for event type 32784
00> rtt:~$ [00:10:54.893,493] <inf> chip: [FS]Fail-safe cleanly disarmed
00> rtt:~$ rtt:~$ [00:10:54.893,676] <inf> chip: [ZCL]ThreadDiagnosticsDelegate: OnConnectionStatusChanged
00> rtt:~$ [00:10:54.894,012] <inf> chip: [ZCL]ThreadDiagnosticsDelegate: OnNetworkFaultChanged
00> rtt:~$ [00:10:54.895,141] <inf> app: BLE is Connected
00> rtt:~$ [00:10:54.896,026] <inf> app: BLE is Connected
00> rtt:~$ [00:10:54.896,087] <inf> app: BLE is Connected
00> rtt:~$ [00:10:54.896,148] <inf> app: BLE is Connected
00> rtt:~$ rtt:~$ [00:10:54.896,392] <inf> chip: [TS]Pending Last Known Good Time: 2023-10-14T01:16:48
00> rtt:~$ [00:10:54.897,216] <inf> chip: [TS]Previous Last Known Good Time: 2023-10-14T01:16:48
00> rtt:~$ [00:10:54.897,308] <inf> chip: [TS]Reverted Last Known Good Time to previous value
00> rtt:~$ [00:10:54.897,644] <inf> app: BLE is Connected
00> rtt:~$ rtt:~$ [00:10:54.897,735] <inf> chip: [DL]Performing factory reset

[Marte Myrvold]

Hi Patrick,

Andreas is out of office, so the ticket has been assigned to me until he is back.

From the logs, I see that the device does not receive the message to set up CASE connection from the commissioner, but things look correct before that. 

Can you test with chip-tool to see if you get the same problem? If so, please share the chip-tool and device logs from that test.

Best regards,
Marte