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.  

[Charlie]

Hi Michal,

Matter SDK 1.0 is integrated into NCS since v2.1.1 and its support for Matter over Thread is no longer experimental, so it is better to start your development with NCS above v2.1.1.

For Google Home, the developer preview update of Google Nest Hub 2nd which supports Mater 1.0 may still not reach your device. We have a customer who successfully tested NCSv2.1.0 with the alpha beta update channel, but it is not clear for NCS v2.1.1 or NCS v2.1.2, because even our device did not get updated yet. The out-of-data guidance using NCS1.7.1 should still work, we expect google will have an update for support on the Matter 1.0 device.

For  Apple HomePod mini/Samsung SmartThings hub v3, we have confirmed they work well with NCS v2.1.1, if you have any problem you can open a dedicated ticket to discuss.

You can refer to the comment here: https://devzone.nordicsemi.com/support-private/support/298036#permalink=805302

Bes regards,

Charlie

[Michal P]

Thank you Charlie for clarification. I was digging into this subject the whole night to find out why commissioning to Google fabric is not working. I already applied the google patch dedicated for NCS1.7.1  to  NCS2.1.1  (as it was not possible to find a newer one).  I was following https://developers.home.google.com/matter/vendors/nordic-semiconductor guidance once doing that. It goes halfway through  with commissioning (at the end  Google Home App  says that  BR is needed - all devices are in the same network with newer firmware and I can easily have ping between themselves and the internet)
Looks like I need to wait for Nordic or  Google official  SDK/Patch - but at least I know to not look for a reason why it's not working (it was not so obvious why it's not working when you take into consideration that NCS1.7.1 with patch has this possibility)

Thanks to your help we can switch to Apple and I hope in meantime we hope you will be able to provide a solution for Google:)  Do you think on November Nordic Webinar I can get more feedback about it?

[Elfving]

Hi!

Michal P said:

Do you think on November Nordic Webinar I can get more feedback about it?

Unfortunately you will have to wait and see about whether or not this will be mentioned. However, I believe there will be a Q&A part, so you could always ask yourself.

Regards,

Elfving

[Michal P]

Hi, since 21.11.2022 I'm able to perform full commisioning  light example based on nRF5340.

Unfortunatelly I cannot control device  after successful commisioning - it saying device is offline. What might be a problem? 

I'm using the same e-mail account for Nest Hub2 and  commisioning phone, the same wifi network,  and I'm followed https://developers.home.google.com/matter/project/create

to configugre project and add integration.  

I will be appriciated for any help with that.

