[chip-device-ctrl] ble pairing timeouts after operational credential change

[gjc13]

Problem

On latest master (8a51de2), the ble pairing command timeouts in chip-device-ctrl.

chip-device-ctrl output:

$ ./out/python_env/bin/chip-device-ctrl       
CHIP:DIS: Init admin pairing table with server storage.
CHIP:IN: local node id is 0x000000000001b669
CHIP:ZCL: Using ZAP configuration...
CHIP:ZCL: deactivate report event
CHIP:CTL: Getting operational keys
CHIP:CTL: Generating operational certificate for the controller
CHIP:CTL: Getting root certificate for the controller from the issuer
CHIP:CTL: Generating credentials
CHIP:CTL: Loaded credentials successfully
CHIP:DL: Platform main loop started.
^[[AChip Device Controller Shell

chip-device-ctrl > connect -ble 3840 20202021
Device is assigned with nodeid = 524535
CHIP:BLE: BLE removing known devices.
CHIP:BLE: BLE initiating scan.
CHIP:BLE: New device scanned: DC:A6:32:FA:F7:45
CHIP:BLE: Device discriminator match. Attempting to connect.
CHIP:BLE: Scan complete notification without an active scan.
CHIP:BLE: subscribe complete, ep = 0x7fbc926ff0e0
CHIP:BLE: peripheral chose BTP version 3; central expected between 2 and 3
CHIP:BLE: using BTP fragment sizes rx 20 / tx 128.
CHIP:BLE: local and remote recv window size = 3
CHIP:EM: Received message of type 33 and protocolId 0
CHIP:EM: Received message of type 35 and protocolId 0
CHIP:IN: Sending msg from 0x000000000001b669 to 0x00000000000800f7 at utc time: 524254851 msec
CHIP:IN: Sending secure msg on generic transport
CHIP:IN: Secure msg send status No Error
CHIP:IN: Secure transport received message destined to node ID (112233)
CHIP:IN: Setting fabricID 800F7 on admin.
CHIP:IN: Since admin was modified, persisting changes to KVS
CHIP:EM: Received message of type 9 and protocolId 327680
CHIP:CTL: Default DispatchSingleClusterCommand is called, this should be replaced by actual dispatched for cluster commands
Failed to establish secure session to device: 4050
CHIP Error 4050 (0x00000FD2): Timeout

all-cluster-app output on raspberry pi:

CHIP:BLE: Write request received debug 0xffff78033f70                                                                                       
CHIP:IN: Secure transport received message destined to node ID (524535)                                                                      
CHIP:IN: Setting nodeID 800F7 on admin.          
CHIP:IN: Setting fabricID 1B669 on admin.                   
CHIP:IN: Since admin was modified, persisting changes to KVS
CHIP:SVR: Stored value in server storage                    
CHIP:DL: writing settings to file (/tmp/chip_server_kvs.tmp)
CHIP:DL: renamed tmp file to file (/tmp/chip_server_kvs)                                                                                    
CHIP:DIS: Admin (0) persisted to storage. Calling OnAdminPersistedToStorage.                            
CHIP:ZCL: OpCreds: Admin 0 was persisted to storage. FabricId 1B669, NodeId 800F7, VendorId AAAAC6C1B83C                                     
CHIP:ZCL: OpCreds: Call to writeAdminsIntoFabricsListAttribute                                                                              
CHIP:ZCL: OpCreds: Skipping over unitialized admin with fabricId 1B669, nodeId 800F7 vendorId 0                                              
CHIP:ZCL: OpCreds: Stored 0 admins in fabrics list attribute.
CHIP:EM: Received message of type 8 and protocolId 327680
CHIP:EM: ec id: 39018, Delegate: 0xc1324248      
CHIP:DMG: ICR moving to [Initialize]                                  
CHIP:DMG: InvokeCommand =                                             
CHIP:DMG: {                                                           
CHIP:DMG:       CommandList =                                         
CHIP:DMG:       [                                                     
CHIP:DMG:               CommandDataElement =                          
CHIP:DMG:               {                                             
CHIP:DMG:                       CommandPath =                         
CHIP:DMG:                       {                                     
CHIP:DMG:                               EndpointId = 0x0,
CHIP:DMG:                               ClusterId = 0x3e,
CHIP:DMG:                               CommandId = 0x4,              
CHIP:DMG:                       },                                    
CHIP:DMG:                                                             
CHIP:DMG:                       CommandData =                         
CHIP:DMG:                       {                                     
CHIP:DMG:                               0x0 = [                                                                                             
CHIP:DMG:                                       0x8c, 0x36, 0xf9, 0xc, 0x24, 0x86, 0x5f, 0xe8, 0x18, 0x87, 0x6c, 0x8, 0xf3, 0x8f, 0x73, 0xdc, 0xa7, 0x4d, 0x15, 0x95, 0x31, 0x69, 0x6a, 0x87, 0xc1, 0x5c, 0x8a, 0xc5, 0xe1, 0x2f, 0x65, 0xe1, 
CHIP:DMG:                       ]                                     
CHIP:DMG:                       },                                    
CHIP:DMG:               },                                            
CHIP:DMG:                                                             
CHIP:DMG:       ],
CHIP:DMG: 
CHIP:DMG: }
CHIP:ZCL: Received Cluster Command: Cluster=3e Command=4 Endpoint=0
CHIP:ZCL: OpCreds: commissioner has requested an OpCSR
CHIP:ZCL: OpCreds: Finding admin with fabricId  1B669.
CHIP:DIS: Looking at index 0 with fabricID 112233 nodeID 524535 vendorId 0 to see if it matches fabricId 112233 nodeId 0 vendorId 0.
CHIP:DIS: Found a match!
CHIP:ZCL: OpCreds: NewCertificateSigningRequest returned 0
CHIP:DMG: ICR moving to [AddCommand]
CHIP:IN: Secure message was encrypted: Msg ID 1
CHIP:IN: Sending msg from 0x00000000000800f7 to 0x000000000001b669 at utc time: 1752021579 msec
CHIP:IN: Sending secure msg on generic transport
CHIP:IN: Secure msg send status No Error
CHIP:DMG: ICR moving to [   Sending]
CHIP:DMG: ICR moving to [Uninitiali]
CHIP:DL: c1 BluezCharacteristicWriteFD mtu, 517

Proposed Solution

From the line CHIP:CTL: Default DispatchSingleClusterCommand is called, this should be replaced by actual dispatched for cluster commands, looks like the operational credentials cluster is not handled in the chip-dev-ctrl code. We should add this cluster.

[erjiaqing]

Can you verify if #6802 helps?

[gjc13]

Can you verify if #6802 helps?

Yes the PR works.

[erjiaqing]

Since #6802 is merged, close this issue now.