I: nRF5 802154 radio initialized
I: 8 Sectors of 4096 bytes
I: alloc wra: 2, c08
I: data wra: 2, a28
*** Booting Zephyr OS build v2.7.99-ncs1-1  ***
I: Init CHIP stack


uaI: 225 [DL]BLE address: EE:28:76:1F:86:9B
I: SoftDevice Controller build revision:
I: 0e e7 c5 66 67 18 3c ac |...fg.<.
I: b3 d2 cc 81 a3 dc f1 c0 |........
I: c0 36 02 22             |.6."
rt:~$ I: Starting CHIP task
I: Init Thread stack
I: 255 [DL]OpenThread started: OK
I: 260 [DL]Setting OpenThread device type to MINIMAL END DEVICE
I: 266 [ZCL]Using ZAP configuration...
D: 271 [DMG]Failed to read stored attribute (0, 0x0000_002B, 0x0000_0001: a0
D: 279 [DMG]Failed to read stored attribute (0, 0x0000_002C, 0x0000_0000: a0
I: 288 [SVR]Retrieved from server storage: a/0/2c/1
I: 297 [ZCL]Initiating Admin Commissioning cluster.
I: 301 [ZCL]OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
D: 309 [DIS]Set the fabric pairing table delegate
E: 320 [ZCL]Trying to write invalid Calendar Type
D: 332 [DIS]Init fabric pairing table with server storage
D: 345 [IN]UDP::Init bind&listen port=5540
D: 349 [IN]UDP::Init bound to port=5540
D: 353 [IN]TransportMgr initialized
D: 380 [SC]Assigned local session key ID 1
D: 384 [SC]Waiting for PBKDF param request
D: 388 [DL]CHIPoBLE advertising set to on
D: 391 [DIS]DNS-SD StartServer modeHasValue=1 modeValue=1
D: 396 [DL]Using Thread extended MAC for hostname.
I: 401 [DIS]Failed to find a valid admin pairing. Node ID unknown
I: 407 [DIS]Start dns-sd server - no current nodeId
D: 412 [DL]Using Thread extended MAC for hostname.
I: 418 [DIS]Advertise commission parameter vendorID=9050 productID=20052 discriminator=3840/15
E: 426 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003
D: 434 [DIS]Scheduling Discovery timeout in secs=900
E: 439 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
D: 445 [DIS]DNS-SD StartServer modeHasValue=0 modeValue=0
D: 450 [DL]Using Thread extended MAC for hostname.
I: 455 [DIS]Failed to find a valid admin pairing. Node ID unknown
I: 461 [DIS]Start dns-sd server - no current nodeId
D: 466 [DL]Using Thread extended MAC for hostname.
I: 472 [DIS]Advertise commission parameter vendorID=9050 productID=20052 discriminator=3840/15
E: 480 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003
D: 488 [DIS]Scheduling Discovery timeout in secs=900
E: 493 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 499 [IN]CASE Server enabling CASE session setups
D: 504 [DL]Using Thread extended MAC for hostname.
I: 509 [SVR]Server Listening...
I: 511 [DL]Device Configuration:
I: 516 [DL]  Serial Number: TEST_SN
I: 519 [DL]  Vendor Id: 9050 (0x235A)
I: 522 [DL]  Product Id: 20052 (0x4E54)
I: 527 [DL]  Hardware Version: 0
I: 531 [DL]  Setup Pin Code: 20202021
I: 536 [DL]  Setup Discriminator: 3840 (0xF00)
I: 542 [DL]  Manufacturing Date: (not set)
I: 546 [DL]  Device Type: 65535 (0xFFFF)
I: 552 [SVR]SetupQRCode: [MT:CSF25OTB00KA0648G00]
I: 557 [SVR]Copy/paste the below URL in a browser to see the QR Code:
    https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3ACSF25OTB00KA0648G00
I: 573 [SVR]Manual pairing code: [34970112332]
I: 580 [SVR]Long manual pairing code: [749701123309050200520]
D: 586 [DL]CHIP task running
I: 593 [DL]CHIPoBLE advertising started
I: 597 [ZCL]GeneralDiagnosticsDelegate: OnDeviceRebooted
I: 13698 [DL]BLE connection established (ConnId: 0x00)
I: 13703 [DL]Current number of connections: 1/1
I: 13708 [DL]CHIPoBLE advertising stopped
D: 14737 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 14743 [BLE]local and remote recv window sizes = 5
I: 14748 [BLE]selected BTP version 4
I: 14752 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 14827 [DL]ConnId: 0x00, New CCCD value: 0x0001
D: 14832 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6)
D: 14838 [IN]BLE EndPoint 0x20007588 Connection Complete
I: 14843 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 15008 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 15013 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 15019 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:1214745440 on exchange 34717r
D: 15029 [EM]Handling via exchange: 34717r, Delegate: 0x20004f30
D: 15035 [SC]Received PBKDF param request
D: 15039 [SC]Peer assigned session ID 1
D: 15042 [SC]Found MRP parameters in the message
D: 15047 [SC]Including MRP parameters in PBKDF param response
I: 15273 [IN]Prepared unauthenticated message 0x20027950 to 0x0000000000000000 (0)  of type 0x21 and protocolId (0, 0) on exchange 34717r with MessageCounter:1117629971.
I: 15288 [IN]Sending unauthenticated msg 0x20027950 with MessageCounter:1117629971 to 0x0000000000000000 at monotonic time: 15288 msec
D: 15300 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 130)
D: 15306 [SC]Sent PBKDF param response
E: 15310 [DL]Long dispatch time: 297 ms, for event type 16388
D: 15367 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 15412 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 15419 [EM]Received message of type 0x22 with protocolId (0, 0) and MessageCounter:1214745441 on exchange 34717r
D: 15429 [EM]Found matching exchange: 34717r, Delegate: 0x20004f30
D: 15435 [SC]Received spake2p msg1
I: 17442 [IN]Prepared unauthenticated message 0x200278e8 to 0x0000000000000000 (0)  of type 0x23 and protocolId (0, 0) on exchange 34717r with MessageCounter:1117629972.
I: 17457 [IN]Sending unauthenticated msg 0x200278e8 with MessageCounter:1117629972 to 0x0000000000000000 at monotonic time: 17457 msec
D: 17469 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 124)
D: 17476 [SC]Sent spake2p msg2
E: 17479 [DL]Long dispatch time: 2066 ms, for event type 16388
D: 17527 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 17572 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 17578 [EM]Received message of type 0x24 with protocolId (0, 0) and MessageCounter:1214745442 on exchange 34717r
D: 17589 [EM]Found matching exchange: 34717r, Delegate: 0x20004f30
D: 17594 [SC]Received spake2p msg3
D: 17598 [SC]Sending status report. Protocol code 0, exchange 34717
I: 17604 [IN]Prepared unauthenticated message 0x20027978 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 34717r with MessageCounter:1117629973.
I: 17620 [IN]Sending unauthenticated msg 0x20027978 with MessageCounter:1117629973 to 0x0000000000000000 at monotonic time: 17619 msec
D: 17632 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 27)
D: 17638 [IN]New secure session created for device 0xFFFFFFFB00000000, LSID:1 PSID:1!
I: 17647 [SVR]Commissioning completed session establishment step
D: 17653 [DL]CHIPoBLE advertising set to off
I: 17657 [SVR]Device completed Rendezvous process
D: 17707 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 17713 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 17720 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5698866 on exchange 34718r
D: 17729 [EM]Handling via exchange: 34718r, Delegate: 0x20006a70
D: 17736 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
D: 17743 [DMG]ICR moving to [AddingComm]
D: 17747 [DMG]ICR moving to [AddedComma]
D: 17751 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 17758 [IN]Prepared secure message 0x200279d8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 34718r with MessageCounter:9409385.
I: 17772 [IN]Sending encrypted msg 0x200279d8 with MessageCounter:9409385 to 0xFFFFFFFB00000000 (0) at monotonic time: 17772 msec
D: 17784 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 68)
D: 17790 [DMG]ICR moving to [CommandSen]
D: 17794 [DMG]ICR moving to [AwaitingDe]
D: 17842 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 17848 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 17855 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5698867 on exchange 34719r
D: 17864 [EM]Handling via exchange: 34719r, Delegate: 0x20006a70
D: 17871 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 17898 [DMG]ICR moving to [AddingComm]
D: 17901 [DMG]ICR moving to [AddedComma]
D: 17905 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 17912 [IN]Prepared secure message 0x200279d8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 34719r with MessageCounter:9409386.
I: 17926 [IN]Sending encrypted msg 0x200279d8 with MessageCounter:9409386 to 0xFFFFFFFB00000000 (0) at monotonic time: 17926 msec
D: 17938 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 68)
D: 17945 [DMG]ICR moving to [CommandSen]
D: 17948 [DMG]ICR moving to [AwaitingDe]
E: 17952 [DL]Long dispatch time: 104 ms, for event type 16388
D: 18022 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18028 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 18034 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5698868 on exchange 34720r
D: 18044 [EM]Handling via exchange: 34720r, Delegate: 0x20006a70
D: 18051 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 18058 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 18064 [DMG]ICR moving to [AddingComm]
D: 18068 [DMG]ICR moving to [AddedComma]
D: 18072 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 18081 [IN]Prepared secure message 0x200279d8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 34720r with MessageCounter:9409387.
I: 18095 [IN]Sending encrypted msg 0x200279d8 with MessageCounter:9409387 to 0xFFFFFFFB00000000 (0) at monotonic time: 18095 msec
D: 18106 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 18114 [DMG]ICR moving to [CommandSen]
D: 18117 [DMG]ICR moving to [AwaitingDe]
D: 18202 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18207 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 18292 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18297 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 54)
D: 18382 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18388 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 18394 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5698869 on exchange 34721r
D: 18404 [EM]Handling via exchange: 34721r, Delegate: 0x20006a70
D: 18410 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 18418 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 18424 [DMG]ICR moving to [AddingComm]
D: 18428 [DMG]ICR moving to [AddedComma]
D: 18432 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 18441 [IN]Prepared secure message 0x200279d8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 34721r with MessageCounter:9409388.
I: 18455 [IN]Sending encrypted msg 0x200279d8 with MessageCounter:9409388 to 0xFFFFFFFB00000000 (0) at monotonic time: 18455 msec
D: 18467 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 18474 [DMG]ICR moving to [CommandSen]
D: 18477 [DMG]ICR moving to [AwaitingDe]
D: 18562 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18567 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 18652 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18657 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 76)
D: 18743 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18748 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 18755 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5698870 on exchange 34722r
D: 18765 [EM]Handling via exchange: 34722r, Delegate: 0x20006a70
D: 18771 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 18778 [ZCL]OpCreds: received an AttestationRequest
D: 18816 [DMG]ICR moving to [AddingComm]
D: 18820 [DMG]ICR moving to [AddedComma]
D: 18823 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 18833 [IN]Prepared secure message 0x200279d8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 34722r with MessageCounter:9409389.
I: 18847 [IN]Sending encrypted msg 0x200279d8 with MessageCounter:9409389 to 0xFFFFFFFB00000000 (0) at monotonic time: 18847 msec
D: 18858 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 18865 [DMG]ICR moving to [CommandSen]
D: 18869 [DMG]ICR moving to [AwaitingDe]
E: 18872 [DL]Long dispatch time: 124 ms, for event type 16388
D: 18922 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 18927 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 169)
D: 19012 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 19057 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 19064 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5698871 on exchange 34723r
D: 19074 [EM]Handling via exchange: 34723r, Delegate: 0x20006a70
D: 19080 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004
I: 19088 [ZCL]OpCreds: commissioner has requested an OpCSR
I: 19460 [ZCL]OpCreds: NewCertificateSigningRequest returned 0
D: 19499 [DMG]ICR moving to [AddingComm]
D: 19502 [DMG]ICR moving to [AddedComma]
D: 19507 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 19515 [IN]Prepared secure message 0x200279d8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 34723r with MessageCounter:9409390.
I: 19529 [IN]Sending encrypted msg 0x200279d8 with MessageCounter:9409390 to 0xFFFFFFFB00000000 (0) at monotonic time: 19529 msec
D: 19541 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244)
D: 19547 [DMG]ICR moving to [CommandSen]
D: 19551 [DMG]ICR moving to [AwaitingDe]
E: 19555 [DL]Long dispatch time: 498 ms, for event type 16388
D: 19567 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 19572 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 134)
D: 19597 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 19628 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 19657 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 19665 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5698872 on exchange 34724r
D: 19675 [EM]Handling via exchange: 34724r, Delegate: 0x20006a70
D: 19681 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B
I: 19689 [ZCL]OpCreds: commissioner has added a trusted root Cert
D: 19695 [DMG]ICR moving to [AddingComm]
D: 19699 [DMG]ICR moving to [AddedComma]
D: 19703 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 19710 [IN]Prepared secure message 0x200279d8 to 0xFFFFFFFB00000000 (0)  of type 0x9 and protocolId (0, 1) on exchange 34724r with MessageCounter:9409391.
I: 19724 [IN]Sending encrypted msg 0x200279d8 with MessageCounter:9409391 to 0xFFFFFFFB00000000 (0) at monotonic time: 19724 msec
D: 19736 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 65)
D: 19742 [DMG]ICR moving to [CommandSen]
D: 19746 [DMG]ICR moving to [AwaitingDe]
D: 19763 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 19769 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 19793 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 19800 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5698873 on exchange 34725r
D: 19810 [EM]Handling via exchange: 34725r, Delegate: 0x20006a70
D: 19817 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006
I: 19825 [ZCL]OpCreds: commissioner has added a NOC
I: 19831 [DIS]Verifying the received credentials
D: 19897 [IN]Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000000 and root pubkey
D: 19907 [IN]0x04, 0x9e, 0xad, 0x9f, 0x20, 0xb9, 0x5b, 0x5e,
D: 19913 [IN]0xc1, 0x85, 0x1f, 0x56, 0x18, 0x21, 0xa5, 0x1f,
D: 19918 [IN]0xf8, 0xa0, 0x74, 0x09, 0x29, 0x32, 0x59, 0x78,
D: 19924 [IN]0x93, 0x01, 0xc1, 0x97, 0xc3, 0x69, 0xe7, 0xf0,
D: 19930 [IN]0x24, 0x59, 0x40, 0x77, 0xde, 0xb1, 0xb5, 0xe4,
D: 19935 [IN]0x2d, 0x69, 0x0a, 0xe9, 0x57, 0xc4, 0xc4, 0x6a,
D: 19941 [IN]0xbb, 0x90, 0xfc, 0xc4, 0x7c, 0x94, 0xfe, 0x58,
D: 19947 [IN]0x75, 0x2d, 0xe7, 0x66, 0x4c, 0xe0, 0xc0, 0x27,
D: 19952 [IN]0xed,
D: 19955 [IN]Generated compressed fabric ID
D: 19959 [IN]0x60, 0x0c, 0xde, 0xd1, 0x84, 0xb0, 0x94, 0x4e,
I: 19965 [DIS]Added new fabric at index: 1, Initialized: 1
I: 19970 [DIS]Assigned compressed fabric ID: 0x600CDED184B0944E, node ID: 0x0000000000000002
I: 19978 [DIS]Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I: 19986 [ZCL]OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000002, VendorId 0x0000
I: 19998 [ZCL]OpCreds: Call to fabricListChanged
I: 20140 [DIS]Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
I: 20148 [ZCL]OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000000, NodeId 0000000000000002, VendorId 0x0000
I: 20159 [ZCL]OpCreds: Call to fabricListChanged
I: 20163 [DIS]Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I: 20171 [ZCL]OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000002, VendorId 0x0000
I: 20183 [ZCL]OpCreds: Call to fabricListChanged
I: 20188 [DIS]Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
I: 20195 [ZCL]OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000000, NodeId 0000000000000002, VendorId 0x0000
I: 20207 [ZCL]OpCreds: Call to fabricListChanged
I: 20211 [ZCL]OpCreds: ACL entry created for Fabric 1 CASE Admin NodeId 0x000000000001B669
D: 20219 [DL]Using Thread extended MAC for hostname.
I: 20224 [DIS]Advertise operational node 600CDED184B0944E-0000000000000002
D: 20231 [DMG]ICR moving to [AddingComm]
D: 20235 [DMG]ICR moving to [AddedComma]
I: 20239 [ZCL]OpCreds: successfully added a NOC
D: 20243 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 20250 [IN]Prepared secure message 0x200279d8 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 34725r with MessageCounter:9409392.
I: 20264 [IN]Sending encrypted msg 0x200279d8 with MessageCounter:9409392 to 0xFFFFFFFB00000000 (1) at monotonic time: 20264 msec
D: 20276 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
D: 20282 [DMG]ICR moving to [CommandSen]
D: 20286 [DMG]ICR moving to [AwaitingDe]
E: 20290 [DL]Long dispatch time: 498 ms, for event type 16388
D: 20302 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 20317 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 20324 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5698874 on exchange 34726r
D: 20334 [EM]Handling via exchange: 34726r, Delegate: 0x20006a70
D: 20341 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003
D: 20349 [ZCL]AddOrUpdateThreadNetwork: 0
D: 20352 [DMG]ICR moving to [AddingComm]
D: 20356 [DMG]ICR moving to [AddedComma]
D: 20360 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 20367 [IN]Prepared secure message 0x200279d8 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 34726r with MessageCounter:9409393.
I: 20381 [IN]Sending encrypted msg 0x200279d8 with MessageCounter:9409393 to 0xFFFFFFFB00000000 (1) at monotonic time: 20381 msec
D: 20393 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 68)
D: 20399 [DMG]ICR moving to [CommandSen]
D: 20403 [DMG]ICR moving to [AwaitingDe]
D: 20422 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 20437 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 20444 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:5698875 on exchange 34727r
D: 20454 [EM]Handling via exchange: 34727r, Delegate: 0x20006a70
D: 20460 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006
D: 20487 [DL]Using Thread extended MAC for hostname.
I: 20492 [DIS]Advertise operational node 600CDED184B0944E-0000000000000002
E: 20499 [SVR]Operational advertising enabled
D: 20504 [DMG]ICR moving to [AddingComm]
D: 20507 [DMG]ICR moving to [AddedComma]
D: 20511 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 20519 [IN]Prepared secure message 0x200279d8 to 0xFFFFFFFB00000000 (1)  of type 0x9 and protocolId (0, 1) on exchange 34727r with MessageCounter:9409394.
I: 20533 [IN]Sending encrypted msg 0x200279d8 with MessageCounter:9409394 to 0xFFFFFFFB00000000 (1) at monotonic time: 20533 msec
D: 20545 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71)
D: 20552 [DMG]ICR moving to [CommandSen]
D: 20555 [DMG]ICR moving to [AwaitingDe]
E: 20559 [DL]Long dispatch time: 122 ms, for event type 16388
D: 20565 [DL]OpenThread State Changed (Flags: 0x1006c100)
D: 20570 [DL]   Network Name: OpenThread
D: 20574 [DL]   PAN Id: 0x1234
D: 20577 [DL]   Extended PAN Id: 0x1111111122222222
D: 20582 [DL]   Channel: 15
D: 20584 [DL]   Mesh Prefix: fdde:ad00:beef::/64
D: 20590 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 20595 [DL]   Device Role: DETACHED
D: 20598 [DL]   Thread Unicast Addresses:
D: 20602 [DL]        fdde:ad00:beef:0:a056:5e82:18b9:6b3e/64 valid
D: 20609 [DL]        fe80::b0d2:6b38:e28:c06c/64 valid preferred
D: 20615 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
I: 21718 [DL]SRP Client was started, detected server: fdaf:9c27:ea3a:72b9:65b3:3542:5f36:f973
D: 21728 [DL]OpenThread State Changed (Flags: 0x301132b7)
D: 21733 [DL]   Device Role: CHILD
D: 21736 [DL]   Network Name: OpenThread-e95e
D: 21740 [DL]   PAN Id: 0x1234
D: 21744 [DL]   Extended PAN Id: 0x1111111122222222
D: 21748 [DL]   Channel: 15
D: 21751 [DL]   Mesh Prefix: fdaf:9c27:ea3a:72b9::/64
D: 21756 [DL]   Partition Id: 0x190AF261
D: 21760 [DL]   Thread Unicast Addresses:
D: 21764 [DL]        fd50:a5b4:c22b:8c99:3550:c09b:50af:b697/64 valid preferred
D: 21771 [DL]        fdaf:9c27:ea3a:72b9:0:ff:fe00:7815/64 valid rloc
D: 21777 [DL]        fdaf:9c27:ea3a:72b9:a056:5e82:18b9:6b3e/64 valid
D: 21784 [DL]        fe80::b0d2:6b38:e28:c06c/64 valid preferred
E: 22029 [DL]Long dispatch time: 301 ms, for event type 32780
D: 22035 [DL]OpenThread State Changed (Flags: 0x00000001)
D: 22041 [DL]   Thread Unicast Addresses:
D: 22045 [DL]        fd50:a5b4:c22b:8c99:3550:c09b:50af:b697/64 valid preferred
D: 22052 [DL]        fdaf:9c27:ea3a:72b9:0:ff:fe00:7815/64 valid rloc
D: 22059 [DL]        fdaf:9c27:ea3a:72b9:a056:5e82:18b9:6b3e/64 valid
D: 22065 [DL]        fe80::b0d2:6b38:e28:c06c/64 valid preferred
I: 22202 [DL]OnSrpClientNotification: Last requested operation completed successfully
D: 22210 [DIS]DNS-SD StartServer modeHasValue=0 modeValue=0
D: 22216 [DL]Using Thread extended MAC for hostname.
I: 22221 [DIS]Advertise operational node 600CDED184B0944E-0000000000000002
I: 22228 [DL]advertising srp service: 600CDED184B0944E-0000000000000002._matter._tcp
I: 22236 [DIS]Have operational credentials
E: 22242 [DIS]Failed to get extended timeout configuration err: Error CHIP:0x000000A0
D: 22289 [DIS]GetExtendedDiscoveryTimeoutSecs -1
D: 22293 [DL]Using Thread extended MAC for hostname.
I: 22301 [DIS]Advertise commission parameter vendorID=9050 productID=20052 discriminator=3840/15
I: 22311 [DL]advertising srp service: DD334A5BCDBEBAAC._matterc._udp
E: 22320 [DIS]Failed to get extended timeout configuration err: Error CHIP:0x000000A0
D: 22368 [DIS]GetExtendedDiscoveryTimeoutSecs -1
E: 22373 [DL]Long dispatch time: 163 ms, for event type 32786
D: 23092 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 23187 [DL]OnSrpClientNotification: Last requested operation completed successfully
I: 23782 [EM]Received message of type 0x30 with protocolId (0, 0) and MessageCounter:1214745443 on exchange 34728r
D: 23792 [EM]Handling via exchange: 34728r, Delegate: 0x200035dc
I: 23799 [IN]CASE Server received Sigma1 message. Starting handshake. EC 0x20004948
I: 23806 [DIS]CASE handshake initiated, closing all BLE Connections
D: 23813 [IN]Clearing BLE pending packets.
I: 23816 [BLE]Releasing end point's BLE connection back to application.
I: 23823 [DL]Closing BLE GATT connection (ConnId 00)
D: 23828 [SC]Waiting for Sigma1 msg
I: 23832 [IN]CASE Server disabling CASE session setups
D: 23836 [SC]Received Sigma1 msg
D: 23839 [SC]Found MRP parameters in the message
D: 23844 [SC]Peer assigned session key ID 2
I: 23848 [DIS]Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I: 23856 [ZCL]OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000002, VendorId 0x0000
I: 23868 [ZCL]OpCreds: Call to fabricListChanged
D: 23873 [IN]Generating DestinationID. Fabric ID 0x0000000000000000, Dest node ID 0x0000000000000002, Random data
D: 23883 [IN]0x05, 0xa0, 0x36, 0x77, 0x84, 0xb2, 0xb7, 0xbe,
D: 23889 [IN]0x50, 0x97, 0xd4, 0xf3, 0xee, 0x4b, 0x17, 0xbe,
D: 23895 [IN]0x23, 0xa8, 0xa4, 0x27, 0xcd, 0x41, 0xe3, 0x26,
D: 23900 [IN]0x5a, 0x75, 0x36, 0x6c, 0x3d, 0x04, 0xb7, 0x85,
D: 23906 [IN]Root pubkey
D: 23908 [IN]0x04, 0x9e, 0xad, 0x9f, 0x20, 0xb9, 0x5b, 0x5e,
D: 23914 [IN]0xc1, 0x85, 0x1f, 0x56, 0x18, 0x21, 0xa5, 0x1f,
D: 23919 [IN]0xf8, 0xa0, 0x74, 0x09, 0x29, 0x32, 0x59, 0x78,
D: 23925 [IN]0x93, 0x01, 0xc1, 0x97, 0xc3, 0x69, 0xe7, 0xf0,
D: 23931 [IN]0x24, 0x59, 0x40, 0x77, 0xde, 0xb1, 0xb5, 0xe4,
D: 23936 [IN]0x2d, 0x69, 0x0a, 0xe9, 0x57, 0xc4, 0xc4, 0x6a,
D: 23942 [IN]0xbb, 0x90, 0xfc, 0xc4, 0x7c, 0x94, 0xfe, 0x58,
D: 23948 [IN]0x75, 0x2d, 0xe7, 0x66, 0x4c, 0xe0, 0xc0, 0x27,
D: 23953 [IN]0xed,
D: 23955 [IN]IPK
D: 23957 [IN]0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
D: 23962 [IN]0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
D: 23968 [IN]Generated DestinationID output
D: 23972 [IN]0x49, 0x18, 0xfa, 0xbe, 0x35, 0x47, 0xc5, 0x5f,
D: 23978 [IN]0xec, 0x77, 0x28, 0x49, 0x42, 0x45, 0x44, 0x64,
D: 23983 [IN]0x2c, 0x76, 0x99, 0x9e, 0xd3, 0x43, 0x7e, 0x5b,
D: 23989 [IN]0x0f, 0x20, 0x9f, 0x88, 0x03, 0x62, 0xe2, 0x0f,
I: 23995 [DIS]Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage
I: 24002 [ZCL]OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000002, VendorId 0x0000
I: 24014 [ZCL]OpCreds: Call to fabricListChanged
D: 24244 [SC]Including MRP parameters
I: 24248 [IN]Prepared unauthenticated message 0x20004864 to 0x0000000000000000 (0)  of type 0x31 and protocolId (0, 0) on exchange 34728r with MessageCounter:1117629974.
I: 24263 [IN]Sending unauthenticated msg 0x20004864 with MessageCounter:1117629974 to 0x0000000000000000 at monotonic time: 24263 msec
D: 24276 [SC]Sent Sigma2 msg
I: 24280 [DL]BLE GAP connection terminated (reason 0x16)
I: 24285 [DL]Current number of connections: 0/1
I: 24646 [EM]Received message of type 0x32 with protocolId (0, 0) and MessageCounter:1214745444 on exchange 34728r
D: 24656 [EM]Found matching exchange: 34728r, Delegate: 0x200035e8
D: 24662 [EM]Rxd Ack; Removing MessageCounter:1117629974 from Retrans Table on exchange 34728r
D: 24671 [EM]Removed CHIP MessageCounter:1117629974 from RetransTable on exchange 34728r
D: 24679 [SC]Received Sigma3 msg
E: 24685 [SC]The device does not support GetClock_RealTimeMS() API. This will eventually result in CASE session setup failures.
D: 24759 [IN]Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000000 and root pubkey
D: 24768 [IN]0x04, 0x9e, 0xad, 0x9f, 0x20, 0xb9, 0x5b, 0x5e,
D: 24774 [IN]0xc1, 0x85, 0x1f, 0x56, 0x18, 0x21, 0xa5, 0x1f,
D: 24780 [IN]0xf8, 0xa0, 0x74, 0x09, 0x29, 0x32, 0x59, 0x78,
D: 24785 [IN]0x93, 0x01, 0xc1, 0x97, 0xc3, 0x69, 0xe7, 0xf0,
D: 24791 [IN]0x24, 0x59, 0x40, 0x77, 0xde, 0xb1, 0xb5, 0xe4,
D: 24797 [IN]0x2d, 0x69, 0x0a, 0xe9, 0x57, 0xc4, 0xc4, 0x6a,
D: 24802 [IN]0xbb, 0x90, 0xfc, 0xc4, 0x7c, 0x94, 0xfe, 0x58,
D: 24808 [IN]0x75, 0x2d, 0xe7, 0x66, 0x4c, 0xe0, 0xc0, 0x27,
D: 24813 [IN]0xed,
D: 24816 [IN]Generated compressed fabric ID
D: 24820 [IN]0x60, 0x0c, 0xde, 0xd1, 0x84, 0xb0, 0x94, 0x4e,
D: 24885 [SC]Sending status report. Protocol code 0, exchange 34728
I: 24891 [IN]Prepared unauthenticated message 0x20004864 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 34728r with MessageCounter:1117629975.
I: 24906 [IN]Sending unauthenticated msg 0x20004864 with MessageCounter:1117629975 to 0x0000000000000000 at monotonic time: 24906 msec
I: 24919 [IN]CASE Session established. Setting up the secure channel.
D: 24926 [IN]New secure session created for device 0x000000000001B669, LSID:2 PSID:2!
I: 24935 [IN]CASE secure channel is available now.
I: 24939 [IN]CASE Server enabling CASE session setups
I: 25411 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8755650 on exchange 34729r
D: 25422 [EM]Handling via exchange: 34729r, Delegate: 0x20006a70
D: 25428 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
D: 25436 [DMG]ICR moving to [AddingComm]
D: 25440 [DMG]ICR moving to [AddedComma]
D: 25443 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 25451 [IN]Prepared secure message 0x2000487c to 0x000000000001B669 (1)  of type 0x9 and protocolId (0, 1) on exchange 34729r with MessageCounter:205528.
I: 25465 [IN]Sending encrypted msg 0x2000487c with MessageCounter:205528 to 0x000000000001B669 (1) at monotonic time: 25464 msec
D: 25477 [DMG]ICR moving to [CommandSen]
D: 25481 [DMG]ICR moving to [AwaitingDe]
I: 25485 [SVR]Commissioning completed successfully
D: 25490 [DIS]DNS-SD StartServer modeHasValue=1 modeValue=0
D: 25495 [DL]Using Thread extended MAC for hostname.
I: 25500 [DIS]Advertise operational node 600CDED184B0944E-0000000000000002
I: 25507 [DL]advertising srp service: 600CDED184B0944E-0000000000000002._matter._tcp
I: 25514 [DIS]Have operational credentials
E: 25559 [DIS]Failed to get extended timeout configuration err: Error CHIP:0x000000A0
D: 25568 [DIS]GetExtendedDiscoveryTimeoutSecs -1
D: 25572 [DL]Using Thread extended MAC for hostname.
I: 25581 [DIS]Advertise commission parameter vendorID=9050 productID=20052 discriminator=3840/15
I: 25591 [DL]advertising srp service: DD334A5BCDBEBAAC._matterc._udp
E: 25640 [DIS]Failed to get extended timeout configuration err: Error CHIP:0x000000A0
D: 25648 [DIS]GetExtendedDiscoveryTimeoutSecs -1
E: 25652 [DL]Long dispatch time: 167 ms, for event type 32784
I: 25659 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:1214745445 on exchange 34728r
D: 25669 [EM]Found matching exchange: 34728r, Delegate: (nil)
D: 25675 [EM]Rxd Ack; Removing MessageCounter:1117629975 from Retrans Table on exchange 34728r
D: 25684 [EM]Removed CHIP MessageCounter:1117629975 from RetransTable on exchange 34728r
I: 25845 [DL]OnSrpClientNotification: Last requested operation completed successfully
I: 26933 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:8755651 on exchange 34729r
D: 26943 [EM]Found matching exchange: 34729r, Delegate: (nil)
D: 26948 [EM]Rxd Ack; Removing MessageCounter:205528 from Retrans Table on exchange 34729r
D: 26956 [EM]Removed CHIP MessageCounter:205528 from RetransTable on exchange 34729r
I: 58406 [EM]Received message of type 0x2 with protocolId (0, 1) and MessageCounter:8755652 on exchange 34730r
D: 58416 [EM]Handling via exchange: 34730r, Delegate: 0x20006a70
D: 58422 [IM]Received Read request
D: 58425 [DMG]IM RH moving to [Initialized]
D: 58429 [DMG]IM RH moving to [GeneratingReports]
D: 58434 [DMG]<RE:Run> Cluster 201, Attribute 12 is dirty
D: 58439 [DMG]Reading attribute: Cluster=0x0000_0201 Endpoint=1 AttributeId=0x0000_0012 (expanded=0)
D: 58448 [DMG]<RE> Sending report (payload has 32 bytes)...
I: 58454 [IN]Prepared secure message 0x20004864 to 0x000000000001B669 (1)  of type 0x5 and protocolId (0, 1) on exchange 34730r with MessageCounter:205529.
I: 58468 [IN]Sending encrypted msg 0x20004864 with MessageCounter:205529 to 0x000000000001B669 (1) at monotonic time: 58468 msec
D: 58481 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 58485 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 58493 [DMG]IM RH moving to [Uninitialized]
I: 58518 [EM]Received message of type 0x10 with protocolId (0, 0) and MessageCounter:8755653 on exchange 34730r
D: 58528 [EM]Found matching exchange: 34730r, Delegate: (nil)
D: 58534 [EM]Rxd Ack; Removing MessageCounter:205529 from Retrans Table on exchange 34730r
D: 58542 [EM]Removed CHIP MessageCounter:205529 from RetransTable on exchange 34730r