Thingy53 Matter commissioning with Apple HomePod mini fails with "OnSrpClientNotification: Operation refused for security reasons"

Hi,

i have a Thingy53 with the Matter Weather Station Example (unmodified) installed, but I cannot commission it into my Apple Home Network. My Network already contains Thread Devices from Eve (not Matter-Certified) therefore the Thread network should be available. For evaluation purpose, I want to add the Thingy53 to my Network.I have made the following steps: Scanning the QR Code with the Apple Home App, which prompts me to add an uncertified device (accept this). Then the Thingy53 LED starts flashing fast (indicating BLE connection). After some time the LED flashes purple which indicates the switch to Thread, but the commissioning stops here with the error "OnSrpClientNotification: Operation refused for security reasons".

Full device log:

[00:01:36.185,882] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ef4eba07
[00:01:36.186,035] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to c93dca30
[00:01:36.186,218] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to f2611188
[00:01:36.191,040] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f64
[00:01:36.191,253] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f65
[00:01:36.191,436] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f66
[00:01:36.191,619] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f67
[00:01:36.191,802] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f68
[00:01:36.191,986] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f69
[00:01:36.192,169] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f6a
[00:01:36.601,928] <inf> chip: [DL]BLE connection established (ConnId: 0x00)
[00:01:36.602,020] <inf> chip: [DL]Current number of connections: 1/1
[00:01:36.602,325] <inf> chip: [DL]CHIPoBLE advertising stopped
[00:01:36.602,478] <inf> chip: [DL]NFC Tag emulation stopped
[00:01:37.059,875] <wrn> bt_l2cap: Ignoring data for unknown channel ID 0x003a
[00:01:37.659,881] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:37.659,973] <inf> chip: [BLE]local and remote recv window sizes = 5
[00:01:37.660,034] <inf> chip: [BLE]selected BTP version 4
[00:01:37.660,095] <inf> chip: [BLE]using BTP fragment sizes rx 244 / tx 244.
[00:01:37.779,846] <dbg> chip: [DL]ConnId: 0x00, New CCCD value: 0x0001
[00:01:37.779,937] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6)
[00:01:37.780,212] <dbg> chip: [IN]BLE EndPoint 0x2000ef20 Connection Complete
[00:01:37.780,334] <inf> chip: [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 498)
[00:01:37.840,301] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:37.840,423] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:37.840,728] <inf> chip: [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:233438293 on exchange 19896r
[00:01:37.840,850] <dbg> chip: [EM]Handling via exchange: 19896r, Delegate: 0x20008cc8
[00:01:37.840,911] <dbg> chip: [SC]Received PBKDF param request
[00:01:37.841,064] <dbg> chip: [SC]Peer assigned session ID 9019
[00:01:37.841,156] <dbg> chip: [SC]Found MRP parameters in the message
--- 2 messages dropped ---
[00:01:37.842,529] <inf> chip: [IN]Sending unauthenticated msg 0x20033978 with MessageCounter:1378459828 to 0x0000000000000000 at monotonic time: 0000000000017E32 msec
[00:01:37.842,620] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 140)
[00:01:37.842,895] <dbg> chip: [SC]Sent PBKDF param response
[00:01:37.899,597] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:37.930,267] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:37.930,572] <inf> chip: [EM]Received message of type 0x22 with protocolId (0, 0) and MessageCounter:233438294 on exchange 19896r
[00:01:37.930,694] <dbg> chip: [EM]Found matching exchange: 19896r, Delegate: 0x20008cc8
[00:01:37.930,786] <dbg> chip: [SC]Received spake2p msg1
--- 12 messages dropped ---
[00:01:39.509,002] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 132)
[00:01:39.509,277] <dbg> chip: [SC]Sent spake2p msg2
[00:01:39.509,399] <err> chip: [DL]Long dispatch time: 1579 ms, for event type 16388
--- 15 messages dropped ---
[00:01:39.585,327] <err> chip: [DIS]Failed to advertise extended commissionable node: Error CHIP:0x00000003
[00:01:39.585,388] <dbg> chip: [DIS]Scheduling extended discovery timeout in 900s
[00:01:39.585,540] <err> chip: [DIS]Failed to finalize service update: Error CHIP:0x0000001C
--- 16 messages dropped ---
[00:01:39.644,592] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:39.644,653] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
--- 2 messages dropped ---
[00:01:39.700,286] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:39.701,049] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:9449054 on exchange 19898r
--- 2 messages dropped ---
[00:01:39.701,782] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:39.702,087] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:39.702,148] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
--- 14 messages dropped ---
[00:01:39.880,371] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:39.881,134] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:9449055 on exchange 19899r
[00:01:39.881,286] <dbg> chip: [EM]Handling via exchange: 19899r, Delegate: 0x2000cd14
[00:01:39.881,347] <dbg> chip: [IM]Received Read request
[00:01:39.881,866] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:39.882,171] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:39.882,293] <dbg> chip: [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
[00:01:39.882,446] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
[00:01:39.882,629] <dbg> chip: [DMG]<RE> Sending report (payload has 37 bytes)...
[00:01:39.883,514] <inf> chip: [IN]Prepared secure message 0x20033b40 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 19899r with MessageCounter:11673217.
[00:01:39.883,789] <inf> chip: [IN]Sending encrypted msg 0x20033b40 with MessageCounter:11673217 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001862B msec
[00:01:39.883,880] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 72)
[00:01:39.884,155] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:39.884,277] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:39.884,338] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:39.884,429] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:39.940,307] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:39.940,399] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:39.941,192] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:9449056 on exchange 19900r
[00:01:39.941,314] <dbg> chip: [EM]Handling via exchange: 19900r, Delegate: 0x2000cd14
[00:01:39.941,406] <dbg> chip: [IM]Received Read request
[00:01:39.941,894] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:39.942,199] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:39.942,321] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
[00:01:39.942,474] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
[00:01:39.942,718] <dbg> chip: [DMG]<RE> Sending report (payload has 120 bytes)...
[00:01:39.944,000] <inf> chip: [IN]Prepared secure message 0x20033b40 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 19900r with MessageCounter:11673218.
[00:01:39.944,274] <inf> chip: [IN]Sending encrypted msg 0x20033b40 with MessageCounter:11673218 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000018668 msec
[00:01:39.944,396] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 155)
[00:01:39.944,671] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:39.944,763] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:39.944,854] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:39.944,915] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:40.000,305] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:40.000,427] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:40.001,190] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:9449057 on exchange 19901r
[00:01:40.001,342] <dbg> chip: [EM]Handling via exchange: 19901r, Delegate: 0x2000cd14
[00:01:40.001,403] <dbg> chip: [IM]Received Read request
[00:01:40.001,922] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:40.002,227] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:40.002,319] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
[00:01:40.002,471] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:01:40.003,204] <dbg> chip: [DMG]<RE> Sending report (payload has 512 bytes)...
[00:01:40.006,561] <inf> chip: [IN]Prepared secure message 0x20033b40 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 19901r with MessageCounter:11673219.
[00:01:40.006,805] <inf> chip: [IN]Sending encrypted msg 0x20033b40 with MessageCounter:11673219 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000186A6 msec
[00:01:40.006,927] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
[00:01:40.007,202] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:40.007,324] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:40.007,385] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:40.007,476] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:40.059,539] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:40.059,661] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
[00:01:40.119,628] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:40.119,750] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 63)
[00:01:40.180,267] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:40.180,389] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:40.181,152] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:9449058 on exchange 19902r
[00:01:40.181,304] <dbg> chip: [EM]Handling via exchange: 19902r, Delegate: 0x2000cd14
[00:01:40.181,365] <dbg> chip: [IM]Received Read request
[00:01:40.181,884] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:40.182,189] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:40.182,312] <dbg> chip: [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
[00:01:40.182,464] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
[00:01:40.182,647] <dbg> chip: [DMG]<RE> Sending report (payload has 37 bytes)...
[00:01:40.183,532] <inf> chip: [IN]Prepared secure message 0x20033b40 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 19902r with MessageCounter:11673220.
[00:01:40.183,776] <inf> chip: [IN]Sending encrypted msg 0x20033b40 with MessageCounter:11673220 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000018757 msec
[00:01:40.183,898] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 72)
[00:01:40.184,173] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:40.184,295] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:40.184,356] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:40.184,448] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:40.239,624] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:41.710,388] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:41.711,578] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:9449059 on exchange 19903r
[00:01:41.711,700] <dbg> chip: [EM]Handling via exchange: 19903r, Delegate: 0x2000cd14
[00:01:41.711,761] <dbg> chip: [IM]Received Read request
[00:01:41.713,714] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:41.713,989] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:41.714,111] <dbg> chip: [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty
[00:01:41.714,263] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
[00:01:41.714,477] <dbg> chip: [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
[00:01:41.714,630] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
[00:01:41.714,782] <dbg> chip: [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
[00:01:41.714,935] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
[00:01:41.715,087] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
[00:01:41.715,240] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
[00:01:41.715,393] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty
[00:01:41.715,545] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
[00:01:41.715,698] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty
[00:01:41.715,850] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:01:41.716,003] <dbg> chip: [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty
[00:01:41.716,156] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
[00:01:41.716,400] <dbg> chip: [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
[00:01:41.716,552] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
[00:01:41.716,735] <dbg> chip: [DMG]<RE> Sending report (payload has 224 bytes)...
[00:01:41.718,566] <inf> chip: [IN]Prepared secure message 0x20033b40 to 0xFFFFFFFB00000000 (0)  of type 0x5 and protocolId (0, 1) on exchange 19903r with MessageCounter:11673221.
[00:01:41.718,811] <inf> chip: [IN]Sending encrypted msg 0x20033b40 with MessageCounter:11673221 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000018D56 msec
[00:01:41.718,933] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
[00:01:41.719,207] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:41.719,329] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:41.719,390] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:41.719,482] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:41.769,653] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:41.769,775] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 17)
[00:01:41.830,322] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:41.830,444] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:41.831,329] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9449060 on exchange 19904r
[00:01:41.831,451] <dbg> chip: [EM]Handling via exchange: 19904r, Delegate: 0x2000cd14
[00:01:41.831,970] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
[00:01:41.832,672] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_0030 update version to de6e85cf
[00:01:41.832,794] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:41.832,855] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:41.832,946] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:41.833,160] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:41.834,045] <inf> chip: [IN]Prepared secure message 0x20033a08 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 19904r with MessageCounter:11673222.
[00:01:41.834,320] <inf> chip: [IN]Sending encrypted msg 0x20033a08 with MessageCounter:11673222 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000018DCA msec
[00:01:41.834,411] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
[00:01:41.834,686] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:41.834,747] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:41.890,472] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:41.890,563] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:41.891,448] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9449061 on exchange 19905r
[00:01:41.891,571] <dbg> chip: [EM]Handling via exchange: 19905r, Delegate: 0x2000cd14
[00:01:41.892,120] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
[00:01:41.895,111] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_0030 update version to de6e85d0
[00:01:41.895,233] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:41.895,324] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:41.895,385] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:41.895,629] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:41.896,514] <inf> chip: [IN]Prepared secure message 0x20033a08 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 19905r with MessageCounter:11673223.
[00:01:41.896,759] <inf> chip: [IN]Sending encrypted msg 0x20033a08 with MessageCounter:11673223 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000018E08 msec
[00:01:41.896,881] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
[00:01:41.897,125] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:41.897,186] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:42.010,253] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:42.010,406] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:42.011,260] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9449062 on exchange 19906r
[00:01:42.011,383] <dbg> chip: [EM]Handling via exchange: 19906r, Delegate: 0x2000cd14
[00:01:42.011,932] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
[00:01:42.011,993] <inf> chip: [ZCL]OpCreds: Certificate Chain request received for PAI
[00:01:42.012,145] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:42.012,237] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:42.012,359] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:42.012,573] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:42.015,716] <inf> chip: [IN]Prepared secure message 0x20033a08 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 19906r with MessageCounter:11673224.
[00:01:42.015,991] <inf> chip: [IN]Sending encrypted msg 0x20033a08 with MessageCounter:11673224 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000018E7F msec
[00:01:42.016,113] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
[00:01:42.016,418] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:42.016,479] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:42.129,638] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:42.129,760] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
[00:01:42.186,096] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ef4eba09
[00:01:42.186,279] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to c93dca32
[00:01:42.186,462] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to f261118a
[00:01:42.191,314] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f72
[00:01:42.191,497] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f73
[00:01:42.191,680] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f74
[00:01:42.191,864] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f75
[00:01:42.192,047] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f76
[00:01:42.192,230] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f77
[00:01:42.192,413] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f78
[00:01:42.249,664] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:42.249,755] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 48)
[00:01:42.370,239] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:42.370,391] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:42.371,246] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9449063 on exchange 19907r
[00:01:42.371,398] <dbg> chip: [EM]Handling via exchange: 19907r, Delegate: 0x2000cd14
[00:01:42.371,917] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
[00:01:42.372,009] <inf> chip: [ZCL]OpCreds: Certificate Chain request received for DAC
[00:01:42.372,131] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:42.372,222] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:42.372,344] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:42.372,558] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:42.375,885] <inf> chip: [IN]Prepared secure message 0x20033a08 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 19907r with MessageCounter:11673225.
[00:01:42.376,129] <inf> chip: [IN]Sending encrypted msg 0x20033a08 with MessageCounter:11673225 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000018FE7 msec
[00:01:42.376,251] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
[00:01:42.376,556] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:42.376,617] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:42.489,776] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:42.489,868] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
[00:01:42.609,680] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:42.609,771] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 76)
[00:01:42.730,407] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:42.730,529] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:42.731,536] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9449064 on exchange 19908r
[00:01:42.731,658] <dbg> chip: [EM]Handling via exchange: 19908r, Delegate: 0x2000cd14
[00:01:42.732,208] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
[00:01:42.732,269] <inf> chip: [ZCL]OpCreds: received an AttestationRequest
[00:01:42.762,084] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:42.762,176] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:42.762,298] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:42.762,573] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:42.766,662] <inf> chip: [IN]Prepared secure message 0x20033a08 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 19908r with MessageCounter:11673226.
[00:01:42.766,937] <inf> chip: [IN]Sending encrypted msg 0x20033a08 with MessageCounter:11673226 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000001916E msec
[00:01:42.767,028] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
[00:01:42.767,333] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:42.767,395] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:42.849,700] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:42.849,822] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
[00:01:42.969,696] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:42.969,818] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 237)
[00:01:43.090,454] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:43.090,576] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:43.091,430] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9449065 on exchange 19909r
[00:01:43.091,552] <dbg> chip: [EM]Handling via exchange: 19909r, Delegate: 0x2000cd14
[00:01:43.092,102] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
[00:01:43.092,834] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_0030 update version to de6e85d1
[00:01:43.092,926] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:43.093,017] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:43.093,109] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:43.093,322] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:43.094,177] <inf> chip: [IN]Prepared secure message 0x20033a08 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 19909r with MessageCounter:11673227.
[00:01:43.094,451] <inf> chip: [IN]Sending encrypted msg 0x20033a08 with MessageCounter:11673227 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000192B6 msec
[00:01:43.094,573] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
[00:01:43.094,848] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:43.094,909] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:43.209,747] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:44.410,461] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:44.411,499] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9449066 on exchange 19910r
[00:01:44.411,621] <dbg> chip: [EM]Handling via exchange: 19910r, Delegate: 0x2000cd14
[00:01:44.412,139] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
[00:01:44.412,231] <inf> chip: [ZCL]OpCreds: commissioner has requested a CSR
[00:01:44.706,939] <inf> chip: [ZCL]OpCreds: NewCertificateSigningRequest returned 0
[00:01:44.736,511] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:44.736,602] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:44.736,724] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:44.736,968] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:44.739,349] <inf> chip: [IN]Prepared secure message 0x20033a08 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 19910r with MessageCounter:11673228.
[00:01:44.739,624] <inf> chip: [IN]Sending encrypted msg 0x20033a08 with MessageCounter:11673228 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000019923 msec
[00:01:44.739,715] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
[00:01:44.740,020] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:44.740,081] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:44.740,203] <err> chip: [DL]Long dispatch time: 330 ms, for event type 16388
[00:01:44.889,709] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:44.889,831] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 138)
[00:01:45.011,352] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:45.011,474] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:45.130,340] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:45.132,415] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9449067 on exchange 19911r
[00:01:45.132,568] <dbg> chip: [EM]Handling via exchange: 19911r, Delegate: 0x2000cd14
[00:01:45.133,087] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
[00:01:45.133,178] <inf> chip: [ZCL]OpCreds: commissioner has added a trusted root Cert
[00:01:45.133,300] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:45.133,392] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:45.133,483] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:45.133,636] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_003E update version to c78f8369
[00:01:45.133,850] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:45.134,735] <inf> chip: [IN]Prepared secure message 0x20033a08 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 19911r with MessageCounter:11673229.
[00:01:45.134,979] <inf> chip: [IN]Sending encrypted msg 0x20033a08 with MessageCounter:11673229 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000019AAE msec
[00:01:45.135,101] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 68)
[00:01:45.135,375] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:45.135,437] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:45.186,096] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ef4eba0a
[00:01:45.186,248] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to c93dca33
[00:01:45.186,431] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to f261118b
[00:01:45.191,406] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f79
[00:01:45.191,589] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f7a
[00:01:45.191,772] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f7b
[00:01:45.191,955] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f7c
[00:01:45.192,138] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f7d
[00:01:45.192,321] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f7e
[00:01:45.192,504] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f7f
[00:01:45.251,159] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:45.251,251] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:45.370,635] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:45.372,863] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9449068 on exchange 19912r
[00:01:45.372,985] <dbg> chip: [EM]Handling via exchange: 19912r, Delegate: 0x2000cd14
[00:01:45.373,596] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
[00:01:45.373,687] <inf> chip: [ZCL]OpCreds: Received AddNOC command
[00:01:45.374,267] <inf> chip: [DIS]Verifying the received credentials
[00:01:45.430,938] <inf> chip: [DIS]Added new fabric at index: 0x1, Initialized: 1
[00:01:45.431,091] <inf> chip: [DIS]Assigned compressed fabric ID: 0x403A2619E233485A, node ID: 0x00000000A62D7EF9
[00:01:45.443,786] <inf> chip: [DIS]Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
[00:01:45.444,000] <inf> chip: [ZCL]OpCreds: Fabric  index 0x1 was persisted to storage. FabricId 0000000000000002, NodeId 00000000A62D7EF9, VendorId 0x1349
[00:01:45.444,030] <inf> chip: [ZCL]OpCreds: Call to fabricListChanged
[00:01:45.444,183] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_003E update version to c78f836a
[00:01:45.444,335] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_003E update version to c78f836b
[00:01:45.457,336] <dbg> chip: [EVL]LogEvent event number: 0x0000000000080002 priority: 1, endpoint id:  0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x0000000000019BF0
[00:01:45.457,489] <inf> chip: [ZCL]OpCreds: ACL entry created for Fabric 1 CASE Admin NodeId 0x20A8376795EEA4E8
[00:01:45.457,580] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:45.457,733] <inf> chip: [DIS]Advertise operational node 403A2619E233485A-00000000A62D7EF9
[00:01:45.457,977] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:45.458,068] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:45.458,160] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:45.458,221] <inf> chip: [ZCL]OpCreds: successfully created fabric index 1 via AddNOC
[00:01:45.458,496] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:45.459,350] <inf> chip: [IN]Prepared secure message 0x20033a08 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 19912r with MessageCounter:11673230.
[00:01:45.459,625] <inf> chip: [IN]Sending encrypted msg 0x20033a08 with MessageCounter:11673230 to 0xFFFFFFFB00000000 (1) at monotonic time: 0000000000019BF3 msec
[00:01:45.459,747] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
[00:01:45.459,991] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:45.460,052] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:45.550,689] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:45.550,811] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:45.552,001] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9449069 on exchange 19913r
[00:01:45.552,124] <dbg> chip: [EM]Handling via exchange: 19913r, Delegate: 0x2000cd14
[00:01:45.552,673] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
[00:01:45.555,084] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:45.555,145] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:45.555,236] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:45.555,480] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:45.556,335] <inf> chip: [IN]Prepared secure message 0x20033a08 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 19913r with MessageCounter:11673231.
[00:01:45.556,610] <inf> chip: [IN]Sending encrypted msg 0x20033a08 with MessageCounter:11673231 to 0xFFFFFFFB00000000 (1) at monotonic time: 0000000000019C54 msec
[00:01:45.556,732] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
[00:01:45.556,976] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:45.557,037] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:45.670,562] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:45.670,684] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:45.671,630] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:9449070 on exchange 19914r
[00:01:45.671,752] <dbg> chip: [EM]Handling via exchange: 19914r, Delegate: 0x2000cd14
[00:01:45.672,302] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
[00:01:45.682,952] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 1
[00:01:45.683,074] <dbg> chip: [DL]OpenThread State Changed (Flags: 0x1007c100)
[00:01:45.683,135] <dbg> chip: [DL]   Network Name: MyHome66
[00:01:45.683,197] <dbg> chip: [DL]   PAN Id: 0xAE3C
[00:01:45.683,349] <dbg> chip: [DL]   Extended PAN Id: 0xCCA4FF56F4BB405F
[00:01:45.683,410] <dbg> chip: [DL]   Channel: 25
[00:01:45.683,502] <dbg> chip: [DL]   Mesh Prefix: fdde:ad00:beef::/64
[00:01:45.684,600] <inf> chip: [DL]CHIPoBLE advertising disabled because device is fully provisioned
[00:01:45.684,722] <dbg> chip: [DL]OpenThread State Changed (Flags: 0x1100101d)
[00:01:45.684,783] <dbg> chip: [DL]   Device Role: DETACHED
[00:01:45.684,814] <dbg> chip: [DL]   Thread Unicast Addresses:
[00:01:45.684,936] <dbg> chip: [DL]        fdde:ad00:beef:0:ec73:425d:27d9:65d0/64 valid
[00:01:45.685,058] <dbg> chip: [DL]        fe80::5062:7c85:9540:8505/64 valid preferred
[00:01:45.816,894] <dbg> chip: [DL]OpenThread State Changed (Flags: 0x00000100)
[00:01:46.626,739] <inf> chip: [DL]SRP Client was started, detected server: fdcc:6968:4a1c:0000:6127:871b:c392:28a3
[00:01:46.627,746] <dbg> chip: [DL]OpenThread State Changed (Flags: 0x301032b7)
[00:01:46.627,807] <dbg> chip: [DL]   Device Role: CHILD
[00:01:46.627,868] <dbg> chip: [DL]   Partition Id: 0x7E54527D
[00:01:46.627,929] <dbg> chip: [DL]   Thread Unicast Addresses:
[00:01:46.628,051] <dbg> chip: [DL]        fdcc:6968:4a1c:0:52ca:eb27:9cbb:2e96/64 valid preferred
[00:01:46.628,173] <dbg> chip: [DL]        fdcc:a4ff:56f4::ff:fe00:140e/64 valid rloc
[00:01:46.628,295] <dbg> chip: [DL]        fdcc:a4ff:56f4:0:ec73:425d:27d9:65d0/64 valid
[00:01:46.628,417] <dbg> chip: [DL]        fe80::5062:7c85:9540:8505/64 valid preferred
[00:01:46.629,547] <dbg> chip: [DL]OpenThread State Changed (Flags: 0x00000001)
[00:01:46.629,577] <dbg> chip: [DL]   Thread Unicast Addresses:
[00:01:46.629,699] <dbg> chip: [DL]        fdcc:6968:4a1c:0:52ca:eb27:9cbb:2e96/64 valid preferred
[00:01:46.629,821] <dbg> chip: [DL]        fdcc:a4ff:56f4::ff:fe00:140e/64 valid rloc
[00:01:46.629,974] <dbg> chip: [DL]        fdcc:a4ff:56f4:0:ec73:425d:27d9:65d0/64 valid
[00:01:46.630,065] <dbg> chip: [DL]        fe80::5062:7c85:9540:8505/64 valid preferred
[00:01:46.631,164] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:46.631,347] <inf> chip: [DIS]Advertise operational node 403A2619E233485A-00000000A62D7EF9
[00:01:46.631,469] <inf> chip: [SVR]Operational advertising enabled
[00:01:46.631,561] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:46.631,652] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:46.631,713] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:46.631,805] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:46.632,690] <inf> chip: [IN]Prepared secure message 0x20033bf0 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 19914r with MessageCounter:11673232.
[00:01:46.632,934] <inf> chip: [IN]Sending encrypted msg 0x20033bf0 with MessageCounter:11673232 to 0xFFFFFFFB00000000 (1) at monotonic time: 000000000001A088 msec
[00:01:46.633,056] <dbg> chip: [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 70)
[00:01:46.633,331] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:46.633,392] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:46.808,166] <dbg> chip: [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
[00:01:47.037,078] <dbg> chip: [DL]OnSrpClientNotification: Last requested operation completed successfully
[00:01:47.037,170] <inf> chip: [DIS]Setting operational delegate post init
[00:01:47.037,658] <inf> chip: [DIS]Updating services using commissioning mode 0
[00:01:47.037,750] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:47.037,902] <inf> chip: [DIS]Advertise operational node 403A2619E233485A-00000000A62D7EF9
[00:01:47.038,330] <inf> chip: [DL]advertising srp service: 403A2619E233485A-00000000A62D7EF9._matter._tcp
[00:01:47.038,574] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:47.039,337] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32781 discriminator=3840/15
[00:01:47.039,825] <inf> chip: [DL]advertising srp service: 9616B9B2B9B86D04._matterc._udp
[00:01:47.040,039] <dbg> chip: [DIS]Scheduling extended discovery timeout in 900s
[00:01:47.983,734] <dbg> chip: [DL]OnSrpClientNotification: Last requested operation completed successfully
[00:01:48.185,821] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ef4eba0b
[00:01:48.186,004] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to c93dca34
[00:01:48.186,187] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to f261118c
[00:01:48.191,009] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f80
[00:01:48.191,192] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f81
[00:01:48.191,375] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f82
[00:01:48.191,558] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f83
[00:01:48.191,741] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f84
[00:01:48.191,925] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f85
[00:01:48.192,108] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f86
[00:01:49.005,187] <inf> chip: [EM]Received message of type 0x30 with protocolId (0, 0) and MessageCounter:233438296 on exchange 19915r
[00:01:49.005,310] <dbg> chip: [EM]Handling via exchange: 19915r, Delegate: 0x200072b0
[00:01:49.005,462] <inf> chip: [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20008638
[00:01:49.005,859] <dbg> chip: [SC]Waiting for Sigma1 msg
[00:01:49.005,920] <inf> chip: [IN]CASE Server disabling CASE session setups
[00:01:49.005,950] <inf> chip: [SC]Received Sigma1 msg
[00:01:49.006,195] <dbg> chip: [SC]Found MRP parameters in the message
[00:01:49.006,286] <dbg> chip: [SC]Peer assigned session key ID 9020
[00:01:49.008,819] <inf> chip: [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x00000000A62D7EF9
[00:01:49.196,960] <dbg> chip: [SC]Including MRP parameters
[00:01:49.197,662] <inf> chip: [IN]Prepared unauthenticated message 0x200088ec to 0x0000000000000000 (0)  of type 0x31 and protocolId (0, 0) on exchange 19915r with MessageCounter:1378459831.
[00:01:49.197,906] <inf> chip: [IN]Sending unauthenticated msg 0x200088ec with MessageCounter:1378459831 to 0x0000000000000000 at monotonic time: 000000000001AA8D msec
[00:01:49.200,805] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:49.200,866] <inf> chip: [SC]Sent Sigma2 msg
[00:01:49.210,815] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:49.681,365] <inf> chip: [EM]Received message of type 0x32 with protocolId (0, 0) and MessageCounter:233438297 on exchange 19915r
[00:01:49.681,488] <dbg> chip: [EM]Found matching exchange: 19915r, Delegate: 0x200072c4
[00:01:49.681,671] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:1378459831 from Retrans Table on exchange 19915r
[00:01:49.681,793] <dbg> chip: [EM]Removed CHIP MessageCounter:1378459831 from RetransTable on exchange 19915r
[00:01:49.681,884] <inf> chip: [SC]Received Sigma3 msg
[00:01:49.804,077] <dbg> chip: [SC]Sending status report. Protocol code 0, exchange 19915
[00:01:49.804,412] <inf> chip: [IN]Prepared unauthenticated message 0x200088ec to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 19915r with MessageCounter:1378459832.
[00:01:49.804,656] <inf> chip: [IN]Sending unauthenticated msg 0x200088ec with MessageCounter:1378459832 to 0x0000000000000000 at monotonic time: 000000000001ACEC msec
[00:01:49.808,105] <dbg> chip: [IN]New secure session created for device <20A8376795EEA4E8, 1>, LSID:22411 PSID:9020!
[00:01:49.808,227] <inf> chip: [IN]CASE Session established to peer: <20A8376795EEA4E8, 1>
[00:01:49.808,288] <inf> chip: [IN]CASE Server enabling CASE session setups
[00:01:50.083,892] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:46848394 on exchange 19916r
[00:01:50.084,045] <dbg> chip: [EM]Handling via exchange: 19916r, Delegate: 0x2000cd14
[00:01:50.084,594] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
[00:01:50.086,364] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_0030 update version to de6e85d2
[00:01:50.086,486] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:50.086,578] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:50.086,669] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:50.086,853] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:50.088,836] <inf> chip: [IN]Prepared secure message 0x20008904 to 0x20A8376795EEA4E8 (1)  of type 0x9 and protocolId (0, 1) on exchange 19916r with MessageCounter:11257459.
[00:01:50.089,111] <inf> chip: [IN]Sending encrypted msg 0x20008904 with MessageCounter:11257459 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001AE08 msec
[00:01:50.090,057] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:50.090,148] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:50.090,209] <inf> chip: [SVR]Commissioning completed successfully
[00:01:50.090,362] <inf> chip: [DIS]Updating services using commissioning mode 0
[00:01:50.090,454] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:50.090,637] <inf> chip: [DIS]Advertise operational node 403A2619E233485A-00000000A62D7EF9
[00:01:50.091,156] <inf> chip: [DL]advertising srp service: 403A2619E233485A-00000000A62D7EF9._matter._tcp
[00:01:50.091,369] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:50.092,224] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32781 discriminator=3840/15
[00:01:50.093,231] <inf> chip: [DL]advertising srp service: 9616B9B2B9B86D04._matterc._udp
[00:01:50.096,069] <dbg> chip: [DIS]Scheduling extended discovery timeout in 900s
[00:01:50.096,191] <dbg> chip: [IN]Expiring all PASE pairings
[00:01:50.096,466] <dbg> chip: [IN]Clearing BLE pending packets.
[00:01:50.096,527] <inf> chip: [BLE]Releasing end point's BLE connection back to application.
[00:01:50.096,618] <inf> chip: [DL]Closing BLE GATT connection (ConnId 00)
[00:01:50.097,534] <inf> chip: [SWU]Device commissioned, schedule a default provider query
[00:01:50.097,625] <dbg> chip: [ZCL]Commissioning complete, notify platform driver to persist network credentials.
[00:01:50.098,724] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:233438298 on exchange 19915r
[00:01:50.098,815] <dbg> chip: [EM]Found matching exchange: 19915r, Delegate: (nil)
[00:01:50.098,999] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:1378459832 from Retrans Table on exchange 19915r
[00:01:50.099,121] <dbg> chip: [EM]Removed CHIP MessageCounter:1378459832 from RetransTable on exchange 19915r
[00:01:50.170,288] <inf> chip: [DL]BLE GAP connection terminated (reason 0x16)
[00:01:50.170,379] <inf> chip: [DL]Current number of connections: 0/1
[00:01:50.173,828] <inf> chip: [DL]Started SMP service BLE advertising
[00:01:50.232,238] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:46848395 on exchange 19916r
[00:01:50.232,330] <dbg> chip: [EM]Found matching exchange: 19916r, Delegate: (nil)
[00:01:50.232,482] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:11257459 from Retrans Table on exchange 19916r
[00:01:50.232,635] <dbg> chip: [EM]Removed CHIP MessageCounter:11257459 from RetransTable on exchange 19916r
[00:01:50.232,757] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:50.417,297] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:46848396 on exchange 19917r
[00:01:50.417,449] <dbg> chip: [EM]Handling via exchange: 19917r, Delegate: 0x2000cd14
[00:01:50.417,541] <dbg> chip: [IM]Received Read request
[00:01:50.418,029] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:50.418,151] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:50.418,426] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:50.418,518] <dbg> chip: [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
[00:01:50.418,670] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:01:50.420,440] <dbg> chip: [DMG]<RE> Sending report (payload has 151 bytes)...
[00:01:50.421,966] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19917r with MessageCounter:11257460.
[00:01:50.422,241] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257460 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001AF55 msec
[00:01:50.423,248] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:50.423,370] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
--- 16 messages dropped ---
[00:01:50.641,296] <dbg> chip: [DMG]<RE> Sending report (payload has 120 bytes)...
[00:01:50.642,669] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19918r with MessageCounter:11257461.
[00:01:50.642,913] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257461 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001B032 msec
[00:01:50.645,385] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:50.645,721] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:50.645,782] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:50.645,843] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:50.839,477] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:46848399 on exchange 19918r
--- 14 messages dropped ---
[00:01:50.854,644] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257462 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001B106 msec
[00:01:50.857,299] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:50.857,391] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:50.857,452] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:50.857,543] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:51.051,208] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:46848401 on exchange 19919r
[00:01:51.051,300] <dbg> chip: [EM]Found matching exchange: 19919r, Delegate: (nil)
[00:01:51.051,452] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:11257462 from Retrans Table on exchange 19919r
[00:01:51.051,574] <dbg> chip: [EM]Removed CHIP MessageCounter:11257462 from RetransTable on exchange 19919r
[00:01:51.051,757] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:51.062,255] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:46848402 on exchange 19920r
[00:01:51.062,408] <dbg> chip: [EM]Handling via exchange: 19920r, Delegate: 0x2000cd14
[00:01:51.062,500] <dbg> chip: [IM]Received Read request
[00:01:51.062,988] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:51.063,140] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:51.063,415] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
--- 5 messages dropped ---
[00:01:51.067,932] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:51.068,054] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:51.068,115] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:51.068,176] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:51.186,126] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ef4eba0c
[00:01:51.186,309] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to c93dca35
[00:01:51.186,462] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to f261118d
[00:01:51.191,436] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f87
[00:01:51.191,650] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f88
[00:01:51.191,833] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f89
--- 10 messages dropped ---
[00:01:51.274,444] <dbg> chip: [EM]Handling via exchange: 19921r, Delegate: 0x2000cd14
[00:01:51.274,566] <dbg> chip: [IM]Received Read request
[00:01:51.275,054] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:51.275,207] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:51.275,482] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:51.275,573] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 0 is dirty
[00:01:51.275,756] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=3 AttributeId=0x0000_0000 (expanded=0)
[00:01:51.275,970] <dbg> chip: [DMG]<RE> Sending report (payload has 71 bytes)...
[00:01:51.277,099] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19921r with MessageCounter:11257464.
--- 12 messages dropped ---
[00:01:51.484,954] <dbg> chip: [IM]Received Read request
[00:01:51.485,443] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:51.485,595] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:51.485,900] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:51.485,992] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
[00:01:51.486,145] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0003 (expanded=0)
[00:01:51.486,328] <dbg> chip: [DMG]<RE> Sending report (payload has 36 bytes)...
[00:01:51.487,213] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19922r with MessageCounter:11257465.
[00:01:51.487,487] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257465 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001B37F msec
--- 13 messages dropped ---
[00:01:51.814,758] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:51.815,063] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:51.815,124] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
[00:01:51.815,277] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0001 (expanded=0)
[00:01:51.815,521] <dbg> chip: [DMG]<RE> Sending report (payload has 93 bytes)...
[00:01:51.816,741] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19923r with MessageCounter:11257466.
[00:01:51.817,016] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257466 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001B4C8 msec
[00:01:51.819,702] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:51.819,793] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
--- 11 messages dropped ---
[00:01:52.026,702] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:52.027,008] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:52.027,099] <dbg> chip: [DMG]<RE:Run> Cluster 402, Attribute fffc is dirty
[00:01:52.027,252] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0402 Endpoint=1 AttributeId=0x0000_FFFC (expanded=0)
[00:01:52.027,435] <dbg> chip: [DMG]<RE> Sending report (payload has 38 bytes)...
[00:01:52.028,350] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19924r with MessageCounter:11257467.
[00:01:52.028,625] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257467 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001B59C msec
[00:01:52.031,066] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
--- 10 messages dropped ---
[00:01:52.241,210] <dbg> chip: [IM]Received Read request
[00:01:52.241,699] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:52.241,882] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:52.242,156] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:52.242,248] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
[00:01:52.242,401] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=2 AttributeId=0x0000_0003 (expanded=0)
[00:01:52.242,584] <dbg> chip: [DMG]<RE> Sending report (payload has 36 bytes)...
[00:01:52.243,499] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19925r with MessageCounter:11257468.
[00:01:52.243,774] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257468 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001B673 msec
--- 13 messages dropped ---
[00:01:52.455,139] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:52.455,444] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:52.455,535] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
[00:01:52.455,688] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=2 AttributeId=0x0000_0001 (expanded=0)
[00:01:52.455,932] <dbg> chip: [DMG]<RE> Sending report (payload has 93 bytes)...
[00:01:52.457,153] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19926r with MessageCounter:11257469.
[00:01:52.457,427] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257469 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001B749 msec
[00:01:52.460,083] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:52.460,205] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
--- 11 messages dropped ---
[00:01:52.667,449] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:52.667,724] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:52.667,846] <dbg> chip: [DMG]<RE:Run> Cluster 405, Attribute fffc is dirty
[00:01:52.667,999] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0405 Endpoint=2 AttributeId=0x0000_FFFC (expanded=0)
[00:01:52.668,182] <dbg> chip: [DMG]<RE> Sending report (payload has 38 bytes)...
[00:01:52.669,097] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19927r with MessageCounter:11257470.
[00:01:52.669,372] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257470 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001B81D msec
[00:01:52.671,997] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:52.672,119] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:52.672,180] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:52.672,271] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:52.866,851] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:46848417 on exchange 19927r
[00:01:52.866,943] <dbg> chip: [EM]Found matching exchange: 19927r, Delegate: (nil)
[00:01:52.867,095] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:11257470 from Retrans Table on exchange 19927r
[00:01:52.867,218] <dbg> chip: [EM]Removed CHIP MessageCounter:11257470 from RetransTable on exchange 19927r
[00:01:52.867,370] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:52.877,685] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:46848418 on exchange 19928r
[00:01:52.877,807] <dbg> chip: [EM]Handling via exchange: 19928r, Delegate: 0x2000cd14
[00:01:52.877,899] <dbg> chip: [IM]Received Read request
[00:01:52.878,387] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:52.878,540] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:52.878,845] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:52.878,936] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 3 is dirty
[00:01:52.879,089] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=3 AttributeId=0x0000_0003 (expanded=0)
[00:01:52.879,272] <dbg> chip: [DMG]<RE> Sending report (payload has 36 bytes)...
[00:01:52.880,157] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19928r with MessageCounter:11257471.
[00:01:52.880,432] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257471 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001B8F0 msec
[00:01:52.883,056] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:52.883,178] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:52.883,239] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:52.883,331] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:53.077,697] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:46848419 on exchange 19928r
[00:01:53.077,789] <dbg> chip: [EM]Found matching exchange: 19928r, Delegate: (nil)
[00:01:53.077,941] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:11257471 from Retrans Table on exchange 19928r
[00:01:53.078,063] <dbg> chip: [EM]Removed CHIP MessageCounter:11257471 from RetransTable on exchange 19928r
[00:01:53.078,216] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:53.089,569] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:46848420 on exchange 19929r
[00:01:53.089,691] <dbg> chip: [EM]Handling via exchange: 19929r, Delegate: 0x2000cd14
[00:01:53.089,813] <dbg> chip: [IM]Received Read request
[00:01:53.090,270] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:53.090,454] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:53.090,759] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:53.090,850] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
[00:01:53.091,003] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=3 AttributeId=0x0000_0001 (expanded=0)
[00:01:53.091,247] <dbg> chip: [DMG]<RE> Sending report (payload has 93 bytes)...
[00:01:53.092,437] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19929r with MessageCounter:11257472.
[00:01:53.092,742] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257472 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001B9C4 msec
[00:01:53.095,397] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:53.095,520] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:53.095,581] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:53.095,672] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:53.291,473] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:46848421 on exchange 19929r
[00:01:53.291,564] <dbg> chip: [EM]Found matching exchange: 19929r, Delegate: (nil)
[00:01:53.291,748] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:11257472 from Retrans Table on exchange 19929r
[00:01:53.291,870] <dbg> chip: [EM]Removed CHIP MessageCounter:11257472 from RetransTable on exchange 19929r
[00:01:53.292,022] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:53.305,419] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:46848422 on exchange 19930r
[00:01:53.305,541] <dbg> chip: [EM]Handling via exchange: 19930r, Delegate: 0x2000cd14
[00:01:53.305,633] <dbg> chip: [IM]Received Read request
[00:01:53.306,121] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:53.306,304] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:53.306,579] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:53.306,671] <dbg> chip: [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
[00:01:53.306,823] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:01:53.307,495] <dbg> chip: [DMG]<RE> Sending report (payload has 151 bytes)...
[00:01:53.309,020] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x5 and protocolId (0, 1) on exchange 19930r with MessageCounter:11257473.
[00:01:53.309,295] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257473 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001BA9D msec
[00:01:53.311,798] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:53.312,103] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:53.312,164] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:53.312,255] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:53.501,708] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:46848423 on exchange 19930r
[00:01:53.501,800] <dbg> chip: [EM]Found matching exchange: 19930r, Delegate: (nil)
[00:01:53.501,953] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:11257473 from Retrans Table on exchange 19930r
[00:01:53.502,075] <dbg> chip: [EM]Removed CHIP MessageCounter:11257473 from RetransTable on exchange 19930r
[00:01:53.502,227] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:54.186,126] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ef4eba0d
[00:01:54.186,279] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to c93dca36
[00:01:54.186,462] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to f261118e
[00:01:54.191,345] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f8e
[00:01:54.191,528] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f8f
[00:01:54.191,741] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f90
[00:01:54.191,925] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f91
[00:01:54.192,077] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f92
[00:01:54.192,260] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f93
[00:01:54.192,474] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f94
[00:01:54.502,777] <inf> chip: [EM]Received message of type 0xa with protocolId (0, 1) and MessageCounter:46848424 on exchange 19931r
[00:01:54.502,929] <dbg> chip: [EM]Handling via exchange: 19931r, Delegate: 0x2000cd14
[00:01:54.503,173] <dbg> chip: [DMG]Got Timed Request with timeout 10000: handler 0x2000d0e8 exchange 19931r
[00:01:54.504,028] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x1 and protocolId (0, 1) on exchange 19931r with MessageCounter:11257474.
[00:01:54.504,272] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257474 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001BF48 msec
[00:01:54.505,859] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:54.506,408] <dbg> chip: [DMG]Timed Request time limit 0x000000000001E65A: handler 0x2000d0e8 exchange 19931r
[00:01:54.631,347] <dbg> chip: [IN]Received a duplicate message with MessageCounter:46848424 on exchange 19931r
[00:01:54.631,530] <inf> chip: [EM]Received message of type 0xa with protocolId (0, 1) and MessageCounter:46848424 on exchange 19931r
[00:01:54.631,622] <dbg> chip: [EM]Found matching exchange: 19931r, Delegate: 0x2000d0e8
[00:01:54.631,774] <dbg> chip: [EM]Forcing tx of solitary ack for duplicate MessageCounter:46848424 on exchange 19931r
[00:01:54.631,896] <dbg> chip: [EM]Sending Standalone Ack for MessageCounter:46848424 on exchange 19931r
[00:01:54.633,056] <inf> chip: [IN]Prepared secure message 0x200338b8 to 0x20A8376795EEA4E8 (1)  of type 0x10 and protocolId (0, 0) on exchange 19931r with MessageCounter:11257475.
[00:01:54.633,972] <inf> chip: [IN]Sending encrypted msg 0x200338b8 with MessageCounter:11257475 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001BFC9 msec
[00:01:54.643,066] <dbg> chip: [IN]Received a duplicate message with MessageCounter:46848424 on exchange 19931r
[00:01:54.643,249] <inf> chip: [EM]Received message of type 0xa with protocolId (0, 1) and MessageCounter:46848424 on exchange 19931r
[00:01:54.643,341] <dbg> chip: [EM]Found matching exchange: 19931r, Delegate: 0x2000d0e8
[00:01:54.643,493] <dbg> chip: [EM]Forcing tx of solitary ack for duplicate MessageCounter:46848424 on exchange 19931r
[00:01:54.643,615] <dbg> chip: [EM]Sending Standalone Ack for MessageCounter:46848424 on exchange 19931r
[00:01:54.644,317] <inf> chip: [IN]Prepared secure message 0x200338b8 to 0x20A8376795EEA4E8 (1)  of type 0x10 and protocolId (0, 0) on exchange 19931r with MessageCounter:11257476.
[00:01:54.644,592] <inf> chip: [IN]Sending encrypted msg 0x200338b8 with MessageCounter:11257476 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001BFD4 msec
[00:01:54.815,490] <dbg> chip: [EM]Retransmitting MessageCounter:11257474 on exchange 19931r Send Cnt 0
[00:01:54.816,070] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257474 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001C07F msec
[00:01:54.865,173] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:46848425 on exchange 19931r
[00:01:54.865,264] <dbg> chip: [EM]Found matching exchange: 19931r, Delegate: 0x2000d0e8
[00:01:54.865,417] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:11257474 from Retrans Table on exchange 19931r
[00:01:54.865,539] <dbg> chip: [EM]Removed CHIP MessageCounter:11257474 from RetransTable on exchange 19931r
[00:01:54.865,753] <dbg> chip: [DMG]Timed following action arrived at 0x000000000001C0B1: handler 0x2000d0e8 exchange 19931r
[00:01:54.865,875] <dbg> chip: [DMG]Handing timed invoke to IM engine: handler 0x2000d0e8 exchange 19931r
[00:01:54.866,455] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000
[00:01:54.866,577] <inf> chip: [ZCL]Received command to open commissioning window
[00:01:54.867,370] <dbg> chip: [SC]Assigned local session key ID 22412
[00:01:54.867,462] <dbg> chip: [SC]Waiting for PBKDF param request
[00:01:54.867,553] <inf> chip: [DIS]Updating services using commissioning mode 2
[00:01:54.867,645] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:54.867,828] <inf> chip: [DIS]Advertise operational node 403A2619E233485A-00000000A62D7EF9
[00:01:54.868,347] <inf> chip: [DL]advertising srp service: 403A2619E233485A-00000000A62D7EF9._matter._tcp
[00:01:54.868,530] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:54.869,384] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32781 discriminator=0484/01
[00:01:54.869,903] <inf> chip: [DL]advertising srp service: 588B3EFC481E4B70._matterc._udp
[00:01:54.870,147] <inf> chip: [DL]removing srp service: 9616B9B2B9B86D04._matterc._udp
[00:01:54.870,208] <inf> chip: [ZCL]Commissioning window is now open
[00:01:54.870,300] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:54.870,391] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:54.870,483] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:54.870,727] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:54.871,612] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x20A8376795EEA4E8 (1)  of type 0x9 and protocolId (0, 1) on exchange 19931r with MessageCounter:11257477.
[00:01:54.871,887] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:11257477 to 0x20A8376795EEA4E8 (1) at monotonic time: 000000000001C0B7 msec
[00:01:54.874,298] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:54.874,542] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:54.946,655] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:46848426 on exchange 19931r
[00:01:54.946,777] <dbg> chip: [EM]Found matching exchange: 19931r, Delegate: (nil)
[00:01:54.946,899] <dbg> chip: [EM]CHIP MessageCounter:11257474 not in RetransTable on exchange 19931r
[00:01:54.966,979] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:46848427 on exchange 19931r
[00:01:54.967,071] <dbg> chip: [EM]Found matching exchange: 19931r, Delegate: (nil)
[00:01:54.967,224] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:11257477 from Retrans Table on exchange 19931r
[00:01:54.967,346] <dbg> chip: [EM]Removed CHIP MessageCounter:11257477 from RetransTable on exchange 19931r
[00:01:55.151,641] <err> chip: [DL]OnSrpClientNotification: Operation refused for security reasons
[00:01:56.955,810] <err> chip: [DL]OnSrpClientNotification: Operation refused for security reasons
[00:01:57.185,882] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ef4eba0e
[00:01:57.186,035] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to c93dca37
[00:01:57.186,218] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to f261118f
[00:01:57.191,040] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f95
[00:01:57.191,223] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f96
[00:01:57.191,406] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f97
[00:01:57.191,589] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f98
[00:01:57.191,741] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f99
[00:01:57.191,955] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f9a
[00:01:57.192,138] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f9b
[00:02:00.136,352] <err> chip: [DL]OnSrpClientNotification: Operation refused for security reasons
[00:02:00.185,852] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ef4eba0f
[00:02:00.186,035] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to c93dca38
[00:02:00.186,218] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to f2611190
[00:02:00.191,040] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f9c
[00:02:00.191,223] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f9d
[00:02:00.191,406] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f9e
[00:02:00.191,589] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5f9f
[00:02:00.191,772] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5fa0
[00:02:00.191,955] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5fa1
[00:02:00.192,138] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5fa2
[00:02:03.185,882] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to ef4eba10
[00:02:03.186,065] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to c93dca39
[00:02:03.186,218] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to f2611191
[00:02:03.191,070] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5fa3
[00:02:03.191,253] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5fa4
[00:02:03.191,436] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5fa5
[00:02:03.191,619] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5fa6
[00:02:03.191,802] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5fa7
[00:02:03.191,986] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5fa8
[00:02:03.192,169] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to a26c5fa9


