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.  

[Michal P]

Nest Hub 2 software version is: 47.9.4.447810048

Chromecast firmware version: 1.56.324896 

Google Home App Versoin: 2.60.1.22

Based on information from Nest website it looks like it has the newest firmware installed. 
I checked as well on Goolge Play and Google Home is the newest possible version. 

How I can proceed with development?  For me, it's important to confirm that the hardware and software provided by  Nordic will allow us to complete the design phase. We plan to have a trial with a large number of devices in 2Q2023 (about 10 000)  so getting a fast and accurate response will help us to make correct decisions. 

Are you able to perform your internal tests which confirm integration with Google? Can you support us by getting support from Google to solve the issue which we have? If there is anything I can prepare to tack this issue and solve it please let me know. 

[Michal Szablowski]

Hello,

I've just checked on Nest Hub 2nd Gen:

Software Version: 47.9.4.447810048

Chromecast fw version: 1.56.324896.

The commissioning and led control of nrf5340 light bulb (NCS 2.1.2) works correctly.

If you've already created the device in developer console (Matter integrations), then the issue could be with new update of Nest Hub. After that update, you need to factory reset the device (hold 2 buttons for 10 seconds) and link to the account (with Google Home App) once again. After that, the commissioning should go smooth. The device will be fully operational after couple seconds after finished commissioning.

Best regards,
Michał

[Michal P]

Hi,  it looks like some flags sent to the cloud are not set all properly in Matter SDK  github.com/.../23761

[Michal P]

 Charlie 

Just now installed fresh Nordic SDK v2.2.0-rc1. Still, the device is offline after successful commissioning.
Does anybody know where I can find information on how I can fix the device's offline problem?

• Nest Hub 2 software version is: 47.9.4.447810048

• Chromecast firmware version: 1.56.324896

• Google Home App Versoin: 2.60.1.22

• Nordic Light Example from SDK v2.2.0-rc1

• nRF5340  with Matter 1.0 Light_Bulb example.

