Hi there,
I have gotten to the very last step of the following tutorial: https://www.youtube.com/watch?v=kdMJQFDRoss
The issue I am facing is that when pairing the Matter device to the thread network, it appears to timeout or not successfully pair.
I currently have a Rpi with nRF52840 Dongle setup as a border router and have formed a thread network.
I flashed a nRF52840 DK with the sample matter light bulb application. Upon boot the output is as follows. Note that there are a few errors shown, I am not sure if this is expected/normal.
uart:~$ I: nRF5 802154 radio initialized
I: 8 Sectors of 4096 bytes
I: alloc wra: 0, fd0
I: data wra: 0, 1c
*** Booting Zephyr OS build v2.7.99-ncs1-17-gc3208e7ff49d ***
I: Init CHIP stack
uart:~$ I: 223 [DL]BLE address: F6:A6:C4:23:09:AE
I: SoftDevice Controller build revision:
I: 73 50 13 e4 e1 27 34 b5 |sP...'4.
I: aa 22 21 6a b2 cb 9e 5e |."!j...^
I: a9 55 8d 25 |.U.%
I: 248 [DL]OpenThread started: OK
I: 251 [DL]Setting OpenThread device type to FULL END DEVICE
I: 257 [ZCL]Using ZAP configuration...
I: 263 [ZCL]Initiating Admin Commissioning cluster.
I: 267 [ZCL]OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
D: 275 [DIS]Set the fabric pairing table delegate
I: 280 [ZCL]0xc5744ep 0 clus 0x0000_0028 attr 0x0000_000F not supported
E: 287 [ZCL]Error setting Serial Number String: 0x86
I: 292 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: 296 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 302 [DIS]Init fabric pairing table with server storage
D: 309 [IN]UDP::Init bind&listen port=5540
D: 313 [IN]UDP::Init bound to port=5540
D: 317 [IN]TransportMgr initialized
D: 325 [SC]Assigned local session key ID 1
D: 329 [SC]Waiting for PBKDF param request
D: 332 [DL]CHIPoBLE advertising set to on
D: 336 [DIS]DNS-SD StartServer modeHasValue=1 modeValue=1
D: 341 [DL]Using Thread extended MAC for hostname.
I: 346 [DIS]Failed to find a valid admin pairing. Node ID unknown
I: 352 [DIS]Start dns-sd server - no current nodeId
D: 357 [DL]Using Thread extended MAC for hostname.
I: 361 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15
E: 370 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003
D: 378 [DIS]Scheduling Discovery timeout in secs=900
E: 383 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
D: 389 [DIS]DNS-SD StartServer modeHasValue=0 modeValue=0
D: 394 [DL]Using Thread extended MAC for hostname.
I: 399 [DIS]Failed to find a valid admin pairing. Node ID unknown
I: 405 [DIS]Start dns-sd server - no current nodeId
D: 410 [DL]Using Thread extended MAC for hostname.
I: 414 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15
E: 423 [DIS]Failed to advertise unprovisioned commissionable node: Error CHIP:0x00000003
D: 431 [DIS]Scheduling Discovery timeout in secs=900
E: 436 [DIS]Failed to finalize service update: Error CHIP:0x0000001C
I: 442 [IN]CASE Server enabling CASE session setups
D: 446 [DL]Using Thread extended MAC for hostname.
I: 451 [SVR]Server Listening...
I: 454 [DL]Device Configuration:
I: 457 [DL] Serial Number: TEST_SN
I: 460 [DL] Vendor Id: 9050 (0x235A)
I: 464 [DL] Product Id: 20044 (0x4E4C)
I: 467 [DL] Hardware Version: 0
I: 470 [DL] Setup Pin Code: 20202021
I: 474 [DL] Setup Discriminator: 3840 (0xF00)
I: 478 [DL] Manufacturing Date: (not set)
I: 482 [DL] Device Type: 65535 (0xFFFF)
I: 486 [SVR]SetupQRCode: [MT:Y3.13OTB00KA0648G00]
I: 491 [SVR]Copy/paste the below URL in a browser to see the QR Code:
https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3AY3.13OTB00KA0648G00
I: 505 [SVR]Manual pairing code: [34970112332]
I: 510 [SVR]Long manual pairing code: [749701123309050200447]
D: 516 [IN]UDP::Init bind&listen port=12345
D: 520 [IN]UDP::Init bound to port=12345
D: 524 [DL]CHIP task running
I: 529 [DL]CHIPoBLE advertising started
I: 533 [ZCL]GeneralDiagnosticsDelegate: OnDeviceRebooted
I: 540 [DL]NFC Tag emulation started
I then open the CHIP tool on an android phone, press 'PROVISION CHIP DEVICE WITH THREAD' and then scan the QR code provided in the link from the text above.
The android app will show the little text saying 'pairing' for about 2 seconds and then just displays a blank white screen. After about 1-2 minutes it shows 'pairing failed;.
During this 'pairing' LED1 on the DK goes from flashing to solid green.
The output of the comm port during this 'pairing' is as follows:
I: 212015 [DL]BLE connection established (ConnId: 0x00) I: 212020 [DL]Current number of connections: 1/1 I: 212025 [DL]CHIPoBLE advertising stopped I: 212029 [DL]NFC Tag emulation stopped D: 213008 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 213014 [BLE]local and remote recv window sizes = 5 I: 213018 [BLE]selected BTP version 4 I: 213022 [BLE]using BTP fragment sizes rx 244 / tx 244. D: 213154 [DL]ConnId: 0x00, New CCCD value: 0x0001 D: 213158 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6) D: 213165 [IN]BLE EndPoint 0x20008440 Connection Complete I: 213170 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247) D: 213251 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 213258 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 213264 [EM]Received message of type 0x20 with protocolId (0, 0) and MessageCounter:3812032413 on exchange 23286r D: 213274 [EM]Handling via exchange: 23286r, Delegate: 0x20005658 D: 213280 [SC]Received PBKDF param request D: 213284 [SC]Peer assigned session ID 1 D: 213288 [SC]Found MRP parameters in the message D: 213293 [SC]Including MRP parameters in PBKDF param response I: 213524 [IN]Prepared unauthenticated message 0x2002c760 to 0x0000000000000000 (0) of type 0x21 and protocolId (0, 0) on exchange 23286r with MessageCounter:1702822331. I: 213539 [IN]Sending unauthenticated msg 0x2002c760 with MessageCounter:1702822331 to 0x0000000000000000 at monotonic time: 213539 msec D: 213552 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 130) D: 213558 [SC]Sent PBKDF param response E: 213562 [DL]Long dispatch time: 304 ms, for event type 16388 D: 213690 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 213790 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 213796 [EM]Received message of type 0x22 with protocolId (0, 0) and MessageCounter:3812032414 on exchange 23286r D: 213807 [EM]Found matching exchange: 23286r, Delegate: 0x20005658 D: 213813 [SC]Received spake2p msg1 I: 215860 [IN]Prepared unauthenticated message 0x2002c6f0 to 0x0000000000000000 (0) of type 0x23 and protocolId (0, 0) on exchange 23286r with MessageCounter:1702822332. I: 215875 [IN]Sending unauthenticated msg 0x2002c6f0 with MessageCounter:1702822332 to 0x0000000000000000 at monotonic time: 215875 msec D: 215887 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 124) D: 215894 [SC]Sent spake2p msg2 E: 215897 [DL]Long dispatch time: 2107 ms, for event type 16388 D: 215981 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 216177 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 216183 [EM]Received message of type 0x24 with protocolId (0, 0) and MessageCounter:3812032415 on exchange 23286r D: 216193 [EM]Found matching exchange: 23286r, Delegate: 0x20005658 D: 216199 [SC]Received spake2p msg3 D: 216203 [SC]Sending status report. Protocol code 0, exchange 23286 I: 216209 [IN]Prepared unauthenticated message 0x2002c778 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 23286r with MessageCounter:1702822333. I: 216224 [IN]Sending unauthenticated msg 0x2002c778 with MessageCounter:1702822333 to 0x0000000000000000 at monotonic time: 216224 msec D: 216236 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 27) D: 216243 [IN]New secure session created for device 0xFFFFFFFB00000000, LSID:1 PSID:1! I: 216252 [SVR]Commissioning completed session establishment step D: 216258 [DL]CHIPoBLE advertising set to off I: 216262 [SVR]Device completed Rendezvous process D: 216323 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 216329 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 216336 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8796674 on exchange 23287r D: 216346 [EM]Handling via exchange: 23287r, Delegate: 0x20007928 D: 216352 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 D: 216360 [DMG]ICR moving to [AddingComm] D: 216363 [DMG]ICR moving to [AddedComma] D: 216367 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 216375 [IN]Prepared secure message 0x2002c7e0 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 23287r with MessageCounter:4735841. I: 216389 [IN]Sending encrypted msg 0x2002c7e0 with MessageCounter:4735841 to 0xFFFFFFFB00000000 (0) at monotonic time: 216389 msec D: 216400 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 68) D: 216407 [DMG]ICR moving to [CommandSen] D: 216411 [DMG]ICR moving to [AwaitingDe] D: 216469 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 216475 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 216482 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8796675 on exchange 23288r D: 216492 [EM]Handling via exchange: 23288r, Delegate: 0x20007928 D: 216498 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 D: 216529 [DMG]ICR moving to [AddingComm] D: 216532 [DMG]ICR moving to [AddedComma] D: 216536 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 216544 [IN]Prepared secure message 0x2002c7e0 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 23288r with MessageCounter:4735842. I: 216558 [IN]Sending encrypted msg 0x2002c7e0 with MessageCounter:4735842 to 0xFFFFFFFB00000000 (0) at monotonic time: 216557 msec D: 216570 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 68) D: 216576 [DMG]ICR moving to [CommandSen] D: 216580 [DMG]ICR moving to [AwaitingDe] E: 216584 [DL]Long dispatch time: 109 ms, for event type 16388 D: 216664 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 216670 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 216677 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8796676 on exchange 23289r D: 216687 [EM]Handling via exchange: 23289r, Delegate: 0x20007928 D: 216693 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 216701 [ZCL]OpCreds: Certificate Chain request received for PAI D: 216707 [DMG]ICR moving to [AddingComm] D: 216711 [DMG]ICR moving to [AddedComma] D: 216715 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 216724 [IN]Prepared secure message 0x2002c7e0 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 23289r with MessageCounter:4735843. I: 216738 [IN]Sending encrypted msg 0x2002c7e0 with MessageCounter:4735843 to 0xFFFFFFFB00000000 (0) at monotonic time: 216738 msec D: 216750 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 216756 [DMG]ICR moving to [CommandSen] D: 216761 [DMG]ICR moving to [AwaitingDe] D: 216907 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 216913 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 217053 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 217059 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 54) D: 217249 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 217255 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 217262 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8796677 on exchange 23290r D: 217272 [EM]Handling via exchange: 23290r, Delegate: 0x20007928 D: 217278 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 I: 217286 [ZCL]OpCreds: Certificate Chain request received for DAC D: 217292 [DMG]ICR moving to [AddingComm] D: 217296 [DMG]ICR moving to [AddedComma] D: 217300 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 217309 [IN]Prepared secure message 0x2002c7e0 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 23290r with MessageCounter:4735844. I: 217323 [IN]Sending encrypted msg 0x2002c7e0 with MessageCounter:4735844 to 0xFFFFFFFB00000000 (0) at monotonic time: 217323 msec D: 217335 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 217342 [DMG]ICR moving to [CommandSen] D: 217347 [DMG]ICR moving to [AwaitingDe] D: 217516 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 217521 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 217651 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 217656 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 76) D: 217741 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 217748 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 217755 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8796678 on exchange 23291r D: 217765 [EM]Handling via exchange: 23291r, Delegate: 0x20007928 D: 217771 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 I: 217779 [ZCL]OpCreds: received an AttestationRequest D: 217815 [DMG]ICR moving to [AddingComm] D: 217818 [DMG]ICR moving to [AddedComma] D: 217822 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 217832 [IN]Prepared secure message 0x2002c7e0 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 23291r with MessageCounter:4735845. I: 217846 [IN]Sending encrypted msg 0x2002c7e0 with MessageCounter:4735845 to 0xFFFFFFFB00000000 (0) at monotonic time: 217846 msec D: 217857 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 217864 [DMG]ICR moving to [CommandSen] D: 217868 [DMG]ICR moving to [AwaitingDe] E: 217872 [DL]Long dispatch time: 124 ms, for event type 16388 D: 218011 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 218016 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 169) D: 218146 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 218283 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 218290 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8796679 on exchange 23292r D: 218300 [EM]Handling via exchange: 23292r, Delegate: 0x20007928 D: 218306 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 I: 218314 [ZCL]OpCreds: commissioner has requested an OpCSR I: 218687 [ZCL]OpCreds: NewCertificateSigningRequest returned 0 D: 218723 [DMG]ICR moving to [AddingComm] D: 218727 [DMG]ICR moving to [AddedComma] D: 218731 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 218740 [IN]Prepared secure message 0x2002c7e0 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 23292r with MessageCounter:4735846. I: 218754 [IN]Sending encrypted msg 0x2002c7e0 with MessageCounter:4735846 to 0xFFFFFFFB00000000 (0) at monotonic time: 218754 msec D: 218766 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 244) D: 218772 [DMG]ICR moving to [CommandSen] D: 218777 [DMG]ICR moving to [AwaitingDe] E: 218781 [DL]Long dispatch time: 498 ms, for event type 16388 D: 218911 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 218916 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 135) D: 219046 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 219229 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 219317 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 219325 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8796680 on exchange 23293r D: 219335 [EM]Handling via exchange: 23293r, Delegate: 0x20007928 D: 219341 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B I: 219349 [ZCL]OpCreds: commissioner has added a trusted root Cert D: 219355 [DMG]ICR moving to [AddingComm] D: 219359 [DMG]ICR moving to [AddedComma] D: 219363 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 219370 [IN]Prepared secure message 0x2002c7e0 to 0xFFFFFFFB00000000 (0) of type 0x9 and protocolId (0, 1) on exchange 23293r with MessageCounter:4735847. I: 219384 [IN]Sending encrypted msg 0x2002c7e0 with MessageCounter:4735847 to 0xFFFFFFFB00000000 (0) at monotonic time: 219384 msec D: 219396 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 65) D: 219402 [DMG]ICR moving to [CommandSen] D: 219407 [DMG]ICR moving to [AwaitingDe] D: 219496 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 219586 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 219678 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 219686 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8796681 on exchange 23294r D: 219696 [EM]Handling via exchange: 23294r, Delegate: 0x20007928 D: 219702 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006 I: 219710 [ZCL]OpCreds: commissioner has added a NOC I: 219716 [DIS]Verifying the received credentials D: 219779 [IN]Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000000 and root pubkey D: 219789 [IN]0x04, 0xbc, 0xdc, 0xef, 0xe6, 0x7d, 0xe6, 0x22, D: 219794 [IN]0xe4, 0x39, 0x04, 0x0e, 0xd3, 0x68, 0xf9, 0xa1, D: 219800 [IN]0xab, 0xbb, 0xa7, 0xb7, 0x0a, 0xf4, 0xd0, 0xb5, D: 219806 [IN]0x26, 0x31, 0xe1, 0xdc, 0x78, 0x01, 0x6a, 0xbe, D: 219812 [IN]0x0a, 0x3a, 0xf3, 0x40, 0x5f, 0x85, 0xee, 0x53, D: 219817 [IN]0x2d, 0xdc, 0x6d, 0x6b, 0x44, 0x68, 0x81, 0x2a, D: 219823 [IN]0x11, 0x8e, 0xee, 0x06, 0x18, 0x76, 0x89, 0x40, D: 219829 [IN]0x12, 0xd2, 0xa4, 0x79, 0x9a, 0xce, 0x79, 0x4e, D: 219834 [IN]0x16, D: 219837 [IN]Generated compressed fabric ID D: 219841 [IN]0xf3, 0x8d, 0x27, 0xdb, 0xa7, 0x5a, 0x0b, 0x3f, I: 219847 [DIS]Added new fabric at index: 1, Initialized: 1 I: 219852 [DIS]Assigned compressed fabric ID: 0xF38D27DBA75A0B3F, node ID: 0x0000000000000005 I: 219861 [DIS]Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage I: 219868 [ZCL]OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000005, VendorId 0x0000 I: 219880 [ZCL]OpCreds: Call to fabricListChanged I: 219913 [DIS]Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage I: 219921 [ZCL]OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000000, NodeId 0000000000000005, VendorId 0x0000 I: 219932 [ZCL]OpCreds: Call to fabricListChanged I: 219936 [DIS]Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage I: 219944 [ZCL]OpCreds: Fabric 0x1 was retrieved from storage. FabricId 0x0000000000000000, NodeId 0x0000000000000005, VendorId 0x0000 I: 219956 [ZCL]OpCreds: Call to fabricListChanged I: 219961 [DIS]Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage I: 219969 [ZCL]OpCreds: Fabric 1 was persisted to storage. FabricId 0000000000000000, NodeId 0000000000000005, VendorId 0x0000 I: 219980 [ZCL]OpCreds: Call to fabricListChanged I: 219984 [ZCL]OpCreds: ACL entry created for Fabric 1 CASE Admin NodeId 0x000000000001B669 D: 219993 [DL]Using Thread extended MAC for hostname. I: 219998 [DIS]Advertise operational node F38D27DBA75A0B3F-0000000000000005 D: 220005 [DMG]ICR moving to [AddingComm] D: 220008 [DMG]ICR moving to [AddedComma] I: 220012 [ZCL]OpCreds: successfully added a NOC D: 220016 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 220024 [IN]Prepared secure message 0x2002c7e0 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 23294r with MessageCounter:4735848. I: 220038 [IN]Sending encrypted msg 0x2002c7e0 with MessageCounter:4735848 to 0xFFFFFFFB00000000 (1) at monotonic time: 220038 msec D: 220050 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71) D: 220056 [DMG]ICR moving to [CommandSen] D: 220060 [DMG]ICR moving to [AwaitingDe] E: 220064 [DL]Long dispatch time: 386 ms, for event type 16388 D: 220126 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 220171 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 220178 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8796682 on exchange 23295r D: 220188 [EM]Handling via exchange: 23295r, Delegate: 0x20007928 D: 220194 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0003 D: 220202 [ZCL]AddOrUpdateThreadNetwork: 0 D: 220206 [DMG]ICR moving to [AddingComm] D: 220209 [DMG]ICR moving to [AddedComma] D: 220213 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 220221 [IN]Prepared secure message 0x2002c7e0 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 23295r with MessageCounter:4735849. I: 220235 [IN]Sending encrypted msg 0x2002c7e0 with MessageCounter:4735849 to 0xFFFFFFFB00000000 (1) at monotonic time: 220235 msec D: 220246 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 68) D: 220253 [DMG]ICR moving to [CommandSen] D: 220257 [DMG]ICR moving to [AwaitingDe] D: 220351 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 220358 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 220364 [EM]Received message of type 0x8 with protocolId (0, 1) and MessageCounter:8796683 on exchange 23296r D: 220374 [EM]Handling via exchange: 23296r, Delegate: 0x20007928 D: 220381 [DMG]Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006 D: 220405 [DL]Using Thread extended MAC for hostname. I: 220410 [DIS]Advertise operational node F38D27DBA75A0B3F-0000000000000005 E: 220417 [SVR]Operational advertising enabled D: 220421 [DMG]ICR moving to [AddingComm] D: 220425 [DMG]ICR moving to [AddedComma] D: 220428 [DMG]Decreasing reference count for CommandHandler, remaining 0 I: 220436 [IN]Prepared secure message 0x2002c7e0 to 0xFFFFFFFB00000000 (1) of type 0x9 and protocolId (0, 1) on exchange 23296r with MessageCounter:4735850. I: 220450 [IN]Sending encrypted msg 0x2002c7e0 with MessageCounter:4735850 to 0xFFFFFFFB00000000 (1) at monotonic time: 220450 msec D: 220462 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 71) D: 220469 [DMG]ICR moving to [CommandSen] D: 220472 [DMG]ICR moving to [AwaitingDe] E: 220476 [DL]Long dispatch time: 118 ms, for event type 16388 D: 220482 [DL]OpenThread State Changed (Flags: 0x1006c100) D: 220488 [DL] Network Name: OpenThread D: 220491 [DL] PAN Id: 0x1234 D: 220494 [DL] Extended PAN Id: 0x1111111122222222 D: 220499 [DL] Channel: 15 D: 220502 [DL] Mesh Prefix: fdde:ad00:beef::/64 D: 220507 [DL]OpenThread State Changed (Flags: 0x1100101d) D: 220512 [DL] Device Role: DETACHED D: 220516 [DL] Thread Unicast Addresses: D: 220519 [DL] fdde:ad00:beef:0:ede4:932b:28b3:2a06/64 valid D: 220526 [DL] fe80::50a2:bcfe:d851:4675/64 valid preferred D: 220533 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) I: 221986 [DL]SRP Client was started, detected server: fdb6:2cf1:9619:f655:ba17:85a0:a74c:71cb D: 221996 [DL]OpenThread State Changed (Flags: 0x301932b7) D: 222001 [DL] Device Role: CHILD D: 222005 [DL] Network Name: OpenThreadDemo D: 222009 [DL] PAN Id: 0x1234 D: 222012 [DL] Extended PAN Id: 0x1111111122222222 D: 222017 [DL] Channel: 15 D: 222019 [DL] Mesh Prefix: fdb6:2cf1:9619:f655::/64 D: 222024 [DL] Partition Id: 0x5029DCC9 D: 222028 [DL] Thread Unicast Addresses: D: 222032 [DL] fd11:22::de0e:cbc8:365f:ea23/64 valid preferred D: 222038 [DL] fdb6:2cf1:9619:f655:0:ff:fe00:f002/64 valid rloc D: 222045 [DL] fdb6:2cf1:9619:f655:ede4:932b:28b3:2a06/64 valid D: 222051 [DL] fe80::50a2:bcfe:d851:4675/64 valid preferred E: 222343 [DL]Long dispatch time: 346 ms, for event type 32780 D: 222348 [DL]OpenThread State Changed (Flags: 0x00000001) D: 222354 [DL] Thread Unicast Addresses: D: 222358 [DL] fd11:22::de0e:cbc8:365f:ea23/64 valid preferred D: 222364 [DL] fdb6:2cf1:9619:f655:0:ff:fe00:f002/64 valid rloc D: 222370 [DL] fdb6:2cf1:9619:f655:ede4:932b:28b3:2a06/64 valid D: 222377 [DL] fe80::50a2:bcfe:d851:4675/64 valid preferred I: 222566 [DL]OnSrpClientNotification: Last requested operation completed successfully D: 222574 [DIS]DNS-SD StartServer modeHasValue=0 modeValue=0 D: 222579 [DL]Using Thread extended MAC for hostname. I: 222584 [DIS]Advertise operational node F38D27DBA75A0B3F-0000000000000005 I: 222591 [DL]advertising srp service: F38D27DBA75A0B3F-0000000000000005._matter._tcp I: 222599 [DIS]Have operational credentials E: 222605 [DIS]Failed to get extended timeout configuration err: Error CHIP:0x000000A0 D: 222650 [DIS]GetExtendedDiscoveryTimeoutSecs -1 D: 222654 [DL]Using Thread extended MAC for hostname. I: 222663 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15 I: 222672 [DL]advertising srp service: 84817FF4A8B7870D._matterc._udp E: 222681 [DIS]Failed to get extended timeout configuration err: Error CHIP:0x000000A0 D: 222727 [DIS]GetExtendedDiscoveryTimeoutSecs -1 E: 222731 [DL]Long dispatch time: 157 ms, for event type 32786 D: 223006 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) I: 223627 [DL]OnSrpClientNotification: Last requested operation completed successfully D: 225513 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 225571 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 228091 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 230597 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 230656 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 233131 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 235637 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 235740 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 238216 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 240721 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 240780 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 243301 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 245807 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 245910 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 248385 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 250892 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 250950 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 253470 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 255976 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 256035 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 258555 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 261062 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 261120 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 263640 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 266147 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 266205 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 268680 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 271186 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 271289 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) D: 273765 [DL]Write request received for CHIPoBLE RX (ConnId 0x00) D: 276270 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3) D: 276329 [DL]Notification for CHIPoBLE TX done (ConnId 0x00) E: 276360 [SVR]Commissioning failed with error 32 E: 276365 [SVR]Commissioning failed (attempt 1): Error CHIP:0x00000032 I: 276371 [BLE]Releasing end point's BLE connection back to application. I: 276378 [DL]Closing BLE GATT connection (ConnId 00) D: 276385 [SC]Assigned local session key ID 2 D: 276389 [SC]Waiting for PBKDF param request D: 276393 [DL]CHIPoBLE advertising set to on D: 276397 [DIS]DNS-SD StartServer modeHasValue=1 modeValue=1 D: 276403 [DL]Using Thread extended MAC for hostname. I: 276408 [DIS]Advertise operational node F38D27DBA75A0B3F-0000000000000005 I: 276415 [DL]advertising srp service: F38D27DBA75A0B3F-0000000000000005._matter._tcp I: 276423 [DIS]Have operational credentials D: 276464 [DL]Using Thread extended MAC for hostname. I: 276472 [DIS]Advertise commission parameter vendorID=9050 productID=20044 discriminator=3840/15 I: 276481 [DL]advertising srp service: 84817FF4A8B7870D._matterc._udp E: 276488 [DL]Long dispatch time: 128 ms, for event type 32784 I: 276531 [DL]BLE GAP connection terminated (reason 0x16) I: 276536 [DL]Current number of connections: 0/1 I: 276546 [DL]CHIPoBLE advertising started I: 276556 [DL]NFC Tag emulation started I: 277552 [DL]OnSrpClientNotification: Last requested operation completed successfully E: 291277 [BLE]ack recv timeout, closing ep 0x20008440 D: 291282 [IN]Clearing BLE pending packets. I: 306550 [DL]CHIPoBLE advertising mode changed to slow
Thanks in advance for your support.
Regards,
Gideon