Disconnected

Note: By creating my own Matter Network with an Open Thread Border Router (on Raspberry Pi 4) and the chip-tool as controller the commissioning succeeds.

My setup:

  • Apple HomePod mini (Version 16.2)
  • Thingy53
  • "Matter Weather Station" 2.0 from the NRF Programmer App

Is it even possible to commission the "Matter Weather Station" to an Apple Matter Network?

Parents Reply Children
  • Hello again, 

    "Matter Weather Station" 2.0 from the NRF Programmer App

    Can you provide more information on the Matter Weather station application? What version is the 2.0? Did you download from a precompiled package?

    commissioning stops here with the error "OnSrpClientNotification: Operation refused for security reasons"

    I found a similar question with our developers, and the answer was:

    "...you can see "E: 121100 [DL]OnSrpClientNotification: Operation refused for security reasons" error messages in the device logs which means that OTBR refuses to register DNS-SD services on behalf of the device. It is worth using the newest OTBR revision to rule out numerous SRP bugs that have been fixed in the past. Another (more probable) reason may be that the customer is trying to use an already-reserved nodeID to commission the device. A typical mistake is the following scenario: 1) Customer commissions device using node ID 1 2) Customer factory resets the device 3) Customer tries to commission the same device using node ID=1. In such a case, OTBR won't allow to register the same service again because it thinks it's already reserved. Resetting OTBR can be a workaround."
    By creating my own Matter Network with an Open Thread Border Router (on Raspberry Pi 4) and the chip-tool as controller the commissioning succeeds.

    Was this before of after trying to connect with the Apple Homepod mini?

    Our Matter developers have written a blog post on how to test Matter against Google, Apple and Samsung ecosystems. Perhaps there are some tips here that can help with the setip. 

    Let me know if following the steps above works, and if not we will find another solution.

    Kind regards,
    Øyvind

  • Hi,

    the nrf Programmer uses 2.0. But after building and flashing the "Matter Weather Station" myself, it works. Seems like the pre compiled version, provided by nrf Programmer app, is outdated.

    Thx for your help.

Related