Hello DevZone,
I'm building a Matter development environment with OTBR and CHIP-Tool:
- NB: Ubuntu 22.04 with WIFI and BT, get CHIP tool from official pre-built (V2.5.1 corresponding version: chip-tool-linux_x64.zip)
- DK: nRF52840DK with Light Bulb examples(build from V2.5.1)
- Raspberry Pi4 with OTBR configured
- DK: nRF52840DK with coprocessor examples(build from V2.5.1)
But when I want to commission the bulb, it popup errors(as below attachments):
Then I check this issue in DevZone(CHIP error 0x32), it's solution is the credentials is not correct, but I have checked my credentials before commission that they are all correct.
So I am confusing why commission fail with CHIP-Tools: CHIP Error 0x00000032: Timeout?
Looking forward to your response! thx
CHIP tool log:
[1732796087.845465][6682:6684] CHIP:EM: <<< [E:50772i S:59916 M:206939600] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1732796087.845531][6682:6684] CHIP:IN: (S) Sending msg 206939600 on secure session with LSID: 59916
[1732796087.845908][6682:6684] CHIP:DMG: ICR moving to [CommandSen]
[1732796087.928892][6682:6684] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1732796087.975564][6682:6683] CHIP:DL: Indication received, conn = 0x7fb2b8049220
[1732796087.975800][6682:6684] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1732796087.975985][6682:6684] CHIP:EM: >>> [E:50772i S:59916 M:91052311] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1732796087.976033][6682:6684] CHIP:EM: Found matching exchange: 50772i, Delegate: 0x7fb2b0022108
[1732796087.976068][6682:6684] CHIP:DMG: ICR moving to [ResponseRe]
[1732796087.976130][6682:6684] CHIP:DMG: InvokeResponseMessage =
[1732796087.976167][6682:6684] CHIP:DMG: {
[1732796087.976196][6682:6684] CHIP:DMG: suppressResponse = false,
[1732796087.976224][6682:6684] CHIP:DMG: InvokeResponseIBs =
[1732796087.976274][6682:6684] CHIP:DMG: [
[1732796087.976308][6682:6684] CHIP:DMG: InvokeResponseIB =
[1732796087.976355][6682:6684] CHIP:DMG: {
[1732796087.976386][6682:6684] CHIP:DMG: CommandDataIB =
[1732796087.976426][6682:6684] CHIP:DMG: {
[1732796087.976461][6682:6684] CHIP:DMG: CommandPathIB =
[1732796087.976495][6682:6684] CHIP:DMG: {
[1732796087.976529][6682:6684] CHIP:DMG: EndpointId = 0x0,
[1732796087.976569][6682:6684] CHIP:DMG: ClusterId = 0x30,
[1732796087.976608][6682:6684] CHIP:DMG: CommandId = 0x1,
[1732796087.976638][6682:6684] CHIP:DMG: },
[1732796087.976674][6682:6684] CHIP:DMG:
[1732796087.976712][6682:6684] CHIP:DMG: CommandFields =
[1732796087.976748][6682:6684] CHIP:DMG: {
[1732796087.976793][6682:6684] CHIP:DMG: 0x0 = 0,
[1732796087.976838][6682:6684] CHIP:DMG: 0x1 = "" (0 chars),
[1732796087.976883][6682:6684] CHIP:DMG: },
[1732796087.976919][6682:6684] CHIP:DMG: },
[1732796087.976970][6682:6684] CHIP:DMG:
[1732796087.977003][6682:6684] CHIP:DMG: },
[1732796087.977051][6682:6684] CHIP:DMG:
[1732796087.977083][6682:6684] CHIP:DMG: ],
[1732796087.977135][6682:6684] CHIP:DMG:
[1732796087.977167][6682:6684] CHIP:DMG: InteractionModelRevision = 1
[1732796087.977196][6682:6684] CHIP:DMG: },
[1732796087.977316][6682:6684] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1732796087.977366][6682:6684] CHIP:CTL: Status of extending fail-safe for CASE retry: 0
[1732796087.977437][6682:6684] CHIP:DMG: ICR moving to [AwaitingDe]
[1732796088.043671][6682:6684] CHIP:DIS: Checking node lookup status after 200 ms
[1732796090.673956][6682:6684] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1732796092.848031][6682:6684] CHIP:DL: Re-trying resolve
[1732796093.234041][6682:6683] CHIP:DL: Indication received, conn = 0x7fb2b8049220
[1732796093.234198][6682:6684] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1732796095.938689][6682:6684] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1732796097.852483][6682:6684] CHIP:DL: Re-trying resolve
[1732796098.498303][6682:6683] CHIP:DL: Indication received, conn = 0x7fb2b8049220
[1732796098.498623][6682:6684] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1732796101.204178][6682:6684] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1732796102.856444][6682:6684] CHIP:DL: Re-trying resolve
[1732796103.761917][6682:6683] CHIP:DL: Indication received, conn = 0x7fb2b8049220
[1732796103.762122][6682:6684] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1732796106.514139][6682:6684] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1732796107.861795][6682:6684] CHIP:DL: Avahi resolve failed
[1732796108.291628][6682:6682] CHIP:CTL: Shutting down the commissioner
[1732796108.291691][6682:6682] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1732796108.291731][6682:6682] CHIP:DIS: Closing all BLE connections
[1732796108.291770][6682:6682] CHIP:IN: Clearing BLE pending packets.
[1732796108.292258][6682:6682] CHIP:BLE: Auto-closing end point's BLE connection.
[1732796108.292309][6682:6682] CHIP:DL: Closing BLE GATT connection (con 0x7fb2b8049220)
[1732796108.292438][6682:6683] CHIP:DL: BluezDisconnect peer=F4:AB:1E:3F:C9:43
[1732796108.450873][6682:6682] CHIP:IN: SecureSession[0x7fb2b0020200]: MarkForEviction Type:1 LSID:59916
[1732796108.450927][6682:6682] CHIP:SC: SecureSession[0x7fb2b0020200]: Moving from state 'kActive' --> 'kPendingEviction'
[1732796108.450988][6682:6682] CHIP:IN: SecureSession[0x7fb2b0020200]: Released - Type:1 LSID:59916
[1732796108.451066][6682:6682] CHIP:CTL: Shutting down the controller
[1732796108.451098][6682:6682] CHIP:DIS: OperationalSessionSetup[1:000000000000000C]: Cancelling incomplete address resolution as device is being deleted.
[1732796108.451171][6682:6682] CHIP:CTL: Device connection failed. Error src/app/OperationalSessionSetup.cpp:438: CHIP Error 0x00000074: The operation has been cancelled
[1732796108.451209][6682:6682] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1732796108.451235][6682:6682] CHIP:FP: Forgetting fabric 0x1
[1732796108.451275][6682:6682] CHIP:TS: Pending Last Known Good Time: 2023-10-26T12:12:01
[1732796108.451458][6682:6682] CHIP:TS: Previous Last Known Good Time: 2023-10-26T12:12:01
[1732796108.451486][6682:6682] CHIP:TS: Reverted Last Known Good Time to previous value
[1732796108.451530][6682:6682] CHIP:CTL: Shutting down the commissioner
[1732796108.451554][6682:6682] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1732796108.451588][6682:6682] CHIP:CTL: Shutting down the controller
[1732796108.451624][6682:6682] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1732796108.452117][6682:6683] CHIP:DL: Bluez disconnected
[1732796108.452133][6682:6683] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1732796108.452242][6682:6682] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1732796108.452280][6682:6682] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1732796108.452302][6682:6682] CHIP:FP: Shutting down FabricTable
[1732796108.452316][6682:6682] CHIP:TS: Pending Last Known Good Time: 2023-10-26T12:12:01
[1732796108.452373][6682:6682] CHIP:TS: Previous Last Known Good Time: 2023-10-26T12:12:01
[1732796108.452383][6682:6682] CHIP:TS: Reverted Last Known Good Time to previous value
[1732796108.452523][6682:6682] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-FFMNZu)
[1732796108.452770][6682:6682] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1732796108.452794][6682:6682] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1732796108.452803][6682:6682] CHIP:DL: Inet Layer shutdown
[1732796108.452811][6682:6682] CHIP:DL: BLE shutdown
[1732796108.453326][6682:6682] CHIP:DL: System Layer shutdown
[1732796108.453446][6682:6682] CHIP:TOO: Run command failure: examples/chip-tool/commands/common/CHIPCommand.cpp:537: CHIP Error 0x00000032: Timeout
ss1@nb18020136:~/Downloads/chip-tool-linux_x64$
Bulb log:
I: 114077 [EM]>>> [E:50772r S:54053 M:206939600] (S) Msg RX from 1:FFFFFFFB00000000 [1540] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 114089 [FS]GeneralCommissioning: Received ArmFailSafe (120s)
I: 114096 [EM]<<< [E:50772r S:54053 M:91052311] (S) Msg TX to 1:FFFFFFFB00000000 [1540] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 114107 [IN](S) Sending msg 91052311 on secure session with LSID: 54053
D: 114114 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 114202 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 116812 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 119320 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 119422 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 122077 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 124585 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 124687 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 127342 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 129849 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 3)
D: 129952 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 130550 [DL]SRP update error: timed out waiting on server response
D: 131332 [DL]OpenThread State Changed (Flags: 0x00002044)
D: 131337 [DL] Device Role: DETACHED
D: 132607 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
D: 134497 [DL]ConnId: 0x00, New CCCD value: 0x0000
D: 134501 [IN]Clearing BLE pending packets.
I: 134505 [BLE]Releasing end point's BLE connection back to application.
I: 134512 [DL]Closing BLE GATT connection (ConnId 00)
I: 134631 [DL]BLE GAP connection terminated (reason 0x16)
I: 134637 [DL]Current number of connections: 0/1
I: 234094 [FS]Fail-safe timer expired
E: 234098 [SVR]Failsafe timer expired
D: 234101 [IN]SecureSession[0x200031b0]: MarkForEviction Type:1 LSID:54053
I: 234108 [SC]SecureSession[0x200031b0]: Moving from state 'kActive' --> 'kPendingEviction'
D: 234116 [IN]SecureSession[0x200031b0]: Released - Type:1 LSID:54053
E: 234122 [SVR]Commissioning failed (attempt 1): 32
D: 234127 [IN]SecureSession[0x200031b0]: Allocated Type:1 LSID:54055
D: 234133 [DL]CHIPoBLE advertising set to on
I: 234137 [DIS]Updating services using commissioning mode 1
D: 234143 [DL]Using Thread extended MAC for hostname.
I: 234148 [DIS]Advertise operational node FCEA78D788151540-000000000000000C
D: 234155 [DL]Using Thread extended MAC for hostname.
I: 234160 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
I: 234169 [DL]advertising srp service: 96D7216D347D602A._matterc._udp
E: 234175 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 234180 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
D: 234186 [IN]Expiring all sessions for fabric 0x1!!
E: 234191 [FP]Reverting pending fabric data for fabric 0x1
E: 234197 [FP]Warning: metadata not found during delete of fabric 0x1
I: 234257 [FP]Fabric (0x1) deleted.
I: 234261 [ZCL]OpCreds: Fabric index 0x1 was removed
I: 234265 [DIS]Updating services using commissioning mode 1
D: 234271 [DL]Using Thread extended MAC for hostname.
I: 234276 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
I: 234285 [DL]advertising srp service: 96D7216D347D602A._matterc._udp
I: 234292 [DL]removing srp service: FCEA78D788151540-000000000000000C._matter._tcp
I: 234406 [TS]Pending Last Known Good Time: 2024-10-24T15:40:36
I: 234412 [TS]Previous Last Known Good Time: 2024-10-24T15:40:36
I: 234418 [TS]Reverted Last Known Good Time to previous value
E: 234424 [FP]Warning: metadata not found during delete of fabric 0x1
E: 234433 [ZCL]OpCreds: failed to delete fabric at index 1: d8
I: 234439 [NP]Reverting Thread operational dataset
E: 234451 [DL]Long dispatch time: 353 ms, for event type 32782
I: 234457 [FS]Fail-safe cleanly disarmed
I: 234462 [DL]CHIPoBLE advertising started
D: 234466 [DL]OpenThread State Changed (Flags: 0x11002006)
D: 234471 [DL] Device Role: DISABLED
D: 234475 [DL] Thread Unicast Addresses:
D: 234479 [DL] fd85:5aa5:57b8:1:3780:d3e4:1c1a:9f86/64 valid preferred
D: 234486 [DL]OpenThread State Changed (Flags: 0x10000000)
I: 234492 [DL]NFC Tag emulation started
I: 235261 [TS]Pending Last Known Good Time: 2024-10-24T15:40:36
I: 235268 [TS]Previous Last Known Good Time: 2024-10-24T15:40:36
I: 235273 [TS]Reverted Last Known Good Time to previous value
I: 235279 [DL]Performing factory reset