search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.49k stars 2.01k forks source link

[1.1][Android] After invoke ChipDeviceController.shutdownCommissioning, every thing is not worked. #28681

Open Allen-Guof opened 1 year ago

Allen-Guof commented 1 year ago

Reproduction steps

  1. Commissionee a device to an Android phone.
  2. Invoke ON/OFF command, and it worked well.
  3. Invoke ChipDeviceController.shutdownCommissioning() command. Then every thing is not worked. Even if I create a new controller, it still doesn't work.

Bug prevalence

Every time.

GitHub hash of the SDK that was being used

5a21d17fd2bb0a48f4a356937f4741f6c9dc7975

Platform

android

Platform Version(s)

No response

Type

Platform Issue

Anything else?

2023-08-14 15:35:11.093 CTL D IO thread stopping 2023-08-14 15:35:11.094 CTL D IO thread ending 2023-08-14 15:35:11.095 CTL D Shutting down the commissioner 2023-08-14 15:35:11.095 CTL D Stopping commissioning discovery over DNS-SD 2023-08-14 15:35:11.095 CTL D Shutting down the controller 2023-08-14 15:35:11.095 IN D Expiring all sessions for fabric 0x3!! 2023-08-14 15:35:11.095 IN D SecureSession[0xb40000782912ca88]: MarkForEviction Type:2 LSID:38680 2023-08-14 15:35:11.095 SC D SecureSession[0xb40000782912ca88]: Moving from state 'kActive' --> 'kPendingEviction' 2023-08-14 15:35:11.095 IN D SecureSession[0xb40000782912ca88]: Released - Type:2 LSID:38680 2023-08-14 15:35:11.095 FP D Forgetting fabric 0x3 2023-08-14 15:35:11.095 TS D Pending Last Known Good Time: 2023-07-25T14:40:26 2023-08-14 15:35:11.095 TOO D KVS: Getting key g/lkgt 2023-08-14 15:35:11.095 TS D Previous Last Known Good Time: 2023-07-25T14:40:26 2023-08-14 15:35:11.095 TS D Reverted Last Known Good Time to previous value 2023-08-14 15:35:11.095 CTL D newDeviceController() called 2023-08-14 15:35:11.096 CTL D AllocateNew nodeId value: 112233 2023-08-14 15:35:11.096 CTL D Stopping commissioning discovery over DNS-SD 2023-08-14 15:35:11.096 CTL D Setting attestation nonce to random value 2023-08-14 15:35:11.096 CTL D Setting CSR nonce to random value 2023-08-14 15:35:11.096 CTL D Setting attestation nonce to random value 2023-08-14 15:35:11.096 CTL D Setting CSR nonce to random value 2023-08-14 15:35:11.096 CTL D Setting attestation nonce from parameters 2023-08-14 15:35:11.096 CTL D Setting CSR nonce from parameters 2023-08-14 15:35:11.096 TOO D KVS: Getting key AndroidDeviceControllerKey 2023-08-14 15:35:11.096 CTL D No existing credentials provided: generating ephemeral local NOC chain with OperationalCredentialsIssuer 2023-08-14 15:35:11.101 TOO D KVS: Getting key AndroidCARootCert1 2023-08-14 15:35:11.101 CTL D Generating NOC 2023-08-14 15:35:11.106 CTL E Device Controller Factory already initialized... 2023-08-14 15:35:11.106 CTL D Intermediate CA is not needed 2023-08-14 15:35:11.106 TOO D KVS: Getting key f/4/r 2023-08-14 15:35:11.106 KeyValueStoreManager D Key 'f/4/r' not found in shared preferences 2023-08-14 15:35:11.107 TOO D KVS: Getting key f/4/n 2023-08-14 15:35:11.107 KeyValueStoreManager D Key 'f/4/n' not found in shared preferences 2023-08-14 15:35:11.107 TOO D KVS: Getting key f/4/i 2023-08-14 15:35:11.107 KeyValueStoreManager D Key 'f/4/i' not found in shared preferences 2023-08-14 15:35:11.107 FP D Validating NOC chain 2023-08-14 15:35:11.111 FP D NOC chain validation successful 2023-08-14 15:35:11.111 FP D Added new fabric at index: 0x4 2023-08-14 15:35:11.111 FP D Assigned compressed fabric ID: 0xADFCFFDEA07135D0, node ID: 0x000000000001B669 2023-08-14 15:35:11.111 TS D Last Known Good Time: 2023-07-25T14:40:26 2023-08-14 15:35:11.111 TS D New proposed Last Known Good Time: 2021-06-10T00:00:00 2023-08-14 15:35:11.111 TS D Retaining current Last Known Good Time 2023-08-14 15:35:11.111 TOO D KVS: Getting key g/sri 2023-08-14 15:35:11.111 TOO D KVS: Setting key g/fs/c 2023-08-14 15:35:11.112 TOO D KVS: Setting key f/4/m 2023-08-14 15:35:11.112 FP D Metadata for Fabric 0x4 persisted to storage. 2023-08-14 15:35:11.112 TOO D KVS: Setting key f/4/n 2023-08-14 15:35:11.112 TOO D KVS: Deleting key f/4/i 2023-08-14 15:35:11.112 TOO D KVS: Setting key f/4/r 2023-08-14 15:35:11.112 TS D Committing Last Known Good Time to storage: 2023-07-25T14:40:26 2023-08-14 15:35:11.112 TOO D KVS: Setting key g/lkgt 2023-08-14 15:35:11.112 TOO D KVS: Setting key g/fidx 2023-08-14 15:35:11.112 TOO D KVS: Deleting key g/fs/c 2023-08-14 15:35:11.112 CTL D Joined the fabric at index 4. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: ADFCFFDEA07135D0) 2023-08-14 15:35:11.112 CTL D Missing DeviceAttestationVerifier configuration at DeviceCommissioner init: using global default, consider passing one in CommissionerInitParams. 2023-08-14 15:35:11.112 CTL D Setting up group data for Fabric Index 4 with Compressed Fabric ID: 2023-08-14 15:35:11.112 SPT D 0xad, 0xfc, 0xff, 0xde, 0xa0, 0x71, 0x35, 0xd0, 2023-08-14 15:35:11.112 TOO D KVS: Getting key f/4/g 2023-08-14 15:35:11.112 KeyValueStoreManager D Key 'f/4/g' not found in shared preferences 2023-08-14 15:35:11.112 TOO D KVS: Setting key f/4/k/0 2023-08-14 15:35:11.112 TOO D KVS: Getting key g/gfl 2023-08-14 15:35:11.112 TOO D KVS: Getting key f/3/g 2023-08-14 15:35:11.112 TOO D KVS: Getting key f/2/g 2023-08-14 15:35:11.112 TOO D KVS: Getting key f/1/g 2023-08-14 15:35:11.112 TOO D KVS: Setting key g/gfl 2023-08-14 15:35:11.112 TOO D KVS: Setting key f/4/g 2023-08-14 15:35:11.113 CTL D setAttestationTrustStoreDelegate() called 2023-08-14 15:35:11.114 CTL D IO thread starting 2023-08-14 15:35:16.295 CTL D newDeviceController() called 2023-08-14 15:35:16.295 CTL D AllocateNew nodeId value: 112233 2023-08-14 15:35:16.295 CTL D Stopping commissioning discovery over DNS-SD 2023-08-14 15:35:16.295 CTL D Setting attestation nonce to random value 2023-08-14 15:35:16.295 CTL D Setting CSR nonce to random value 2023-08-14 15:35:16.296 CTL D Setting attestation nonce to random value 2023-08-14 15:35:16.296 CTL D Setting CSR nonce to random value 2023-08-14 15:35:16.296 CTL D Setting attestation nonce from parameters 2023-08-14 15:35:16.296 CTL D Setting CSR nonce from parameters 2023-08-14 15:35:16.296 TOO D KVS: Getting key AndroidDeviceControllerKey 2023-08-14 15:35:16.296 CTL D No existing credentials provided: generating ephemeral local NOC chain with OperationalCredentialsIssuer 2023-08-14 15:35:16.299 TOO D KVS: Getting key AndroidCARootCert1 2023-08-14 15:35:16.299 CTL D Generating NOC 2023-08-14 15:35:16.302 CTL E Device Controller Factory already initialized... 2023-08-14 15:35:16.302 CTL D Intermediate CA is not needed 2023-08-14 15:35:16.302 TOO D KVS: Getting key f/4/r 2023-08-14 15:35:16.302 TOO D KVS: Getting key f/4/r 2023-08-14 15:35:16.302 TOO D KVS: Getting key f/4/n 2023-08-14 15:35:16.302 TOO D KVS: Getting key f/4/r 2023-08-14 15:35:16.303 FP D Validating NOC chain 2023-08-14 15:35:16.306 FP D NOC chain validation successful 2023-08-14 15:35:16.306 FP D Updated fabric at index: 0x4, Node ID: 0x000000000001B669 2023-08-14 15:35:16.306 TS D Last Known Good Time: 2023-07-25T14:40:26 2023-08-14 15:35:16.306 TS D New proposed Last Known Good Time: 2021-06-10T00:00:00 2023-08-14 15:35:16.306 TS D Retaining current Last Known Good Time 2023-08-14 15:35:16.306 TOO D KVS: Getting key g/sri 2023-08-14 15:35:16.306 TOO D KVS: Setting key g/fs/c 2023-08-14 15:35:16.306 TOO D KVS: Setting key f/4/m 2023-08-14 15:35:16.307 FP D Metadata for Fabric 0x4 persisted to storage. 2023-08-14 15:35:16.307 TOO D KVS: Setting key f/4/n 2023-08-14 15:35:16.307 TOO D KVS: Deleting key f/4/i 2023-08-14 15:35:16.307 TS D Committing Last Known Good Time to storage: 2023-07-25T14:40:26 2023-08-14 15:35:16.307 TOO D KVS: Setting key g/lkgt 2023-08-14 15:35:16.307 TOO D KVS: Deleting key g/fs/c 2023-08-14 15:35:16.307 CTL D Joined the fabric at index 4. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: ADFCFFDEA07135D0) 2023-08-14 15:35:16.307 CTL D Missing DeviceAttestationVerifier configuration at DeviceCommissioner init: using global default, consider passing one in CommissionerInitParams. 2023-08-14 15:35:16.307 CTL D Setting up group data for Fabric Index 4 with Compressed Fabric ID: 2023-08-14 15:35:16.307 SPT D 0xad, 0xfc, 0xff, 0xde, 0xa0, 0x71, 0x35, 0xd0, 2023-08-14 15:35:16.307 TOO D KVS: Getting key f/4/g 2023-08-14 15:35:16.307 TOO D KVS: Getting key f/4/k/0 2023-08-14 15:35:16.307 TOO D KVS: Setting key f/4/k/0 2023-08-14 15:35:16.307 CTL D setAttestationTrustStoreDelegate() called 2023-08-14 15:35:16.307 CSM D FindOrEstablishSession: PeerId = [4:0000000000000002] 2023-08-14 15:35:16.307 CSM D FindOrEstablishSession: No existing OperationalSessionSetup instance found 2023-08-14 15:35:16.307 DIS D OperationalSessionSetup[4:0000000000000002]: State change 1 --> 2 2023-08-14 15:35:16.307 DIS D Resolving ADFCFFDEA07135D0:0000000000000002 ... 2023-08-14 15:35:16.307 NsdManager...ceResolver D resolve: Starting service resolution for 'ADFCFFDEA07135D0-0000000000000002' type '_matter._tcp' 2023-08-14 15:35:16.309 CTL D IO thread ending 2023-08-14 15:35:16.313 NsdService...ndResolver D Service discovery started. regType: _matter._tcp 2023-08-14 15:35:16.313 NsdService...ndResolver D onServiceFound: found service not a target for resolution, ignoring name: 966B1DD99B0C0318-00843F91638AB000, type: _matter._tcp., host: null, port: 0, txtRecord: 2023-08-14 15:35:16.314 NsdService...ndResolver D onServiceFound: found target service name: ADFCFFDEA07135D0-0000000000000002, type: _matter._tcp., host: null, port: 0, txtRecord: 2023-08-14 15:35:16.315 NsdService...ndResolver D onServiceFound: found service not a target for resolution, ignoring name: D5FBB42750BF2D47-000000004EAA4C72, type: _matter._tcp., host: null, port: 0, txtRecord: 2023-08-14 15:35:16.315 NsdService...ndResolver D onServiceFound: found service not a target for resolution, ignoring name: 2192EEA2F4515914-008F6158620FE800, type: _matter._tcp., host: null, port: 0, txtRecord: 2023-08-14 15:35:16.315 NsdService...ndResolver D onServiceFound: found service not a target for resolution, ignoring name: D5FBB42750BF2D47-00000000EC800DA8, type: _matter._tcp., host: null, port: 0, txtRecord: 2023-08-14 15:35:16.315 NsdService...ndResolver D onServiceFound: found service not a target for resolution, ignoring name: E4DEC2EA3A56170D-0091254267452000, type: _matter._tcp., host: null, port: 0, txtRecord: 2023-08-14 15:35:16.316 NsdService...ndResolver I Discovery stopped: _matter._tcp 2023-08-14 15:35:16.322 NsdService...ndResolver I Resolved service 'ADFCFFDEA07135D0-0000000000000002' to /192.168.2.119 2023-08-14 15:35:16.323 NetdClient D queryResolvNetidForUid nid:0, uid:10325, command.cmdId:15 2023-08-14 15:35:16.325 DIS D ----- entry [0] : T 1 2023-08-14 15:35:16.325 DIS D Node ID resolved for ADFCFFDEA07135D0:0000000000000002 2023-08-14 15:35:16.325 DIS D Hostname: 192.168.2.119 2023-08-14 15:35:16.325 DIS D IP Address #1: 192.168.2.119 2023-08-14 15:35:16.325 DIS D Port: 5540 2023-08-14 15:35:16.325 DIS D Mrp Interval idle: not present 2023-08-14 15:35:16.325 DIS D Mrp Interval active: not present 2023-08-14 15:35:16.325 DIS D TCP Supported: 1 2023-08-14 15:35:16.325 DIS D Lookup clearing interface for non LL address 2023-08-14 15:35:16.325 DIS D UDP:192.168.2.119:5540: new best score: 2 2023-08-14 15:35:16.326 DIS D Checking node lookup status after 18 ms 2023-08-14 15:35:16.326 DIS D Keeping DNSSD lookup active

TheWalkingDead2 commented 1 year ago

I think this is an issue with Multiple Initializations of DeviceControllerFactory in Android

Single Initialization in iOS: In iOS, the running status of DeviceControllerFactory is indirectly determined through the isRunning method. As a result, the init method of DeviceControllerFactory is called only once. Therefore, there is no need for DeviceControllerFactory to execute a shutdown. img_v2_3e21fa7d-b411-44e4-b05c-6c8948ba39fg

Multiple Initializations in Android: In contrast, in the Android environment, each time a new controller is generated, DeviceControllerFactory is initialized once again. This behavior is causing the “Device Controller Factory already initialized...” warning message to be displayed. img_v2_dcf2b60d-4539-4ded-b2da-04c92477f87g

Potential Solutions: To resolve this issue, one approach could be to add logic within the init method to prevent multiple initializations of DeviceControllerFactory. Alternatively, executing a shutdown for the factory before initializing it again could be another solution. img_v2_b0c199c0-3fd2-4440-a450-f13851e8f89g

However, we are not familiar with the underlying details of the Matter stack, and we are concerned that making such changes might introduce other unforeseen issues. Hence, we are raising this issue for your attention and action. Request: