[BUG] Commissioning completed with result: 50 This error is happening during commissioning using Android Chiptool

[Mukhammadjon-Jalolov]

Reproduction steps

I have built and started experimenting with CHiptool on Android devices. During commissioning of different devices from Matter examples folder I face commissioning error: Commissioning failed. and then: Commissioning completed with result: 50. What does this output mean? If commissioning is successful it CHiptool commissions with the code 0

Bug prevalence

It happens not everytime when I try to commission. Around 3/4 in 10 commissioning attempts I get this error. Other times commissioning goes well

Platform

android

Platform Version(s)

No response

Anything else?

No response

[yunhanw-google]

https://github.com/project-chip/connectedhomeip/blob/master/src/lib/core/CHIPError.h#L854C9-L854C27, 50 ==> 0x32, mean timeout,

please upload the detailed log for analysis, thanks

[sghunterfan]

Hey @yunhanw-google ,

I have the same issue on a ameba-d platform (0x32) using both iOS 17.3.1 (iPhone 14 Pro Max) and Android 15 Preview (Pixel 7 Pro). Here are my logs:

• out_rtl.txt (Android)
• out_rtl_ios.txt (iOS)

Tested routers:

• Eero Pro 6
• Dynalink dl-wrx36 (OpenWRT 23.05.2)
• GL.iNet GL-MT6000 (OpenWRT 23.05.3)

Furthermore, on enabling timestamps I see the problem happens immediately:

12:16:11.514 -> 
chip[ZCL] OpCreds: Received an AddTrustedRootCertificate command
12:16:11.514 -> 
chip[ZCL] OpCreds: Failed AddTrustedRootCertificate request with IM error 0x01 (err = 3)
12:16:11.743 -> 
chip[DMG] Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B status 0x01 (no additional context)
12:16:11.743 -> 
chip[DMG] Command handler moving to [NewRespons]
12:16:11.743 -> 
chip[DMG] Command handler moving to [ Preparing]
12:16:11.743 -> 
chip[DMG] Command handler moving to [AddingComm]
12:16:11.743 -> 
chip[DMG] Command handler moving to [AddedComma]
12:16:11.743 -> 
chip[DMG] Decreasing reference count for CommandHandler, remaining 1
12:16:11.775 -> 
chip[DMG] Decreasing reference count for CommandHandler, remaining 0
12:16:11.775 -> 
chip[DMG] Command handler moving to [AwaitingDe]
12:16:11.775 -> 
chip[EM] <<< [E:39030r S:17993 M:112984354] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)
12:16:11.775 -> 
chip[DMG] Command response sender moving to [AllInvokeR]
12:16:11.808 -> 
chip[DL] Long dispatch time: 304 ms, for event type 7
12:16:11.808 -> 
chip[DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
12:16:11.841 -> 
chip[DL] _OnPlatformEvent kCHIPoBLEWriteReceived
12:16:11.841 -> 
chip[EM] >>> [E:39031r S:17993 M:246911180] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
12:16:11.873 -> 
chip[EM] Handling via exchange: 39031r, Delegate: 0x100369d4
12:16:11.873 -> 
chip[DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
12:16:11.873 -> 
chip[FS] GeneralCommissioning: Received ArmFailSafe (0s)
12:16:11.873 -> 
chip[FS] Fail-safe timer expired
12:16:11.873 -> 
chip[DMG] Command handler moving to [NewRespons]
12:16:11.905 -> 
chip[DMG] Command handler moving to [ Preparing]
12:16:11.905 -> 
chip[DMG] Command handler moving to [AddingComm]
12:16:11.905 -> 
chip[DMG] Command handler moving to [AddedComma]
12:16:11.905 -> 
chip[DMG] Decreasing reference count for CommandHandler, remaining 1
12:16:11.905 -> 
chip[DMG] Decreasing reference count for CommandHandler, remaining 0
12:16:11.905 -> 
chip[DMG] Command handler moving to [AwaitingDe]
12:16:11.937 -> 
chip[EM] <<< [E:39031r S:17993 M:112984355] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse)
12:16:11.937 -> 
chip[DMG] Command response sender moving to [AllInvokeR]
12:16:11.937 -> 
chip[SVR] Failsafe timer expired
12:16:11.937 -> 
chip[IN] SecureSession[0x1002e830]: MarkForEviction Type:1 LSID:17993
12:16:11.937 -> 
chip[SC] SecureSession[0x1002e830, LSID:17993]: State change 'kActive' --> 'kPendingEviction'
12:16:11.969 -> 
chip[IN] SecureSession[0x1002e830]: Released - Type:1 LSID:17993
12:16:11.969 -> 
chip[SVR] Commissioning failed (attempt 1): 32
12:16:11.969 -> 
chip[IN] Clearing BLE pending packets.
12:16:11.969 -> 
chip[BLE] Releasing end point's BLE connection back to application.
12:16:11.969 -> 
chip[IN] SecureSession[0x1002e830]: Allocated Type:1 LSID:17995
12:16:12.002 -> 
chip[SC] Assigned local session key ID 17995
12:16:12.002 -> 
chip[SC] Waiting for PBKDF param request
12:16:12.002 -> 
checkExist key=life-count found.
12:16:12.002 -> 
chip[DL] ClearConfigValue : chip-counters/life-count failed
12:16:12.034 -> 

12:16:12.034 -> 
chip[DL] Warning, KVS leakage, failed to remove old KVS value
12:16:12.068 -> 
chip[DL] NVS set: chip-counters/life-count = 49 (0x31)
12:16:12.068 -> 
chip[DIS] Updating services using commissioning mode 1
12:16:12.068 -> 
chip[DIS] CHIP minimal mDNS started advertising.
12:16:12.100 -> 
chip[DL] Using WiFi MAC for hostname
12:16:12.100 -> 
chip[DIS] Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1 cp=0
12:16:12.100 -> 
chip[DIS] Responding with _matterc._udp.local
12:16:12.100 -> 
chip[DIS] Responding with 2FF89B7991B4B752._matterc._udp.local
12:16:12.133 -> 
chip[DIS] Responding with B84D4346D20A.local
12:16:12.133 -> 
chip[DIS] Responding with B84D4346D20A.local
12:16:12.133 -> 
chip[DIS] Responding with _V65521._sub._matterc._udp.local
12:16:12.133 -> 
chip[DIS] Responding with _T65535._sub._matterc._udp.local
12:16:12.133 -> 
chip[DIS] Responding with _S15._sub._matterc._udp.local
12:16:12.133 -> 
chip[DIS] Responding with _L3840._sub._matterc._udp.local
12:16:12.165 -> 
chip[DIS] Responding with _CM._sub._matterc._udp.local
12:16:12.165 -> 
chip[DIS] Responding with 2FF89B7991B4B752._matterc._udp.local
12:16:12.165 -> 
chip[DIS] CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 2FF89B7991B4B752.
12:16:12.165 -> 
chip[DIS] mDNS service published: _matterc._udp
12:16:12.165 -> 
chip[DL] Ameba Observer: Commissioning error (0x32)
12:16:12.165 -> 
chip[ZCL] Failsafe timeout, tell platform driver to revert network credentials.
12:16:12.165 -> 
chip[DMG] Endpoint 0, Cluster 0x0000_0031 update version to 2c4cb1f9
12:16:12.198 -> 
chip[ZCL] OpCreds: Got FailSafeTimerExpired
12:16:12.198 -> 
chip[ZCL] OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
12:16:12.198 -> 
chip[TS] Pending Last Known Good Time: 2024-05-07T17:16:08
12:16:12.198 -> 
chip[TS] Previous Last Known Good Time: 2024-05-07T17:16:08