I am trying to get familiar with matter, and have the following two devices:
- Thingy:53 flashed with the matter weather station example (https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/applications/matter_weather_station/README.html_
- nRF52840 Dongle flashed with nrf/samples/openthread/coprocessor/ as explained here: https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/ug_thread_tools.html#ug-thread-tools-tbr
Codes for both has been compiled with nRF Connect SDK v2.1.2.
I have setup a border router using the flashed nRF52940 dongle, as well as a Raspberry Pi with OPBT (https://openthread.io/guides/border-router/build).
I was able to sucessfully form a thread network, with the default credentials.
However, I'm unable to commision the Thingy:53 into the network. I have tried both the android app as well as the cli tool. For the latter I make sure to extract the dataset before pairing.
This is the output from the Thingy:53. It shows two attempts to commision, the first via the android app and the first QR code mentioned here (https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/applications/matter_weather_station/README.html#onboarding-information), the second via the chip-tool.
[00:23:21.199,035] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488284 [00:23:21.199,218] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488285 [00:23:21.199,371] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488286 [00:23:22.109,741] <inf> chip: [DL]BLE connection established (ConnId: 0x00) [00:23:22.109,832] <inf> chip: [DL]Current number of connections: 1/1 [00:23:22.109,924] <inf> chip: [DL]CHIPoBLE advertising stopped [00:23:22.110,229] <inf> chip: [DL]NFC Tag emulation stopped [00:23:23.231,323] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:23.231,445] <inf> chip: [BLE]local and remote recv window sizes = 5 [00:23:23.231,506] <inf> chip: [BLE]selected BTP version 4 [00:23:23.231,597] <inf> chip: [BLE]using BTP fragment sizes rx 244 / tx 244. [00:23:23.355,041] <dbg> chip: [DL]ConnId: 0x00, New CCCD value: 0x0002 [00:23:23.355,163] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6) [00:23:23.355,468] <dbg> chip: [IN]BLE EndPoint 0x200149a0 Connection Complete [00:23:23.355,560] <inf> chip: [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) [00:23:23.534,759] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:23.535,980] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:23.536,376] <inf> chip: [EM]>>> [E:65188r M:108497553] (U) Msg RX from 0:2C67DD3491779F07 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [00:23:23.536,529] <dbg> chip: [EM]Handling via exchange: 65188r, Delegate: 0x20008a7c [00:23:23.536,590] <dbg> chip: [SC]Received PBKDF param request [00:23:23.536,773] <dbg> chip: [SC]Peer assigned session ID 43340 [00:23:23.536,865] <dbg> chip: [SC]Found MRP parameters in the message [00:23:23.537,322] <dbg> chip: [SC]Including MRP parameters in PBKDF param response [00:23:23.537,963] <inf> chip: [EM]<<< [E:65188r M:264107691] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [00:23:23.538,085] <inf> chip: [IN](U) Sending msg 264107691 to IP address 'BLE' [00:23:23.538,208] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140) [00:23:23.538,513] <dbg> chip: [SC]Sent PBKDF param response [00:23:23.670,318] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:23.670,715] <inf> chip: [EM]>>> [E:65188r M:108497554] (U) Msg RX from 0:2C67DD3491779F07 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) [00:23:23.670,837] <dbg> chip: [EM]Found matching exchange: 65188r, Delegate: 0x20008a7c [00:23:23.670,898] <dbg> chip: [SC]Received spake2p msg1 [00:23:24.196,014] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd18 [00:23:24.196,197] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e31 [00:23:24.196,350] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aed2 [00:23:24.198,303] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488287 [00:23:24.198,486] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488288 [00:23:24.198,638] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488289 [00:23:24.198,822] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448828a [00:23:24.199,005] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448828b [00:23:24.199,188] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448828c [00:23:24.199,371] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448828d [00:23:25.239,868] <inf> chip: [EM]<<< [E:65188r M:264107692] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [00:23:25.240,020] <inf> chip: [IN](U) Sending msg 264107692 to IP address 'BLE' [00:23:25.240,142] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132) [00:23:25.240,447] <dbg> chip: [SC]Sent spake2p msg2 [00:23:25.240,570] <err> chip: [DL]Long dispatch time: 1570 ms, for event type 16388 [00:23:25.290,069] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:25.425,354] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:25.425,750] <inf> chip: [EM]>>> [E:65188r M:108497555] (U) Msg RX from 0:2C67DD3491779F07 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) [00:23:25.425,872] <dbg> chip: [EM]Found matching exchange: 65188r, Delegate: 0x20008a7c [00:23:25.425,964] <dbg> chip: [SC]Received spake2p msg3 [00:23:25.426,483] <dbg> chip: [SC]Sending status report. Protocol code 0, exchange 65188 [00:23:25.426,788] <inf> chip: [EM]<<< [E:65188r M:264107693] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [00:23:25.426,910] <inf> chip: [IN](U) Sending msg 264107693 to IP address 'BLE' [00:23:25.427,062] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35) [00:23:25.428,283] <inf> chip: [SC]SecureSession[0x20006898]: Moving from state 'kEstablishing' --> 'kActive' [00:23:25.428,405] <dbg> chip: [IN]SecureSession[0x20006898]: Activated - Type:1 LSID:19972 [00:23:25.428,558] <dbg> chip: [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:19972 PSID:43340! [00:23:25.428,649] <inf> chip: [SVR]Commissioning completed session establishment step [00:23:25.429,046] <inf> chip: [DIS]Updating services using commissioning mode 0 [00:23:25.429,107] <dbg> chip: [DL]Using Thread extended MAC for hostname. [00:23:25.429,626] <dbg> chip: [DL]Using Thread extended MAC for hostname. [00:23:25.430,175] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32781 discriminator=3840/15 cm=0 [00:23:25.430,511] <err> chip: [DIS]Failed to advertise extended commissionable node: 3 [00:23:25.430,572] <dbg> chip: [DIS]Scheduling extended discovery timeout in 900s [00:23:25.430,664] <err> chip: [DIS]Failed to finalize service update: 1c [00:23:25.430,725] <dbg> chip: [DL]CHIPoBLE advertising set to off [00:23:25.430,847] <inf> chip: [SVR]Device completed Rendezvous process [00:23:25.514,862] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:25.516,113] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:25.517,364] <inf> chip: [EM]>>> [E:65189r M:215136318] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) [00:23:25.517,517] <dbg> chip: [EM]Handling via exchange: 65189r, Delegate: 0x2001236c [00:23:25.517,578] <dbg> chip: [IM]Received Read request [00:23:25.520,141] <dbg> chip: [DMG]IM RH moving to [GeneratingReports] [00:23:25.520,385] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 [00:23:25.520,507] <dbg> chip: [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty [00:23:25.520,660] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1) [00:23:25.520,843] <dbg> chip: [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty [00:23:25.520,996] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) [00:23:25.521,179] <dbg> chip: [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty [00:23:25.521,331] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) [00:23:25.521,484] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty [00:23:25.521,636] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) [00:23:25.521,789] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty [00:23:25.521,942] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) [00:23:25.522,125] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty [00:23:25.522,277] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0) [00:23:25.522,430] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty [00:23:25.522,583] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0) [00:23:25.522,796] <dbg> chip: [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty [00:23:25.522,949] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1) [00:23:25.523,162] <dbg> chip: [DMG]<RE> Sending report (payload has 228 bytes)... [00:23:25.524,932] <inf> chip: [EM]<<< [E:65189r M:193490170] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [00:23:25.525,085] <inf> chip: [IN](S) Sending msg 193490170 on secure session with LSID: 19972 [00:23:25.525,207] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:25.525,543] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0 [00:23:25.525,665] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages [00:23:25.525,726] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction] [00:23:25.525,817] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet [00:23:25.605,133] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:25.605,255] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 21) [00:23:25.695,068] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:25.740,631] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:25.741,607] <inf> chip: [EM]>>> [E:65190r M:215136319] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:25.741,729] <dbg> chip: [EM]Handling via exchange: 65190r, Delegate: 0x2001236c [00:23:25.742,279] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 [00:23:25.742,401] <inf> chip: [FS]GeneralCommissioning: Received ArmFailSafe (30s) [00:23:25.742,614] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 7d16fe09 [00:23:25.742,706] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:25.742,797] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:25.742,889] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:25.743,164] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:25.743,988] <inf> chip: [EM]<<< [E:65190r M:193490171] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:25.744,140] <inf> chip: [IN](S) Sending msg 193490171 on secure session with LSID: 19972 [00:23:25.744,262] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) [00:23:25.744,598] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:25.744,659] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:25.829,895] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:25.830,963] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:25.831,939] <inf> chip: [EM]>>> [E:65191r M:215136320] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:25.832,092] <dbg> chip: [EM]Handling via exchange: 65191r, Delegate: 0x2001236c [00:23:25.832,641] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 [00:23:25.833,099] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 7d16fe0a [00:23:25.833,221] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:25.833,312] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:25.833,404] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:25.833,648] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:25.834,503] <inf> chip: [EM]<<< [E:65191r M:193490172] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:25.834,655] <inf> chip: [IN](S) Sending msg 193490172 on secure session with LSID: 19972 [00:23:25.834,777] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) [00:23:25.835,113] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:25.835,174] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:25.920,196] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:25.921,325] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:25.922,271] <inf> chip: [EM]>>> [E:65192r M:215136321] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:25.922,424] <dbg> chip: [EM]Handling via exchange: 65192r, Delegate: 0x2001236c [00:23:25.922,943] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [00:23:25.923,065] <inf> chip: [ZCL]OpCreds: Certificate Chain request received for PAI [00:23:25.923,217] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:25.923,309] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:25.923,431] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:25.923,645] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:25.926,727] <inf> chip: [EM]<<< [E:65192r M:193490173] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:25.926,849] <inf> chip: [IN](S) Sending msg 193490173 on secure session with LSID: 19972 [00:23:25.926,971] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:25.927,337] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:25.927,398] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:26.055,297] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:26.055,419] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:26.145,111] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:26.145,233] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48) [00:23:26.235,260] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:26.236,358] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:26.237,304] <inf> chip: [EM]>>> [E:65193r M:215136322] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:26.237,457] <dbg> chip: [EM]Handling via exchange: 65193r, Delegate: 0x2001236c [00:23:26.237,976] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [00:23:26.238,098] <inf> chip: [ZCL]OpCreds: Certificate Chain request received for DAC [00:23:26.238,250] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:26.238,342] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:26.238,464] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:26.238,677] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:26.241,912] <inf> chip: [EM]<<< [E:65193r M:193490174] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:26.242,034] <inf> chip: [IN](S) Sending msg 193490174 on secure session with LSID: 19972 [00:23:26.242,187] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:26.242,523] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:26.242,584] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:26.325,347] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:26.325,500] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:26.415,039] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:26.415,283] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 76) [00:23:26.504,974] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:26.506,134] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:26.507,263] <inf> chip: [EM]>>> [E:65194r M:215136323] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:26.507,385] <dbg> chip: [EM]Handling via exchange: 65194r, Delegate: 0x2001236c [00:23:26.507,904] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 [00:23:26.508,026] <inf> chip: [ZCL]OpCreds: Received an AttestationRequest command [00:23:26.537,872] <inf> chip: [ZCL]OpCreds: AttestationRequest successful. [00:23:26.537,963] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:26.538,055] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:26.538,208] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:26.538,452] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:26.542,449] <inf> chip: [EM]<<< [E:65194r M:193490175] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:26.542,602] <inf> chip: [IN](S) Sending msg 193490175 on secure session with LSID: 19972 [00:23:26.542,724] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:26.543,060] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:26.543,151] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:26.595,123] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:26.595,245] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:26.685,302] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:26.685,424] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 236) [00:23:26.775,085] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:26.910,308] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:26.911,254] <inf> chip: [EM]>>> [E:65195r M:215136324] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:26.911,407] <dbg> chip: [EM]Handling via exchange: 65195r, Delegate: 0x2001236c [00:23:26.911,926] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 [00:23:26.912,048] <inf> chip: [FS]GeneralCommissioning: Received ArmFailSafe (0s) [00:23:26.912,139] <inf> chip: [FS]Fail-safe timer expired [00:23:26.912,292] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:26.912,353] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:26.912,475] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:26.912,689] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:26.913,574] <inf> chip: [EM]<<< [E:65195r M:193490176] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:26.913,696] <inf> chip: [IN](S) Sending msg 193490176 on secure session with LSID: 19972 [00:23:26.913,818] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) [00:23:26.914,154] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:26.914,215] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:26.914,337] <err> chip: [SVR]Failsafe timer expired [00:23:26.914,459] <dbg> chip: [IN]SecureSession[0x20006898]: MarkForEviction Type:1 LSID:19972 [00:23:26.914,550] <inf> chip: [SC]SecureSession[0x20006898]: Moving from state 'kActive' --> 'kPendingEviction' [00:23:26.914,672] <dbg> chip: [IN]SecureSession[0x20006898]: Released - Type:1 LSID:19972 [00:23:26.914,764] <err> chip: [SVR]Commissioning failed (attempt 1): 32 [00:23:26.914,825] <dbg> chip: [IN]Clearing BLE pending packets. [00:23:26.914,916] <inf> chip: [BLE]Releasing end point's BLE connection back to application. [00:23:26.914,978] <inf> chip: [DL]Closing BLE GATT connection (ConnId 00) [00:23:26.917,053] <dbg> chip: [IN]SecureSession[0x20006898]: Allocated Type:1 LSID:19973 [00:23:26.917,175] <dbg> chip: [SC]Assigned local session key ID 19973 [00:23:26.917,236] <dbg> chip: [SC]Waiting for PBKDF param request [00:23:26.917,541] <dbg> chip: [DL]CHIPoBLE advertising set to on [00:23:26.917,633] <inf> chip: [DIS]Updating services using commissioning mode 1 [00:23:26.917,724] <dbg> chip: [DL]Using Thread extended MAC for hostname. [00:23:26.918,273] <dbg> chip: [DL]Using Thread extended MAC for hostname. [00:23:26.918,792] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32781 discriminator=3840/15 cm=1 [00:23:26.919,128] <err> chip: [DIS]Failed to advertise commissionable node: 3 [00:23:26.919,219] <err> chip: [DIS]Failed to finalize service update: 1c [00:23:26.919,281] <err> chip: [ZCL]OpCreds: Got FailSafeTimerExpired [00:23:26.919,342] <err> chip: [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! [00:23:26.919,525] <inf> chip: [TS]Pending Last Known Good Time: 2023-01-17T22:28:56 [00:23:26.919,891] <inf> chip: [TS]Previous Last Known Good Time: 2023-01-17T22:28:56 [00:23:26.919,982] <inf> chip: [TS]Reverted Last Known Good Time to previous value [00:23:26.920,135] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 7d16fe0b [00:23:26.920,257] <dbg> chip: [ZCL]Failsafe timeout, tell platform driver to revert network credentials. [00:23:26.920,562] <inf> chip: [FS]Fail-safe cleanly disarmed [00:23:27.000,274] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:27.000,335] <err> chip: [BLE]no endpoint for BLE sent data ack [00:23:27.044,799] <inf> chip: [DL]BLE GAP connection terminated (reason 0x16) [00:23:27.044,891] <inf> chip: [DL]Current number of connections: 0/1 [00:23:27.049,163] <inf> chip: [DL]CHIPoBLE advertising started [00:23:27.049,774] <inf> chip: [DL]NFC Tag emulation started [00:23:27.197,021] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd19 [00:23:27.197,204] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e32 [00:23:27.197,387] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aed3 [00:23:27.199,707] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448828e [00:23:27.199,859] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448828f [00:23:27.200,042] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488290 [00:23:27.200,225] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488291 [00:23:27.200,408] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488292 [00:23:27.200,561] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488293 [00:23:27.200,744] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488294 [00:23:30.196,014] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd1a [00:23:30.196,197] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e33 [00:23:30.196,380] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aed4 [00:23:30.198,364] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488295 [00:23:30.198,547] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488296 [00:23:30.198,699] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488297 [00:23:30.198,883] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488298 [00:23:30.199,035] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d4488299 [00:23:30.199,218] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448829a [00:23:30.199,401] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448829b [00:23:33.196,014] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd1b [00:23:33.196,197] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e34 [00:23:33.196,380] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aed5 [00:23:33.198,333] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448829c [00:23:33.198,516] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448829d [00:23:33.198,699] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448829e [00:23:33.198,883] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d448829f [00:23:33.199,035] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882a0 [00:23:33.199,218] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882a1 [00:23:33.199,401] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882a2 [00:23:36.196,014] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd1c [00:23:36.196,197] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e35 [00:23:36.196,380] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aed6 [00:23:36.198,333] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882a3 [00:23:36.198,516] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882a4 [00:23:36.198,699] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882a5 [00:23:36.198,883] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882a6 [00:23:36.199,035] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882a7 [00:23:36.199,218] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882a8 [00:23:36.199,401] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882a9 [00:23:39.196,044] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd1d [00:23:39.196,228] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e36 [00:23:39.196,380] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aed7 [00:23:39.198,364] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882aa [00:23:39.198,516] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882ab [00:23:39.198,699] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882ac [00:23:39.198,883] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882ad [00:23:39.199,066] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882ae [00:23:39.199,218] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882af [00:23:39.199,401] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882b0 [00:23:39.823,730] <inf> chip: [DL]BLE connection established (ConnId: 0x00) [00:23:39.823,822] <inf> chip: [DL]Current number of connections: 1/1 [00:23:39.823,944] <inf> chip: [DL]CHIPoBLE advertising stopped [00:23:39.824,249] <inf> chip: [DL]NFC Tag emulation stopped [00:23:41.105,224] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:41.105,316] <inf> chip: [BLE]local and remote recv window sizes = 5 [00:23:41.105,377] <inf> chip: [BLE]selected BTP version 4 [00:23:41.105,468] <inf> chip: [BLE]using BTP fragment sizes rx 244 / tx 244. [00:23:41.205,169] <dbg> chip: [DL]ConnId: 0x00, New CCCD value: 0x0002 [00:23:41.205,261] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6) [00:23:41.205,566] <dbg> chip: [IN]BLE EndPoint 0x200149a0 Connection Complete [00:23:41.205,688] <inf> chip: [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 498) [00:23:41.304,901] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:41.307,739] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:41.308,166] <inf> chip: [EM]>>> [E:59609r M:128302565] (U) Msg RX from 0:5E4C83847FBB514F [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [00:23:41.308,319] <dbg> chip: [EM]Handling via exchange: 59609r, Delegate: 0x20008a7c [00:23:41.308,380] <dbg> chip: [SC]Received PBKDF param request [00:23:41.308,532] <dbg> chip: [SC]Peer assigned session ID 44071 [00:23:41.308,624] <dbg> chip: [SC]Found MRP parameters in the message [00:23:41.309,112] <dbg> chip: [SC]Including MRP parameters in PBKDF param response [00:23:41.309,722] <inf> chip: [EM]<<< [E:59609r M:264107694] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [00:23:41.309,875] <inf> chip: [IN](U) Sending msg 264107694 to IP address 'BLE' [00:23:41.309,997] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140) [00:23:41.310,302] <dbg> chip: [SC]Sent PBKDF param response [00:23:41.404,876] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:41.408,172] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:41.408,569] <inf> chip: [EM]>>> [E:59609r M:128302566] (U) Msg RX from 0:5E4C83847FBB514F [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) [00:23:41.408,691] <dbg> chip: [EM]Found matching exchange: 59609r, Delegate: 0x20008a7c [00:23:41.408,752] <dbg> chip: [SC]Received spake2p msg1 [00:23:42.196,014] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd1e [00:23:42.196,166] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e37 [00:23:42.196,350] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aed8 [00:23:42.198,303] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882b1 [00:23:42.198,486] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882b2 [00:23:42.198,638] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882b3 [00:23:42.198,822] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882b4 [00:23:42.199,005] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882b5 [00:23:42.199,188] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882b6 [00:23:42.199,371] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882b7 [00:23:42.980,682] <inf> chip: [EM]<<< [E:59609r M:264107695] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [00:23:42.980,804] <inf> chip: [IN](U) Sending msg 264107695 to IP address 'BLE' [00:23:42.980,957] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132) [00:23:42.981,231] <dbg> chip: [SC]Sent spake2p msg2 [00:23:42.981,353] <err> chip: [DL]Long dispatch time: 1573 ms, for event type 16388 [00:23:43.055,267] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:43.057,281] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:43.057,678] <inf> chip: [EM]>>> [E:59609r M:128302567] (U) Msg RX from 0:5E4C83847FBB514F [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) [00:23:43.057,800] <dbg> chip: [EM]Found matching exchange: 59609r, Delegate: 0x20008a7c [00:23:43.057,891] <dbg> chip: [SC]Received spake2p msg3 [00:23:43.058,410] <dbg> chip: [SC]Sending status report. Protocol code 0, exchange 59609 [00:23:43.058,715] <inf> chip: [EM]<<< [E:59609r M:264107696] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [00:23:43.058,837] <inf> chip: [IN](U) Sending msg 264107696 to IP address 'BLE' [00:23:43.058,990] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35) [00:23:43.060,180] <inf> chip: [SC]SecureSession[0x20006898]: Moving from state 'kEstablishing' --> 'kActive' [00:23:43.060,302] <dbg> chip: [IN]SecureSession[0x20006898]: Activated - Type:1 LSID:19973 [00:23:43.060,485] <dbg> chip: [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:19973 PSID:44071! [00:23:43.060,546] <inf> chip: [SVR]Commissioning completed session establishment step [00:23:43.060,943] <inf> chip: [DIS]Updating services using commissioning mode 0 [00:23:43.061,004] <dbg> chip: [DL]Using Thread extended MAC for hostname. [00:23:43.061,523] <dbg> chip: [DL]Using Thread extended MAC for hostname. [00:23:43.062,072] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32781 discriminator=3840/15 cm=0 [00:23:43.062,408] <err> chip: [DIS]Failed to advertise extended commissionable node: 3 [00:23:43.062,469] <dbg> chip: [DIS]Scheduling extended discovery timeout in 900s [00:23:43.062,561] <err> chip: [DIS]Failed to finalize service update: 1c [00:23:43.062,622] <dbg> chip: [DL]CHIPoBLE advertising set to off [00:23:43.062,744] <inf> chip: [SVR]Device completed Rendezvous process [00:23:43.154,968] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:43.159,332] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:43.160,614] <inf> chip: [EM]>>> [E:59610r M:7718912] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) [00:23:43.160,736] <dbg> chip: [EM]Handling via exchange: 59610r, Delegate: 0x2001236c [00:23:43.160,827] <dbg> chip: [IM]Received Read request [00:23:43.163,360] <dbg> chip: [DMG]IM RH moving to [GeneratingReports] [00:23:43.163,604] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 [00:23:43.163,726] <dbg> chip: [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty [00:23:43.163,879] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1) [00:23:43.164,093] <dbg> chip: [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty [00:23:43.164,245] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) [00:23:43.164,398] <dbg> chip: [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty [00:23:43.164,550] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) [00:23:43.164,733] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty [00:23:43.164,886] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) [00:23:43.165,039] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty [00:23:43.165,191] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) [00:23:43.165,374] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty [00:23:43.165,527] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0) [00:23:43.165,679] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty [00:23:43.165,832] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0) [00:23:43.166,046] <dbg> chip: [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty [00:23:43.166,198] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1) [00:23:43.166,412] <dbg> chip: [DMG]<RE> Sending report (payload has 228 bytes)... [00:23:43.168,182] <inf> chip: [EM]<<< [E:59610r M:214452935] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [00:23:43.168,334] <inf> chip: [IN](S) Sending msg 214452935 on secure session with LSID: 19973 [00:23:43.168,457] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:43.168,792] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0 [00:23:43.168,884] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages [00:23:43.168,975] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction] [00:23:43.169,067] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet [00:23:43.255,401] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:43.255,523] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 21) [00:23:43.355,072] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:43.357,543] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:43.358,489] <inf> chip: [EM]>>> [E:59611r M:7718913] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:43.358,612] <dbg> chip: [EM]Handling via exchange: 59611r, Delegate: 0x2001236c [00:23:43.359,161] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 [00:23:43.359,283] <inf> chip: [FS]GeneralCommissioning: Received ArmFailSafe (60s) [00:23:43.359,497] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 7d16fe0c [00:23:43.359,619] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:43.359,710] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:43.359,802] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:43.360,046] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:43.360,900] <inf> chip: [EM]<<< [E:59611r M:214452936] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:43.361,022] <inf> chip: [IN](S) Sending msg 214452936 on secure session with LSID: 19973 [00:23:43.361,145] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) [00:23:43.361,480] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:43.361,541] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:43.455,017] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:43.458,160] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:43.459,136] <inf> chip: [EM]>>> [E:59612r M:7718914] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:43.459,259] <dbg> chip: [EM]Handling via exchange: 59612r, Delegate: 0x2001236c [00:23:43.459,808] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 [00:23:43.460,296] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 7d16fe0d [00:23:43.460,418] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:43.460,510] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:43.460,601] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:43.460,845] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:43.461,700] <inf> chip: [EM]<<< [E:59612r M:214452937] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:43.461,822] <inf> chip: [IN](S) Sending msg 214452937 on secure session with LSID: 19973 [00:23:43.461,975] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) [00:23:43.462,280] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:43.462,341] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:43.555,175] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:43.557,647] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:43.558,624] <inf> chip: [EM]>>> [E:59613r M:7718915] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:43.558,746] <dbg> chip: [EM]Handling via exchange: 59613r, Delegate: 0x2001236c [00:23:43.559,295] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [00:23:43.559,387] <inf> chip: [ZCL]OpCreds: Certificate Chain request received for PAI [00:23:43.559,539] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:43.559,631] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:43.559,753] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:43.559,997] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:43.563,079] <inf> chip: [EM]<<< [E:59613r M:214452938] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:43.563,201] <inf> chip: [IN](S) Sending msg 214452938 on secure session with LSID: 19973 [00:23:43.563,354] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:43.563,690] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:43.563,751] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:43.705,108] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:43.705,230] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:43.805,236] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:43.805,358] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48) [00:23:43.905,364] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:43.907,653] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:43.908,630] <inf> chip: [EM]>>> [E:59614r M:7718916] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:43.908,752] <dbg> chip: [EM]Handling via exchange: 59614r, Delegate: 0x2001236c [00:23:43.909,301] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [00:23:43.909,393] <inf> chip: [ZCL]OpCreds: Certificate Chain request received for DAC [00:23:43.909,545] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:43.909,637] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:43.909,790] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:43.910,003] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:43.913,238] <inf> chip: [EM]<<< [E:59614r M:214452939] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:43.913,360] <inf> chip: [IN](S) Sending msg 214452939 on secure session with LSID: 19973 [00:23:43.913,513] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:43.913,848] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:43.913,909] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:44.005,371] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:44.005,493] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:44.105,133] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:44.105,255] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 76) [00:23:44.205,322] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:44.208,221] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:44.209,320] <inf> chip: [EM]>>> [E:59615r M:7718917] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:44.209,472] <dbg> chip: [EM]Handling via exchange: 59615r, Delegate: 0x2001236c [00:23:44.210,021] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 [00:23:44.210,113] <inf> chip: [ZCL]OpCreds: Received an AttestationRequest command [00:23:44.239,959] <inf> chip: [ZCL]OpCreds: AttestationRequest successful. [00:23:44.240,051] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:44.240,142] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:44.240,295] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:44.240,539] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:44.244,537] <inf> chip: [EM]<<< [E:59615r M:214452940] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:44.244,659] <inf> chip: [IN](S) Sending msg 214452940 on secure session with LSID: 19973 [00:23:44.244,781] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:44.245,147] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:44.245,208] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:44.355,438] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:44.355,560] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244) [00:23:44.455,444] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:44.455,596] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 236) [00:23:44.555,023] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:44.557,403] <dbg> chip: [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00) [00:23:44.558,380] <inf> chip: [EM]>>> [E:59616r M:7718918] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [00:23:44.558,502] <dbg> chip: [EM]Handling via exchange: 59616r, Delegate: 0x2001236c [00:23:44.559,051] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 [00:23:44.559,173] <inf> chip: [FS]GeneralCommissioning: Received ArmFailSafe (0s) [00:23:44.559,265] <inf> chip: [FS]Fail-safe timer expired [00:23:44.559,387] <dbg> chip: [DMG]Command handler moving to [ Preparing] [00:23:44.559,478] <dbg> chip: [DMG]Command handler moving to [AddingComm] [00:23:44.559,570] <dbg> chip: [DMG]Command handler moving to [AddedComma] [00:23:44.559,814] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0 [00:23:44.560,668] <inf> chip: [EM]<<< [E:59616r M:214452941] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [00:23:44.560,821] <inf> chip: [IN](S) Sending msg 214452941 on secure session with LSID: 19973 [00:23:44.560,943] <dbg> chip: [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71) [00:23:44.561,279] <dbg> chip: [DMG]Command handler moving to [CommandSen] [00:23:44.561,340] <dbg> chip: [DMG]Command handler moving to [AwaitingDe] [00:23:44.561,431] <err> chip: [SVR]Failsafe timer expired [00:23:44.561,553] <dbg> chip: [IN]SecureSession[0x20006898]: MarkForEviction Type:1 LSID:19973 [00:23:44.561,676] <inf> chip: [SC]SecureSession[0x20006898]: Moving from state 'kActive' --> 'kPendingEviction' [00:23:44.561,798] <dbg> chip: [IN]SecureSession[0x20006898]: Released - Type:1 LSID:19973 [00:23:44.561,889] <err> chip: [SVR]Commissioning failed (attempt 2): 32 [00:23:44.561,950] <dbg> chip: [IN]Clearing BLE pending packets. [00:23:44.562,042] <inf> chip: [BLE]Releasing end point's BLE connection back to application. [00:23:44.562,103] <inf> chip: [DL]Closing BLE GATT connection (ConnId 00) [00:23:44.564,086] <dbg> chip: [IN]SecureSession[0x20006898]: Allocated Type:1 LSID:19974 [00:23:44.564,178] <dbg> chip: [SC]Assigned local session key ID 19974 [00:23:44.564,270] <dbg> chip: [SC]Waiting for PBKDF param request [00:23:44.564,575] <dbg> chip: [DL]CHIPoBLE advertising set to on [00:23:44.564,666] <inf> chip: [DIS]Updating services using commissioning mode 1 [00:23:44.564,727] <dbg> chip: [DL]Using Thread extended MAC for hostname. [00:23:44.565,307] <dbg> chip: [DL]Using Thread extended MAC for hostname. [00:23:44.565,826] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32781 discriminator=3840/15 cm=1 [00:23:44.566,162] <err> chip: [DIS]Failed to advertise commissionable node: 3 [00:23:44.566,223] <err> chip: [DIS]Failed to finalize service update: 1c [00:23:44.566,284] <err> chip: [ZCL]OpCreds: Got FailSafeTimerExpired [00:23:44.566,375] <err> chip: [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry! [00:23:44.566,528] <inf> chip: [TS]Pending Last Known Good Time: 2023-01-17T22:28:56 [00:23:44.566,925] <inf> chip: [TS]Previous Last Known Good Time: 2023-01-17T22:28:56 [00:23:44.566,986] <inf> chip: [TS]Reverted Last Known Good Time to previous value [00:23:44.567,169] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 7d16fe0e [00:23:44.567,260] <dbg> chip: [ZCL]Failsafe timeout, tell platform driver to revert network credentials. [00:23:44.567,565] <inf> chip: [FS]Fail-safe cleanly disarmed [00:23:44.655,487] <err> bt_conn: not connected! [00:23:44.655,822] <dbg> chip: [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00) [00:23:44.655,883] <err> chip: [BLE]no endpoint for BLE sent data ack [00:23:44.655,975] <dbg> chip: [DL]ConnId: 0x00, New CCCD value: 0x0000 [00:23:44.656,066] <err> chip: [BLE]no endpoint for unsub recvd [00:23:44.823,455] <err> bt_conn: not connected! [00:23:45.005,004] <inf> chip: [DL]BLE GAP connection terminated (reason 0x22) [00:23:45.005,096] <inf> chip: [DL]Current number of connections: 0/1 [00:23:45.008,361] <inf> chip: [DL]CHIPoBLE advertising started [00:23:45.008,972] <inf> chip: [DL]NFC Tag emulation started [00:23:45.196,044] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd1f [00:23:45.196,228] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e38 [00:23:45.196,380] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aed9 [00:23:45.198,364] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882b8 [00:23:45.198,516] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882b9 [00:23:45.198,699] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882ba [00:23:45.198,852] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882bb [00:23:45.199,066] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882bc [00:23:45.199,249] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882bd [00:23:45.199,401] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882be [00:23:48.196,044] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd20 [00:23:48.196,228] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e39 [00:23:48.196,411] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aeda [00:23:48.198,394] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882bf [00:23:48.198,547] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882c0 [00:23:48.198,730] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882c1 [00:23:48.198,883] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882c2 [00:23:48.199,066] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882c3 [00:23:48.199,249] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882c4 [00:23:48.199,432] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882c5 [00:23:51.196,014] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd21 [00:23:51.196,197] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e3a [00:23:51.196,380] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aedb [00:23:51.198,364] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882c6 [00:23:51.198,547] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882c7 [00:23:51.198,730] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882c8 [00:23:51.198,883] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882c9 [00:23:51.199,066] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882ca [00:23:51.199,218] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882cb [00:23:51.199,432] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882cc [00:23:54.196,014] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd22 [00:23:54.196,197] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e3b [00:23:54.196,380] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aedc [00:23:54.198,333] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882cd [00:23:54.198,516] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882ce [00:23:54.198,699] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882cf [00:23:54.198,883] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882d0 [00:23:54.199,035] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882d1 [00:23:54.199,218] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882d2 [00:23:54.199,401] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882d3 [00:23:57.196,014] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd23 [00:23:57.196,197] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e3c [00:23:57.196,380] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aedd [00:23:57.198,333] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882d4 [00:23:57.198,516] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882d5 [00:23:57.198,699] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882d6 [00:23:57.198,883] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882d7 [00:23:57.199,035] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882d8 [00:23:57.199,218] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882d9 [00:23:57.199,401] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882da [00:24:00.196,014] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ed67bd24 [00:24:00.196,197] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to e5406e3d [00:24:00.196,380] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 8fd1aede [00:24:00.198,333] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882db [00:24:00.198,516] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882dc [00:24:00.198,669] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882dd [00:24:00.198,852] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882de [00:24:00.199,035] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882df [00:24:00.199,218] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882e0 [00:24:00.199,371] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to d44882e1 uart:~$ %
The command and output of the chip-tool:
./chip-tool-debug pairing ble-thread 2 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fd8d8d9a0b4f190d051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0f7f8 20202021 3840
[1673994866.603579][37215:37215] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1673994866.603652][37215:37215] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1673994866.603668][37215:37215] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1673994866.603677][37215:37215] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1673994866.603737][37215:37215] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-jUPC7d)
[1673994866.603832][37215:37215] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1673994866.603841][37215:37215] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4)
[1673994866.604139][37215:37215] CHIP:DL: Got Ethernet interface: enp5s0
[1673994866.604357][37215:37215] CHIP:DL: Found the primary Ethernet interface:enp5s0
[1673994866.604620][37215:37215] CHIP:DL: Failed to get WiFi interface
[1673994866.604623][37215:37215] CHIP:DL: Failed to reset WiFi statistic counts
[1673994866.604632][37215:37215] CHIP:IN: UDP::Init bind&listen port=0
[1673994866.604644][37215:37215] CHIP:IN: UDP::Init bound to port=59020
[1673994866.604646][37215:37215] CHIP:IN: UDP::Init bind&listen port=0
[1673994866.604654][37215:37215] CHIP:IN: UDP::Init bound to port=44926
[1673994866.604656][37215:37215] CHIP:IN: BLEBase::Init - setting/overriding transport
[1673994866.604657][37215:37215] CHIP:IN: TransportMgr initialized
[1673994866.604663][37215:37215] CHIP:FP: Initializing FabricTable from persistent storage
[1673994866.604686][37215:37215] CHIP:TS: Last Known Good Time: 2022-11-30T10:12:56
[1673994866.604785][37215:37215] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x18D3B463800CC4DB, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1673994866.605015][37215:37215] CHIP:ZCL: Using ZAP configuration...
[1673994866.606055][37215:37215] CHIP:DL: Avahi client registered
[1673994866.606313][37215:37215] CHIP:CTL: System State Initialized...
[1673994866.606327][37215:37215] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1673994866.606336][37215:37215] CHIP:CTL: Setting attestation nonce to random value
[1673994866.606340][37215:37215] CHIP:CTL: Setting CSR nonce to random value
[1673994866.606375][37215:37220] CHIP:DL: CHIP task running
[1673994866.606435][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1673994866.606498][37215:37220] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1673994866.606510][37215:37220] CHIP:CTL: Setting attestation nonce to random value
[1673994866.606526][37215:37220] CHIP:CTL: Setting CSR nonce to random value
[1673994866.607486][37215:37220] CHIP:CTL: Generating NOC
[1673994866.607756][37215:37220] CHIP:FP: Validating NOC chain
[1673994866.608311][37215:37220] CHIP:FP: NOC chain validation successful
[1673994866.608371][37215:37220] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1673994866.608378][37215:37220] CHIP:TS: Last Known Good Time: 2022-11-30T10:12:56
[1673994866.608382][37215:37220] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1673994866.608385][37215:37220] CHIP:TS: Retaining current Last Known Good Time
[1673994866.608799][37215:37220] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1673994866.609171][37215:37220] CHIP:TS: Committing Last Known Good Time to storage: 2022-11-30T10:12:56
[1673994866.609575][37215:37220] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1673994866.611788][37215:37220] CHIP:IN: SecureSession[0x7fed900215a0]: Allocated Type:1 LSID:44071
[1673994866.611802][37215:37220] CHIP:SC: Assigned local session key ID 44071
[1673994866.611822][37215:37220] CHIP:SC: Including MRP parameters in PBKDF param request
[1673994866.611845][37215:37220] CHIP:EM: <<< [E:59609i M:128302565] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1673994866.611858][37215:37220] CHIP:IN: (U) Sending msg 128302565 to IP address 'BLE'
[1673994866.611865][37215:37220] CHIP:IN: Message appended to BLE send queue
[1673994866.611870][37215:37220] CHIP:SC: Sent PBKDF param request
[1673994866.611877][37215:37220] CHIP:CTL: Setting thread operational dataset from parameters
[1673994866.611882][37215:37220] CHIP:CTL: Setting attempt thread scan from parameters
[1673994866.611887][37215:37220] CHIP:CTL: Setting attestation nonce to random value
[1673994866.611895][37215:37220] CHIP:CTL: Setting CSR nonce to random value
[1673994866.611902][37215:37220] CHIP:CTL: Commission called for node ID 0x0000000000000002
[1673994866.611963][37215:37221] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1673994866.612003][37215:37218] CHIP:DL: TRACE: Bus acquired for name C-915f
[1673994866.615869][37215:37220] CHIP:DL: PlatformBlueZInit init success
[1673994866.617891][37215:37218] CHIP:BLE: BLE removing known devices.
[1673994866.624188][37215:37218] CHIP:BLE: BLE initiating scan.
[1673994867.074817][37215:37220] CHIP:DL: Long dispatch time: 463 ms, for event type 2
[1673994867.095924][37215:37218] CHIP:BLE: New device scanned: CD:CC:01:50:92:8F
[1673994867.095944][37215:37218] CHIP:BLE: Device discriminator match. Attempting to connect.
[1673994867.110647][37215:37218] CHIP:BLE: Scan complete notification without an active scan.
[1673994867.632973][37215:37218] CHIP:DL: ConnectDevice complete
[1673994867.960032][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0010
[1673994867.960048][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960055][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0010
[1673994867.960058][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960063][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0010
[1673994867.960067][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960073][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0001
[1673994867.960076][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960081][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0001
[1673994867.960085][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960089][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0001
[1673994867.960093][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960098][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960102][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960110][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960113][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960118][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960122][37215:37218] CHIP:DL: Char1 /org/bluez/hci0/dev_CD_CC_01_50_92_8F/service0014
[1673994867.960130][37215:37218] CHIP:DL: New BLE connection 0x7fed98039250, device CD:CC:01:50:92:8F, path /org/bluez/hci0/dev_CD_CC_01_50_92_8F
[1673994867.960163][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1673994867.960176][37215:37220] CHIP:IN: BleConnectionComplete: endPoint 0x556f2b646c20
[1673994868.482398][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1673994868.582833][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1673994868.582851][37215:37220] CHIP:BLE: subscribe complete, ep = 0x556f2b646c20
[1673994868.583247][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994868.583297][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994868.583309][37215:37220] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1673994868.583314][37215:37220] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1673994868.583316][37215:37220] CHIP:BLE: local and remote recv window size = 5
[1673994868.583341][37215:37220] CHIP:IN: BLE EndPoint 0x556f2b646c20 Connection Complete
[1673994868.682348][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1673994868.686601][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994868.686627][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994868.686666][37215:37220] CHIP:EM: >>> [E:59609i M:264107694] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[1673994868.686673][37215:37220] CHIP:EM: Found matching exchange: 59609i, Delegate: 0x7fed900236e0
[1673994868.686681][37215:37220] CHIP:SC: Received PBKDF param response
[1673994868.686692][37215:37220] CHIP:SC: Peer assigned session ID 19973
[1673994868.686698][37215:37220] CHIP:SC: Found MRP parameters in the message
[1673994868.688100][37215:37220] CHIP:EM: <<< [E:59609i M:128302566] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[1673994868.688112][37215:37220] CHIP:IN: (U) Sending msg 128302566 to IP address 'BLE'
[1673994868.688133][37215:37220] CHIP:SC: Sent spake2p msg1
[1673994868.782369][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1673994870.336207][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994870.336251][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994870.336291][37215:37220] CHIP:EM: >>> [E:59609i M:264107695] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[1673994870.336298][37215:37220] CHIP:EM: Found matching exchange: 59609i, Delegate: 0x7fed900236e0
[1673994870.336305][37215:37220] CHIP:SC: Received spake2p msg2
[1673994870.336613][37215:37220] CHIP:EM: <<< [E:59609i M:128302567] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[1673994870.336622][37215:37220] CHIP:IN: (U) Sending msg 128302567 to IP address 'BLE'
[1673994870.336641][37215:37220] CHIP:SC: Sent spake2p msg3
[1673994870.432325][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1673994870.433880][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994870.433907][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994870.433952][37215:37220] CHIP:EM: >>> [E:59609i M:264107696] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1673994870.433961][37215:37220] CHIP:EM: Found matching exchange: 59609i, Delegate: 0x7fed900236e0
[1673994870.433995][37215:37220] CHIP:SC: SecureSession[0x7fed900215a0]: Moving from state 'kEstablishing' --> 'kActive'
[1673994870.434000][37215:37220] CHIP:IN: SecureSession[0x7fed900215a0]: Activated - Type:1 LSID:44071
[1673994870.434004][37215:37220] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:44071 PSID:19973!
[1673994870.434011][37215:37220] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1673994870.434015][37215:37220] CHIP:TOO: Pairing Success
[1673994870.434019][37215:37220] CHIP:TOO: PASE establishment successful
[1673994870.434024][37215:37220] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1673994870.434031][37215:37220] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1673994870.434036][37215:37220] CHIP:CTL: Sending request for commissioning information
[1673994870.434050][37215:37220] CHIP:DMG: SendReadRequest ReadClient[0x7fed90034c20]: Sending Read Request
[1673994870.434092][37215:37220] CHIP:EM: <<< [E:59610i M:7718912] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
[1673994870.434102][37215:37220] CHIP:IN: (S) Sending msg 7718912 on secure session with LSID: 44071
[1673994870.434128][37215:37220] CHIP:DMG: MoveToState ReadClient[0x7fed90034c20]: Moving to [AwaitingIn]
[1673994870.532317][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1673994870.539280][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994870.539345][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994870.639978][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994870.640021][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994870.640065][37215:37220] CHIP:EM: >>> [E:59610i M:214452935] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[1673994870.640073][37215:37220] CHIP:EM: Found matching exchange: 59610i, Delegate: 0x7fed90034c30
[1673994870.640104][37215:37220] CHIP:DMG: ReportDataMessage =
[1673994870.640110][37215:37220] CHIP:DMG: {
[1673994870.640113][37215:37220] CHIP:DMG: AttributeReportIBs =
[1673994870.640118][37215:37220] CHIP:DMG: [
[1673994870.640121][37215:37220] CHIP:DMG: AttributeReportIB =
[1673994870.640127][37215:37220] CHIP:DMG: {
[1673994870.640130][37215:37220] CHIP:DMG: AttributeDataIB =
[1673994870.640134][37215:37220] CHIP:DMG: {
[1673994870.640139][37215:37220] CHIP:DMG: DataVersion = 0x6a0dece1,
[1673994870.640143][37215:37220] CHIP:DMG: AttributePathIB =
[1673994870.640149][37215:37220] CHIP:DMG: {
[1673994870.640154][37215:37220] CHIP:DMG: Endpoint = 0x0,
[1673994870.640158][37215:37220] CHIP:DMG: Cluster = 0x31,
[1673994870.640164][37215:37220] CHIP:DMG: Attribute = 0x0000_0003,
[1673994870.640168][37215:37220] CHIP:DMG: }
[1673994870.640173][37215:37220] CHIP:DMG:
[1673994870.640178][37215:37220] CHIP:DMG: Data = 20,
[1673994870.640182][37215:37220] CHIP:DMG: },
[1673994870.640187][37215:37220] CHIP:DMG:
[1673994870.640190][37215:37220] CHIP:DMG: },
[1673994870.640197][37215:37220] CHIP:DMG:
[1673994870.640200][37215:37220] CHIP:DMG: AttributeReportIB =
[1673994870.640205][37215:37220] CHIP:DMG: {
[1673994870.640208][37215:37220] CHIP:DMG: AttributeDataIB =
[1673994870.640212][37215:37220] CHIP:DMG: {
[1673994870.640216][37215:37220] CHIP:DMG: DataVersion = 0x51dd4ab9,
[1673994870.640220][37215:37220] CHIP:DMG: AttributePathIB =
[1673994870.640223][37215:37220] CHIP:DMG: {
[1673994870.640228][37215:37220] CHIP:DMG: Endpoint = 0x0,
[1673994870.640233][37215:37220] CHIP:DMG: Cluster = 0x28,
[1673994870.640238][37215:37220] CHIP:DMG: Attribute = 0x0000_0004,
[1673994870.640243][37215:37220] CHIP:DMG: }
[1673994870.640249][37215:37220] CHIP:DMG:
[1673994870.640253][37215:37220] CHIP:DMG: Data = 32781,
[1673994870.640258][37215:37220] CHIP:DMG: },
[1673994870.640263][37215:37220] CHIP:DMG:
[1673994870.640267][37215:37220] CHIP:DMG: },
[1673994870.640275][37215:37220] CHIP:DMG:
[1673994870.640278][37215:37220] CHIP:DMG: AttributeReportIB =
[1673994870.640287][37215:37220] CHIP:DMG: {
[1673994870.640290][37215:37220] CHIP:DMG: AttributeDataIB =
[1673994870.640294][37215:37220] CHIP:DMG: {
[1673994870.640299][37215:37220] CHIP:DMG: DataVersion = 0x51dd4ab9,
[1673994870.640303][37215:37220] CHIP:DMG: AttributePathIB =
[1673994870.640307][37215:37220] CHIP:DMG: {
[1673994870.640312][37215:37220] CHIP:DMG: Endpoint = 0x0,
[1673994870.640320][37215:37220] CHIP:DMG: Cluster = 0x28,
[1673994870.640325][37215:37220] CHIP:DMG: Attribute = 0x0000_0002,
[1673994870.640329][37215:37220] CHIP:DMG: }
[1673994870.640334][37215:37220] CHIP:DMG:
[1673994870.640340][37215:37220] CHIP:DMG: Data = 65521,
[1673994870.640344][37215:37220] CHIP:DMG: },
[1673994870.640350][37215:37220] CHIP:DMG:
[1673994870.640354][37215:37220] CHIP:DMG: },
[1673994870.640360][37215:37220] CHIP:DMG:
[1673994870.640365][37215:37220] CHIP:DMG: AttributeReportIB =
[1673994870.640369][37215:37220] CHIP:DMG: {
[1673994870.640372][37215:37220] CHIP:DMG: AttributeDataIB =
[1673994870.640377][37215:37220] CHIP:DMG: {
[1673994870.640382][37215:37220] CHIP:DMG: DataVersion = 0x7d16fe0b,
[1673994870.640387][37215:37220] CHIP:DMG: AttributePathIB =
[1673994870.640390][37215:37220] CHIP:DMG: {
[1673994870.640394][37215:37220] CHIP:DMG: Endpoint = 0x0,
[1673994870.640399][37215:37220] CHIP:DMG: Cluster = 0x30,
[1673994870.640404][37215:37220] CHIP:DMG: Attribute = 0x0000_0003,
[1673994870.640408][37215:37220] CHIP:DMG: }
[1673994870.640413][37215:37220] CHIP:DMG:
[1673994870.640426][37215:37220] CHIP:DMG: Data = 0,
[1673994870.640432][37215:37220] CHIP:DMG: },
[1673994870.640439][37215:37220] CHIP:DMG:
[1673994870.640444][37215:37220] CHIP:DMG: },
[1673994870.640454][37215:37220] CHIP:DMG:
[1673994870.640459][37215:37220] CHIP:DMG: AttributeReportIB =
[1673994870.640467][37215:37220] CHIP:DMG: {
[1673994870.640472][37215:37220] CHIP:DMG: AttributeDataIB =
[1673994870.640478][37215:37220] CHIP:DMG: {
[1673994870.640484][37215:37220] CHIP:DMG: DataVersion = 0x7d16fe0b,
[1673994870.640489][37215:37220] CHIP:DMG: AttributePathIB =
[1673994870.640494][37215:37220] CHIP:DMG: {
[1673994870.640500][37215:37220] CHIP:DMG: Endpoint = 0x0,
[1673994870.640512][37215:37220] CHIP:DMG: Cluster = 0x30,
[1673994870.640528][37215:37220] CHIP:DMG: Attribute = 0x0000_0002,
[1673994870.640536][37215:37220] CHIP:DMG: }
[1673994870.640544][37215:37220] CHIP:DMG:
[1673994870.640552][37215:37220] CHIP:DMG: Data = 0,
[1673994870.640558][37215:37220] CHIP:DMG: },
[1673994870.640567][37215:37220] CHIP:DMG:
[1673994870.640573][37215:37220] CHIP:DMG: },
[1673994870.640584][37215:37220] CHIP:DMG:
[1673994870.640588][37215:37220] CHIP:DMG: AttributeReportIB =
[1673994870.640597][37215:37220] CHIP:DMG: {
[1673994870.640602][37215:37220] CHIP:DMG: AttributeDataIB =
[1673994870.640608][37215:37220] CHIP:DMG: {
[1673994870.640615][37215:37220] CHIP:DMG: DataVersion = 0x7d16fe0b,
[1673994870.640622][37215:37220] CHIP:DMG: AttributePathIB =
[1673994870.640629][37215:37220] CHIP:DMG: {
[1673994870.640634][37215:37220] CHIP:DMG: Endpoint = 0x0,
[1673994870.640641][37215:37220] CHIP:DMG: Cluster = 0x30,
[1673994870.640649][37215:37220] CHIP:DMG: Attribute = 0x0000_0001,
[1673994870.640656][37215:37220] CHIP:DMG: }
[1673994870.640664][37215:37220] CHIP:DMG:
[1673994870.640671][37215:37220] CHIP:DMG: Data =
[1673994870.640677][37215:37220] CHIP:DMG: {
[1673994870.640685][37215:37220] CHIP:DMG: 0x0 = 60,
[1673994870.640693][37215:37220] CHIP:DMG: 0x1 = 900,
[1673994870.640700][37215:37220] CHIP:DMG: },
[1673994870.640706][37215:37220] CHIP:DMG: },
[1673994870.640715][37215:37220] CHIP:DMG:
[1673994870.640720][37215:37220] CHIP:DMG: },
[1673994870.640731][37215:37220] CHIP:DMG:
[1673994870.640736][37215:37220] CHIP:DMG: AttributeReportIB =
[1673994870.640745][37215:37220] CHIP:DMG: {
[1673994870.640750][37215:37220] CHIP:DMG: AttributeDataIB =
[1673994870.640756][37215:37220] CHIP:DMG: {
[1673994870.640762][37215:37220] CHIP:DMG: DataVersion = 0x7d16fe0b,
[1673994870.640770][37215:37220] CHIP:DMG: AttributePathIB =
[1673994870.640779][37215:37220] CHIP:DMG: {
[1673994870.640785][37215:37220] CHIP:DMG: Endpoint = 0x0,
[1673994870.640791][37215:37220] CHIP:DMG: Cluster = 0x30,
[1673994870.640797][37215:37220] CHIP:DMG: Attribute = 0x0000_0000,
[1673994870.640802][37215:37220] CHIP:DMG: }
[1673994870.640811][37215:37220] CHIP:DMG:
[1673994870.640819][37215:37220] CHIP:DMG: Data = 0,
[1673994870.640825][37215:37220] CHIP:DMG: },
[1673994870.640833][37215:37220] CHIP:DMG:
[1673994870.640839][37215:37220] CHIP:DMG: },
[1673994870.640848][37215:37220] CHIP:DMG:
[1673994870.640853][37215:37220] CHIP:DMG: AttributeReportIB =
[1673994870.640861][37215:37220] CHIP:DMG: {
[1673994870.640865][37215:37220] CHIP:DMG: AttributeDataIB =
[1673994870.640871][37215:37220] CHIP:DMG: {
[1673994870.640878][37215:37220] CHIP:DMG: DataVersion = 0x6a0dece1,
[1673994870.640885][37215:37220] CHIP:DMG: AttributePathIB =
[1673994870.640892][37215:37220] CHIP:DMG: {
[1673994870.640899][37215:37220] CHIP:DMG: Endpoint = 0x0,
[1673994870.640907][37215:37220] CHIP:DMG: Cluster = 0x31,
[1673994870.640914][37215:37220] CHIP:DMG: Attribute = 0x0000_FFFC,
[1673994870.640918][37215:37220] CHIP:DMG: }
[1673994870.640923][37215:37220] CHIP:DMG:
[1673994870.640928][37215:37220] CHIP:DMG: Data = 2,
[1673994870.640932][37215:37220] CHIP:DMG: },
[1673994870.640937][37215:37220] CHIP:DMG:
[1673994870.640940][37215:37220] CHIP:DMG: },
[1673994870.640945][37215:37220] CHIP:DMG:
[1673994870.640948][37215:37220] CHIP:DMG: ],
[1673994870.640964][37215:37220] CHIP:DMG:
[1673994870.640968][37215:37220] CHIP:DMG: SuppressResponse = true,
[1673994870.640971][37215:37220] CHIP:DMG: InteractionModelRevision = 1
[1673994870.640974][37215:37220] CHIP:DMG: }
[1673994870.641236][37215:37220] CHIP:CTL: ----- NetworkCommissioning Features: has Thread. endpointid = 0
[1673994870.641258][37215:37220] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1673994870.641264][37215:37220] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1673994870.641269][37215:37220] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1673994870.641272][37215:37220] CHIP:CTL: Arming failsafe (60 seconds)
[1673994870.641287][37215:37220] CHIP:DMG: ICR moving to [AddingComm]
[1673994870.641291][37215:37220] CHIP:DMG: ICR moving to [AddedComma]
[1673994870.641314][37215:37220] CHIP:EM: <<< [E:59611i M:7718913] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1673994870.641322][37215:37220] CHIP:IN: (S) Sending msg 7718913 on secure session with LSID: 44071
[1673994870.641343][37215:37220] CHIP:DMG: ICR moving to [CommandSen]
[1673994870.732283][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1673994870.734646][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994870.734679][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994870.734746][37215:37220] CHIP:EM: >>> [E:59611i M:214452936] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1673994870.734759][37215:37220] CHIP:EM: Found matching exchange: 59611i, Delegate: 0x7fed98039f78
[1673994870.734770][37215:37220] CHIP:DMG: ICR moving to [ResponseRe]
[1673994870.734792][37215:37220] CHIP:DMG: InvokeResponseMessage =
[1673994870.734799][37215:37220] CHIP:DMG: {
[1673994870.734805][37215:37220] CHIP:DMG: suppressResponse = false,
[1673994870.734811][37215:37220] CHIP:DMG: InvokeResponseIBs =
[1673994870.734820][37215:37220] CHIP:DMG: [
[1673994870.734825][37215:37220] CHIP:DMG: InvokeResponseIB =
[1673994870.734833][37215:37220] CHIP:DMG: {
[1673994870.734837][37215:37220] CHIP:DMG: CommandDataIB =
[1673994870.734843][37215:37220] CHIP:DMG: {
[1673994870.734847][37215:37220] CHIP:DMG: CommandPathIB =
[1673994870.734853][37215:37220] CHIP:DMG: {
[1673994870.734858][37215:37220] CHIP:DMG: EndpointId = 0x0,
[1673994870.734864][37215:37220] CHIP:DMG: ClusterId = 0x30,
[1673994870.734869][37215:37220] CHIP:DMG: CommandId = 0x1,
[1673994870.734875][37215:37220] CHIP:DMG: },
[1673994870.734881][37215:37220] CHIP:DMG:
[1673994870.734886][37215:37220] CHIP:DMG: CommandFields =
[1673994870.734891][37215:37220] CHIP:DMG: {
[1673994870.734897][37215:37220] CHIP:DMG: 0x0 = 0,
[1673994870.734904][37215:37220] CHIP:DMG: 0x1 = "" (0 chars),
[1673994870.734909][37215:37220] CHIP:DMG: },
[1673994870.734913][37215:37220] CHIP:DMG: },
[1673994870.734922][37215:37220] CHIP:DMG:
[1673994870.734926][37215:37220] CHIP:DMG: },
[1673994870.734933][37215:37220] CHIP:DMG:
[1673994870.734937][37215:37220] CHIP:DMG: ],
[1673994870.734945][37215:37220] CHIP:DMG:
[1673994870.734949][37215:37220] CHIP:DMG: InteractionModelRevision = 1
[1673994870.734953][37215:37220] CHIP:DMG: },
[1673994870.734974][37215:37220] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1673994870.734986][37215:37220] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1673994870.734995][37215:37220] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1673994870.735001][37215:37220] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks
[1673994870.735005][37215:37220] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1673994870.735012][37215:37220] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1673994870.735017][37215:37220] CHIP:CTL: Setting Regulatory Config
[1673994870.735022][37215:37220] CHIP:CTL: Device does not support configurable regulatory location
[1673994870.735048][37215:37220] CHIP:DMG: ICR moving to [AddingComm]
[1673994870.735058][37215:37220] CHIP:DMG: ICR moving to [AddedComma]
[1673994870.735084][37215:37220] CHIP:EM: <<< [E:59612i M:7718914] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1673994870.735094][37215:37220] CHIP:IN: (S) Sending msg 7718914 on secure session with LSID: 44071
[1673994870.735120][37215:37220] CHIP:DMG: ICR moving to [CommandSen]
[1673994870.735143][37215:37220] CHIP:DMG: ICR moving to [AwaitingDe]
[1673994870.832300][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1673994870.834606][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994870.834628][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994870.834689][37215:37220] CHIP:EM: >>> [E:59612i M:214452937] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1673994870.834700][37215:37220] CHIP:EM: Found matching exchange: 59612i, Delegate: 0x7fed90020fd8
[1673994870.834709][37215:37220] CHIP:DMG: ICR moving to [ResponseRe]
[1673994870.834726][37215:37220] CHIP:DMG: InvokeResponseMessage =
[1673994870.834730][37215:37220] CHIP:DMG: {
[1673994870.834735][37215:37220] CHIP:DMG: suppressResponse = false,
[1673994870.834739][37215:37220] CHIP:DMG: InvokeResponseIBs =
[1673994870.834747][37215:37220] CHIP:DMG: [
[1673994870.834751][37215:37220] CHIP:DMG: InvokeResponseIB =
[1673994870.834758][37215:37220] CHIP:DMG: {
[1673994870.834763][37215:37220] CHIP:DMG: CommandDataIB =
[1673994870.834768][37215:37220] CHIP:DMG: {
[1673994870.834773][37215:37220] CHIP:DMG: CommandPathIB =
[1673994870.834780][37215:37220] CHIP:DMG: {
[1673994870.834786][37215:37220] CHIP:DMG: EndpointId = 0x0,
[1673994870.834792][37215:37220] CHIP:DMG: ClusterId = 0x30,
[1673994870.834801][37215:37220] CHIP:DMG: CommandId = 0x3,
[1673994870.834809][37215:37220] CHIP:DMG: },
[1673994870.834815][37215:37220] CHIP:DMG:
[1673994870.834820][37215:37220] CHIP:DMG: CommandFields =
[1673994870.834826][37215:37220] CHIP:DMG: {
[1673994870.834833][37215:37220] CHIP:DMG: 0x0 = 0,
[1673994870.834841][37215:37220] CHIP:DMG: 0x1 = "" (0 chars),
[1673994870.834847][37215:37220] CHIP:DMG: },
[1673994870.834853][37215:37220] CHIP:DMG: },
[1673994870.834859][37215:37220] CHIP:DMG:
[1673994870.834864][37215:37220] CHIP:DMG: },
[1673994870.834870][37215:37220] CHIP:DMG:
[1673994870.834873][37215:37220] CHIP:DMG: ],
[1673994870.834881][37215:37220] CHIP:DMG:
[1673994870.834885][37215:37220] CHIP:DMG: InteractionModelRevision = 1
[1673994870.834888][37215:37220] CHIP:DMG: },
[1673994870.834909][37215:37220] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1673994870.834930][37215:37220] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0
[1673994870.834939][37215:37220] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'
[1673994870.834944][37215:37220] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[1673994870.834951][37215:37220] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'
[1673994870.834955][37215:37220] CHIP:CTL: Sending request for PAI certificate
[1673994870.834958][37215:37220] CHIP:CTL: Sending Certificate Chain request to 0x7fed90023690 device
[1673994870.834978][37215:37220] CHIP:DMG: ICR moving to [AddingComm]
[1673994870.834984][37215:37220] CHIP:DMG: ICR moving to [AddedComma]
[1673994870.835008][37215:37220] CHIP:EM: <<< [E:59613i M:7718915] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1673994870.835017][37215:37220] CHIP:IN: (S) Sending msg 7718915 on secure session with LSID: 44071
[1673994870.835043][37215:37220] CHIP:DMG: ICR moving to [CommandSen]
[1673994870.835066][37215:37220] CHIP:DMG: ICR moving to [AwaitingDe]
[1673994870.932322][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1673994870.988268][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994870.988321][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994871.088929][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994871.088977][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994871.184066][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994871.184115][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994871.184163][37215:37220] CHIP:EM: >>> [E:59613i M:214452938] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1673994871.184172][37215:37220] CHIP:EM: Found matching exchange: 59613i, Delegate: 0x7fed98039f78
[1673994871.184182][37215:37220] CHIP:DMG: ICR moving to [ResponseRe]
[1673994871.184198][37215:37220] CHIP:DMG: InvokeResponseMessage =
[1673994871.184202][37215:37220] CHIP:DMG: {
[1673994871.184207][37215:37220] CHIP:DMG: suppressResponse = false,
[1673994871.184212][37215:37220] CHIP:DMG: InvokeResponseIBs =
[1673994871.184219][37215:37220] CHIP:DMG: [
[1673994871.184223][37215:37220] CHIP:DMG: InvokeResponseIB =
[1673994871.184230][37215:37220] CHIP:DMG: {
[1673994871.184235][37215:37220] CHIP:DMG: CommandDataIB =
[1673994871.184240][37215:37220] CHIP:DMG: {
[1673994871.184244][37215:37220] CHIP:DMG: CommandPathIB =
[1673994871.184250][37215:37220] CHIP:DMG: {
[1673994871.184255][37215:37220] CHIP:DMG: EndpointId = 0x0,
[1673994871.184261][37215:37220] CHIP:DMG: ClusterId = 0x3e,
[1673994871.184267][37215:37220] CHIP:DMG: CommandId = 0x3,
[1673994871.184272][37215:37220] CHIP:DMG: },
[1673994871.184278][37215:37220] CHIP:DMG:
[1673994871.184284][37215:37220] CHIP:DMG: CommandFields =
[1673994871.184290][37215:37220] CHIP:DMG: {
[1673994871.184296][37215:37220] CHIP:DMG: 0x0 = [
[1673994871.184343][37215:37220] CHIP:DMG: 0x30, 0x82, 0x01, 0xcb, 0x30, 0x82, 0x01, 0x71, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x0f, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0x0c, 0x8c, 0x87, 0x6d, 0x03, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x05, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x09, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0x0b, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x06, 0x03, 0x55, 0x1d, 0x
[1673994871.184365][37215:37220] CHIP:DMG: ] (463 bytes)
[1673994871.184370][37215:37220] CHIP:DMG: },
[1673994871.184374][37215:37220] CHIP:DMG: },
[1673994871.184381][37215:37220] CHIP:DMG:
[1673994871.184385][37215:37220] CHIP:DMG: },
[1673994871.184392][37215:37220] CHIP:DMG:
[1673994871.184396][37215:37220] CHIP:DMG: ],
[1673994871.184403][37215:37220] CHIP:DMG:
[1673994871.184407][37215:37220] CHIP:DMG: InteractionModelRevision = 1
[1673994871.184411][37215:37220] CHIP:DMG: },
[1673994871.184429][37215:37220] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1673994871.184438][37215:37220] CHIP:CTL: Received certificate chain from the device
[1673994871.184448][37215:37220] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
[1673994871.184454][37215:37220] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[1673994871.184460][37215:37220] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'
[1673994871.184464][37215:37220] CHIP:CTL: Sending request for DAC certificate
[1673994871.184468][37215:37220] CHIP:CTL: Sending Certificate Chain request to 0x7fed90023690 device
[1673994871.184486][37215:37220] CHIP:DMG: ICR moving to [AddingComm]
[1673994871.184492][37215:37220] CHIP:DMG: ICR moving to [AddedComma]
[1673994871.184511][37215:37220] CHIP:EM: <<< [E:59614i M:7718916] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1673994871.184519][37215:37220] CHIP:IN: (S) Sending msg 7718916 on secure session with LSID: 44071
[1673994871.184543][37215:37220] CHIP:DMG: ICR moving to [CommandSen]
[1673994871.184557][37215:37220] CHIP:DMG: ICR moving to [AwaitingDe]
[1673994871.282319][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1673994871.289270][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994871.289308][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994871.388856][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994871.388900][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994871.484745][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994871.484797][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994871.484849][37215:37220] CHIP:EM: >>> [E:59614i M:214452939] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1673994871.484858][37215:37220] CHIP:EM: Found matching exchange: 59614i, Delegate: 0x7fed9803a588
[1673994871.484868][37215:37220] CHIP:DMG: ICR moving to [ResponseRe]
[1673994871.484885][37215:37220] CHIP:DMG: InvokeResponseMessage =
[1673994871.484889][37215:37220] CHIP:DMG: {
[1673994871.484895][37215:37220] CHIP:DMG: suppressResponse = false,
[1673994871.484899][37215:37220] CHIP:DMG: InvokeResponseIBs =
[1673994871.484907][37215:37220] CHIP:DMG: [
[1673994871.484911][37215:37220] CHIP:DMG: InvokeResponseIB =
[1673994871.484919][37215:37220] CHIP:DMG: {
[1673994871.484923][37215:37220] CHIP:DMG: CommandDataIB =
[1673994871.484933][37215:37220] CHIP:DMG: {
[1673994871.484938][37215:37220] CHIP:DMG: CommandPathIB =
[1673994871.484943][37215:37220] CHIP:DMG: {
[1673994871.484949][37215:37220] CHIP:DMG: EndpointId = 0x0,
[1673994871.484954][37215:37220] CHIP:DMG: ClusterId = 0x3e,
[1673994871.484962][37215:37220] CHIP:DMG: CommandId = 0x3,
[1673994871.484967][37215:37220] CHIP:DMG: },
[1673994871.484972][37215:37220] CHIP:DMG:
[1673994871.484977][37215:37220] CHIP:DMG: CommandFields =
[1673994871.484982][37215:37220] CHIP:DMG: {
[1673994871.484993][37215:37220] CHIP:DMG: 0x0 = [
[1673994871.485043][37215:37220] CHIP:DMG: 0x30, 0x82, 0x01, 0xe7, 0x30, 0x82, 0x01, 0x8e, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x24, 0x01, 0x4c, 0xae, 0x54, 0xae, 0xbf, 0xa3, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x44, 0x41, 0x43, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x2f, 0x30, 0x78, 0x38, 0x30, 0x30, 0x44, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x38, 0x30, 0x30, 0x44, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0xcc, 0x06, 0x56, 0x50, 0x7e, 0xcb, 0x0f, 0x6d, 0xbe, 0x9d, 0x2f, 0xf6, 0x71, 0x89, 0x2b, 0x3b, 0xdc, 0x12, 0x87, 0x2b, 0x16, 0x10, 0x24, 0x7d, 0x4e, 0xac, 0x00, 0x26, 0x3d, 0x80, 0xea, 0xf8, 0x44, 0xa3, 0x64, 0x21, 0x4b, 0xbb, 0x6a, 0x
[1673994871.485065][37215:37220] CHIP:DMG: ] (491 bytes)
[1673994871.485070][37215:37220] CHIP:DMG: },
[1673994871.485075][37215:37220] CHIP:DMG: },
[1673994871.485084][37215:37220] CHIP:DMG:
[1673994871.485088][37215:37220] CHIP:DMG: },
[1673994871.485094][37215:37220] CHIP:DMG:
[1673994871.485098][37215:37220] CHIP:DMG: ],
[1673994871.485105][37215:37220] CHIP:DMG:
[1673994871.485109][37215:37220] CHIP:DMG: InteractionModelRevision = 1
[1673994871.485116][37215:37220] CHIP:DMG: },
[1673994871.485134][37215:37220] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1673994871.485143][37215:37220] CHIP:CTL: Received certificate chain from the device
[1673994871.485151][37215:37220] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
[1673994871.485157][37215:37220] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[1673994871.485164][37215:37220] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'
[1673994871.485168][37215:37220] CHIP:CTL: Sending Attestation Request to the device.
[1673994871.485172][37215:37220] CHIP:CTL: Sending Attestation request to 0x7fed90023690 device
[1673994871.485192][37215:37220] CHIP:DMG: ICR moving to [AddingComm]
[1673994871.485197][37215:37220] CHIP:DMG: ICR moving to [AddedComma]
[1673994871.485217][37215:37220] CHIP:EM: <<< [E:59615i M:7718917] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1673994871.485225][37215:37220] CHIP:IN: (S) Sending msg 7718917 on secure session with LSID: 44071
[1673994871.485249][37215:37220] CHIP:DMG: ICR moving to [CommandSen]
[1673994871.485255][37215:37220] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information
[1673994871.485267][37215:37220] CHIP:DMG: ICR moving to [AwaitingDe]
[1673994871.582297][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1673994871.634154][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994871.634201][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994871.738850][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994871.738899][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994871.838334][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994871.838383][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994871.838436][37215:37220] CHIP:EM: >>> [E:59615i M:214452940] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1673994871.838446][37215:37220] CHIP:EM: Found matching exchange: 59615i, Delegate: 0x7fed9803aaa8
[1673994871.838459][37215:37220] CHIP:DMG: ICR moving to [ResponseRe]
[1673994871.838475][37215:37220] CHIP:DMG: InvokeResponseMessage =
[1673994871.838479][37215:37220] CHIP:DMG: {
[1673994871.838484][37215:37220] CHIP:DMG: suppressResponse = false,
[1673994871.838488][37215:37220] CHIP:DMG: InvokeResponseIBs =
[1673994871.838495][37215:37220] CHIP:DMG: [
[1673994871.838499][37215:37220] CHIP:DMG: InvokeResponseIB =
[1673994871.838512][37215:37220] CHIP:DMG: {
[1673994871.838517][37215:37220] CHIP:DMG: CommandDataIB =
[1673994871.838522][37215:37220] CHIP:DMG: {
[1673994871.838527][37215:37220] CHIP:DMG: CommandPathIB =
[1673994871.838532][37215:37220] CHIP:DMG: {
[1673994871.838537][37215:37220] CHIP:DMG: EndpointId = 0x0,
[1673994871.838544][37215:37220] CHIP:DMG: ClusterId = 0x3e,
[1673994871.838549][37215:37220] CHIP:DMG: CommandId = 0x1,
[1673994871.838554][37215:37220] CHIP:DMG: },
[1673994871.838560][37215:37220] CHIP:DMG:
[1673994871.838565][37215:37220] CHIP:DMG: CommandFields =
[1673994871.838572][37215:37220] CHIP:DMG: {
[1673994871.838578][37215:37220] CHIP:DMG: 0x0 = [
[1673994871.838628][37215:37220] CHIP:DMG: 0x15, 0x31, 0x01, 0x1c, 0x02, 0x30, 0x82, 0x02, 0x18, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x02, 0xa0, 0x82, 0x02, 0x09, 0x30, 0x82, 0x02, 0x05, 0x02, 0x01, 0x03, 0x31, 0x0d, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x82, 0x01, 0x70, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x01, 0xa0, 0x82, 0x01, 0x61, 0x04, 0x82, 0x01, 0x5d, 0x15, 0x24, 0x00, 0x01, 0x25, 0x01, 0xf1, 0xff, 0x36, 0x02, 0x05, 0x00, 0x80, 0x05, 0x01, 0x80, 0x05, 0x02, 0x80, 0x05, 0x03, 0x80, 0x05, 0x04, 0x80, 0x05, 0x05, 0x80, 0x05, 0x06, 0x80, 0x05, 0x07, 0x80, 0x05, 0x08, 0x80, 0x05, 0x09, 0x80, 0x05, 0x0a, 0x80, 0x05, 0x0b, 0x80, 0x05, 0x0c, 0x80, 0x05, 0x0d, 0x80, 0x05, 0x0e, 0x80, 0x05, 0x0f, 0x80, 0x05, 0x10, 0x80, 0x05, 0x11, 0x80, 0x05, 0x12, 0x80, 0x05, 0x13, 0x80, 0x05, 0x14, 0x80, 0x05, 0x15, 0x80, 0x05, 0x16, 0x80, 0x05, 0x17, 0x80, 0x05, 0x18, 0x80, 0x05, 0x19, 0x80, 0x05, 0x1a, 0x80, 0x05, 0x1b, 0x80, 0x05, 0x1c, 0x80, 0x05, 0x1d, 0x80, 0x05, 0x1e, 0x80, 0x05, 0x1f, 0x80, 0x05, 0x20, 0x80, 0x05, 0x21, 0x80, 0x05, 0x22, 0x80, 0x05, 0x23, 0x80, 0x05, 0x24, 0x80, 0x05, 0x25, 0x80, 0x05, 0x26, 0x80, 0x05, 0x27, 0x80, 0x05, 0x28, 0x80, 0x05, 0x29, 0x80, 0x05, 0x2a, 0x80, 0x05, 0x2b, 0x80, 0x05, 0x2c, 0x80, 0x05, 0x2d, 0x80, 0x05, 0x2e, 0x80, 0x05, 0x2f, 0x80, 0x05, 0x30, 0x80, 0x05, 0x31, 0x80, 0x05, 0x32, 0x80, 0x05, 0x33, 0x80, 0x05, 0x34, 0x80, 0x05, 0x35, 0x80, 0x05, 0x36, 0x80, 0x05, 0x37, 0x80, 0x05, 0x38, 0x80, 0x05, 0x39, 0x80, 0x05, 0x3a, 0x80, 0x05, 0x3b, 0x80, 0x05, 0x3c, 0x80, 0x05, 0x3d, 0x80, 0x05, 0x3e, 0x80, 0x05, 0x3f, 0x80, 0x05, 0x40, 0x80, 0x05, 0x41, 0x80, 0x05, 0x42, 0x80, 0x05, 0x43, 0x80, 0x
[1673994871.838650][37215:37220] CHIP:DMG: ] (584 bytes)
[1673994871.838658][37215:37220] CHIP:DMG: 0x1 = [
[1673994871.838676][37215:37220] CHIP:DMG: 0x7e, 0x2a, 0xa9, 0x77, 0x8d, 0x61, 0x2b, 0xb0, 0x34, 0x12, 0x23, 0xfd, 0xe9, 0x80, 0xe3, 0x43, 0x28, 0x22, 0x6a, 0x26, 0x13, 0x77, 0x1f, 0x16, 0xf9, 0x5e, 0x2c, 0x8b, 0x09, 0x8a, 0x8f, 0x91, 0xdb, 0xed, 0xf8, 0x42, 0x9c, 0x37, 0x7f, 0xfc, 0x5b, 0xeb, 0x01, 0x94, 0xdc, 0x4c, 0x77, 0x52, 0xb3, 0xea, 0x44, 0x44, 0x6e, 0x89, 0xb6, 0xed, 0x2e, 0xeb, 0x4d, 0x0f, 0x90, 0xfc, 0x23, 0x78,
[1673994871.838687][37215:37220] CHIP:DMG: ] (64 bytes)
[1673994871.838694][37215:37220] CHIP:DMG: },
[1673994871.838700][37215:37220] CHIP:DMG: },
[1673994871.838709][37215:37220] CHIP:DMG:
[1673994871.838713][37215:37220] CHIP:DMG: },
[1673994871.838719][37215:37220] CHIP:DMG:
[1673994871.838723][37215:37220] CHIP:DMG: ],
[1673994871.838729][37215:37220] CHIP:DMG:
[1673994871.838733][37215:37220] CHIP:DMG: InteractionModelRevision = 1
[1673994871.838737][37215:37220] CHIP:DMG: },
[1673994871.838756][37215:37220] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1673994871.838765][37215:37220] CHIP:CTL: Received Attestation Information from the device
[1673994871.838774][37215:37220] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'
[1673994871.838780][37215:37220] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 584/584
[1673994871.838794][37215:37220] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1673994871.838800][37215:37220] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1673994871.838805][37215:37220] CHIP:CTL: Verifying attestation
[1673994871.840344][37215:37220] CHIP:CTL: Failed in verifying 'Attestation Information' command received from the device: err 601. Look at AttestationVerificationResult enum to understand the errors
[1673994871.840360][37215:37220] CHIP:CTL: Error on commissioning step 'AttestationVerification': '../../src/controller/CHIPDeviceController.cpp:1031: CHIP Error 0x000000AC: Internal error'
[1673994871.840366][37215:37220] CHIP:CTL: Failed to perform commissioning step 8
[1673994871.840370][37215:37220] CHIP:CTL: Going from commissioning step 'AttestationVerification' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1031: CHIP Error 0x000000AC: Internal error' -> 'Cleanup'
[1673994871.840378][37215:37220] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../src/controller/CHIPDeviceController.cpp:1031: CHIP Error 0x000000AC: Internal error'
[1673994871.840383][37215:37220] CHIP:CTL: Expiring failsafe on proxy 0x7fed90023690
[1673994871.840408][37215:37220] CHIP:DMG: ICR moving to [AddingComm]
[1673994871.840421][37215:37220] CHIP:DMG: ICR moving to [AddedComma]
[1673994871.840446][37215:37220] CHIP:EM: <<< [E:59616i M:7718918] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1673994871.840455][37215:37220] CHIP:IN: (S) Sending msg 7718918 on secure session with LSID: 44071
[1673994871.840479][37215:37220] CHIP:DMG: ICR moving to [CommandSen]
[1673994871.840495][37215:37220] CHIP:DMG: ICR moving to [AwaitingDe]
[1673994871.932348][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1673994871.934685][37215:37218] CHIP:DL: Indication received, conn = 0x7fed98039250
[1673994871.934735][37215:37220] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1673994871.934808][37215:37220] CHIP:EM: >>> [E:59616i M:214452941] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1673994871.934824][37215:37220] CHIP:EM: Found matching exchange: 59616i, Delegate: 0x7fed9803ade8
[1673994871.934836][37215:37220] CHIP:DMG: ICR moving to [ResponseRe]
[1673994871.934858][37215:37220] CHIP:DMG: InvokeResponseMessage =
[1673994871.934865][37215:37220] CHIP:DMG: {
[1673994871.934873][37215:37220] CHIP:DMG: suppressResponse = false,
[1673994871.934878][37215:37220] CHIP:DMG: InvokeResponseIBs =
[1673994871.934886][37215:37220] CHIP:DMG: [
[1673994871.934891][37215:37220] CHIP:DMG: InvokeResponseIB =
[1673994871.934903][37215:37220] CHIP:DMG: {
[1673994871.934908][37215:37220] CHIP:DMG: CommandDataIB =
[1673994871.934915][37215:37220] CHIP:DMG: {
[1673994871.934921][37215:37220] CHIP:DMG: CommandPathIB =
[1673994871.934930][37215:37220] CHIP:DMG: {
[1673994871.934938][37215:37220] CHIP:DMG: EndpointId = 0x0,
[1673994871.934944][37215:37220] CHIP:DMG: ClusterId = 0x30,
[1673994871.934950][37215:37220] CHIP:DMG: CommandId = 0x1,
[1673994871.934956][37215:37220] CHIP:DMG: },
[1673994871.934962][37215:37220] CHIP:DMG:
[1673994871.934967][37215:37220] CHIP:DMG: CommandFields =
[1673994871.934973][37215:37220] CHIP:DMG: {
[1673994871.934979][37215:37220] CHIP:DMG: 0x0 = 0,
[1673994871.934986][37215:37220] CHIP:DMG: 0x1 = "" (0 chars),
[1673994871.934993][37215:37220] CHIP:DMG: },
[1673994871.934998][37215:37220] CHIP:DMG: },
[1673994871.935005][37215:37220] CHIP:DMG:
[1673994871.935010][37215:37220] CHIP:DMG: },
[1673994871.935021][37215:37220] CHIP:DMG:
[1673994871.935025][37215:37220] CHIP:DMG: ],
[1673994871.935033][37215:37220] CHIP:DMG:
[1673994871.935038][37215:37220] CHIP:DMG: InteractionModelRevision = 1
[1673994871.935043][37215:37220] CHIP:DMG: },
[1673994871.935065][37215:37220] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1673994871.935077][37215:37220] CHIP:CTL: Failsafe disarmed
[1673994871.935086][37215:37220] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1673994871.935099][37215:37220] CHIP:TOO: Device commissioning Failure: ../../src/controller/CHIPDeviceController.cpp:1031: CHIP Error 0x000000AC: Internal error
[1673994871.935114][37215:37220] CHIP:DIS: Closing all BLE connections
[1673994871.935119][37215:37220] CHIP:IN: Clearing BLE pending packets.
[1673994871.935135][37215:37220] CHIP:BLE: Auto-closing end point's BLE connection.
[1673994871.935139][37215:37220] CHIP:DL: Closing BLE GATT connection (con 0x7fed98039250)
[1673994871.935158][37215:37220] CHIP:IN: SecureSession[0x7fed900215a0]: MarkForEviction Type:1 LSID:44071
[1673994871.935164][37215:37220] CHIP:SC: SecureSession[0x7fed900215a0]: Moving from state 'kActive' --> 'kPendingEviction'
[1673994871.935196][37215:37220] CHIP:DMG: ICR moving to [AwaitingDe]
[1673994871.935204][37215:37220] CHIP:IN: SecureSession[0x7fed900215a0]: Released - Type:1 LSID:44071
[1673994871.935225][37215:37218] CHIP:DL: BluezDisconnect peer=CD:CC:01:50:92:8F
[1673994871.935295][37215:37215] CHIP:CTL: Shutting down the commissioner
[1673994871.935302][37215:37215] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1673994871.935308][37215:37215] CHIP:CTL: Shutting down the controller
[1673994871.935314][37215:37215] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1673994871.935319][37215:37215] CHIP:FP: Forgetting fabric 0x1
[1673994871.935329][37215:37215] CHIP:TS: Pending Last Known Good Time: 2022-11-30T10:12:56
[1673994871.935373][37215:37215] CHIP:TS: Previous Last Known Good Time: 2022-11-30T10:12:56
[1673994871.935377][37215:37215] CHIP:TS: Reverted Last Known Good Time to previous value
[1673994871.935389][37215:37215] CHIP:CTL: Shutting down the commissioner
[1673994871.935393][37215:37215] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1673994871.935397][37215:37215] CHIP:CTL: Shutting down the controller
[1673994871.935401][37215:37215] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1673994871.936134][37215:37215] CHIP:DMG: IM WH moving to [Uninitialized]
[1673994871.936144][37215:37215] CHIP:DMG: IM WH moving to [Uninitialized]
[1673994871.936149][37215:37215] CHIP:DMG: IM WH moving to [Uninitialized]
[1673994871.936153][37215:37215] CHIP:DMG: IM WH moving to [Uninitialized]
[1673994871.936158][37215:37215] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1673994871.936179][37215:37215] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1673994871.936191][37215:37215] CHIP:FP: Shutting down FabricTable
[1673994871.936196][37215:37215] CHIP:TS: Pending Last Known Good Time: 2022-11-30T10:12:56
[1673994871.936231][37215:37215] CHIP:TS: Previous Last Known Good Time: 2022-11-30T10:12:56
[1673994871.936234][37215:37215] CHIP:TS: Reverted Last Known Good Time to previous value
[1673994871.936315][37215:37215] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-HsfOLd)
[1673994871.936509][37215:37215] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1673994871.936526][37215:37215] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1673994871.936532][37215:37215] CHIP:DL: Inet Layer shutdown
[1673994871.936536][37215:37215] CHIP:DL: BLE shutdown
[1673994871.936784][37215:37215] CHIP:DL: System Layer shutdown
[1673994871.936803][37215:37215] CHIP:TOO: Run command failure: ../../src/controller/CHIPDeviceController.cpp:1031: CHIP Error 0x000000AC: Internal error
Any idea what I could be doing wrong? I don't see an obvious issue here.
