Google Home Commissioning Problem

[Michal P]

HI,

I have compiled Nordic Light Example for nRF5340-DK   and flashed it.

I'm using a border router based on beagle bone and OpenThread 1.3

On nRF5340-DK I have set up an active dataset (the same as BR).

When I'm sending ping 2001:db8:1:ffff::808:808   from nRF5340-DK I'm getting a nice response confirming my connection with the internet. I'm able as well to ping mobile phone IP from  nRF5340-DK.

When I doing commissioning with Google Home app on phone after device discovery and scanning QR code I'm getting information that the device requires Thread Border Router (information in Polish language). It says that I should connect with Border Router and configure the device once again. 
The problem is that this device already is connected to Border Router and has internet access, as proved by ping 2001:db8:1:ffff::808:808 and phone IP . 

Below is log from my nRF5340-DK which I'm getting during this process.

uart:~$ I: BLE advertising is already enabled
I: 231303 [DL]BLE connection established (ConnId: 0x00)
I: 231308 [DL]Current number of connections: 1/1
I: 231313 [DL]CHIPoBLE advertising stopped
I: 231317 [DL]NFC Tag emulation stopped
D: 231996 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 232003 [BLE]local and remote recv window sizes = 5
I: 232008 [BLE]selected BTP version 4
I: 232011 [BLE]using BTP fragment sizes rx 128 / tx 128.
D: 232100 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 232105 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 232112 [IN]BLE EndPoint 0x200127d0 Connection Complete
I: 232118 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
D: 232240 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 232248 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 232256 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:193343940 on exchange 51106r
D: 232266 [EM]Handling via exchange: 51106r, Delegate: 0x20006614
D: 232272 [SC]Received PBKDF param request
D: 232276 [SC]Peer assigned session ID 37342
D: 232279 [SC]Found MRP parameters in the message
D: 232284 [SC]Including MRP parameters in PBKDF param response
I: 232290 [IN]Prepared unauthenticated message 0x2002ece0 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 51106r with MessageCounter:164129078.
I: 232306 [IN]Sending unauthenticated msg 0x2002ece0 with MessageCounter:164129078 to 0x0000000000000000 at monotonic time: 0000000000038B71 msec
D: 232319 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 232326 [SC]Sent PBKDF param response
D: 232380 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 232388 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 14)
D: 232450 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 232458 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 232466 [EM]Received message of type 0x22 with protocolId (0, 0) and MessageCounter:193343941 on exchange 51106r
D: 232476 [EM]Found matching exchange: 51106r, Delegate: 0x20006614
D: 232482 [SC]Received spake2p msg1
I: 234057 [IN]Prepared unauthenticated message 0x2002ec70 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 51106r with MessageCounter:164129079.
I: 234072 [IN]Sending unauthenticated msg 0x2002ec70 with MessageCounter:164129079 to 0x0000000000000000 at monotonic time: 0000000000039258 msec
D: 234085 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 234093 [SC]Sent spake2p msg2
E: 234095 [DL]Long dispatch time: 1637 ms, for event type 16388
D: 234130 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 234138 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 234200 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 234208 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 234216 [EM]Received message of type 0x24 with protocolId (0, 0) and MessageCounter:193343942 on exchange 51106r
D: 234226 [EM]Found matching exchange: 51106r, Delegate: 0x20006614
D: 234232 [SC]Received spake2p msg3
D: 234235 [SC]Sending status report. Protocol code 0, exchange 51106
I: 234242 [IN]Prepared unauthenticated message 0x2002ecf8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 51106r with MessageCounter:164129080.
I: 234257 [IN]Sending unauthenticated msg 0x2002ecf8 with MessageCounter:164129080 to 0x0000000000000000 at monotonic time: 0000000000039311 msec
D: 234270 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 234279 [SC]SecureSession[0x20004430]: Moving from state 'kEstablishing' --> 'kActive'
D: 234286 [IN]SecureSession[0x20004430]: Activated - Type:1 LSID:36426
D: 234293 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:36426 PSID:37342!
I: 234302 [SVR]Commissioning completed session establishment step
I: 234308 [DIS]Updating services using commissioning mode 0
D: 234313 [DL]Using Thread extended MAC for hostname.
I: 234319 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 234328 [DL]advertising srp service: F599816147F4BA1C._matterc._udp
D: 234334 [DIS]Scheduling extended discovery timeout in 900s
D: 234341 [DL]CHIPoBLE advertising set to off
I: 234380 [SVR]Device completed Rendezvous process
E: 234385 [DL]Long dispatch time: 176 ms, for event type 16388
D: 234391 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 234399 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 234409 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:74440050 on exchange 51107r
D: 234420 [EM]Handling via exchange: 51107r, Delegate: 0x2001019c
D: 234426 [IM]Received Read request
D: 234431 [DMG]IM RH moving to [GeneratingReports]
D: 234436 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 234445 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 234451 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 234461 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 234467 [IN]Prepared secure message 0x2002ee90 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 51107r with MessageCounter:203257533.
I: 234483 [IN]Sending encrypted msg 0x2002ee90 with MessageCounter:203257533 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000393F1 msec
D: 234496 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 234504 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 234509 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 234516 [DMG]IM RH moving to [AwaitingDestruction]
D: 234522 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 234550 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 234558 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 234566 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:74440051 on exchange 51108r
D: 234576 [EM]Handling via exchange: 51108r, Delegate: 0x2001019c
D: 234582 [IM]Received Read request
D: 234586 [DMG]IM RH moving to [GeneratingReports]
D: 234590 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 234599 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 234604 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 234613 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 234620 [IN]Prepared secure message 0x2002ee90 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 51108r with MessageCounter:203257534.
I: 234634 [IN]Sending encrypted msg 0x2002ee90 with MessageCounter:203257534 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000003948A msec
D: 234647 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 234654 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 234659 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 234666 [DMG]IM RH moving to [AwaitingDestruction]
D: 234671 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 234725 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 234733 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 234741 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:74440052 on exchange 51109r
D: 234751 [EM]Handling via exchange: 51109r, Delegate: 0x2001019c
D: 234757 [IM]Received Read request
D: 234761 [DMG]IM RH moving to [GeneratingReports]
D: 234765 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 234774 [DMG]<RE:Run> Cluster 3e, Attribute 2 is dirty
D: 234779 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 234788 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 234795 [IN]Prepared secure message 0x2002ee90 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 51109r with MessageCounter:203257535.
I: 234809 [IN]Sending encrypted msg 0x2002ee90 with MessageCounter:203257535 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000039539 msec
D: 234822 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 234829 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 234834 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 234841 [DMG]IM RH moving to [AwaitingDestruction]
D: 234846 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 234900 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 234908 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 234916 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:74440053 on exchange 51110r
D: 234926 [EM]Handling via exchange: 51110r, Delegate: 0x2001019c
D: 234932 [IM]Received Read request
D: 234936 [DMG]IM RH moving to [GeneratingReports]
D: 234940 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 234949 [DMG]<RE:Run> Cluster 3e, Attribute 3 is dirty
D: 234954 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 234963 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 234970 [IN]Prepared secure message 0x2002ee90 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 51110r with MessageCounter:203257536.
I: 234984 [IN]Sending encrypted msg 0x2002ee90 with MessageCounter:203257536 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000000395E8 msec
D: 234997 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 235004 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 235009 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 235016 [DMG]IM RH moving to [AwaitingDestruction]
D: 235021 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 235075 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 235083 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 235091 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:74440054 on exchange 51111r
D: 235101 [EM]Handling via exchange: 51111r, Delegate: 0x2001019c
D: 235107 [IM]Received Read request
D: 235111 [DMG]IM RH moving to [GeneratingReports]
D: 235115 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 235124 [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
D: 235129 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 235138 [DMG]<RE> Sending report (payload has 36 bytes)...
I: 235145 [IN]Prepared secure message 0x2002ee90 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 51111r with MessageCounter:203257537.
I: 235159 [IN]Sending encrypted msg 0x2002ee90 with MessageCounter:203257537 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000039697 msec
D: 235172 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 235179 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 235184 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 235191 [DMG]IM RH moving to [AwaitingDestruction]
D: 235196 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 235250 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 235258 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 235266 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:74440055 on exchange 51112r
D: 235276 [EM]Handling via exchange: 51112r, Delegate: 0x2001019c
D: 235282 [IM]Received Read request
D: 235286 [DMG]IM RH moving to [GeneratingReports]
D: 235290 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 235299 [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
D: 235304 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 235314 [DMG]<RE> Sending report (payload has 400 bytes)...
I: 235322 [IN]Prepared secure message 0x2002ee90 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 51112r with MessageCounter:203257538.
I: 235336 [IN]Sending encrypted msg 0x2002ee90 with MessageCounter:203257538 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000039748 msec
D: 235349 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 235357 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 235361 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 235369 [DMG]IM RH moving to [AwaitingDestruction]
D: 235374 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 235382 [DL]SRP update succeeded
D: 235425 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 235433 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 235495 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 235503 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 235565 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 235573 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57)
D: 235636 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 235643 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 235705 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 235713 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:74440056 on exchange 51113r
D: 235723 [EM]Handling via exchange: 51113r, Delegate: 0x2001019c
D: 235729 [IM]Received Read request
D: 235733 [DMG]IM RH moving to [GeneratingReports]
D: 235738 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 235746 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 235752 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D: 235761 [DMG]<RE> Sending report (payload has 37 bytes)...
I: 235767 [IN]Prepared secure message 0x2002ee90 to 0xFFFFFFFB00000000 (0) of type 0x5 and protocolId (0, 1) on exchange 51113r with MessageCounter:203257539.
I: 235781 [IN]Sending encrypted msg 0x2002ee90 with MessageCounter:203257539 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000039905 msec
D: 235794 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 235802 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 235807 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 235814 [DMG]IM RH moving to [AwaitingDestruction]
D: 235819 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 235845 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 238360 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 240868 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 240925 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 241961 [DL]BLE GAP connection terminated (reason 0x13)
I: 241966 [DL]Current number of connections: 0/1
E: 255875 [BLE]ack recv timeout, closing ep 0x200127d0
D: 255880 [IN]Clearing BLE pending packets.
I: 255884 [BLE]Releasing end point's BLE connection back to application.
I: 255890 [DL]Closing BLE GATT connection (ConnId 00)

In the google developer console, I have the below configuration. I also have to check if email address used in the developer console is the same one I'm using on my phone's Google Home App. Any idea why I have a problem with adding nRF5340-DK  as a device in Google Home App?  This is my first attempt to commission Matter device so I will appreciate any help.  

[Revilo]

Hi Michal and Charlie

It now works! I posted a comment in the already mentioned GitHub issue: https://github.com/project-chip/connectedhomeip/issues/23761#issuecomment-1339171127

I hope that helps.

Best regards,

Oliver

[Michal P]

Hi, thank you for the information.  I did a Samsung software upgrade of Samsung Note20 Ultra 5G in meantime. Now I lost the possibility to find any Matter device with Android Phone (no matter device is seen). When I scan NFC it redirects me to SmartThings app and showing that the accessory is not valid (before the update it was redirecting me to Google Home App as it should). It looks like Samsung did something weird with the last update.

On iPhone I can  find and commision device and everything is working fine with Siri.  With Google its a problem after a problem I contacted Google and Samsung  and described this issue. I will let you know about the progress with it. 

[Michal P]

Revilo Lukasz Duda Fantastic news - today I did a check and I was able to perform successful commissioning at Google Home App (both light bulb example and Weather Station example working on Thingy53). I'm able to control this devices with voice, all works great!

On Apple  I was able to perform commissioning only with light bulb example. Weather Station commissioning on Apple has some problem, below I placed log from commissioning process. 

[00:01:25.603,912] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:25.604,064] <inf> chip: [DIS]Advertise operational node 58892A5EB69E62C6-00000000848254C1
[00:01:25.604,461] <inf> chip: [DL]advertising srp service: 58892A5EB69E62C6-00000000848254C1._matter._tcp
[00:01:25.604,705] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:25.605,468] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32781 discriminator=3840/15
[00:01:25.605,957] <inf> chip: [DL]advertising srp service: CE7F149708085439._matterc._udp
[00:01:25.606,201] <dbg> chip: [DIS]Scheduling extended discovery timeout in 900s
[00:01:26.548,889] <dbg> chip: [DL]OnSrpClientNotification: Last requested operation completed successfully
[00:01:27.181,945] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to 7d258a2b
[00:01:27.182,098] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to dcc34f8
[00:01:27.182,281] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 95cce045
[00:01:27.187,103] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827a9
[00:01:27.187,286] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827aa
[00:01:27.187,469] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827ab
[00:01:27.187,622] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827ac
[00:01:27.187,805] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827ad
[00:01:27.188,018] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827ae
[00:01:27.188,201] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827af
[00:01:27.569,152] <inf> chip: [EM]Received message of type 0x30 with protocolId (0, 0) and MessageCounter:188836076 on exchange 56199r
[00:01:27.569,305] <dbg> chip: [EM]Handling via exchange: 56199r, Delegate: 0x200072b0
[00:01:27.569,427] <inf> chip: [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20008638
[00:01:27.569,793] <dbg> chip: [SC]Waiting for Sigma1 msg
[00:01:27.569,854] <inf> chip: [IN]CASE Server disabling CASE session setups
[00:01:27.569,946] <inf> chip: [SC]Received Sigma1 msg
[00:01:27.570,159] <dbg> chip: [SC]Found MRP parameters in the message
[00:01:27.570,251] <dbg> chip: [SC]Peer assigned session key ID 37440
[00:01:27.572,784] <inf> chip: [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x00000000848254C1
[00:01:27.760,742] <dbg> chip: [SC]Including MRP parameters
[00:01:27.761,474] <inf> chip: [IN]Prepared unauthenticated message 0x200088ec to 0x0000000000000000 (0)  of type 0x31 and protocolId (0, 0) on exchange 56199r with MessageCounter:2152039681.
[00:01:27.761,718] <inf> chip: [IN]Sending unauthenticated msg 0x200088ec with MessageCounter:2152039681 to 0x0000000000000000 at monotonic time: 00000000000156D1 msec
[00:01:27.764,617] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:27.764,678] <inf> chip: [SC]Sent Sigma2 msg
[00:01:27.790,771] <dbg> chip: [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
[00:01:28.328,338] <dbg> chip: [EM]Retransmitting MessageCounter:2152039681 on exchange 56199r Send Cnt 0
[00:01:28.328,857] <inf> chip: [IN]Sending unauthenticated msg 0x200088ec with MessageCounter:2152039681 to 0x0000000000000000 at monotonic time: 0000000000015908 msec
[00:01:28.468,963] <inf> chip: [EM]Received message of type 0x32 with protocolId (0, 0) and MessageCounter:188836077 on exchange 56199r
[00:01:28.469,268] <dbg> chip: [EM]Found matching exchange: 56199r, Delegate: 0x200072c4
[00:01:28.469,421] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:2152039681 from Retrans Table on exchange 56199r
[00:01:28.469,543] <dbg> chip: [EM]Removed CHIP MessageCounter:2152039681 from RetransTable on exchange 56199r
[00:01:28.469,635] <inf> chip: [SC]Received Sigma3 msg
[00:01:28.599,243] <dbg> chip: [SC]Sending status report. Protocol code 0, exchange 56199
[00:01:28.599,578] <inf> chip: [IN]Prepared unauthenticated message 0x200088ec to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 56199r with MessageCounter:2152039682.
[00:01:28.599,822] <inf> chip: [IN]Sending unauthenticated msg 0x200088ec with MessageCounter:2152039682 to 0x0000000000000000 at monotonic time: 0000000000015A17 msec
[00:01:28.603,271] <dbg> chip: [IN]New secure session created for device <7C2808038175E546, 1>, LSID:18091 PSID:37440!
[00:01:28.603,393] <inf> chip: [IN]CASE Session established to peer: <7C2808038175E546, 1>
[00:01:28.603,454] <inf> chip: [IN]CASE Server enabling CASE session setups
[00:01:28.622,406] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:188836078 on exchange 56199r
[00:01:28.622,528] <dbg> chip: [EM]Found matching exchange: 56199r, Delegate: (nil)
[00:01:28.622,650] <dbg> chip: [EM]CHIP MessageCounter:2152039681 not in RetransTable on exchange 56199r
[00:01:29.110,595] <dbg> chip: [IN]Received a duplicate message with MessageCounter:188836077 on exchange 56199r
[00:01:29.110,961] <inf> chip: [EM]Received message of type 0x32 with protocolId (0, 0) and MessageCounter:188836077 on exchange 56199r
[00:01:29.111,083] <dbg> chip: [EM]Found matching exchange: 56199r, Delegate: (nil)
[00:01:29.111,206] <dbg> chip: [EM]Forcing tx of solitary ack for duplicate MessageCounter:188836077 on exchange 56199r
[00:01:29.111,328] <dbg> chip: [EM]Sending Standalone Ack for MessageCounter:188836077 on exchange 56199r
[00:01:29.111,633] <inf> chip: [IN]Prepared unauthenticated message 0x200338b0 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 56199r with MessageCounter:2152039683.
[00:01:29.111,877] <inf> chip: [IN]Sending unauthenticated msg 0x200338b0 with MessageCounter:2152039683 to 0x0000000000000000 at monotonic time: 0000000000015C17 msec
[00:01:29.124,908] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:221520946 on exchange 56200r
[00:01:29.125,030] <dbg> chip: [EM]Handling via exchange: 56200r, Delegate: 0x2000cd14
[00:01:29.125,579] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
[00:01:29.127,410] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_0030 update version to 45b2a538
[00:01:29.127,532] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:29.127,624] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:29.127,685] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:29.127,899] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:29.130,340] <inf> chip: [IN]Prepared secure message 0x20008904 to 0x7C2808038175E546 (1)  of type 0x9 and protocolId (0, 1) on exchange 56200r with MessageCounter:15893243.
[00:01:29.130,615] <inf> chip: [IN]Sending encrypted msg 0x20008904 with MessageCounter:15893243 to 0x7C2808038175E546 (1) at monotonic time: 0000000000015C2A msec
[00:01:29.131,591] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:29.131,652] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:29.131,744] <inf> chip: [SVR]Commissioning completed successfully
[00:01:29.131,896] <inf> chip: [DIS]Updating services using commissioning mode 0
--- 3 messages dropped ---
[00:01:29.132,873] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:29.133,728] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32781 discriminator=3840/15
[00:01:29.134,765] <inf> chip: [DL]advertising srp service: CE7F149708085439._matterc._udp
[00:01:29.135,284] <dbg> chip: [DIS]Scheduling extended discovery timeout in 900s
[00:01:29.135,986] <dbg> chip: [IN]Expiring all PASE pairings
[00:01:29.136,077] <dbg> chip: [IN]Clearing BLE pending packets.
[00:01:29.136,138] <inf> chip: [BLE]Releasing end point's BLE connection back to application.
[00:01:29.136,199] <inf> chip: [DL]Closing BLE GATT connection (ConnId 00)
[00:01:29.137,145] <inf> chip: [SWU]Device commissioned, schedule a default provider query
[00:01:29.137,237] <dbg> chip: [ZCL]Commissioning complete, notify platform driver to persist network credentials.
--- 15 messages dropped ---
[00:01:29.251,800] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:29.273,681] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:221520948 on exchange 56201r
[00:01:29.273,803] <dbg> chip: [EM]Handling via exchange: 56201r, Delegate: 0x2000cd14
[00:01:29.273,895] <dbg> chip: [IM]Received Read request
[00:01:29.274,383] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:29.274,505] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:29.274,780] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:29.274,871] <dbg> chip: [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
[00:01:29.275,054] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:01:29.275,695] <dbg> chip: [DMG]<RE> Sending report (payload has 151 bytes)...
--- 11 messages dropped ---
[00:01:29.474,090] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:29.486,480] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:221520950 on exchange 56202r
--- 5 messages dropped ---
[00:01:29.492,279] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
--- 5 messages dropped ---
[00:01:29.492,370] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:29.492,431] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:29.492,706] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:29.686,157] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:221520951 on exchange 56202r
[00:01:29.686,279] <dbg> chip: [EM]Found matching exchange: 56202r, Delegate: (nil)
[00:01:29.686,431] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:15893245 from Retrans Table on exchange 56202r
--- 14 messages dropped ---
[00:01:29.704,559] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:29.704,620] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:29.704,711] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:29.897,430] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:221520953 on exchange 56203r
[00:01:29.897,521] <dbg> chip: [EM]Found matching exchange: 56203r, Delegate: (nil)
[00:01:29.897,674] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:15893246 from Retrans Table on exchange 56203r
[00:01:29.897,796] <dbg> chip: [EM]Removed CHIP MessageCounter:15893246 from RetransTable on exchange 56203r
[00:01:29.897,949] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:29.909,423] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:221520954 on exchange 56204r
--- 12 messages dropped ---
[00:01:29.915,313] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:29.915,405] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:30.108,825] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:221520955 on exchange 56204r
[00:01:30.108,917] <dbg> chip: [EM]Found matching exchange: 56204r, Delegate: (nil)
[00:01:30.109,100] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:15893247 from Retrans Table on exchange 56204r
[00:01:30.109,222] <dbg> chip: [EM]Removed CHIP MessageCounter:15893247 from RetransTable on exchange 56204r
[00:01:30.109,375] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:30.121,032] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:221520956 on exchange 56205r
[00:01:30.121,154] <dbg> chip: [EM]Handling via exchange: 56205r, Delegate: 0x2000cd14
--- 10 messages dropped ---
[00:01:30.126,831] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:30.126,892] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:30.126,983] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:30.182,159] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to 7d258a2c
[00:01:30.182,312] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to dcc34f9
[00:01:30.182,495] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 95cce046
[00:01:30.187,469] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827b0
[00:01:30.187,652] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827b1
[00:01:30.187,835] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827b2
[00:01:30.188,018] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827b3
--- 8 messages dropped ---
[00:01:30.332,916] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:221520958 on exchange 56206r
[00:01:30.333,068] <dbg> chip: [EM]Handling via exchange: 56206r, Delegate: 0x2000cd14
[00:01:30.333,160] <dbg> chip: [IM]Received Read request
[00:01:30.333,618] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:30.333,801] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:30.334,106] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:30.334,197] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
[00:01:30.334,350] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0001 (expanded=0)
[00:01:30.334,594] <dbg> chip: [DMG]<RE> Sending report (payload has 93 bytes)...
[00:01:30.335,784] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x7C2808038175E546 (1)  of type 0x5 and protocolId (0, 1) on exchange 56206r with MessageCounter:15893249.
--- 12 messages dropped ---
[00:01:30.543,518] <dbg> chip: [IM]Received Read request
[00:01:30.544,006] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:30.544,189] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:30.544,464] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:30.544,586] <dbg> chip: [DMG]<RE:Run> Cluster 402, Attribute fffc is dirty
[00:01:30.544,738] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0402 Endpoint=1 AttributeId=0x0000_FFFC (expanded=0)
[00:01:30.544,921] <dbg> chip: [DMG]<RE> Sending report (payload has 38 bytes)...
[00:01:30.545,837] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x7C2808038175E546 (1)  of type 0x5 and protocolId (0, 1) on exchange 56207r with MessageCounter:15893250.
[00:01:30.546,112] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:15893250 to 0x7C2808038175E546 (1) at monotonic time: 00000000000161B1 msec
[00:01:30.548,553] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:30.548,858] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:30.548,919] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:30.548,980] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:30.743,316] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:221520961 on exchange 56207r
[00:01:30.743,408] <dbg> chip: [EM]Found matching exchange: 56207r, Delegate: (nil)
[00:01:30.743,560] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:15893250 from Retrans Table on exchange 56207r
[00:01:30.743,682] <dbg> chip: [EM]Removed CHIP MessageCounter:15893250 from RetransTable on exchange 56207r
[00:01:30.743,835] <inf> chip: [DL]OpenThread SED interval set to 1000ms
--- 1 messages dropped ---
[00:01:30.757,965] <dbg> chip: [EM]Handling via exchange: 56208r, Delegate: 0x2000cd14
[00:01:30.758,056] <dbg> chip: [IM]Received Read request
[00:01:30.758,544] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:30.758,728] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:30.759,002] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:30.759,094] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
[00:01:30.759,277] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=2 AttributeId=0x0000_0001 (expanded=0)
[00:01:30.759,521] <dbg> chip: [DMG]<RE> Sending report (payload has 93 bytes)...
[00:01:30.760,711] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x7C2808038175E546 (1)  of type 0x5 and protocolId (0, 1) on exchange 56208r with MessageCounter:15893251.
[00:01:30.760,986] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:15893251 to 0x7C2808038175E546 (1) at monotonic time: 0000000000016288 msec
[00:01:30.763,488] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:30.763,793] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:30.763,854] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:30.763,916] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:30.955,413] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:221520963 on exchange 56208r
[00:01:30.955,505] <dbg> chip: [EM]Found matching exchange: 56208r, Delegate: (nil)
[00:01:30.955,657] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:15893251 from Retrans Table on exchange 56208r
[00:01:30.955,780] <dbg> chip: [EM]Removed CHIP MessageCounter:15893251 from RetransTable on exchange 56208r
[00:01:30.955,932] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:30.967,926] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:221520964 on exchange 56209r
[00:01:30.968,078] <dbg> chip: [EM]Handling via exchange: 56209r, Delegate: 0x2000cd14
[00:01:30.968,170] <dbg> chip: [IM]Received Read request
[00:01:30.968,627] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:30.968,811] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:30.969,085] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:30.969,207] <dbg> chip: [DMG]<RE:Run> Cluster 405, Attribute fffc is dirty
[00:01:30.969,360] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_0405 Endpoint=2 AttributeId=0x0000_FFFC (expanded=0)
[00:01:30.969,543] <dbg> chip: [DMG]<RE> Sending report (payload has 38 bytes)...
[00:01:30.970,458] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x7C2808038175E546 (1)  of type 0x5 and protocolId (0, 1) on exchange 56209r with MessageCounter:15893252.
[00:01:30.970,733] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:15893252 to 0x7C2808038175E546 (1) at monotonic time: 000000000001635A msec
[00:01:30.973,175] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:30.973,480] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:30.973,541] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:30.973,602] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:31.168,914] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:221520965 on exchange 56209r
[00:01:31.169,036] <dbg> chip: [EM]Found matching exchange: 56209r, Delegate: (nil)
[00:01:31.169,189] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:15893252 from Retrans Table on exchange 56209r
[00:01:31.169,311] <dbg> chip: [EM]Removed CHIP MessageCounter:15893252 from RetransTable on exchange 56209r
[00:01:31.169,464] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:31.182,067] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:221520966 on exchange 56210r
[00:01:31.182,189] <dbg> chip: [EM]Handling via exchange: 56210r, Delegate: 0x2000cd14
[00:01:31.182,281] <dbg> chip: [IM]Received Read request
[00:01:31.182,769] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:31.182,922] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:31.183,227] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:31.183,319] <dbg> chip: [DMG]<RE:Run> Cluster 1d, Attribute 1 is dirty
[00:01:31.183,471] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=3 AttributeId=0x0000_0001 (expanded=0)
[00:01:31.183,715] <dbg> chip: [DMG]<RE> Sending report (payload has 93 bytes)...
[00:01:31.184,936] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x7C2808038175E546 (1)  of type 0x5 and protocolId (0, 1) on exchange 56210r with MessageCounter:15893253.
[00:01:31.185,211] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:15893253 to 0x7C2808038175E546 (1) at monotonic time: 0000000000016430 msec
[00:01:31.187,683] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:31.187,988] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:31.188,049] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:31.188,140] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:31.581,298] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:221520967 on exchange 56210r
[00:01:31.581,390] <dbg> chip: [EM]Found matching exchange: 56210r, Delegate: (nil)
[00:01:31.581,542] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:15893253 from Retrans Table on exchange 56210r
[00:01:31.581,665] <dbg> chip: [EM]Removed CHIP MessageCounter:15893253 from RetransTable on exchange 56210r
[00:01:31.581,817] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:31.593,811] <inf> chip: [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:221520968 on exchange 56211r
[00:01:31.593,933] <dbg> chip: [EM]Handling via exchange: 56211r, Delegate: 0x2000cd14
[00:01:31.594,024] <dbg> chip: [IM]Received Read request
[00:01:31.594,543] <dbg> chip: [DMG]IM RH moving to [GeneratingReports]
[00:01:31.594,696] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:31.594,970] <dbg> chip: [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
[00:01:31.595,062] <dbg> chip: [DMG]<RE:Run> Cluster 3e, Attribute 1 is dirty
[00:01:31.595,245] <dbg> chip: [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
[00:01:31.595,886] <dbg> chip: [DMG]<RE> Sending report (payload has 151 bytes)...
[00:01:31.597,412] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x7C2808038175E546 (1)  of type 0x5 and protocolId (0, 1) on exchange 56211r with MessageCounter:15893254.
[00:01:31.597,686] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:15893254 to 0x7C2808038175E546 (1) at monotonic time: 00000000000165CD msec
[00:01:31.600,189] <dbg> chip: [DMG]<RE> OnReportConfirm: NumReports = 0
[00:01:31.600,463] <dbg> chip: [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
[00:01:31.600,555] <dbg> chip: [DMG]IM RH moving to [AwaitingDestruction]
[00:01:31.600,616] <dbg> chip: [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
[00:01:31.898,468] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:221520969 on exchange 56211r
[00:01:31.898,559] <dbg> chip: [EM]Found matching exchange: 56211r, Delegate: (nil)
[00:01:31.898,712] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:15893254 from Retrans Table on exchange 56211r
[00:01:31.898,834] <dbg> chip: [EM]Removed CHIP MessageCounter:15893254 from RetransTable on exchange 56211r
[00:01:31.898,986] <inf> chip: [DL]OpenThread SED interval set to 1000ms
[00:01:32.898,834] <inf> chip: [EM]Received message of type 0xa with protocolId (0, 1) and MessageCounter:221520970 on exchange 56212r
[00:01:32.898,956] <dbg> chip: [EM]Handling via exchange: 56212r, Delegate: 0x2000cd14
[00:01:32.899,230] <dbg> chip: [DMG]Got Timed Request with timeout 10000: handler 0x2000d0e8 exchange 56212r
[00:01:32.900,054] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x7C2808038175E546 (1)  of type 0x1 and protocolId (0, 1) on exchange 56212r with MessageCounter:15893255.
[00:01:32.900,360] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:15893255 to 0x7C2808038175E546 (1) at monotonic time: 0000000000016AE4 msec
[00:01:32.901,397] <inf> chip: [DL]OpenThread SED interval set to 200ms
[00:01:32.901,550] <dbg> chip: [DMG]Timed Request time limit 0x00000000000191F5: handler 0x2000d0e8 exchange 56212r
[00:01:32.911,834] <dbg> chip: [IN]Received a duplicate message with MessageCounter:221520970 on exchange 56212r
[00:01:32.912,017] <inf> chip: [EM]Received message of type 0xa with protocolId (0, 1) and MessageCounter:221520970 on exchange 56212r
[00:01:32.912,139] <dbg> chip: [EM]Found matching exchange: 56212r, Delegate: 0x2000d0e8
[00:01:32.912,292] <dbg> chip: [EM]Forcing tx of solitary ack for duplicate MessageCounter:221520970 on exchange 56212r
[00:01:32.912,414] <dbg> chip: [EM]Sending Standalone Ack for MessageCounter:221520970 on exchange 56212r
[00:01:32.913,116] <inf> chip: [IN]Prepared secure message 0x200338b8 to 0x7C2808038175E546 (1)  of type 0x10 and protocolId (0, 0) on exchange 56212r with MessageCounter:15893256.
[00:01:32.913,421] <inf> chip: [IN]Sending encrypted msg 0x200338b8 with MessageCounter:15893256 to 0x7C2808038175E546 (1) at monotonic time: 0000000000016AF1 msec
[00:01:33.136,383] <inf> chip: [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:221520971 on exchange 56212r
[00:01:33.136,505] <dbg> chip: [EM]Found matching exchange: 56212r, Delegate: 0x2000d0e8
[00:01:33.136,657] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:15893255 from Retrans Table on exchange 56212r
[00:01:33.136,779] <dbg> chip: [EM]Removed CHIP MessageCounter:15893255 from RetransTable on exchange 56212r
[00:01:33.136,962] <dbg> chip: [DMG]Timed following action arrived at 0x0000000000016BD0: handler 0x2000d0e8 exchange 56212r
[00:01:33.137,084] <dbg> chip: [DMG]Handing timed invoke to IM engine: handler 0x2000d0e8 exchange 56212r
[00:01:33.137,695] <dbg> chip: [DMG]Received command for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000
[00:01:33.137,817] <inf> chip: [ZCL]Received command to open commissioning window
[00:01:33.138,610] <dbg> chip: [SC]Assigned local session key ID 18092
[00:01:33.138,702] <dbg> chip: [SC]Waiting for PBKDF param request
[00:01:33.138,763] <inf> chip: [DIS]Updating services using commissioning mode 2
[00:01:33.138,854] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:33.139,038] <inf> chip: [DIS]Advertise operational node 58892A5EB69E62C6-00000000848254C1
[00:01:33.139,556] <inf> chip: [DL]advertising srp service: 58892A5EB69E62C6-00000000848254C1._matter._tcp
[00:01:33.139,739] <dbg> chip: [DL]Using Thread extended MAC for hostname.
[00:01:33.140,625] <inf> chip: [DIS]Advertise commission parameter vendorID=65521 productID=32781 discriminator=2290/08
[00:01:33.141,113] <inf> chip: [DL]advertising srp service: C36070D39961A92A._matterc._udp
[00:01:33.141,357] <inf> chip: [DL]removing srp service: CE7F149708085439._matterc._udp
[00:01:33.141,448] <inf> chip: [ZCL]Commissioning window is now open
[00:01:33.141,540] <dbg> chip: [DMG]ICR moving to [ Preparing]
[00:01:33.141,632] <dbg> chip: [DMG]ICR moving to [AddingComm]
[00:01:33.141,693] <dbg> chip: [DMG]ICR moving to [AddedComma]
[00:01:33.141,937] <dbg> chip: [DMG]Decreasing reference count for CommandHandler, remaining 0
[00:01:33.142,822] <inf> chip: [IN]Prepared secure message 0x200088ec to 0x7C2808038175E546 (1)  of type 0x9 and protocolId (0, 1) on exchange 56212r with MessageCounter:15893257.
[00:01:33.143,096] <inf> chip: [IN]Sending encrypted msg 0x200088ec with MessageCounter:15893257 to 0x7C2808038175E546 (1) at monotonic time: 0000000000016BD6 msec
[00:01:33.145,538] <dbg> chip: [DMG]ICR moving to [CommandSen]
[00:01:33.145,782] <dbg> chip: [DMG]ICR moving to [AwaitingDe]
[00:01:33.187,469] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to 7d258a2d
[00:01:33.187,652] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to dcc34fa
[00:01:33.188,018] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 95cce047
[00:01:33.192,962] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827b7
[00:01:33.193,145] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827b8
[00:01:33.193,359] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827b9
[00:01:33.193,542] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827ba
[00:01:33.193,695] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827bb
[00:01:33.194,915] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827bc
[00:01:33.195,526] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827bd
[00:01:33.210,235] <inf> chip: [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:221520972 on exchange 56212r
[00:01:33.210,327] <dbg> chip: [EM]Found matching exchange: 56212r, Delegate: (nil)
[00:01:33.210,479] <dbg> chip: [EM]Rxd Ack; Removing MessageCounter:15893257 from Retrans Table on exchange 56212r
[00:01:33.210,601] <dbg> chip: [EM]Removed CHIP MessageCounter:15893257 from RetransTable on exchange 56212r
[00:01:33.394,470] <err> chip: [DL]OnSrpClientNotification: Operation refused for security reasons
[00:01:35.183,654] <err> chip: [DL]OnSrpClientNotification: Operation refused for security reasons
[00:01:36.181,915] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to 7d258a2e
[00:01:36.182,098] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to dcc34fb
[00:01:36.182,250] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 95cce048
[00:01:36.187,194] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827be
[00:01:36.187,408] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827bf
[00:01:36.187,591] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827c0
[00:01:36.187,774] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827c1
[00:01:36.187,927] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827c2
[00:01:36.188,110] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827c3
[00:01:36.188,293] <dbg> chip: [DMG]Endpoint 0, Cluster 0x0000_002F update version to ec6827c4
[00:01:38.360,198] <err> chip: [DL]OnSrpClientNotification: Operation refused for security reasons
[00:01:39.181,915] <dbg> chip: [DMG]Endpoint 1, Cluster 0x0000_0402 update version to 7d258a2f
[00:01:39.182,098] <dbg> chip: [DMG]Endpoint 3, Cluster 0x0000_0403 update version to dcc34fc
[00:01:39.182,250] <dbg> chip: [DMG]Endpoint 2, Cluster 0x0000_0405 update version to 95cce049

[Charlie]

Hi Michal,

I suggest you generate a new ticket for this new problem.

Remember also to provide the information about your testing environment(NCS version, Apple OTBR device, software version and so on).

Best regards,

Charlie