[mI: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 0, fe8
I: data wra: 0, 0
*** Booting Zephyr OS build v3.2.99-ncs1-rc1 ***
I: Init CHIP stack
I: 493 [DL]BLE address: DB:98:BC:80:56:3E
I: 515 [DL]OpenThread started: OK
I: 518 [DL]Setting OpenThread device type to ROUTER
I: 523 [SVR]Server initializing...
D: 526 [FP]Initializing FabricTable from persistent storage
I: 532 [TS]Last Known Good Time: [unknown]
I: 536 [TS]Setting Last Known Good Time to firmware build time 2022-11-28T22:24:32
I: 544 [DMG]AccessControl: initializing
I: 547 [DMG]Examples::AccessControlDelegate::Init
I: 552 [DMG]AccessControl: setting
I: 555 [DMG]DefaultAclStorage: initializing
I: 559 [DMG]DefaultAclStorage: 0 entries loaded
D: 563 [IN]UDP::Init bind&listen port=5540
E: 567 [IN]SO_REUSEPORT failed: 109
D: 571 [IN]UDP::Init bound to port=5540
D: 574 [IN]BLEBase::Init - setting/overriding transport
D: 579 [IN]TransportMgr initialized
D: 585 [DL]Using Thread extended MAC for hostname.
I: 591 [ZCL]Using ZAP configuration...
D: 595 [DMG]Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: a0
D: 603 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_0000: a0
D: 610 [DMG]Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: a0
D: 617 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_0000: a0
D: 624 [DMG]Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: a0
I: 631 [DMG]AccessControlCluster: initializing
D: 635 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685672
D: 641 [DL]Boot reason: 1
D: 644 [ZCL]GeneralDiagnostics: OnDeviceReboot
D: 648 [DMG]Endpoint 0, Cluster 0x0000_0033 update version to 268fd0e8
D: 655 [EVL]LogEvent event number: 0x0000000000000000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x000000000000028E
I: 668 [ZCL]Initiating Admin Commissioning cluster.
D: 673 [DMG]Endpoint 1, Cluster 0x0000_0003 update version to 626c8919
D: 680 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 1f51a49
D: 686 [DMG]Endpoint 1, Cluster 0x0000_0004 update version to 1f51a4a
I: 692 [ZCL]On/Off set value: 1 0
I: 695 [ZCL]On/off already set to new value
D: 700 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to fd42720
I: 706 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 1
D: 712 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
D: 721 [IN]SecureSession[0x20004430]: Allocated Type:1 LSID:23688
D: 727 [SC]Assigned local session key ID 23688
D: 731 [SC]Waiting for PBKDF param request
D: 735 [DL]CHIPoBLE advertising set to on
I: 739 [DIS]Updating services using commissioning mode 1
D: 744 [DL]Using Thread extended MAC for hostname.
D: 749 [DL]Using Thread extended MAC for hostname.
I: 754 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 763 [DIS]Failed to advertise commissionable node: 3
E: 768 [DIS]Failed to finalize service update: 1c
I: 772 [DIS]Updating services using commissioning mode 1
D: 777 [DL]Using Thread extended MAC for hostname.
D: 782 [DL]Using Thread extended MAC for hostname.
I: 787 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 796 [DIS]Failed to advertise commissionable node: 3
E: 801 [DIS]Failed to finalize service update: 1c
I: 806 [DIS]Delaying proxy of operational discovery: missing delegate
I: 812 [IN]CASE Server enabling CASE session setups
D: 817 [IN]SecureSession[0x200044e8]: Allocated Type:2 LSID:23689
D: 823 [SC]Allocated SecureSession (0x200044e8) - waiting for Sigma1 msg
I: 829 [SVR]Joining Multicast groups
D: 833 [ZCL]Emitting StartUp event
D: 836 [EVL]LogEvent event number: 0x0000000000000001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x0000000000000344
I: 850 [SVR]Server Listening...
I: 853 [DL]Device Configuration:
I: 856 [DL] Serial Number: 11223344556677889900
I: 860 [DL] Vendor Id: 65521 (0xFFF1)
I: 864 [DL] Product Id: 32773 (0x8005)
I: 868 [DL] Hardware Version: 0
I: 871 [DL] Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 876 [DL] Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 883 [DL] Manufacturing Date: (not set)
I: 887 [DL] Device Type: 65535 (0xFFFF)
I: 891 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 895 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 901 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 910 [SVR]Manual pairing code: [34970112332]
I: 915 [DL]CHIP task running
I: 922 [DL]CHIPoBLE advertising started
D: 926 [DMG]Endpoint 1, Cluster 0x0000_0006 update version to a3dbcb10
I: 933 [ZCL]Cluster OnOff: attribute OnOff set to 0
D: 938 [DMG]Endpoint 1, Cluster 0x0000_0008 update version to fd42721
I: 944 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 950 [ZCL]LED is off. Try to use move-to-level-with-on-off instead of move-to-level
I: 958 [DL]NFC Tag emulation started
I: 30925 [DL]CHIPoBLE advertising mode changed to slow
I: 100168 [DL]BLE connection established (ConnId: 0x00)
I: 100174 [DL]Current number of connections: 1/2
I: 100178 [DL]CHIPoBLE advertising stopped
I: 100182 [DL]NFC Tag emulation stopped
I: 100624 [DL]BLE GAP connection terminated (reason 0x2a)
I: 100630 [DL]Current number of connections: 0/2
I: 100637 [DL]CHIPoBLE advertising started
I: 100641 [DL]NFC Tag emulation started
I: 130641 [DL]CHIPoBLE advertising mode changed to slow
I: 178981 [DL]BLE connection established (ConnId: 0x00)
I: 178986 [DL]Current number of connections: 1/2
I: 178991 [DL]CHIPoBLE advertising stopped
I: 178995 [DL]NFC Tag emulation stopped
I: 179428 [DL]BLE GAP connection terminated (reason 0x2a)
I: 179433 [DL]Current number of connections: 0/2
I: 179441 [DL]CHIPoBLE advertising started
I: 179445 [DL]NFC Tag emulation started
I: 209444 [DL]CHIPoBLE advertising mode changed to slow
I: 390034 [DL]BLE connection established (ConnId: 0x00)
I: 390039 [DL]Current number of connections: 1/2
I: 390044 [DL]CHIPoBLE advertising stopped
I: 390048 [DL]NFC Tag emulation stopped
I: 390499 [DL]BLE GAP connection terminated (reason 0x2a)
I: 390504 [DL]Current number of connections: 0/2
I: 390512 [DL]CHIPoBLE advertising started
I: 390516 [DL]NFC Tag emulation started
I: 420516 [DL]CHIPoBLE advertising mode changed to slow
I: 537740 [DL]BLE connection established (ConnId: 0x00)
I: 537746 [DL]Current number of connections: 1/2
I: 537750 [DL]CHIPoBLE advertising stopped
I: 537754 [DL]NFC Tag emulation stopped
I: 541107 [DL]BLE GAP connection terminated (reason 0x13)
I: 541112 [DL]Current number of connections: 0/2
I: 541119 [DL]CHIPoBLE advertising started
I: 541124 [DL]NFC Tag emulation started
I: 541577 [DL]BLE connection established (ConnId: 0x00)
I: 541583 [DL]Current number of connections: 1/2
I: 541587 [DL]CHIPoBLE advertising stopped
I: 541591 [DL]NFC Tag emulation stopped
I: 544957 [DL]BLE GAP connection terminated (reason 0x13)
I: 544962 [DL]Current number of connections: 0/2
I: 544969 [DL]CHIPoBLE advertising started
I: 544974 [DL]NFC Tag emulation started
I: 557881 [DL]BLE connection established (ConnId: 0x00)
I: 557886 [DL]Current number of connections: 1/2
I: 557891 [DL]CHIPoBLE advertising stopped
I: 557895 [DL]NFC Tag emulation stopped
I: 561215 [DL]BLE GAP connection terminated (reason 0x13)
I: 561220 [DL]Current number of connections: 0/2
I: 561227 [DL]CHIPoBLE advertising started
I: 561231 [DL]NFC Tag emulation started
I: 561517 [DL]BLE connection established (ConnId: 0x00)
I: 561523 [DL]Current number of connections: 1/2
I: 561527 [DL]CHIPoBLE advertising stopped
I: 561531 [DL]NFC Tag emulation stopped
I: 564872 [DL]BLE GAP connection terminated (reason 0x13)
I: 564877 [DL]Current number of connections: 0/2
I: 564885 [DL]CHIPoBLE advertising started
I: 564889 [DL]NFC Tag emulation started
I: 565912 [DL]BLE connection established (ConnId: 0x00)
I: 565918 [DL]Current number of connections: 1/2
I: 565922 [DL]CHIPoBLE advertising stopped
I: 565926 [DL]NFC Tag emulation stopped
I: 569247 [DL]BLE GAP connection terminated (reason 0x13)
I: 569252 [DL]Current number of connections: 0/2
I: 569260 [DL]CHIPoBLE advertising started
I: 569264 [DL]NFC Tag emulation started
I: 599264 [DL]CHIPoBLE advertising mode changed to slow
I: 601294 [DL]BLE connection established (ConnId: 0x00)
I: 601299 [DL]Current number of connections: 1/2
I: 601303 [DL]CHIPoBLE advertising stopped
I: 601307 [DL]NFC Tag emulation stopped
I: 601728 [DL]BLE GAP connection terminated (reason 0x2a)
I: 601733 [DL]Current number of connections: 0/2
I: 601741 [DL]CHIPoBLE advertising started
I: 601745 [DL]NFC Tag emulation started
I: 631744 [DL]CHIPoBLE advertising mode changed to slow
I: 900720 [SVR]Closing pairing window
D: 900724 [IN]SecureSession[0x20004430]: Released - Type:1 LSID:23688
I: 900730 [DIS]Updating services using commissioning mode 0
D: 900735 [DL]Using Thread extended MAC for hostname.
D: 900740 [DL]Using Thread extended MAC for hostname.
I: 900746 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
E: 900755 [DIS]Failed to advertise extended commissionable node: 3
D: 900761 [DIS]Scheduling extended discovery timeout in 900s
E: 900766 [DIS]Failed to finalize service update: 1c
D: 900771 [DL]CHIPoBLE advertising set to off
I: 900776 [DL]CHIPoBLE advertising stopped
I: 900780 [DL]NFC Tag emulation stopped
I: Software update is disabled
D: 948716 [IN]SecureSession[0x20004430]: Allocated Type:1 LSID:23690
D: 948722 [SC]Assigned local session key ID 23690
D: 948727 [SC]Waiting for PBKDF param request
D: 948731 [DL]CHIPoBLE advertising set to on
I: 948735 [DIS]Updating services using commissioning mode 1
D: 948740 [DL]Using Thread extended MAC for hostname.
D: 948746 [DL]Using Thread extended MAC for hostname.
I: 948751 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 948760 [DIS]Failed to advertise commissionable node: 3
E: 948765 [DIS]Failed to finalize service update: 1c
I: 948773 [DL]CHIPoBLE advertising started
I: 948778 [DL]NFC Tag emulation started
I: 949216 [DL]BLE connection established (ConnId: 0x00)
I: 949221 [DL]Current number of connections: 1/2
I: 949226 [DL]CHIPoBLE advertising stopped
I: 949230 [DL]NFC Tag emulation stopped
I: 949669 [DL]BLE GAP connection terminated (reason 0x2a)
I: 949674 [DL]Current number of connections: 0/2
I: 949682 [DL]CHIPoBLE advertising started
I: 949686 [DL]NFC Tag emulation started
I: 979685 [DL]CHIPoBLE advertising mode changed to slow
I: 994467 [DL]BLE connection established (ConnId: 0x00)
I: 994473 [DL]Current number of connections: 1/2
I: 994477 [DL]CHIPoBLE advertising stopped
I: 994481 [DL]NFC Tag emulation stopped
D: 995537 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 995545 [BLE]local and remote recv window sizes = 5
I: 995550 [BLE]selected BTP version 4
I: 995553 [BLE]using BTP fragment sizes rx 128 / tx 128.
D: 995572 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 995577 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 995585 [IN]BLE EndPoint 0x2000b0e8 Connection Complete
I: 995590 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 131)
D: 995677 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 995748 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 995755 [EM]>>> [E:14522r M:132793805] (U) Msg RX from 0:8C1C731D09AF00B0 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D: 995767 [EM]Handling via exchange: 14522r, Delegate: 0x20006614
D: 995773 [SC]Received PBKDF param request
D: 995777 [SC]Peer assigned session ID 49619
D: 995781 [SC]Found MRP parameters in the message
D: 995786 [SC]Including MRP parameters in PBKDF param response
I: 995792 [EM]<<< [E:14522r M:260362351] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 995804 IN Sending msg 260362351 to IP address 'BLE'
D: 995809 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 995817 [SC]Sent PBKDF param response
D: 995887 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 995895 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 14)
D: 995957 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 995966 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 995973 [EM]>>> [E:14522r M:132793806] (U) Msg RX from 0:8C1C731D09AF00B0 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D: 995984 [EM]Found matching exchange: 14522r, Delegate: 0x20006614
D: 995990 [SC]Received spake2p msg1
I: 997547 [EM]<<< [E:14522r M:260362352] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 997558 IN Sending msg 260362352 to IP address 'BLE'
D: 997564 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 997572 [SC]Sent spake2p msg2
E: 997574 [DL]Long dispatch time: 1609 ms, for event type 16388
D: 997637 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 997645 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 997707 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 997716 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 997723 [EM]>>> [E:14522r M:132793807] (U) Msg RX from 0:8C1C731D09AF00B0 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D: 997734 [EM]Found matching exchange: 14522r, Delegate: 0x20006614
D: 997740 [SC]Received spake2p msg3
D: 997744 [SC]Sending status report. Protocol code 0, exchange 14522
I: 997750 [EM]<<< [E:14522r M:260362353] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 997762 IN Sending msg 260362353 to IP address 'BLE'
D: 997767 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 997775 [SC]SecureSession[0x20004430]: Moving from state 'kEstablishing' --> 'kActive'
D: 997784 [IN]SecureSession[0x20004430]: Activated - Type:1 LSID:23690
D: 997790 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:23690 PSID:49619!
I: 997799 [SVR]Commissioning completed session establishment step
I: 997805 [DIS]Updating services using commissioning mode 0
D: 997810 [DL]Using Thread extended MAC for hostname.
D: 997816 [DL]Using Thread extended MAC for hostname.
I: 997822 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
E: 997831 [DIS]Failed to advertise extended commissionable node: 3
D: 997837 [DIS]Scheduling extended discovery timeout in 900s
E: 997842 [DIS]Failed to finalize service update: 1c
D: 997847 [DL]CHIPoBLE advertising set to off
I: 997851 [SVR]Device completed Rendezvous process
E: 997856 [DL]Long dispatch time: 141 ms, for event type 16388
D: 997861 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 997869 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 997877 [EM]>>> [E:14523r M:90317629] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 997888 [EM]Handling via exchange: 14523r, Delegate: 0x20008ab4
D: 997893 [IM]Received Read request
D: 997897 [DMG]IM RH moving to [GeneratingReports]
D: 997902 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 997911 [DMG]RE:Run Cluster 28, Attribute 2 is dirty
D: 997916 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 997925 [DMG] Sending report (payload has 37 bytes)...
I: 997931 [EM]<<< [E:14523r M:133783967] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 997941 IN Sending msg 133783967 on secure session with LSID: 23690
D: 997948 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 997956 [DMG] OnReportConfirm: NumReports = 0
D: 997960 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 997968 [DMG]IM RH moving to [AwaitingDestruction]
D: 997972 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 998022 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 998031 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 998039 [EM]>>> [E:14524r M:90317630] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 998049 [EM]Handling via exchange: 14524r, Delegate: 0x20008ab4
D: 998055 [IM]Received Read request
D: 998059 [DMG]IM RH moving to [GeneratingReports]
D: 998063 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 998072 [DMG]RE:Run Cluster 28, Attribute 4 is dirty
D: 998077 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 998086 [DMG] Sending report (payload has 37 bytes)...
I: 998093 [EM]<<< [E:14524r M:133783968] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 998103 IN Sending msg 133783968 on secure session with LSID: 23690
D: 998109 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 998117 [DMG] OnReportConfirm: NumReports = 0
D: 998122 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 998129 [DMG]IM RH moving to [AwaitingDestruction]
D: 998134 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 998162 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 998171 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 998179 [EM]>>> [E:14525r M:90317631] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 998189 [EM]Handling via exchange: 14525r, Delegate: 0x20008ab4
D: 998195 [IM]Received Read request
D: 998199 [DMG]IM RH moving to [GeneratingReports]
D: 998203 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 998212 [DMG]RE:Run Cluster 3e, Attribute 2 is dirty
D: 998217 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 998226 [DMG] Sending report (payload has 36 bytes)...
I: 998233 [EM]<<< [E:14525r M:133783969] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 998243 IN Sending msg 133783969 on secure session with LSID: 23690
D: 998249 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 998257 [DMG] OnReportConfirm: NumReports = 0
D: 998262 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 998269 [DMG]IM RH moving to [AwaitingDestruction]
D: 998274 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 998302 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 998311 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 998319 [EM]>>> [E:14526r M:90317632] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 998329 [EM]Handling via exchange: 14526r, Delegate: 0x20008ab4
D: 998335 [IM]Received Read request
D: 998339 [DMG]IM RH moving to [GeneratingReports]
D: 998343 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 998352 [DMG]RE:Run Cluster 3e, Attribute 3 is dirty
D: 998357 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 998366 [DMG] Sending report (payload has 36 bytes)...
I: 998373 [EM]<<< [E:14526r M:133783970] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 998383 IN Sending msg 133783970 on secure session with LSID: 23690
D: 998389 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 998397 [DMG] OnReportConfirm: NumReports = 0
D: 998402 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 998409 [DMG]IM RH moving to [AwaitingDestruction]
D: 998414 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 998442 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 998451 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 998459 [EM]>>> [E:14527r M:90317633] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 998469 [EM]Handling via exchange: 14527r, Delegate: 0x20008ab4
D: 998475 [IM]Received Read request
D: 998479 [DMG]IM RH moving to [GeneratingReports]
D: 998483 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 998492 [DMG]RE:Run Cluster 3e, Attribute 1 is dirty
D: 998497 [DMG]Reading attribute: Cluster=0x0000_003E Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 998506 [DMG] Sending report (payload has 36 bytes)...
I: 998513 [EM]<<< [E:14527r M:133783971] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 998523 IN Sending msg 133783971 on secure session with LSID: 23690
D: 998529 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 998537 [DMG] OnReportConfirm: NumReports = 0
D: 998542 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 998549 [DMG]IM RH moving to [AwaitingDestruction]
D: 998554 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 998582 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 998591 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 998599 [EM]>>> [E:14528r M:90317634] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 998609 [EM]Handling via exchange: 14528r, Delegate: 0x20008ab4
D: 998615 [IM]Received Read request
D: 998619 [DMG]IM RH moving to [GeneratingReports]
D: 998623 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 998632 [DMG]RE:Run Cluster 1d, Attribute 1 is dirty
D: 998637 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 998647 [DMG] Sending report (payload has 400 bytes)...
I: 998655 [EM]<<< [E:14528r M:133783972] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 998665 IN Sending msg 133783972 on secure session with LSID: 23690
D: 998672 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 998679 [DMG] OnReportConfirm: NumReports = 0
D: 998684 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 998692 [DMG]IM RH moving to [AwaitingDestruction]
D: 998696 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 998722 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 998730 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 998792 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 998800 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 998862 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 998870 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57)
D: 998933 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 998941 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 999003 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 999011 [EM]>>> [E:14529r M:90317635] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 999021 [EM]Handling via exchange: 14529r, Delegate: 0x20008ab4
D: 999027 [IM]Received Read request
D: 999031 [DMG]IM RH moving to [GeneratingReports]
D: 999036 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 999045 [DMG]RE:Run Cluster 31, Attribute fffc is dirty
D: 999050 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=0)
D: 999059 [DMG] Sending report (payload has 37 bytes)...
I: 999065 [EM]<<< [E:14529r M:133783973] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 999075 IN Sending msg 133783973 on secure session with LSID: 23690
D: 999082 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 72)
D: 999090 [DMG] OnReportConfirm: NumReports = 0
D: 999095 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 999102 [DMG]IM RH moving to [AwaitingDestruction]
D: 999107 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 999142 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1000870 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1000878 [EM]>>> [E:14530r M:90317636] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D: 1000889 [EM]Handling via exchange: 14530r, Delegate: 0x20008ab4
D: 1000895 [DMG]Got Timed Request with timeout 10000: handler 0x20008eb0 exchange 14530r
I: 1000903 [EM]<<< [E:14530r M:133783974] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 1000914 IN Sending msg 133783974 on secure session with LSID: 23690
D: 1000921 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 1000928 [DMG]Timed Request time limit 0x00000000000F6CF0: handler 0x20008eb0 exchange 14530r
D: 1001005 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1001013 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1001021 [EM]>>> [E:14530r M:90317637] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 1001032 [EM]Found matching exchange: 14530r, Delegate: 0x20008eb0
D: 1001039 [DMG]Timed following action arrived at 0x00000000000F464F: handler 0x20008eb0 exchange 14530r
D: 1001048 [DMG]Handing timed invoke to IM engine: handler 0x20008eb0 exchange 14530r
D: 1001056 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 1001064 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
D: 1001070 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685673
D: 1001077 [DMG]Command handler moving to [ Preparing]
D: 1001081 [DMG]Command handler moving to [AddingComm]
D: 1001086 [DMG]Command handler moving to [AddedComma]
D: 1001091 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 1001099 [EM]<<< [E:14530r M:133783975] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1001110 IN Sending msg 133783975 on secure session with LSID: 23690
D: 1001117 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 1001125 [DMG]Command handler moving to [CommandSen]
D: 1001130 [DMG]Command handler moving to [AwaitingDe]
E: 1001135 [DL]Long dispatch time: 121 ms, for event type 16388
D: 1001185 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1001193 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1001201 [EM]>>> [E:14531r M:90317638] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 1001212 [EM]Handling via exchange: 14531r, Delegate: 0x20008ab4
D: 1001218 [IM]Received Read request
D: 1001222 [DMG]IM RH moving to [GeneratingReports]
D: 1001226 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 1001235 [DMG]RE:Run Cluster 30, Attribute 3 is dirty
D: 1001240 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 1001250 [DMG] Sending report (payload has 36 bytes)...
I: 1001256 [EM]<<< [E:14531r M:133783976] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 1001266 IN Sending msg 133783976 on secure session with LSID: 23690
D: 1001273 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 1001281 [DMG] OnReportConfirm: NumReports = 0
D: 1001286 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 1001293 [DMG]IM RH moving to [AwaitingDestruction]
D: 1001298 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 1001365 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1001373 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1001381 [EM]>>> [E:14532r M:90317639] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:0a (IM:TimedRequest)
D: 1001392 [EM]Handling via exchange: 14532r, Delegate: 0x20008ab4
D: 1001398 [DMG]Got Timed Request with timeout 10000: handler 0x20008eb0 exchange 14532r
I: 1001406 [EM]<<< [E:14532r M:133783977] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:01 (IM:StatusResponse)
I: 1001417 IN Sending msg 133783977 on secure session with LSID: 23690
D: 1001424 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 43)
D: 1001431 [DMG]Timed Request time limit 0x00000000000F6EE7: handler 0x20008eb0 exchange 14532r
D: 1001500 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1001508 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1001516 [EM]>>> [E:14532r M:90317640] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 1001528 [EM]Found matching exchange: 14532r, Delegate: 0x20008eb0
D: 1001534 [DMG]Timed following action arrived at 0x00000000000F483E: handler 0x20008eb0 exchange 14532r
D: 1001543 [DMG]Handing timed invoke to IM engine: handler 0x20008eb0 exchange 14532r
D: 1001551 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 1001561 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685674
D: 1001568 [DMG]Command handler moving to [ Preparing]
D: 1001573 [DMG]Command handler moving to [AddingComm]
D: 1001578 [DMG]Command handler moving to [AddedComma]
D: 1001583 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 1001590 [EM]<<< [E:14532r M:133783978] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1001602 IN Sending msg 133783978 on secure session with LSID: 23690
D: 1001608 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 1001616 [DMG]Command handler moving to [CommandSen]
D: 1001621 [DMG]Command handler moving to [AwaitingDe]
E: 1001626 [DL]Long dispatch time: 118 ms, for event type 16388
D: 1001680 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1001688 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1001696 [EM]>>> [E:14533r M:90317641] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 1001708 [EM]Handling via exchange: 14533r, Delegate: 0x20008ab4
D: 1001714 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 1001722 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 1001728 [DMG]Command handler moving to [ Preparing]
D: 1001733 [DMG]Command handler moving to [AddingComm]
D: 1001738 [DMG]Command handler moving to [AddedComma]
D: 1001743 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 1001753 [EM]<<< [E:14533r M:133783979] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1001764 IN Sending msg 133783979 on secure session with LSID: 23690
D: 1001771 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1001779 [DMG]Command handler moving to [CommandSen]
D: 1001783 [DMG]Command handler moving to [AwaitingDe]
D: 1001860 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1001868 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1001950 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1001958 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1002040 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1002048 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1002130 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1002138 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1002146 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 57)
D: 1002220 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1002228 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1002236 [EM]>>> [E:14534r M:90317642] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 1002248 [EM]Handling via exchange: 14534r, Delegate: 0x20008ab4
D: 1002254 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 1002262 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 1002268 [DMG]Command handler moving to [ Preparing]
D: 1002273 [DMG]Command handler moving to [AddingComm]
D: 1002278 [DMG]Command handler moving to [AddedComma]
D: 1002283 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 1002292 [EM]<<< [E:14534r M:133783980] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1002304 IN Sending msg 133783980 on secure session with LSID: 23690
D: 1002311 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1002318 [DMG]Command handler moving to [CommandSen]
D: 1002323 [DMG]Command handler moving to [AwaitingDe]
D: 1002400 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1002408 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1002490 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1002498 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1002580 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1002588 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1002670 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1002678 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1002686 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 28)
D: 1002760 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1002768 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1002777 [EM]>>> [E:14535r M:90317643] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 1002788 [EM]Handling via exchange: 14535r, Delegate: 0x20008ab4
D: 1002794 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 1002802 [ZCL]OpCreds: Received an AttestationRequest command
I: 1002837 [ZCL]OpCreds: AttestationRequest successful.
D: 1002842 [DMG]Command handler moving to [ Preparing]
D: 1002847 [DMG]Command handler moving to [AddingComm]
D: 1002852 [DMG]Command handler moving to [AddedComma]
D: 1002857 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 1002868 [EM]<<< [E:14535r M:133783981] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1002879 IN Sending msg 133783981 on secure session with LSID: 23690
D: 1002886 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1002894 [DMG]Command handler moving to [CommandSen]
D: 1002899 [DMG]Command handler moving to [AwaitingDe]
E: 1002904 [DL]Long dispatch time: 136 ms, for event type 16388
D: 1002985 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1002993 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1003075 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1003083 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1003165 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1003173 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1003255 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1003263 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1003271 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1003345 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1003353 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 90)
D: 1003435 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1003443 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1003452 [EM]>>> [E:14536r M:90317644] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 1003463 [EM]Handling via exchange: 14536r, Delegate: 0x20008ab4
D: 1003469 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 1003477 [ZCL]OpCreds: Received a CSRRequest command
D: 1003482 [ZCL]OpCreds: Finding fabric with fabricIndex 0x0
I: 1003646 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 1003681 [ZCL]OpCreds: CSRRequest successful.
D: 1003685 [DMG]Command handler moving to [ Preparing]
D: 1003690 [DMG]Command handler moving to [AddingComm]
D: 1003695 [DMG]Command handler moving to [AddedComma]
D: 1003700 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 1003709 [EM]<<< [E:14536r M:133783982] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1003720 IN Sending msg 133783982 on secure session with LSID: 23690
D: 1003727 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1003735 [DMG]Command handler moving to [CommandSen]
D: 1003739 [DMG]Command handler moving to [AwaitingDe]
E: 1003744 [DL]Long dispatch time: 301 ms, for event type 16388
D: 1003840 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1003848 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1003930 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1003938 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 128)
D: 1004020 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1005281 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1005371 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1005461 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1005471 [EM]>>> [E:14537r M:90317645] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 1005482 [EM]Handling via exchange: 14537r, Delegate: 0x20008ab4
D: 1005488 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
I: 1005496 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 1005558 [ZCL]OpCreds: AddTrustedRootCertificate successful.
D: 1005563 [DMG]Command handler moving to [ Preparing]
D: 1005568 [DMG]Command handler moving to [AddingComm]
D: 1005573 [DMG]Command handler moving to [AddedComma]
D: 1005578 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 1005586 [EM]<<< [E:14537r M:133783983] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1005597 IN Sending msg 133783983 on secure session with LSID: 23690
D: 1005604 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68)
D: 1005612 [DMG]Command handler moving to [CommandSen]
D: 1005616 [DMG]Command handler moving to [AwaitingDe]
E: 1005621 [DL]Long dispatch time: 160 ms, for event type 16388
D: 1005685 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1005693 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1005776 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1005866 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1005956 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1005964 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 1006090 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1006098 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1006181 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1006192 [EM]>>> [E:14538r M:90317646] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 1006203 [EM]Handling via exchange: 14538r, Delegate: 0x20008ab4
D: 1006210 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
I: 1006218 [ZCL]OpCreds: Received an AddNOC command
I: 1006224 [FP]Validating NOC chain
I: 1006339 [FP]NOC chain validation successful
I: 1006343 [FP]Added new fabric at index: 0x1
I: 1006347 [FP]Assigned compressed fabric ID: 0xB693EC17E2AE5718, node ID: 0x00000000089EC2FD
I: 1006356 [TS]Last Known Good Time: 2022-11-28T22:24:32
I: 1006361 [TS]New proposed Last Known Good Time: 2022-11-28T23:51:29
I: 1006367 [TS]Updating pending Last Known Good Time to 2022-11-28T23:51:29
D: 1006374 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0517076
D: 1006381 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0517077
D: 1006396 [EVL]LogEvent event number: 0x0000000000000002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Sys timestamp: 0x00000000000F5B3C
I: 1006411 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0xFFFFFFFD00010001
D: 1006420 [DL]Using Thread extended MAC for hostname.
I: 1006424 [DIS]Advertise operational node B693EC17E2AE5718-00000000089EC2FD
D: 1006431 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0517078
D: 1006438 [DMG]Endpoint 0, Cluster 0x0000_003E update version to c0517079
D: 1006445 [DMG]Command handler moving to [ Preparing]
D: 1006450 [DMG]Command handler moving to [AddingComm]
D: 1006455 [DMG]Command handler moving to [AddedComma]
I: 1006459 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
D: 1006466 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 1006474 [EM]<<< [E:14538r M:133783984] (S) Msg TX to 1:FFFFFFFB00000000 [5718] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1006485 IN Sending msg 133783984 on secure session with LSID: 23690
D: 1006492 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 1006499 [DMG]Command handler moving to [CommandSen]
D: 1006504 [DMG]Command handler moving to [AwaitingDe]
E: 1006509 [DL]Long dispatch time: 328 ms, for event type 16388
D: 1006585 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1006593 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1006676 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1006684 [EM]>>> [E:14539r M:90317647] (S) Msg RX from 1:FFFFFFFB00000000 [5718] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 1006695 [EM]Handling via exchange: 14539r, Delegate: 0x20008ab4
D: 1006702 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
D: 1006711 [DMG]Command handler moving to [ Preparing]
D: 1006716 [DMG]Command handler moving to [AddingComm]
D: 1006721 [DMG]Command handler moving to [AddedComma]
D: 1006726 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685675
D: 1006733 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 1006740 [EM]<<< [E:14539r M:133783985] (S) Msg TX to 1:FFFFFFFB00000000 [5718] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1006752 IN Sending msg 133783985 on secure session with LSID: 23690
D: 1006758 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 1006766 [DMG]Command handler moving to [CommandSen]
D: 1006771 [DMG]Command handler moving to [AwaitingDe]
E: 1006776 [DL]Long dispatch time: 101 ms, for event type 16388
D: 1006855 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1006863 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1006872 [EM]>>> [E:14540r M:90317648] (S) Msg RX from 1:FFFFFFFB00000000 [5718] --- Type 0001:02 (IM:ReadRequest)
D: 1006882 [EM]Handling via exchange: 14540r, Delegate: 0x20008ab4
D: 1006888 [IM]Received Read request
D: 1006892 [DMG]IM RH moving to [GeneratingReports]
D: 1006897 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 1006905 [DMG]RE:Run Cluster 31, Attribute 3 is dirty
D: 1006911 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 1006920 [DMG] Sending report (payload has 36 bytes)...
I: 1006926 [EM]<<< [E:14540r M:133783986] (S) Msg TX to 1:FFFFFFFB00000000 [5718] --- Type 0001:05 (IM:ReportData)
I: 1006936 IN Sending msg 133783986 on secure session with LSID: 23690
D: 1006943 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 1006951 [DMG] OnReportConfirm: NumReports = 0
D: 1006956 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 1006963 [DMG]IM RH moving to [AwaitingDestruction]
D: 1006968 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 1007035 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1007043 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1007052 [EM]>>> [E:14541r M:90317649] (S) Msg RX from 1:FFFFFFFB00000000 [5718] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 1007063 [EM]Handling via exchange: 14541r, Delegate: 0x20008ab4
D: 1007069 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
D: 1007088 [DMG]Decreasing reference count for CommandHandler, remaining 1
D: 1007094 [DL]OpenThread State Changed (Flags: 0x101fc100)
D: 1007100 [DL] Network Name: NEST-PAN-ACED
D: 1007104 [DL] PAN Id: 0xACED
D: 1007107 [DL] Extended PAN Id: 0x2F258DB1196F8B1D
D: 1007112 [DL] Channel: 14
D: 1007114 [DL] Mesh Prefix: fd98:c16c:90c1::/64
D: 1007120 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 1007125 [DL] Device Role: DETACHED
D: 1007129 [DL] Thread Unicast Addresses:
D: 1007133 [DL] fd98:c16c:90c1:0:f87f:557f:8d2d:2755/64 valid
D: 1007139 [DL] fe80::606f:a9c5:f78c:497e/64 valid preferred
I: 1008295 [DL]SRP Client was started, detected server: fd98:c16c:90c1:0000:5038:2f60:4549:4783
D: 1008304 [DL]OpenThread State Changed (Flags: 0x200012a4)
D: 1008309 [DL] Device Role: CHILD
D: 1008312 [DL] Partition Id: 0x146288D6
D: 1008317 [DL]OpenThread State Changed (Flags: 0x00000001)
D: 1008322 [DL] Thread Unicast Addresses:
D: 1008326 [DL] fd86:7e7b:14e4:1:6535:eb66:a91:8bda/64 valid preferred
D: 1008333 [DL] fd98:c16c:90c1::ff:fe00:3802/64 valid rloc
D: 1008339 [DL] fd98:c16c:90c1:0:f87f:557f:8d2d:2755/64 valid
D: 1008345 [DL] fe80::606f:a9c5:f78c:497e/64 valid preferred
D: 1008352 [DMG]Command handler moving to [ Preparing]
D: 1008357 [DMG]Command handler moving to [AddingComm]
D: 1008362 [DMG]Command handler moving to [AddedComma]
D: 1008367 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685676
D: 1008374 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 1008381 [EM]<<< [E:14541r M:133783987] (S) Msg TX to 1:FFFFFFFB00000000 [5718] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1008392 IN Sending msg 133783987 on secure session with LSID: 23690
D: 1008399 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 70)
D: 1008407 [DMG]Command handler moving to [CommandSen]
D: 1008412 [DMG]Command handler moving to [AwaitingDe]
D: 1008417 [DL]Using Thread extended MAC for hostname.
I: 1008422 [DIS]Advertise operational node B693EC17E2AE5718-00000000089EC2FD
I: 1008428 [SVR]Operational advertising enabled
D: 1008475 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 1008718 [DL]SRP update succeeded
I: 1008721 [DIS]Setting operational delegate post init
I: 1008729 [SWU]Stopping the watchdog timer
I: 1008733 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 1008740 [DIS]Updating services using commissioning mode 0
D: 1008745 [DL]Using Thread extended MAC for hostname.
I: 1008750 [DIS]Advertise operational node B693EC17E2AE5718-00000000089EC2FD
I: 1008757 [DL]advertising srp service: B693EC17E2AE5718-00000000089EC2FD._matter._tcp
D: 1008765 [DL]Using Thread extended MAC for hostname.
I: 1008771 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 1008780 [DL]advertising srp service: A4CA2DC385042010._matterc._udp
D: 1008787 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 2d731668
D: 1008794 [DMG]Endpoint 0, Cluster 0x0000_002A update version to 2d731669
D: 1009461 [DL]SRP update succeeded
D: 1010995 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 1012514 [EM]>>> [E:14542r M:132793808] (U) Msg RX from 0:8939B353A3D2CA2A [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D: 1012525 [EM]Handling via exchange: 14542r, Delegate: 0x200050a0
I: 1012533 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0
I: 1012541 [IN]CASE Server disabling CASE session setups
I: 1012546 [EM]<<< [E:14542r M:260362354 (Ack:132793808)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1012559 IN Sending msg 260362354 to IP address 'UDP:[fdde:ad11:11de:2222:75f4:d723:62ea:f86a]:50909'
D: 1012570 [EM]Flushed pending ack for MessageCounter:132793808 on exchange 14542r
I: 1012577 [SC]Received Sigma1 msg
D: 1012581 [SC]Found MRP parameters in the message
D: 1012586 [SC]Peer assigned session key ID 49620
I: 1012594 [SC]CASE matched destination ID: fabricIndex 1, NodeID 0x00000000089EC2FD
D: 1012789 [SC]Including MRP parameters
I: 1012793 [EM]<<< [E:14542r M:260362355 (Ack:132793808)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
I: 1012806 IN Sending msg 260362355 to IP address 'UDP:[fdde:ad11:11de:2222:75f4:d723:62ea:f86a]:50909'
I: 1012818 [SC]Sent Sigma2 msg
I: 1012948 [EM]>>> [E:14542r M:132793809 (Ack:260362355)] (U) Msg RX from 0:8939B353A3D2CA2A [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1012961 [EM]Found matching exchange: 14542r, Delegate: 0x200050bc
D: 1012968 [EM]Rxd Ack; Removing MessageCounter:260362355 from Retrans Table on exchange 14542r
I: 1013048 [EM]>>> [E:14542r M:132793810 (Ack:260362355)] (U) Msg RX from 0:8939B353A3D2CA2A [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
D: 1013061 [EM]Found matching exchange: 14542r, Delegate: 0x200050bc
D: 1013067 [EM]CHIP MessageCounter:260362355 not in RetransTable on exchange 14542r
I: 1013074 [EM]<<< [E:14542r M:260362356 (Ack:132793810)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1013087 IN Sending msg 260362356 to IP address 'UDP:[fdde:ad11:11de:2222:75f4:d723:62ea:f86a]:50909'
D: 1013098 [EM]Flushed pending ack for MessageCounter:132793810 on exchange 14542r
I: 1013106 [SC]Received Sigma3 msg
E: 1013114 [SC]The device does not support GetClock_RealTimeMS() API: 3. Falling back to Last Known Good UTC Time
D: 1013298 [SC]Sending status report. Protocol code 0, exchange 14542
I: 1013304 [EM]<<< [E:14542r M:260362357 (Ack:132793810)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 1013317 IN Sending msg 260362357 to IP address 'UDP:[fdde:ad11:11de:2222:75f4:d723:62ea:f86a]:50909'
I: 1013329 [SC]SecureSession[0x200044e8]: Moving from state 'kEstablishing' --> 'kActive'
D: 1013337 [IN]SecureSession[0x200044e8]: Activated - Type:2 LSID:23689
D: 1013344 [IN]New secure session activated for device <000000009D6A13AE, 1>, LSID:23689 PSID:49620!
I: 1013354 [IN]CASE Session established to peer: <000000009D6A13AE, 1>
I: 1013360 [IN]CASE Server enabling CASE session setups
D: 1013368 [IN]SecureSession[0x200045a0]: Allocated Type:2 LSID:23691
D: 1013377 [SC]Allocated SecureSession (0x200045a0) - waiting for Sigma1 msg
I: 1013384 [EM]>>> [E:14542r M:132793811 (Ack:260362357)] (U) Msg RX from 0:8939B353A3D2CA2A [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1013397 [EM]Found matching exchange: 14542r, Delegate: (nil)
D: 1013403 [EM]Rxd Ack; Removing MessageCounter:260362357 from Retrans Table on exchange 14542r
I: 1013412 [EM]>>> [E:14543r M:138164629] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest)
D: 1013423 [EM]Handling via exchange: 14543r, Delegate: 0x20008ab4
D: 1013429 [IM]Received Read request
D: 1013433 [DMG]IM RH moving to [GeneratingReports]
D: 1013438 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 1013446 [DMG]RE:Run Cluster 3c, Attribute 0 is dirty
D: 1013451 [DMG]Reading attribute: Cluster=0x0000_003C Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
D: 1013461 [DMG] Sending report (payload has 36 bytes)...
I: 1013467 [EM]<<< [E:14543r M:5901398 (Ack:138164629)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData)
I: 1013479 IN Sending msg 5901398 on secure session with LSID: 23689
D: 1013487 [DMG] OnReportConfirm: NumReports = 0
D: 1013492 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 1013500 [DMG]IM RH moving to [AwaitingDestruction]
D: 1013505 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 1013511 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
I: 1013526 [EM]>>> [E:14543r M:138164630 (Ack:5901398)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1013539 [EM]Found matching exchange: 14543r, Delegate: (nil)
D: 1013544 [EM]Rxd Ack; Removing MessageCounter:5901398 from Retrans Table on exchange 14543r
D: 1013605 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 1013818 [EM]>>> [E:14544r M:138164631] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest)
D: 1013829 [EM]Handling via exchange: 14544r, Delegate: 0x20008ab4
D: 1013834 [IM]Received Read request
D: 1013838 [DMG]IM RH moving to [GeneratingReports]
D: 1013843 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 1013852 [DMG]RE:Run Cluster 1d, Attribute 3 is dirty
D: 1013857 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 1013866 [DMG] Sending report (payload has 64 bytes)...
I: 1013873 [EM]<<< [E:14544r M:5901399 (Ack:138164631)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData)
I: 1013884 IN Sending msg 5901399 on secure session with LSID: 23689
D: 1013893 [DMG] OnReportConfirm: NumReports = 0
D: 1013897 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 1013905 [DMG]IM RH moving to [AwaitingDestruction]
D: 1013911 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 1013944 [EM]>>> [E:14544r M:138164632 (Ack:5901399)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1013959 [EM]Found matching exchange: 14544r, Delegate: (nil)
D: 1013965 [EM]Rxd Ack; Removing MessageCounter:5901399 from Retrans Table on exchange 14544r
I: 1013975 [EM]>>> [E:14545r M:138164633] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest)
D: 1013985 [EM]Handling via exchange: 14545r, Delegate: 0x20008ab4
D: 1013991 [IM]Received Read request
D: 1013995 [DMG]IM RH moving to [GeneratingReports]
D: 1014000 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 1014008 [DMG]RE:Run Cluster 1d, Attribute 0 is dirty
D: 1014014 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
D: 1014023 [DMG] Sending report (payload has 70 bytes)...
I: 1014029 [EM]<<< [E:14545r M:5901400 (Ack:138164633)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData)
I: 1014041 IN Sending msg 5901400 on secure session with LSID: 23689
D: 1014049 [DMG] OnReportConfirm: NumReports = 0
D: 1014054 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 1014061 [DMG]IM RH moving to [AwaitingDestruction]
D: 1014067 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 1014102 [EM]>>> [E:14545r M:138164634 (Ack:5901400)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1014117 [EM]Found matching exchange: 14545r, Delegate: (nil)
D: 1014123 [EM]Rxd Ack; Removing MessageCounter:5901400 from Retrans Table on exchange 14545r
I: 1014132 [EM]>>> [E:14546r M:138164635] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest)
D: 1014142 [EM]Handling via exchange: 14546r, Delegate: 0x20008ab4
D: 1014148 [IM]Received Read request
D: 1014152 [DMG]IM RH moving to [GeneratingReports]
D: 1014157 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 1014166 [DMG]RE:Run Cluster 1d, Attribute 1 is dirty
D: 1014171 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 1014181 [DMG] Sending report (payload has 400 bytes)...
I: 1014189 [EM]<<< [E:14546r M:5901401 (Ack:138164635)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData)
I: 1014200 IN Sending msg 5901401 on secure session with LSID: 23689
D: 1014209 [DMG] OnReportConfirm: NumReports = 0
D: 1014213 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 1014221 [DMG]IM RH moving to [AwaitingDestruction]
D: 1014226 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 1014288 [EM]>>> [E:14546r M:138164636 (Ack:5901401)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1014304 [EM]Found matching exchange: 14546r, Delegate: (nil)
D: 1014310 [EM]Rxd Ack; Removing MessageCounter:5901401 from Retrans Table on exchange 14546r
I: 1014319 [EM]>>> [E:14547r M:138164637] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest)
D: 1014329 [EM]Handling via exchange: 14547r, Delegate: 0x20008ab4
D: 1014335 [IM]Received Read request
D: 1014339 [DMG]IM RH moving to [GeneratingReports]
D: 1014344 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 1014353 [DMG]RE:Run Cluster 1d, Attribute 2 is dirty
D: 1014358 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 1014367 [DMG] Sending report (payload has 64 bytes)...
I: 1014374 [EM]<<< [E:14547r M:5901402 (Ack:138164637)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData)
I: 1014385 IN Sending msg 5901402 on secure session with LSID: 23689
D: 1014393 [DMG] OnReportConfirm: NumReports = 0
D: 1014398 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 1014406 [DMG]IM RH moving to [AwaitingDestruction]
D: 1014411 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 1014449 [EM]>>> [E:14547r M:138164638 (Ack:5901402)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1014465 [EM]Found matching exchange: 14547r, Delegate: (nil)
D: 1014471 [EM]Rxd Ack; Removing MessageCounter:5901402 from Retrans Table on exchange 14547r
I: 1014480 [EM]>>> [E:14548r M:138164639] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest)
D: 1014490 [EM]Handling via exchange: 14548r, Delegate: 0x20008ab4
D: 1014496 [IM]Received Read request
D: 1014500 [DMG]IM RH moving to [GeneratingReports]
D: 1014505 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 1014514 [DMG]RE:Run Cluster 1d, Attribute 3 is dirty
D: 1014519 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0003 (expanded=0)
D: 1014528 [DMG] Sending report (payload has 36 bytes)...
I: 1014534 [EM]<<< [E:14548r M:5901403 (Ack:138164639)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData)
I: 1014546 IN Sending msg 5901403 on secure session with LSID: 23689
D: 1014554 [DMG] OnReportConfirm: NumReports = 0
D: 1014559 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 1014567 [DMG]IM RH moving to [AwaitingDestruction]
D: 1014572 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 1014582 [EM]>>> [E:14548r M:138164640 (Ack:5901403)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1014598 [EM]Found matching exchange: 14548r, Delegate: (nil)
D: 1014604 [EM]Rxd Ack; Removing MessageCounter:5901403 from Retrans Table on exchange 14548r
I: 1014613 [EM]>>> [E:14549r M:138164641] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest)
D: 1014623 [EM]Handling via exchange: 14549r, Delegate: 0x20008ab4
D: 1014629 [IM]Received Read request
D: 1014633 [DMG]IM RH moving to [GeneratingReports]
D: 1014638 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 1014647 [DMG]RE:Run Cluster 1d, Attribute 0 is dirty
D: 1014652 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0000 (expanded=0)
D: 1014661 [DMG] Sending report (payload has 71 bytes)...
I: 1014668 [EM]<<< [E:14549r M:5901404 (Ack:138164641)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData)
I: 1014679 IN Sending msg 5901404 on secure session with LSID: 23689
D: 1014687 [DMG] OnReportConfirm: NumReports = 0
D: 1014692 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 1014700 [DMG]IM RH moving to [AwaitingDestruction]
D: 1014705 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 1014740 [EM]>>> [E:14549r M:138164642 (Ack:5901404)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1014755 [EM]Found matching exchange: 14549r, Delegate: (nil)
D: 1014761 [EM]Rxd Ack; Removing MessageCounter:5901404 from Retrans Table on exchange 14549r
I: 1014770 [EM]>>> [E:14550r M:138164643] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest)
D: 1014781 [EM]Handling via exchange: 14550r, Delegate: 0x20008ab4
D: 1014787 [IM]Received Read request
D: 1014791 [DMG]IM RH moving to [GeneratingReports]
D: 1014796 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 1014804 [DMG]RE:Run Cluster 1d, Attribute 1 is dirty
D: 1014810 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0001 (expanded=0)
D: 1014819 [DMG] Sending report (payload has 176 bytes)...
I: 1014826 [EM]<<< [E:14550r M:5901405 (Ack:138164643)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData)
I: 1014837 IN Sending msg 5901405 on secure session with LSID: 23689
D: 1014846 [DMG] OnReportConfirm: NumReports = 0
D: 1014851 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 1014858 [DMG]IM RH moving to [AwaitingDestruction]
D: 1014864 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 1014905 [EM]>>> [E:14550r M:138164644 (Ack:5901405)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1014918 [EM]Found matching exchange: 14550r, Delegate: (nil)
D: 1014926 [EM]Rxd Ack; Removing MessageCounter:5901405 from Retrans Table on exchange 14550r
I: 1014936 [EM]>>> [E:14551r M:138164645] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:02 (IM:ReadRequest)
D: 1014946 [EM]Handling via exchange: 14551r, Delegate: 0x20008ab4
D: 1014952 [IM]Received Read request
D: 1014956 [DMG]IM RH moving to [GeneratingReports]
D: 1014961 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 1014970 [DMG]RE:Run Cluster 1d, Attribute 2 is dirty
D: 1014975 [DMG]Reading attribute: Cluster=0x0000_001D Endpoint=1 AttributeId=0x0000_0002 (expanded=0)
D: 1014984 [DMG] Sending report (payload has 36 bytes)...
I: 1014990 [EM]<<< [E:14551r M:5901406 (Ack:138164645)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:05 (IM:ReportData)
I: 1015002 IN Sending msg 5901406 on secure session with LSID: 23689
D: 1015010 [DMG] OnReportConfirm: NumReports = 0
D: 1015015 [DMG] ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 1015023 [DMG]IM RH moving to [AwaitingDestruction]
D: 1015028 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
I: 1015039 [EM]>>> [E:14551r M:138164646 (Ack:5901406)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1015052 [EM]Found matching exchange: 14551r, Delegate: (nil)
D: 1015058 [EM]Rxd Ack; Removing MessageCounter:5901406 from Retrans Table on exchange 14551r
D: 1016080 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 1018587 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 1018645 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
I: 1019924 [EM]>>> [E:14552r M:138164647] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 1019935 [EM]Handling via exchange: 14552r, Delegate: 0x20008ab4
D: 1019941 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
I: 1019949 [FS]GeneralCommissioning: Received CommissioningComplete
I: 1019958 [FP]Metadata for Fabric 0x1 persisted to storage.
I: 1019981 [TS]Committing Last Known Good Time to storage: 2022-11-28T23:51:29
I: 1019991 [ZCL]OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0xB693EC17E2AE5718, FabricId 1300E90F1AAADEC2, NodeId 00000000089EC2FD, VendorId 0x6006
I: 1020007 [FS]GeneralCommissioning: Successfully commited pending fabric data
I: 1020014 [FS]Fail-safe cleanly disarmed
D: 1020018 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to e0685677
D: 1020025 [DMG]Command handler moving to [ Preparing]
D: 1020030 [DMG]Command handler moving to [AddingComm]
D: 1020035 [DMG]Command handler moving to [AddedComma]
D: 1020040 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 1020047 [EM]<<< [E:14552r M:5901407 (Ack:138164647)] (S) Msg TX to 1:000000009D6A13AE [5718] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 1020059 IN Sending msg 5901407 on secure session with LSID: 23689
D: 1020068 [DMG]Command handler moving to [CommandSen]
D: 1020073 [DMG]Command handler moving to [AwaitingDe]
I: 1020078 [SWU]Device commissioned, schedule a default provider query
I: 1020085 [SVR]Commissioning completed successfully
I: 1020090 [DIS]Updating services using commissioning mode 0
D: 1020098 [DL]Using Thread extended MAC for hostname.
I: 1020103 [DIS]Advertise operational node B693EC17E2AE5718-00000000089EC2FD
D: 1020110 [DL]Using Thread extended MAC for hostname.
I: 1020116 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
D: 1020126 [IN]Expiring all PASE sessions
D: 1020129 [IN]SecureSession[0x20004430]: MarkForEviction Type:1 LSID:23690
I: 1020136 [SC]SecureSession[0x20004430]: Moving from state 'kActive' --> 'kPendingEviction'
D: 1020144 [IN]SecureSession[0x20004430]: Released - Type:1 LSID:23690
D: 1020151 [IN]Clearing BLE pending packets.
I: 1020155 [BLE]Releasing end point's BLE connection back to application.
I: 1020161 [DL]Closing BLE GATT connection (ConnId 00)
D: 1020167 [ZCL]Commissioning complete, notify platform driver to persist network credentials.
I: 1020177 [EM]>>> [E:14552r M:138164648 (Ack:5901407)] (S) Msg RX from 1:000000009D6A13AE [5718] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1020190 [EM]Found matching exchange: 14552r, Delegate: (nil)
D: 1020196 [EM]Rxd Ack; Removing MessageCounter:5901407 from Retrans Table on exchange 14552r
I: 1020220 [DL]BLE GAP connection terminated (reason 0x16)
I: 1020225 [DL]Current number of connections: 0/2
I: 1031496 [EM]>>> [E:64039r M:56521657] (U) Msg RX from 0:6D9EABC7D5A23C65 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D: 1031507 [EM]Handling via exchange: 64039r, Delegate: 0x200050a0
I: 1031513 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0
I: 1031521 [IN]CASE Server disabling CASE session setups
I: 1031526 [EM]<<< [E:64039r M:260362358 (Ack:56521657)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1031539 IN Sending msg 260362358 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
D: 1031549 [EM]Flushed pending ack for MessageCounter:56521657 on exchange 64039r
I: 1031557 [SC]Received Sigma1 msg
D: 1031561 [SC]Found MRP parameters in the message
D: 1031566 [SC]Peer assigned session key ID 58287
E: 1031574 [SC]CASE failed to match destination ID with local fabrics
D: 1031580 [SC]0x7e, 0x1b, 0x7e, 0x47, 0xc9, 0x5a, 0x1a, 0x2b,
D: 1031586 [SC]0x4c, 0x69, 0xa3, 0x6e, 0x58, 0x0f, 0x4b, 0xbb,
D: 1031592 [SC]0x53, 0xfe, 0x12, 0x73, 0x29, 0xce, 0x62, 0xe6,
D: 1031598 [SC]0xe7, 0xbb, 0xbe, 0x46, 0x01, 0xb0, 0x19, 0x81,
D: 1031603 [SC]Sending status report. Protocol code 2, exchange 64039
I: 1031610 [EM]<<< [E:64039r M:260362359 (Ack:56521657)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 1031622 IN Sending msg 260362359 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
E: 1031633 [IN]CASE Session establishment failed: 71
I: 1031639 [IN]CASE Server enabling CASE session setups
D: 1031644 [IN]SecureSession[0x200045a0]: Released - Type:2 LSID:23691
D: 1031654 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23692
D: 1031660 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
E: 1031667 [EM]OnMessageReceived failed, err = 71
I: 1031671 [IN]CASE Server enabling CASE session setups
D: 1031676 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23692
D: 1031683 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23693
D: 1031689 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
I: 1031696 [EM]>>> [E:64039r M:56521658 (Ack:260362359)] (U) Msg RX from 0:6D9EABC7D5A23C65 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1031709 [EM]Found matching exchange: 64039r, Delegate: (nil)
D: 1031715 [EM]Rxd Ack; Removing MessageCounter:260362359 from Retrans Table on exchange 64039r
I: 1033871 [EM]>>> [E:64040r M:56521659] (U) Msg RX from 0:47147F085086D535 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D: 1033882 [EM]Handling via exchange: 64040r, Delegate: 0x200050a0
I: 1033888 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0
I: 1033896 [IN]CASE Server disabling CASE session setups
I: 1033901 [EM]<<< [E:64040r M:260362360 (Ack:56521659)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1033914 IN Sending msg 260362360 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
D: 1033924 [EM]Flushed pending ack for MessageCounter:56521659 on exchange 64040r
I: 1033932 [SC]Received Sigma1 msg
D: 1033936 [SC]Found MRP parameters in the message
D: 1033941 [SC]Peer assigned session key ID 58288
E: 1033949 [SC]CASE failed to match destination ID with local fabrics
D: 1033955 [SC]0x20, 0x77, 0xd2, 0x94, 0x15, 0x96, 0x12, 0xb7,
D: 1033961 [SC]0x80, 0xd2, 0xef, 0x75, 0xcc, 0xb9, 0x80, 0x2f,
D: 1033967 [SC]0xd7, 0x10, 0x4c, 0x2b, 0x74, 0xdc, 0x52, 0xe7,
D: 1033972 [SC]0xad, 0x69, 0x0f, 0x3a, 0xd6, 0xcc, 0xde, 0x88,
D: 1033978 [SC]Sending status report. Protocol code 2, exchange 64040
I: 1033985 [EM]<<< [E:64040r M:260362361 (Ack:56521659)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 1033997 IN Sending msg 260362361 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
E: 1034009 [IN]CASE Session establishment failed: 71
I: 1034014 [IN]CASE Server enabling CASE session setups
D: 1034019 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23693
D: 1034028 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23694
D: 1034035 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
E: 1034041 [EM]OnMessageReceived failed, err = 71
I: 1034046 [IN]CASE Server enabling CASE session setups
D: 1034051 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23694
D: 1034058 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23695
D: 1034064 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
I: 1034071 [EM]>>> [E:64040r M:56521660 (Ack:260362361)] (U) Msg RX from 0:47147F085086D535 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1034084 [EM]Found matching exchange: 64040r, Delegate: (nil)
D: 1034090 [EM]Rxd Ack; Removing MessageCounter:260362361 from Retrans Table on exchange 64040r
I: 1038255 [EM]>>> [E:64041r M:56521661] (U) Msg RX from 0:6C33328D7A37F9BC [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D: 1038266 [EM]Handling via exchange: 64041r, Delegate: 0x200050a0
I: 1038272 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0
I: 1038280 [IN]CASE Server disabling CASE session setups
I: 1038285 [EM]<<< [E:64041r M:260362362 (Ack:56521661)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1038298 IN Sending msg 260362362 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
D: 1038308 [EM]Flushed pending ack for MessageCounter:56521661 on exchange 64041r
I: 1038316 [SC]Received Sigma1 msg
D: 1038319 [SC]Found MRP parameters in the message
D: 1038324 [SC]Peer assigned session key ID 58289
E: 1038333 [SC]CASE failed to match destination ID with local fabrics
D: 1038339 [SC]0xf8, 0x0b, 0x28, 0x64, 0x3d, 0x80, 0xa2, 0xc4,
D: 1038345 [SC]0x3a, 0xbf, 0x57, 0x4f, 0xac, 0x73, 0x60, 0xc1,
D: 1038351 [SC]0x83, 0xdb, 0x3c, 0xc2, 0xe0, 0x00, 0xe6, 0xbb,
D: 1038357 [SC]0xfc, 0x33, 0x34, 0x13, 0xef, 0xfb, 0x0c, 0x7a,
D: 1038362 [SC]Sending status report. Protocol code 2, exchange 64041
I: 1038369 [EM]<<< [E:64041r M:260362363 (Ack:56521661)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 1038382 IN Sending msg 260362363 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
E: 1038393 [IN]CASE Session establishment failed: 71
I: 1038397 [IN]CASE Server enabling CASE session setups
D: 1038403 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23695
D: 1038413 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23696
D: 1038419 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
E: 1038426 [EM]OnMessageReceived failed, err = 71
I: 1038430 [IN]CASE Server enabling CASE session setups
D: 1038435 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23696
D: 1038442 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23697
D: 1038448 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
I: 1038455 [EM]>>> [E:64041r M:56521662 (Ack:260362363)] (U) Msg RX from 0:6C33328D7A37F9BC [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1038468 [EM]Found matching exchange: 64041r, Delegate: (nil)
D: 1038474 [EM]Rxd Ack; Removing MessageCounter:260362363 from Retrans Table on exchange 64041r
I: 1046632 [EM]>>> [E:64042r M:56521663] (U) Msg RX from 0:FB15CEF7976D7F86 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D: 1046644 [EM]Handling via exchange: 64042r, Delegate: 0x200050a0
I: 1046650 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0
I: 1046657 [IN]CASE Server disabling CASE session setups
I: 1046663 [EM]<<< [E:64042r M:260362364 (Ack:56521663)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1046675 IN Sending msg 260362364 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
D: 1046686 [EM]Flushed pending ack for MessageCounter:56521663 on exchange 64042r
I: 1046694 [SC]Received Sigma1 msg
D: 1046698 [SC]Found MRP parameters in the message
D: 1046703 [SC]Peer assigned session key ID 58290
E: 1046710 [SC]CASE failed to match destination ID with local fabrics
D: 1046717 [SC]0x68, 0x8c, 0x22, 0xf3, 0x9a, 0x56, 0x43, 0xe9,
D: 1046723 [SC]0x87, 0x4d, 0x44, 0x70, 0x00, 0x11, 0xf1, 0x8c,
D: 1046728 [SC]0x66, 0xf9, 0xaa, 0xc7, 0x83, 0x4e, 0xbd, 0x41,
D: 1046734 [SC]0x95, 0x7b, 0xc5, 0xcc, 0x43, 0x89, 0x68, 0x0f,
D: 1046740 [SC]Sending status report. Protocol code 2, exchange 64042
I: 1046746 [EM]<<< [E:64042r M:260362365 (Ack:56521663)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 1046759 IN Sending msg 260362365 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
E: 1046770 [IN]CASE Session establishment failed: 71
I: 1046775 [IN]CASE Server enabling CASE session setups
D: 1046781 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23697
D: 1046790 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23698
D: 1046797 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
E: 1046803 [EM]OnMessageReceived failed, err = 71
I: 1046808 [IN]CASE Server enabling CASE session setups
D: 1046813 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23698
D: 1046820 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23699
D: 1046826 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
I: 1046833 [EM]>>> [E:64042r M:56521664 (Ack:260362365)] (U) Msg RX from 0:FB15CEF7976D7F86 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1046846 [EM]Found matching exchange: 64042r, Delegate: (nil)
D: 1046852 [EM]Rxd Ack; Removing MessageCounter:260362365 from Retrans Table on exchange 64042r
E: 1050085 [SWU]No suitable OTA Provider candidate found
I: 1050090 [SWU]No provider available
I: 1063021 [EM]>>> [E:64043r M:56521665] (U) Msg RX from 0:F7FC311E0205C58F [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D: 1063032 [EM]Handling via exchange: 64043r, Delegate: 0x200050a0
I: 1063038 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0
I: 1063045 [IN]CASE Server disabling CASE session setups
I: 1063051 [EM]<<< [E:64043r M:260362366 (Ack:56521665)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1063064 IN Sending msg 260362366 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
D: 1063074 [EM]Flushed pending ack for MessageCounter:56521665 on exchange 64043r
I: 1063081 [SC]Received Sigma1 msg
D: 1063085 [SC]Found MRP parameters in the message
D: 1063090 [SC]Peer assigned session key ID 58291
E: 1063099 [SC]CASE failed to match destination ID with local fabrics
D: 1063105 [SC]0xff, 0x61, 0xaa, 0x4b, 0xa1, 0x05, 0x92, 0x03,
D: 1063111 [SC]0xfa, 0xc0, 0x30, 0xe1, 0x55, 0xb6, 0xad, 0xec,
D: 1063116 [SC]0xce, 0xa0, 0x51, 0xf5, 0xe4, 0xef, 0x98, 0x23,
D: 1063122 [SC]0x22, 0x56, 0xc4, 0x65, 0xad, 0xfe, 0xb3, 0x9d,
D: 1063128 [SC]Sending status report. Protocol code 2, exchange 64043
I: 1063134 [EM]<<< [E:64043r M:260362367 (Ack:56521665)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 1063147 IN Sending msg 260362367 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
E: 1063158 [IN]CASE Session establishment failed: 71
I: 1063163 [IN]CASE Server enabling CASE session setups
D: 1063169 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23699
D: 1063178 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23700
D: 1063184 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
E: 1063191 [EM]OnMessageReceived failed, err = 71
I: 1063196 [IN]CASE Server enabling CASE session setups
D: 1063201 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23700
D: 1063207 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23701
D: 1063214 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
I: 1063221 [EM]>>> [E:64043r M:56521666 (Ack:260362367)] (U) Msg RX from 0:F7FC311E0205C58F [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1063234 [EM]Found matching exchange: 64043r, Delegate: (nil)
D: 1063239 [EM]Rxd Ack; Removing MessageCounter:260362367 from Retrans Table on exchange 64043r
D: 1067510 [DL]OpenThread State Changed (Flags: 0x00000064)
D: 1067515 [DL] Device Role: ROUTER
I: 1095434 [EM]>>> [E:64044r M:56521667] (U) Msg RX from 0:91FDAF209C3ABBF7 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
D: 1095445 [EM]Handling via exchange: 64044r, Delegate: 0x200050a0
I: 1095451 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20005db0
I: 1095459 [IN]CASE Server disabling CASE session setups
I: 1095464 [EM]<<< [E:64044r M:260362368 (Ack:56521667)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
I: 1095477 IN Sending msg 260362368 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
D: 1095488 [EM]Flushed pending ack for MessageCounter:56521667 on exchange 64044r
I: 1095496 [SC]Received Sigma1 msg
D: 1095500 [SC]Found MRP parameters in the message
D: 1095505 [SC]Peer assigned session key ID 58292
E: 1095515 [SC]CASE failed to match destination ID with local fabrics
D: 1095522 [SC]0x36, 0xfd, 0x1c, 0xef, 0x43, 0xa8, 0x92, 0xe2,
D: 1095528 [SC]0x79, 0x16, 0x3b, 0x91, 0xbe, 0x78, 0x9a, 0x19,
D: 1095534 [SC]0xeb, 0x67, 0x72, 0x74, 0x72, 0xbb, 0x76, 0x0b,
D: 1095540 [SC]0x14, 0x17, 0xb4, 0x82, 0x09, 0xd0, 0x39, 0x65,
D: 1095546 [SC]Sending status report. Protocol code 2, exchange 64044
I: 1095552 [EM]<<< [E:64044r M:260362369 (Ack:56521667)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 1095565 IN Sending msg 260362369 to IP address 'UDP:[fd86:7e7b:14e4:1:45a2:1115:e95c:5cb6]:5540'
E: 1095576 [IN]CASE Session establishment failed: 71
I: 1095581 [IN]CASE Server enabling CASE session setups
D: 1095587 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23701
D: 1095596 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23702
D: 1095603 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
E: 1095609 [EM]OnMessageReceived failed, err = 71
I: 1095614 [IN]CASE Server enabling CASE session setups
D: 1095619 [IN]SecureSession[0x20004430]: Released - Type:2 LSID:23702
D: 1095626 [IN]SecureSession[0x20004430]: Allocated Type:2 LSID:23703
D: 1095632 [SC]Allocated SecureSession (0x20004430) - waiting for Sigma1 msg
I: 1095639 [EM]>>> [E:64044r M:56521668 (Ack:260362369)] (U) Msg RX from 0:91FDAF209C3ABBF7 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
D: 1095652 [EM]Found matching exchange: 64044r, Delegate: (nil)
D: 1095658 [EM]Rxd Ack; Removing MessageCounter:260362369 from Retrans Table on exchange 64044r

[Lukasz Duda]

Have you done factory reset on the Nest Hub 2nd gen? Holding Volume Up and Down for 10 seconds?

You wrote: Hi,  it looks like some flags sent to the cloud are not set all properly in Matter SDK  github.com/.../23761

It's not a flag in Matter SDK but internal Google flag. From the logs it seems that Google controller just tries to establish CASE session with invalid key. It is not a problem with accessory side.