• State Verified Answer
  • Replies 1 reply
  • Subscribers 68 subscribers
  • Views 574 views
  • Users 0 members are here
Attachments (2) Download All
Nordic Case Info
  • Case ID: 314829
Options

Matter over Thread commission error with CHIP-Tools: CHIP Error 0x00000032: Timeout

Jayant Tang

Hello DevZone,

I'm building a Matter development environment with OTBR and CHIP-Tool:

I can add the DK to Apple Home Pod with iOS Home App, it works well.

But when I use CHIP-Tools, it always failed to commission the device to Matter network.

Here are my steps:

  1. initiates the factory reset by long pressing the button1 for 6 seconds.
  2. `sudo modprobe ip6tables_filter` and run the OTBR in docker.
  3. Click the "Form" button on `localhost:8080` to form the Thread network (I can join the network successfully with TTM)
  4. Add the rule to route table: `sudo ip -6 route add fd11:22::/64 dev otbr0 via fd11:db8:1::2`
  5. Click the button4 on the DK to start BLE advertising. And then use CHIP-Tool to commission the device.

Here are my commands and logs:

./chip-tool-debug pairing ble-thread 1 hex:0e08000000000001000035060004001fffe00708fd2aac453d9dca3f0c0402a0f7f8051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f0410445f2b5ca6f2a93a55ce570a70efeecb000300000f0208111111112222222201021234 20202021 3840
 

52840DK log:

Fullscreen 52840.log Download 
 stack
I: 218 [DL]BLE address: C9:5F:1D:63:C9:03
I: 226 