<detail> [DL]    Device Role: CHILD
<detail> [DL]    Partition Id: 0x4C7E0B3D
<info  > [DL] _OnPlatformEvent default:  event->Type = 32777
<detail> [DL] Thread Attached updating Multicast address
<info  > [SVR] Joining Multicast groups
<detail> [DL] OpenThread State Changed (Flags: 0x00000001)
<detail> [DL]    Thread Unicast Addresses:
<detail> [DL]         fdb4:8034:2ab5:1:7045:14d8:9f75:5d00/64 valid preferred
<detail> [DL]         fd98:c16c:90c1:0:0:ff:fe00:d401/64 valid rloc
<detail> [DL]         fd98:c16c:90c1:0:662f:aa2e:ee23:29fc/64 valid
<detail> [DL]         fe80:0:0:0:5d:deaf:532c:6ea2/64 valid preferred
<info  > [DL] _OnPlatformEvent default:  event->Type = 32769
<efr32 > Scheduling OTA Requestor initialization
<detail> [DMG] Command handler moving to [ Preparing]
<detail> [DMG] Command handler moving to [AddingComm]
<detail> [DMG] Command handler moving to [Adde<detail> [DMG] Command handler moving to [CommandSen]
<detail> [DMG] Command handler moving to [AwaitingDe]
<info  > [DL] _OnPlatformEvent default:  event->Type = 32783
<detail> [DL] Using Thread extended MAC for hostname.
<info  > [DIS] Advertise operational node A5F1FAFCDB2C7C6F-000000007B3B173D
<info  > [SVR] Operational advertising enabled
<info  > [DL] Tx Confirmation received
<info  > [DL]  stop soft timer
<info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
<detail> [DL] SRP update succeeded
<info  > [DIS] Setting operational delegate post init
<info  > [DL] _OnPlatformEvent default:  event->Type = 32784
<info  > [DIS] Updating services using commissioning mode 0
<detail> [DL] Using Thread extended MAC for hostname.
<info  > [DIS] Advertise operational node A5F1FAFCDB2C7C6F-000000007B3B173D
<info  > [DL] advertising srp service: A5F1FAFCDB2C7C6F-000000007B3B173D._matter._tcp
<detail> [DL] Using Thread extended MAC for hostname.
<info  > [DIS] Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
<info  > [DL] advertising srp service: A1BE7CAB92985E8C._matterc._udp
<detail> [DL] SRP update succeeded
<info  > [DL] Char Write Req, char : 23
<detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
<info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
<info  > [SWU] Stopping the watchdog timer
<info  > [SWU] Starting the periodic query timer, timeout: 86400 seconds
<detail> [DMG] Endpoint 0, Cluster 0x0000_002A update version to 9a985ded
<info  > [ZCL] Cluster callback: 0x0000_002A
<detail> [DMG] Endpoint 0, Cluster 0x0000_002A update version to 9a985dee
<info  > [ZCL] Cluster callback: 0x0000_002A
<detail> [IN] UDP Message Received packet nb : 1 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 177
<info  > [EM] >>> [E:13472r M:236735631] (U) Msg RX from 0:B14C1DE83D33135C [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
<detail> [EM] Handling via exchange: 13472r, Delegate: 0x2001cf98
<info  > [IN] CASE Server received Sigma1 message. Starting handshake. EC 0x2001dcd8
<info  > [IN] CASE Server disabling CASE session setups
<info  > [EM] <<< [E:13472r M:31879843 (Ack:236735631)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<info  > [IN] (U) Sending msg 31879843 to IP address 'UDP:[fdde:ad11:11de:2222:f051:74c2:b0ab:9778%ot]:35189'
<detail> [EM] Flushed pending ack for MessageCounter:236735631 on exchange 13472r
<info  > [SC] Received Sigma1 msg
<detail> [SC] Found MRP parameters in the message
<detail> [SC] Peer assigned session key ID 10749
<info  > [SC] CASE matched destination ID: fabricIndex 1, NodeID 0x000000007B3B173D
<detail> [SC] Including MRP parameters
<info  > [EM] <<< [E:13472r M:31879844 (Ack:236735631)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
<info  > [IN] (U) Sending msg 31879844 to IP address 'UDP:[fdde:ad11:11de:2222:f051:74c2:b0ab:9778%ot]:35189'
<info  > [SC] Sent Sigma2 msg
<info  > [DL] Tx Confirmation received
<info  > [DL]  stop soft timer
<info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
<detail> [IN] UDP Message Received packet nb : 2 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 26
<info  > [EM] >>> [E:13472r M:236735632 (Ack:31879844)] (U) Msg RX from 0:B14C1DE83D33135C [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13472r, Delegate: 0x2001cfb4
<detail> [EM] Rxd Ack; Removing MessageCounter:31879844 from Retrans Table on exchange 13472r
<detail> [IN] UDP Message Received packet nb : 3 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 736
<info  > [EM] >>> [E:13472r M:236735633 (Ack:31879844)] (U) Msg RX from 0:B14C1DE83D33135C [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
<detail> [EM] Found matching exchange: 13472r, Delegate: 0x2001cfb4
<detail> [EM] CHIP MessageCounter:31879844 not in RetransTable on exchange 13472r
<info  > [EM] <<< [E:13472r M:31879845 (Ack:236735633)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<info  > [IN] (U) Sending msg 31879845 to IP address 'UDP:[fdde:ad11:11de:2222:f051:74c2:b0ab:9778%ot]:35189'
<detail> [EM] Flushed pending ack for MessageCounter:236735633 on exchange 13472r
<info  > [SC] Received Sigma3 msg
<detail> [SC] Certificate's mNotBeforeTime (721393986) is after current time (156)
<detail> [SC] Certificate's mNotBeforeTime (692310848) is after current time (156)
<detail> [SC] Certificate's mNotBeforeTime (692310655) is after current time (156)
<detail> [SC] Sending status report. Protocol code 0, exchange 13472
<info  > [EM] <<< [E:13472r M:31879846 (Ack:236735633)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
<info  > [IN] (U) Sending msg 31879846 to IP address 'UDP:[fdde:ad11:11de:2222:f051:74c2:b0ab:9778%ot]:35189'
<info  > [SC] SecureSession[0x2001c3e0]: Moving from state 'kEstablishing' --> 'kActive'
<detail> [IN] SecureSession[0x2001c3e0]: Activated - Type:2 LSID:1896
<detail> [IN] New secure session activated for device <00000000BDA70E10, 1>, LSID:1896 PSID:10749!
<info  > [IN] CASE Session established to peer: <00000000BDA70E10, 1>
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c498]: Allocated Type:2 LSID:1897
<detail> [SC] Allocated SecureSession (0x2001c498) - waiting for Sigma1 msg
<detail> [IN] UDP Message Received packet nb : 4 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 26
<detail> [IN] UDP Message Received packet nb : 5 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 51
<info  > [EM] >>> [E:13472r M:236735634 (Ack:31879846)] (U) Msg RX from 0:B14C1DE83D33135C [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13472r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:31879846 from Retrans Table on exchange 13472r
<info  > [EM] >>> [E:13473r M:213387818] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0001:02 (IM:ReadRequest)
<detail> [EM] Handling via exchange: 13473r, Delegate: 0x20009e34
<detail> [IM] Received Read request
<detail> [DMG] IM RH moving to [GeneratingReports]
<detail> [DMG] Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
<detail> [DMG] <RE:Run> Cluster 3c, Attribute 0 is dirty
<detail> [DMG] Reading attribute: Cluster=0x0000_003C Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
<detail> [DMG] <RE> Sending report (payload has 36 bytes)...
<info  > [EM] <<< [E:13473r M:71486223 (Ack:213387818)] (S) Msg TX to 1:00000000BDA70E10 [7C6F] --- Type 0001:05 (IM:ReportData)
<info  > [IN] (S) Sending msg 71486223 on secure session with LSID: 1896
<detail> [DMG] <RE> OnReportConfirm: NumReports = 0
<detail> [DMG] <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
<detail> [DMG] IM RH moving to [AwaitingDestruction]
<detail> [DMG] All ReadHandle<detail> [IN] UDP Message Received packet nb : 6 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 34
<info  > [EM] >>> [E:13473r M:213387819 (Ack:71486223)] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13473r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:71486223 from Retrans Table on exchange 13473r
<detail> [IN] UDP Message Received packet nb : 7 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 51
<info  > [EM] >>> [E:13474r M:213387820] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0001:02 (IM:ReadRequest)
<detail> [EM] Handling via exchange: 13474r, Delegate: 0x20009e34
<detail> [IM] Received Read request
<detail> [DMG] IM RH moving to [GeneratingReports]
<detail> [DMG] Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
<detail> [DMG] <RE:Run> Cluster 1d, Attribute 3 is dirty
<detail> [DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
<detail> [DMG] <RE> Sending report (payload has 64 bytes)...
<info  > [EM] <<< [E:13474r M:71486224 (Ack:213387820)] (S) Msg TX to 1:00000000BDA70E10 [7C6F] --- Type 0001:05 (IM:ReportData)
<info  > [IN] (S) Sending msg 71486224 on secure session with LSID: 1896
<detail> [DMG] <RE> OnReportConfirm: NumReports = 0
<detail> [DMG] <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
<detail> [DMG] IM RH moving to [AwaitingDestruction]
<detail> [DMG] All ReadHandle<detail> [IN] UDP Message Received packet nb : 8 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 34
<info  > [EM] >>> [E:13474r M:213387821 (Ack:71486224)] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13474r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:71486224 from Retrans Table on exchange 13474r
<detail> [IN] UDP Message Received packet nb : 9 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 51
<info  > [EM] >>> [E:13475r M:213387822] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0001:02 (IM:ReadRequest)
<detail> [EM] Handling via exchange: 13475r, Delegate: 0x20009e34
<detail> [IM] Received Read request
<detail> [DMG] IM RH moving to [GeneratingReports]
<detail> [DMG] Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
<detail> [DMG] <RE:Run> Cluster 1d, Attribute 0 is dirty
<detail> [DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
<detail> [DMG] <RE> Sending report (payload has 70 bytes)...
<info  > [EM] <<< [E:13475r M:71486225 (Ack:213387822)] (S) Msg TX to 1:00000000BDA70E10 [7C6F] --- Type 0001:05 (IM:ReportData)
<info  > [IN] (S) Sending msg 71486225 on secure session with LSID: 1896
<detail> [DMG] <RE> OnReportConfirm: NumReports = 0
<detail> [DMG] <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
<detail> [DMG] IM RH moving to [AwaitingDestruction]
<detail> [DMG] All ReadHandle<detail> [IN] UDP Message Received packet nb : 10 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 34
<info  > [EM] >>> [E:13475r M:213387823 (Ack:71486225)] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13475r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:71486225 from Retrans Table on exchange 13475r
<detail> [IN] UDP Message Received packet nb : 11 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 51
<info  > [EM] >>> [E:13476r M:213387824] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0001:02 (IM:ReadRequest)
<detail> [EM] Handling via exchange: 13476r, Delegate: 0x20009e34
<detail> [IM] Received Read request
<detail> [DMG] IM RH moving to [GeneratingReports]
<detail> [DMG] Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
<detail> [DMG] <RE:Run> Cluster 1d, Attribute 1 is dirty
<detail> [DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
<detail> [DMG] <RE> Sending report (payload has 624 bytes)...
<info  > [EM] <<< [E:13476r M:71486226 (Ack:213387824)] (S) Msg TX to 1:00000000BDA70E10 [7C6F] --- Type 0001:05 (IM:ReportData)
<info  > [IN] (S) Sending msg 71486226 on secure session with LSID: 1896
<detail> [DMG] <RE> OnReportConfirm: NumReports = 0
<detail> [DMG] <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
<detail> [DMG] IM RH moving to [AwaitingDestruction]
<detail> [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
<detail> [IN] UDP Message Received packet nb : 12 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 34
<info  > [EM] >>> [E:13476r M:213387825 (Ack:71486226)] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13476r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:71486226 from Retrans Table on exchange 13476r
<detail> [IN] UDP Message Received packet nb : 13 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 51
<info  > [EM] >>> [E:13477r M:213387826] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0001:02 (IM:ReadRequest)
<detail> [EM] Handling via exchange: 13477r, Delegate: 0x20009e34
<detail> [IM] Received Read request
<detail> [DMG] IM RH moving to [GeneratingReports]
<detail> [DMG] Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
<detail> [DMG] <RE:Run> Cluster 1d, Attribute 2 is dirty
<detail> [DMG] Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
<detail> [DMG] <RE> Sending report (payload has 64 bytes)...
<info  > [EM] <<< [E:13477r M:71486227 (Ack:213387826)] (S) Msg TX to 1:00000000BDA70E10 [7C6F] --- Type 0001:05 (IM:ReportData)
<info  > [IN] (S) Sending msg 71486227 on secure session with LSID: 1896
<detail> [DMG] <RE> OnReportConfirm: NumReports = 0
<detail> [DMG] <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
<detail> [DMG] IM RH moving to [AwaitingDestruction]
<detail> [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
<detail> [IN] UDP Message Received packet nb : 14 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 34
<detail> [IN] UDP Message Received packet nb : 15 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 51
<info  > [EM] >>> [E:13477r M:213387827 (Ack:71486227)] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13477r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:71486227 from Retrans Table on exchange 13477r
<info  > [EM] >>> [E:13478r M:213387828] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0001:02 (IM:ReadRequest)
<detail> [EM] Handling via exchange: 13478r, Delegate: 0x20009e34
<detail> [IM] Received Read request
<detail> [DMG] IM RH moving to [GeneratingReports]
<detail> [DMG] Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
<detail> [DMG] <RE:Run> Cluster 1d, Attribute 3 is dirty
<detail> [DMG] Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0003 (expanded=0)
<detail> [DMG] <RE> Sending report (payload has 36 bytes)...
<info  > [EM] <<< [E:13478r M:71486228 (Ack:213387828)] (S) Msg TX to 1:00000000BDA70E10 [7C6F] --- Type 0001:05 (IM:ReportD<detail> [DMG] <RE> OnReportConfirm: NumReports = 0
<detail> [DMG] <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
<detail> [DMG] IM RH moving to [AwaitingDestruction]
<detail> [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
<detail> [IN] UDP Message Received packet nb : 16 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 34
<detail> [IN] UDP Message Received packet nb : 17 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 51
<info  > [EM] >>> [E:13478r M:213387829 (Ack:71486228)] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13478r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:71486228 from Retrans Table on exchange 13478r
<info  > [EM] >>> [E:13479r M:213387830] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0001:02 (IM:ReadRequest)
<detail> [EM] Handling via exchange: 13479r, Delegate: 0x20009e34
<detail> [IM] Received Read request
<detail> [DMG] IM RH moving to [GeneratingReports]
<detail> [DMG] Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
<detail> [DMG] <RE:Run> Cluster 1d, Attribute 0 is dirty
<detail> [DMG] Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0000 (expanded=0)
<detai<info  > [EM] <<< [E:13479r M:71486229 (Ack:213387830)] (S) Msg TX to 1:00000000BDA70E10 [7C6F] --- Type 0001:05 (IM:ReportData)
<info  > [IN] (S) Sending msg 71486229 on secure session with LSID: 1896
<detail> [DMG] <RE> OnReportConfirm: NumReports = 0
<detail> [DMG] <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
<detail> [DMG] IM RH moving to [AwaitingDestruction]
<detail> [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
<detail> [IN] UDP Message Received packet nb : 18 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 34
<info  > [EM] >>> [E:13479r M:213387831 (Ack:71486229)] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13479r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:71486229 from Retrans Table on exchange 13479r
<detail> [IN] UDP Message Received packet nb : 19 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 51
<info  > [EM] >>> [E:13480r M:213387832] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0001:02 (IM:ReadRequest)
<detail> [EM] Handling via exchange: 13480r, Delegate: 0x20009e34
<detail> [IM] Received Read request
<detail> [DMG] IM RH moving to [GeneratingReports]
<detail> [DMG] Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
<detail> [DMG] <RE:Run> Cluster 1d, Attribute 1 is dirty
<detail> [DMG] Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0001 (expanded=0)
<detail> [DMG] <RE> Sending report (payload has 234 bytes)...
<info  > [EM] <<< [E:13480r M:71486230 (Ack:213387832)] (S) Msg TX to 1:00000000BDA70E10 [7C6F] --- Type 0001:05 (IM:ReportData)
<info  > [IN] (S) Sending msg 71486230 on secure session with LSID: 1896
<detail> [DMG] <RE> OnReportConfirm: NumReports = 0
<detail> [DMG] <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
<detail> [DMG] IM RH moving to [AwaitingDestruction]
<detail> [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
<detail> [IN] UDP Message Received packet nb : 20 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 34
<info  > [EM] >>> [E:13480r M:213387833 (Ack:71486230)] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13480r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:71486230 from Retrans Table on exchange 13480r
<detail> [IN] UDP Message Received packet nb : 21 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 51
<info  > [EM] >>> [E:13481r M:213387834] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0001:02 (IM:ReadRequest)
<detail> [EM] Handling via exchange: 13481r, Delegate: 0x20009e34
<detail> [IM] Received Read request
<detail> [DMG] IM RH moving to [GeneratingReports]
<detail> [DMG] Building Reports for ReadHandler with LastReportGeneration = lu DirtyGeneration = lu
<detail> [DMG] <RE:Run> Cluster 1d, Attribute 2 is dirty
<detail> [DMG] Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0002 (expanded=0)
<detail> [DMG] <RE> Sending report (payload has 36 bytes)...
<info  > [EM] <<< [E:13481r M:71486231 (Ack:213387834)] (S) Msg TX to 1:00000000BDA70E10 [7C6F] --- Type 0001:05 (IM:ReportData)
<info  > [IN] (S) Sending msg 71486231 on secure session with LSID: 1896
<detail> [DMG] <RE> OnReportConfirm: NumReports = 0
<detail> [DMG] <RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
<detail> [DMG] IM RH moving to [AwaitingDestruction]
<detail> [DMG] All ReadHandle<detail> [IN] UDP Message Received packet nb : 22 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 34
<info  > [EM] >>> [E:13481r M:213387835 (Ack:71486231)] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13481r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:71486231 from Retrans Table on exchange 13481r
<info  > [DL] Char Write Req, char : 23
<detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
<info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
<info  > [DL] Tx Confirmation received
<info  > [DL]  stop soft timer
<info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
<detail> [IN] UDP Message Received packet nb : 23 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 59
<info  > [EM] >>> [E:13482r M:213387836] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0001:08 (IM:InvokeCommandRequest)
<detail> [EM] Handling via exchange: 13482r, Delegate: 0x20009e34
<detail> [DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
<info  > [FS] GeneralCommissioning: Received CommissioningComplete
<info  > [FP] Metadata for Fabric 0x1 persisted to storage.
<info  > [TS] Committing Last Known Good Time to storage: 2022-11-23T18:54:54
<info  > [ZCL] OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0xA5F1FAFCDB2C7C6F, FabricId C6A40CF625A62E22, NodeId 000000007B3B173D, VendorId 0x6006
<info  > [FS] GeneralCommissioning: Successfully commited pending fabric data
<info  > [FS] Fail-safe cleanly disarmed
<detail> [DMG] Endpoint 0, Cluster 0x0000_0030 update version to f063387
<info  > [ZCL] Cluster callback: 0x0000_0030
<detail> [DMG] Command handler moving to [ Preparing]
<detail> [DMG] Command handler moving to [AddingComm]
<detail> [DMG] Command handler moving to [AddedComma]
<detail> [DMG] Decreasing reference count for CommandHandler, remaining 0
<info  > [EM] <<< [E:13482r M:71486232 (Ack:213387836)] (S) Msg TX to 1:00000000BDA70E10 [7C6F] --- Type 0001:09 (IM:InvokeCommandResponse)
<info  > [IN] (S) Sending msg 71486232 on secure session with LSID: 1896
<detail> [DMG] Command handler moving to [CommandSen]
<detail> [DMG] Command handler moving to [AwaitingDe]
<info  > [DL] _OnPlatformEvent default: <detail> [DL] Using Thread extended MAC for hostname.
<info  > [DIS] Advertise operational node A5F1FAFCDB2C7C6F-000000007B3B173D
<detail> [DL] Using Thread extended MAC for hostname.
<info  > [DIS] Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
<detail> [IN] Expiring all PASE sessions
<detail> [IN] SecureSession[0x2001c328]: MarkForEviction Type:1 LSID:1895
<info  > [SC] SecureSession[0x2001c328]: Moving from state 'kActive' --> 'kPendingEviction'
<detail> [IN] SecureSession[0x2001c328]: Released - Type:1 LSID:1895
<detail> [IN] Clearing BLE pending packets.
<info  > [BLE] Releasing end point's BLE connection back to application.
<detail> [ZCL] Commissioning complete, notify platform driver to persist network credentials.
<detail> [IN] UDP Message Received packet nb : 24 SrcAddr : fdde:ad11:11de:2222:f051:74c2:b0ab:9778[35189] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 34
<info  > [EM] >>> [E:13482r M:213387837 (Ack:71486232)] (S) Msg RX from 1:00000000BDA70E10 [7C6F] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 13482r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:71486232 from Retrans Table on exchange 13482r
<info  > [DL] Disconnect Event for handle : 1
<info  > [DL] BLE GATT connection closed (con 1, reason 4115)
<info  > [DL] _OnPlatformEvent kCHIPoBLEConnectionError
<info  > [DL] _OnPlatformEvent default:  event->Type = 32777
<detail> [DL] OpenThread State Changed (Flags: 0x00000064)
<detail> [DL]    Device Role: ROUTER
<detail> [IN] UDP Message Received packet nb : 25 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 177
<info  > [EM] >>> [E:40823r M:149760719] (U) Msg RX from 0:10F8C970751A06EA [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
<detail> [EM] Handling via exchange: 40823r, Delegate: 0x2001cf98
<info  > [IN] CASE Server received Sigma1 message. Starting handshake. EC 0x2001dcd8
<info  > [IN] CASE Server disabling CASE session setups
<info  > [EM] <<< [E:40823r M:31879847 (Ack:149760719)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<info  > [IN] (U) Sending msg 31879847 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<detail> [EM] Flushed pending ack for MessageCounter:149760719 on exchange 40823r
<info  > [SC] Received Sigma1 msg
<detail> [SC] Found MRP parameters in the message
<detail> [SC] Peer assigned session key ID 55857
<error > [SC] CASE failed to match destination ID with local fabrics
<detail> [SC] 0xa1, 0xf3, 0x38, 0x7d, 0x24, 0xa0, 0x14, 0x95, 
<detail> [SC] 0x84, 0x4d, 0x7d, 0x06, 0x91, 0x0d, 0xa7, 0x43, 
<detail> [SC] 0x43, 0x21, 0xc6, 0x7e, 0x04, 0x14, 0x1b, 0x37, 
<detail> [SC] 0x21, 0xc0, 0x29, 0x2d, 0xd5, 0xb4, 0x20, 0x10, 
<detail> [SC] Sending status report. Protocol code 2, exchange 40823
<info  > [EM] <<< [E:40823r M:31879848 (Ack:149760719)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
<info  > [IN] (U) Sending msg 31879848 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<error > [IN] CASE Session establishment failed: 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c498]: Released - Type:2 LSID:1897
<detail> [IN] SecureSession[0x2001c328]: Allocated Type:2 LSID:1898
<detail> [SC] Allocated SecureSession (0x2001c328) - waiting for Sigma1 msg
<error > [EM] OnMessageReceived failed, err = 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c328]: Released - Type:2 LSID:1898
<detail> [IN] SecureSession[0x2001c328]: Allocated Type:2 LSID:1899
<detail> [SC] Allocated SecureSession (0x2001c328) - waiting for Sigma1 msg
<detail> [IN] UDP Message Received packet nb : 26 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 26
<info  > [EM] >>> [E:40823r M:149760720 (Ack:31879848)] (U) Msg RX from 0:10F8C970751A06EA [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 40823r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:31879848 from Retrans Table on exchange 40823r
<detail> [IN] UDP Message Received packet nb : 27 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 177
<info  > [EM] >>> [E:40824r M:149760721] (U) Msg RX from 0:8B6DA3ABAF9C82E2 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
<detail> [EM] Handling via exchange: 40824r, Delegate: 0x2001cf98
<info  > [IN] CASE Server received Sigma1 message. Starting handshake. EC 0x2001dcd8
<info  > [IN] CASE Server disabling CASE session setups
<info  > [EM] <<< [E:40824r M:31879849 (Ack:149760721)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<info  > [IN] (U) Sending msg 31879849 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<detail> [EM] Flushed pending ack for MessageCounter:149760721 on exchange 40824r
<info  > [SC] Received Sigma1 msg
<detail> [SC] Found MRP parameters in the message
<detail> [SC] Peer assigned session key ID 55858
<error > [SC] CASE failed to match destination ID with local fabrics
<detail> [SC] 0xd9, 0x75, 0xa6, 0x37, 0xa4, 0x4f, 0x79, 0x99, 
<detail> [SC] 0x05, 0x40, 0x60, 0x13, 0x06, 0x37, 0x97, 0xf3, 
<detail> [SC] 0x2e, 0x7a, 0x25, 0xf2, 0x42, 0x7e, 0x75, 0x69, 
<detail> [SC] 0x37, 0x0d, 0x41, 0xee, 0x5d, 0xe9, 0x46, 0x62, 
<detail> [SC] Sending status report. Protocol code 2, exchange 40824
<info  > [EM] <<< [E:40824r M:31879850 (Ack:149760721)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
<info  > [IN] (U) Sending msg 31879850 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<error > [IN] CASE Session establishment failed: 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c328]: Released - Type:2 LSID:1899
<detail> [IN] SecureSession[0x2001c328]: Allocated Type:2 LSID:1900
<detail> [SC] Allocated SecureSession (0x2001c328) - waiting for Sigma1 msg
<error > [EM] OnMessageReceived failed, err = 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c328]: Released - Type:2 LSID:1900
<detail> [IN] SecureSession[0x2001c328]: Allocated Type:2 LSID:1901
<detail> [SC] Allocated SecureSession (0x2001c328) - waiting for Sigma1 msg
<detail> [IN] UDP Message Received packet nb : 28 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 26
<info  > [EM] >>> [E:40824r M:149760722 (Ack:31879850)] (U) Msg RX from 0:8B6DA3ABAF9C82E2 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 40824r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:31879850 from Retrans Table on exchange 40824r
<detail> [IN] UDP Message Received packet nb : 29 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 177
<info  > [EM] >>> [E:40825r M:149760723] (U) Msg RX from 0:FE2EF228C6183D0F [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
<detail> [EM] Handling via exchange: 40825r, Delegate: 0x2001cf98
<info  > [IN] CASE Server received Sigma1 message. Starting handshake. EC 0x2001dcd8
<info  > [IN] CASE Server disabling CASE session setups
<info  > [EM] <<< [E:40825r M:31879851 (Ack:149760723)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<info  > [IN] (U) Sending msg 31879851 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<detail> [EM] Flushed pending ack for MessageCounter:149760723 on exchange 40825r
<info  > [SC] Received Sigma1 msg
<detail> [SC] Found MRP parameters in the message
<detail> [SC] Peer assigned session key ID 55859
<error > [SC] CASE failed to match destination ID with local fabrics
<detail> [SC] 0xd5, 0xeb, 0x01, 0x44, 0xa0, 0xa8, 0x56, 0xc3, 
<detail> [SC] 0x00, 0xfe, 0xfd, 0x04, 0x71, 0x2c, 0xfd, 0x03, 
<detail> [SC] 0x59, 0xac, 0xf8, 0x28, 0xc1, 0x24, 0x6b, 0x7a, 
<detail> [SC] 0x4e, 0x5a, 0xd7, 0x92, 0x2c, 0x1c, 0xb9, 0x71, 
<detail> [SC] Sending status report. Protocol code 2, exchange 40825
<info  > [EM] <<< [E:40825r M:31879852 (Ack:149760723)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
<info  > [IN] (U) Sending msg 31879852 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<error > [IN] CASE Session establishment failed: 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c328]: Released - Type:2 LSID:1901
<detail> [IN] SecureSession[0x2001c328]: Allocated Type:2 LSID:1902
<detail> [SC] Allocated SecureSession (0x2001c328) - waiting for Sigma1 msg
<error > [EM] OnMessageReceived failed, err = 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c328]: Released - Type:2 LSID:1902
<detail> [IN] SecureSession[0x2001c328]: Allocated Type:2 LSID:1903
<detail> [SC] Allocated SecureSession (0x2001c328) - waiting for Sigma1 msg
<detail> [IN] UDP Message Received packet nb : 30 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 26
<info  > [EM] >>> [E:40825r M:149760724 (Ack:31879852)] (U) Msg RX from 0:FE2EF228C6183D0F [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 40825r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:31879852 from Retrans Table on exchange 40825r
<detail> [IN] UDP Message Received packet nb : 31 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 177
<info  > [EM] >>> [E:40826r M:149760725] (U) Msg RX from 0:CF394470A3108FBE [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
<detail> [EM] Handling via exchange: 40826r, Delegate: 0x2001cf98
<info  > [IN] CASE Server received Sigma1 message. Starting handshake. EC 0x2001dcd8
<info  > [IN] CASE Server disabling CASE session setups
<info  > [EM] <<< [E:40826r M:31879853 (Ack:149760725)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<info  > [IN] (U) Sending msg 31879853 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<detail> [EM] Flushed pending ack for MessageCounter:149760725 on exchange 40826r
<info  > [SC] Received Sigma1 msg
<detail> [SC] Found MRP parameters in the message
<detail> [SC] Peer assigned session key ID 55860
<error > [SC] CASE failed to match destination ID with local fabrics
<detail> [SC] 0xd9, 0xe5, 0xcd, 0x38, 0x32, 0x7c, 0xb7, 0x6e, 
<detail> [SC] 0x57, 0xc4, 0xdb, 0x78, 0x4d, 0x81, 0x78, 0x04, 
<detail> [SC] 0xec, 0xb5, 0x3c, 0x7c, 0xd4, 0xf2, 0x6d, 0xe8, 
<detail> [SC] 0x95, 0x28, 0x0b, 0xca, 0x73, 0x7b, 0xce, 0x7e, 
<detail> [SC] Sending status report. Protocol code 2, exchange 40826
<info  > [EM] <<< [E:40826r M:31879854 (Ack:149760725)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
<info  > [IN] (U) Sending msg 31879854 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<error > [IN] CASE Session establishment failed: 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c328]: Released - Type:2 LSID:1903
<detail> [IN] SecureSession[0x2001c328]: Allocated Type:2 LSID:1904
<detail> [SC] Allocated SecureSession (0x2001c328) - waiting for Sigma1 msg
<error > [EM] OnMessageReceived failed, err = 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c328]: Released - Type:2 LSID:1904
<detail> [IN] SecureSession[0x2001c328]: Allocated Type:2 LSID:1905
<detail> [SC] Allocated SecureSession (0x2001c328) - waiting for Sigma1 msg
<detail> [IN] UDP Message Received packet nb : 32 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 26
<info  > [EM] >>> [E:40826r M:149760726 (Ack:31879854)] (U) Msg RX from 0:CF394470A3108FBE [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 40826r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:31879854 from Retrans Table on exchange 40826r
<error > [SWU] No suitable OTA Provider candidate found
<info  > [SWU] No provider available
<detail> [IN] UDP Message Received packet nb : 33 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 177
<info  > [EM] >>> [E:40827r M:149760727] (U) Msg RX from 0:BBB31CD41D083B03 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
<detail> [EM] Handling via exchange: 40827r, Delegate: 0x2001cf98
<info  > [IN] CASE Server received Sigma1 message. Starting handshake. EC 0x2001dcd8
<info  > [IN] CASE Server disabling CASE session setups
<info  > [EM] <<< [E:40827r M:31879855 (Ack:149760727)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<info  > [IN] (U) Sending msg 31879855 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<detail> [EM] Flushed pending ack for MessageCounter:149760727 on exchange 40827r
<info  > [SC] Received Sigma1 msg
<detail> [SC] Found MRP parameters in the message
<detail> [SC] Peer assigned session key ID 55861
<error > [SC] CASE failed to match destination ID with local fabrics
<detail> [SC] 0x9e, 0xd3, 0x56, 0x18, 0x42, 0x70, 0xf8, 0x69, 
<detail> [SC] 0xd1, 0xd6, 0xa1, 0x81, 0x46, 0x5c, 0xc4, 0xdb, 
<detail> [SC] 0x46, 0x8b, 0x49, 0x3a, 0x4e, 0x38, 0x0d, 0x99, 
<detail> [SC] 0x98, 0x17, 0xf2, 0x56, 0x9a, 0x7a, 0xed, 0x4b, 
<detail> [SC] Sending status report. Protocol code 2, exchange 40827
<info  > [EM] <<< [E:40827r M:31879856 (Ack:149760727)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
<info  > [IN] (U) Sending msg 31879856 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<error > [IN] CASE Session establishment failed: 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c328]: Released - Type:2 LSID:1905
<detail> [IN] SecureSession[0x2001c328]: Allocated Type:2 LSID:1906
<detail> [SC] Allocated SecureSession (0x2001c328) - waiting for Sigma1 msg
<error > [EM] OnMessageReceived failed, err = 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c328]: Released - Type:2 LSID:1906
<detail><detail> [IN] UDP Message Received packet nb : 34 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 26
<info  > [EM] >>> [E:40827r M:149760728 (Ack:31879856)] (U) Msg RX from 0:BBB31CD41D083B03 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 40827r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:31879856 from Retrans Table on exchange 40827r
<detail> [IN] UDP Message Received packet nb : 35 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 177
<info  > [EM] >>> [E:40828r M:149760729] (U) Msg RX from 0:D59B77B992288F12 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
<detail> [EM] Handling via exchange: 40828r, Delegate: 0x2001cf98
<info  > [IN] CASE Server received Sigma1 message. Starting handshake. EC 0x2001dcd8
<info  > [IN] CASE Server disabling CASE session setups
<info  > [EM] <<< [E:40828r M:31879857 (Ack:149760729)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<info  > [IN] (U) Sending msg 31879857 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<detail> [EM] Flushed pending ack for MessageCounter:149760729 on exchange 40828r
<info  > [SC] Received Sigma1 msg
<detail> [SC] Found MRP parameters in the message
<detail> [SC] Peer assigned session key ID 55862
<error > [SC] CASE failed to match destination ID with local fabrics
<detail> [SC] 0x32, 0xd6, 0xdb, 0x2f, 0x82, 0x9c, 0x5f, 0x3e, 
<detail> [SC] 0xb1, 0x43, 0xc4, 0x68, 0x5c, 0x23, 0xaa, 0x28, 
<detail> [SC] 0x92, 0xfb, 0x0e, 0x08, 0xae, 0x99, 0xba, 0x8c, 
<detail> [SC] 0xec, 0xb1, 0xae, 0x6b, 0x71, 0x20, 0xc3, 0xcb, 
<detail> [SC] Sending status report. Protocol code 2, exchange 40828
<info  > [EM] <<< [E:40828r M:31879858 (Ack:149760729)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
<info  > [IN] (U) Sending msg 31879858 to IP address 'UDP:[fdde:ad11:11de:2222:45d9:19a4:a0d:c61b%ot]:5540'
<error > [IN] CASE Session establishment failed: 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c328]: Released - Type:2 LSID:1907
<detail> [IN] SecureSession[0x2001c328]: Allocated Type:2 LSID:1908
<detail> [SC] Allocated SecureSession (0x2001c328) - waiting for Sigma1 msg
<error > [EM] OnMessageReceived failed, err = 71
<info  > [IN] CASE Server enabling CASE session setups
<detail> [IN] SecureSession[0x2001c328]: Released - Type:2 LSID:1908
<detail><detail> [IN] UDP Message Received packet nb : 36 SrcAddr : fdde:ad11:11de:2222:45d9:19a4:a0d:c61b[5540] DestAddr : fdb4:8034:2ab5:1:7045:14d8:9f75:5d00[5540] Payload Length 26
<info  > [EM] >>> [E:40828r M:149760730 (Ack:31879858)] (U) Msg RX from 0:D59B77B992288F12 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
<detail> [EM] Found matching exchange: 40828r, Delegate: 0
<detail> [EM] Rxd Ack; Removing MessageCounter:31879858 from Retrans Table on exchange 40828r

[Michal P]

I got exactly the same problem with Silicon Labs dev board :(

[Charlie]

Hi Michal,

Did you test with the latest NCS v2.1.2 or still NCS v1.7.1 in Nordic Semiconductor  |  Matter  |  Google Home step 7?

NCS started to support Matter v1.0 from v2.1.1, see nRF Connect SDK v2.1.1 Release Notes — nRF Connect SDK 2.1.2 documentation (nordicsemi.com)

Best regards,

Charlie

[Michal P]

Hi Charlie, thank you for answer.  I was testing with NCS v. 2.1.2     Patch mentioned in step 7  is no compatible anymore with 2.1.2.
I guess since 2.1.1 patch is not necessary?     Have you or anybody in the Nordic community been able to perform commissioning and control the Nordic Matter Light example or any other Matter example? 

[Charlie]

Hi Michal,

1) The latest google document step 7 does not mention any patch, you only need to change the  v1.7.1 to v2.1.2 should be OK.

2) I do not have Nest Hub 2 on hand, so need to wait for our development team to confirm if they have done the tests on NCS v2.1.2.

3) Regarding the logs, it shows that the device was commissioned to the Matter successfully, but then It couldn't establish a secure session with Nest Hub. It looks like the Nest Hub is trying to establish a secure session with the device, but the device isn't allowing do that because it doesn't know Nest Hub's fabric ID and/or Node ID. It also shows that after commissioning Nest Hub has a different IPv6 address and it changed also its NodeId from 00000000BDA70E10 to 0000000000000000 (line 400 vs 408)and it indicates an issue with the Nest Hub.

Best regards,

Charlie