uart:~$ *** Booting Zephyr OS build v3.3.99-ncs1 ***
I: Init CHIP stack
I: 214 [DL]BLE address: D4:36:D5:5A:8D:FE
I: 222 [DL]OpenThread SED interval is 500ms
I: 228 [DL]OpenThread started: OK
I: 231 [DL]Setting OpenThread device type to SYNCHRONIZED SLEEPY END DEVICE
I: 238 [SVR]Subscription persistence not supported
I: 243 [SVR]Server initializing...
I: 246 [TS]Last Known Good Time: 2023-09-19T14:13:01
I: 252 [DMG]AccessControl: initializing
I: 255 [DMG]Examples::AccessControlDelegate::Init
I: 260 [DMG]AccessControl: setting
I: 263 [DMG]DefaultAclStorage: initializing
I: 267 [DMG]DefaultAclStorage: 0 entries loaded
D: 271 [IN]UDP::Init bind&listen port=5540
E: 275 [IN]SO_REUSEPORT failed: 109
D: 278 [IN]UDP::Init bound to port=5540
D: 282 [IN]BLEBase::Init - setting/overriding transport
D: 287 [IN]TransportMgr initialized
D: 294 [DL]Using Thread extended MAC for hostname.
I: 300 [ZCL]Using ZAP configuration...
I: 307 [DMG]AccessControlCluster: initializing
D: 311 [DL]Boot reason: 1
I: 314 [ZCL]Initiating Admin Commissioning cluster.
I: 318 [ZCL]Identify cluster ID: 0x0000_0001 Type: 48 Value: 2, length: 1
I: 325 [ZCL]Window covering cluster ID: 0x0000_000B Type: 231 Value: 0, length: 2
I: 332 [ZCL]Window covering cluster ID: 0x0000_000C Type: 231 Value: 0, length: 2
I: 340 [DIS]Updating services using commissioning mode 0
E: 345 [DIS]Failed to remove advertised services: 3
D: 349 [DL]Using Thread extended MAC for hostname.
I: 354 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
E: 363 [DIS]Failed to advertise extended commissionable node: 3
D: 369 [DIS]Scheduling extended discovery timeout in 900s
E: 374 [DIS]Failed to finalize service update: 3
I: 378 [DIS]Delaying proxy of operational discovery: missing delegate
I: 384 [IN]CASE Server enabling CASE session setups
D: 389 [IN]SecureSession[0x200033c0]: Allocated Type:2 LSID:33827
I: 395 [SVR]Joining Multicast groups
I: 399 [SVR]Server Listening...
I: 401 [DL]Device Configuration:
I: 405 [DL]  Serial Number: 11223344556677889900
I: 409 [DL]  Vendor Id: 65521 (0xFFF1)
I: 413 [DL]  Product Id: 32784 (0x8010)
I: 416 [DL]  Product Name: not-specified
I: 420 [DL]  Hardware Version: 0
I: 423 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 429 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 436 [DL]  Manufacturing Date: (not set)
I: 440 [DL]  Device Type: 65535 (0xFFFF)
I: 444 [SVR]SetupQRCode: [MT:SAGA442C00KA0648G00]
I: 448 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 455 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3ASAGA442C00KA0648G00
I: 463 [SVR]Manual pairing code: [34970112332]
I: 469 [DL]CHIP task running
I: 471 [DIS]Updating services using commissioning mode 0
E: 476 [DIS]Failed to remove advertised services: 3
D: 481 [DL]Using Thread extended MAC for hostname.
I: 486 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
E: 495 [DIS]Failed to advertise extended commissionable node: 3
E: 501 [DIS]Failed to finalize service update: 3
I: 532 [ZCL]Lift[1] Position Set: 0
I: 536 [ZCL]0xc80c8ep 1 clus 0x0000_0102 attr 0x0000_0003 not supported
I: 542 [ZCL]Window covering cluster ID: 0x0000_0008 Type: 230 Value: 0, length: 1
I: 550 [ZCL]Window covering cluster ID: 0x0000_000E Type: 231 Value: 0, length: 2
I: 557 [ZCL]WC POST ATTRIBUTE=8
I: 560 [ZCL]Tilt[1] Position Set: 0
I: 563 [ZCL]0xc80c8ep 1 clus 0x0000_0102 attr 0x0000_0004 not supported
I: 570 [ZCL]Window covering cluster ID: 0x0000_0009 Type: 230 Value: 0, length: 1
I: 578 [ZCL]Window covering cluster ID: 0x0000_000F Type: 231 Value: 0, length: 2
I: 585 [ZCL]WC POST ATTRIBUTE=9
I: 59154 [DL]OpenThread SED interval is 500ms
D: 59159 [IN]SecureSession[0x20003478]: Allocated Type:1 LSID:33828
D: 59165 [DL]CHIPoBLE advertising set to on
I: 59169 [DIS]Updating services using commissioning mode 1
E: 59175 [DIS]Failed to remove advertised services: 3
D: 59180 [DL]Using Thread extended MAC for hostname.
I: 59185 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1
E: 59194 [DIS]Failed to advertise commissionable node: 3
E: 59199 [DIS]Failed to finalize service update: 3
I: 59205 [DL]CHIPoBLE advertising started
I: 59210 [DL]NFC Tag emulation started
I: 62117 [DL]BLE connection established (ConnId: 0x00)
I: 62122 [DL]Current number of connections: 1/1
I: 62126 [DL]CHIPoBLE advertising stopped
I: 62130 [DL]NFC Tag emulation stopped
D: 63707 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 63714 [BLE]local and remote recv window sizes = 5
I: 63719 [BLE]selected BTP version 4
I: 63722 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 63797 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 63802 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 63809 [IN]BLE EndPoint 0x2000a798 Connection Complete
I: 63814 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 63887 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 63895 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 63903 [EM]>>> [E:56763r S:0 M:60017338] (U) Msg RX from 0:21383A76C1C9165A [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I: 63916 [EM]<<< [E:56763r S:0 M:259666780] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 63928 [IN](U) Sending msg 259666780 to IP address 'BLE'
D: 63933 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140)
D: 64022 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 64030 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 64038 [EM]>>> [E:56763r S:0 M:60017339] (U) Msg RX from 0:21383A76C1C9165A [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I: 65737 [EM]<<< [E:56763r S:0 M:259666781] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 65749 [IN](U) Sending msg 259666781 to IP address 'BLE'
D: 65754 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132)
E: 65762 [DL]Long dispatch time: 1732 ms, for event type 16388
D: 65822 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65830 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 65838 [EM]>>> [E:56763r S:0 M:60017340] (U) Msg RX from 0:21383A76C1C9165A [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I: 65850 [EM]<<< [E:56763r S:0 M:259666782] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 65861 [IN](U) Sending msg 259666782 to IP address 'BLE'
D: 65867 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 65875 [SC]SecureSession[0x20003478]: Moving from state 'kEstablishing' --> 'kActive'
D: 65883 [IN]SecureSession[0x20003478]: Activated - Type:1 LSID:33828
D: 65889 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:33828 PSID:13713!
I: 65898 [SVR]Commissioning completed session establishment step
I: 65904 [DIS]Updating services using commissioning mode 0
E: 65909 [DIS]Failed to remove advertised services: 3
D: 65914 [DL]Using Thread extended MAC for hostname.
I: 65920 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
E: 65929 [DIS]Failed to advertise extended commissionable node: 3
D: 65934 [DIS]Scheduling extended discovery timeout in 900s
E: 65940 [DIS]Failed to finalize service update: 3
D: 65944 [DL]CHIPoBLE advertising set to off
I: 65948 [SVR]Device completed Rendezvous process
E: 65953 [DL]Long dispatch time: 123 ms, for event type 16388
D: 65959 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 65967 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 65975 [EM]>>> [E:56764r S:33828 M:126810698] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 65986 [IM]Received Read request
I: 66008 [EM]<<< [E:56764r S:33828 M:253831217] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 66019 [IN](S) Sending msg 253831217 on secure session with LSID: 33828
D: 66025 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 66137 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 66145 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 21)
D: 66227 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 66235 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 66243 [EM]>>> [E:56765r S:33828 M:126810699] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 66255 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 66262 [EM]<<< [E:56765r S:33828 M:253831218] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 66274 [IN](S) Sending msg 253831218 on secure session with LSID: 33828
D: 66280 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 66362 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 66370 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 66378 [EM]>>> [E:56766r S:33828 M:126810700] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 66396 [EM]<<< [E:56766r S:33828 M:253831219] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 66408 [IN](S) Sending msg 253831219 on secure session with LSID: 33828
D: 66415 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 66497 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 66505 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 66513 [EM]>>> [E:56767r S:33828 M:126810701] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 66525 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 66534 [EM]<<< [E:56767r S:33828 M:253831220] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 66546 [IN](S) Sending msg 253831220 on secure session with LSID: 33828
D: 66553 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 66632 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 66640 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 66722 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 66730 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48)
D: 66812 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 66820 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 66828 [EM]>>> [E:56768r S:33828 M:126810702] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 66840 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 66850 [EM]<<< [E:56768r S:33828 M:253831221] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 66861 [IN](S) Sending msg 253831221 on secure session with LSID: 33828
D: 66868 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 66947 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 66955 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 67037 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67045 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 76)
D: 67127 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67135 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 67143 [EM]>>> [E:56769r S:33828 M:126810703] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 67156 [ZCL]OpCreds: Received an AttestationRequest command
I: 67195 [ZCL]OpCreds: AttestationRequest successful.
I: 67204 [EM]<<< [E:56769r S:33828 M:253831222] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 67215 [IN](S) Sending msg 253831222 on secure session with LSID: 33828
D: 67222 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 67307 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67315 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 67397 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67405 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 235)
D: 67532 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67540 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 67548 [EM]>>> [E:56770r S:33828 M:126810704] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 67561 [ZCL]OpCreds: Received a CSRRequest command
I: 67740 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 67779 [ZCL]OpCreds: CSRRequest successful.
I: 67785 [EM]<<< [E:56770r S:33828 M:253831223] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 67797 [IN](S) Sending msg 253831223 on secure session with LSID: 33828
D: 67804 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
E: 67811 [DL]Long dispatch time: 271 ms, for event type 16388
D: 67892 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 67900 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 139)
D: 67982 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 68028 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 68118 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 68127 [EM]>>> [E:56771r S:33828 M:126810705] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 68139 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 68209 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 68215 [EM]<<< [E:56771r S:33828 M:253831224] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 68227 [IN](S) Sending msg 253831224 on secure session with LSID: 33828
D: 68233 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 68)
E: 68241 [DL]Long dispatch time: 123 ms, for event type 16388
D: 68297 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 68343 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 68434 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 68523 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 68533 [EM]>>> [E:56772r S:33828 M:126810706] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 68545 [ZCL]OpCreds: Received an AddNOC command
I: 68552 [FP]Validating NOC chain
I: 68683 [FP]NOC chain validation successful
I: 68687 [FP]Added new fabric at index: 0x1
I: 68691 [FP]Assigned compressed fabric ID: 0x221FB0B2C19FEFEB, node ID: 0x0000000000000001
I: 68699 [TS]Last Known Good Time: 2023-09-19T14:13:01
I: 68704 [TS]New proposed Last Known Good Time: 2021-01-01T00:00:00
I: 68710 [TS]Retaining current Last Known Good Time
I: 68738 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669
D: 68747 [DL]Using Thread extended MAC for hostname.
I: 68752 [DIS]Advertise operational node 221FB0B2C19FEFEB-0000000000000001
I: 68758 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 68766 [EM]<<< [E:56772r S:33828 M:253831225] (S) Msg TX to 1:FFFFFFFB00000000 [EFEB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 68777 [IN](S) Sending msg 253831225 on secure session with LSID: 33828
D: 68784 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
E: 68792 [DL]Long dispatch time: 269 ms, for event type 16388
D: 68882 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 68890 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 68899 [EM]>>> [E:56773r S:33828 M:126810707] (S) Msg RX from 1:FFFFFFFB00000000 [EFEB] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 68918 [EM]<<< [E:56773r S:33828 M:253831226] (S) Msg TX to 1:FFFFFFFB00000000 [EFEB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 68930 [IN](S) Sending msg 253831226 on secure session with LSID: 33828
D: 68936 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 69017 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 69025 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 69033 [EM]>>> [E:56774r S:33828 M:126810708] (S) Msg RX from 1:FFFFFFFB00000000 [EFEB] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 69045 [FS]GeneralCommissioning: Received ArmFailSafe (80s)
I: 69052 [EM]<<< [E:56774r S:33828 M:253831227] (S) Msg TX to 1:FFFFFFFB00000000 [EFEB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 69064 [IN](S) Sending msg 253831227 on secure session with LSID: 33828
D: 69070 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 69152 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 69160 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 69168 [EM]>>> [E:56775r S:33828 M:126810709] (S) Msg RX from 1:FFFFFFFB00000000 [EFEB] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 69191 [DL]OpenThread State Changed (Flags: 0x1017c100)
D: 69197 [DL]   Network Name: OpenThreadDemo
D: 69201 [DL]   PAN Id: 0x1234
D: 69204 [DL]   Extended PAN Id: 0x1111111122222222
D: 69208 [DL]   Channel: 15
D: 69211 [DL]   Mesh Prefix: fd2a:ac45:3d9d:ca3f::/64
D: 69216 [DL]OpenThread State Changed (Flags: 0x1100101d)
D: 69221 [DL]   Device Role: DETACHED
D: 69225 [DL]   Thread Unicast Addresses:
D: 69229 [DL]        fd2a:ac45:3d9d:ca3f:80f7:bca5:23f:a992/64 valid
D: 69235 [DL]        fe80::d8be:d4bc:6e7:8f60/64 valid preferred
I: 70305 [DL]SRP Client was started, detected server: fdd8:27f7:93be:f646:c466:6b12:61db:05f3
D: 70314 [DL]OpenThread State Changed (Flags: 0x200002a4)
D: 70319 [DL]   Device Role: CHILD
D: 70323 [DL]   Partition Id: 0x170487C5
D: 70327 [DL]OpenThread State Changed (Flags: 0x00000001)
D: 70332 [DL]   Thread Unicast Addresses:
D: 70336 [DL]        fd11:22::61ee:a47b:5e9d:dbed/64 valid preferred
D: 70342 [DL]        fd2a:ac45:3d9d:ca3f:0:ff:fe00:4802/64 valid rloc
D: 70349 [DL]        fd2a:ac45:3d9d:ca3f:80f7:bca5:23f:a992/64 valid
D: 70355 [DL]        fe80::d8be:d4bc:6e7:8f60/64 valid preferred
I: 70362 [EM]<<< [E:56775r S:33828 M:253831228] (S) Msg TX to 1:FFFFFFFB00000000 [EFEB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 70374 [IN](S) Sending msg 253831228 on secure session with LSID: 33828
D: 70381 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 70)
D: 70388 [DL]Using Thread extended MAC for hostname.
I: 70393 [DIS]Advertise operational node 221FB0B2C19FEFEB-0000000000000001
I: 70400 [SVR]Operational advertising enabled
D: 70457 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 72748 [DL]SRP update error: timed out waiting on server response
D: 72932 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 75439 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 75497 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 76529 [DL]SRP update error: timed out waiting on server response
D: 77972 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 80479 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 80537 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 81960 [DL]SRP update error: timed out waiting on server response
D: 83012 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 85519 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 85577 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 88052 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 90559 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 90616 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 91315 [DL]SRP update error: timed out waiting on server response
D: 93091 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 95599 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 95656 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 98131 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 100638 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 100696 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 103171 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 105678 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 105736 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 106642 [DL]SRP update error: timed out waiting on server response
D: 108211 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 110719 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 110776 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 113431 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 115457 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 115465 [EM]>>> [E:56776r S:33828 M:126810710] (S) Msg RX from 1:FFFFFFFB00000000 [EFEB] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 115477 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
I: 115484 [EM]<<< [E:56776r S:33828 M:253831229] (S) Msg TX to 1:FFFFFFFB00000000 [EFEB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 115495 [IN](S) Sending msg 253831229 on secure session with LSID: 33828
D: 115502 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 115591 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 118246 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 120754 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 120901 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 123376 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 125883 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 125941 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 128416 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 130923 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 130981 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 132909 [DL]SRP update error: timed out waiting on server response
D: 133456 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 135963 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 136021 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 138495 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 141003 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 141060 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 143535 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 146043 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 146100 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 148575 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 151082 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 151140 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 153750 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 156258 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 156405 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 158880 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 160456 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 160464 [EM]>>> [E:56777r S:33828 M:126810711] (S) Msg RX from 1:FFFFFFFB00000000 [EFEB] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 160476 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
I: 160483 [EM]<<< [E:56777r S:33828 M:253831230] (S) Msg TX to 1:FFFFFFFB00000000 [EFEB] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 160494 [IN](S) Sending msg 253831230 on secure session with LSID: 33828
D: 160501 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 160590 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 163065 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 165573 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 165630 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 168105 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 170612 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 170760 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 173235 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 175742 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 175890 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 176673 [DL]SRP update error: timed out waiting on server response
D: 178500 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 181007 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 181154 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 181875 [DL]ConnId: 0x00, New CCCD value: 0x0000
D: 181879 [IN]Clearing BLE pending packets.
I: 181883 [BLE]Releasing end point's BLE connection back to application.
I: 181889 [DL]Closing BLE GATT connection (ConnId 00)
I: 182009 [DL]BLE GAP connection terminated (reason 0x16)
I: 182015 [DL]Current number of connections: 0/1
E: 250880 [DL]SRP update error: timed out waiting on server response
I: 280482 [FS]Fail-safe timer expired
E: 280486 [SVR]Failsafe timer expired
D: 280489 [IN]SecureSession[0x20003478]: MarkForEviction Type:1 LSID:33828
I: 280496 [SC]SecureSession[0x20003478]: Moving from state 'kActive' --> 'kPendingEviction'
D: 280504 [IN]SecureSession[0x20003478]: Released - Type:1 LSID:33828
E: 280510 [SVR]Commissioning failed (attempt 1): 32
D: 280517 [IN]SecureSession[0x20003478]: Allocated Type:1 LSID:33829
D: 280523 [DL]CHIPoBLE advertising set to on
I: 280527 [DIS]Updating services using commissioning mode 1
E: 280533 [DIS]Failed to remove advertised services: 3
D: 280537 [DL]Using Thread extended MAC for hostname.
I: 280542 [DIS]Advertise operational node 221FB0B2C19FEFEB-0000000000000001
E: 280549 [DIS]Failed to advertise operational node: 3
D: 280554 [DL]Using Thread extended MAC for hostname.
I: 280559 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1
E: 280569 [DIS]Failed to advertise commissionable node: 3
E: 280574 [DIS]Failed to finalize service update: 3
E: 280578 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 280583 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 280589 [IN]Expiring all sessions for fabric 0x1!!
E: 280594 [FP]Reverting pending fabric data for fabric 0x1
E: 280600 [FP]Warning: metadata not found during delete of fabric 0x1
I: 280616 [FP]Fabric (0x1) deleted.
I: 280619 [ZCL]OpCreds: Fabric index 0x1 was removed
I: 280623 [DIS]Updating services using commissioning mode 1
E: 280629 [DIS]Failed to remove advertised services: 3
D: 280634 [DL]Using Thread extended MAC for hostname.
I: 280639 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=1
E: 280648 [DIS]Failed to advertise commissionable node: 3
E: 280653 [DIS]Failed to finalize service update: 3
I: 280677 [TS]Pending Last Known Good Time: 2023-09-19T14:13:01
I: 280683 [TS]Previous Last Known Good Time: 2023-09-19T14:13:01
I: 280689 [TS]Reverted Last Known Good Time to previous value
E: 280695 [FP]Warning: metadata not found during delete of fabric 0x1
E: 280704 [ZCL]OpCreds: failed to delete fabric at index 1: d8
I: 280710 [NP]Reverting Thread operational dataset
E: 280722 [DL]Long dispatch time: 236 ms, for event type 32782
I: 280727 [FS]Fail-safe cleanly disarmed
I: 280733 [DL]CHIPoBLE advertising started
D: 280737 [DL]OpenThread State Changed (Flags: 0x11002046)
D: 280742 [DL]   Device Role: DISABLED
D: 280746 [DL]   Thread Unicast Addresses:
D: 280750 [DL]        fd11:22::61ee:a47b:5e9d:dbed/64 valid preferred
D: 280757 [DL]OpenThread State Changed (Flags: 0x10000000)
I: 280764 [DL]NFC Tag emulation started
I: 310737 [DL]CHIPoBLE advertising mode changed to slow
I: 310746 [DL]CHIPoBLE advertising started
I: 959154 [SVR]Closing pairing window
D: 959158 [IN]SecureSession[0x20003478]: Released - Type:1 LSID:33829
I: 959164 [DIS]Updating services using commissioning mode 0
E: 959169 [DIS]Failed to remove advertised services: 3
D: 959174 [DL]Using Thread extended MAC for hostname.
I: 959180 [DIS]Advertise commission parameter vendorID=65521 productID=32784 discriminator=3840/15 cm=0
E: 959189 [DIS]Failed to advertise extended commissionable node: 3
D: 959195 [DIS]Scheduling extended discovery timeout in 900s
E: 959200 [DIS]Failed to finalize service update: 3
D: 959205 [DL]CHIPoBLE advertising set to off
I: 959209 [DL]OpenThread SED interval is 500ms
I: 959213 [DL]CHIPoBLE advertising stopped
I: 959217 [DL]NFC Tag emulation stopped

CHIP tool log:

5582.chip-tool.log

Best regards,

Jayant

Related