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.44k stars 1.99k forks source link

SVE1 Darwin Automation Tool: Open Commissioning window in ECM not generating Manual Code randomly #20662

Closed Garik098 closed 2 years ago

Garik098 commented 2 years ago

SHA - caf62f709e0a0fdf41b0d3a1652cc26bc46a960a

In the ECM test cases of CADMIN, sometimes when we open the commissioning window, it is showing success response for opening commissioning window part but is giving an error while generating the new Manual Code for the next commissioner to use to provision.

Note: Observing this issue randomly. Saw it four times while running through all the CADMIN test cases.

Below is the log for the same, ``` shyam@shyams-MacBook-Pro debug % ./darwin-framework-tool pairing open-commissioning-window 1 1 300 1000 3840 --commissioner-name alpha objc[4817]: Class MTRErrorHolder is implemented in both /Users/shyam/sve/connectedhomeip/examples/darwin-framework-tool/out/debug/macos_framework_output/Matter.framework/Versions/A/Matter (0x10510cef0) and /Users/shyam/sve/connectedhomeip/examples/darwin-framework-tool/out/debug/./darwin-framework-tool (0x1038f3e50). One of the two will be used. Which one is undefined. objc[4817]: Class BleConnection is implemented in both /Users/shyam/sve/connectedhomeip/examples/darwin-framework-tool/out/debug/macos_framework_output/Matter.framework/Versions/A/Matter (0x10510d328) and /Users/shyam/sve/connectedhomeip/examples/darwin-framework-tool/out/debug/./darwin-framework-tool (0x1038f3f40). One of the two will be used. Which one is undefined. objc[4817]: Class UUIDHelper is implemented in both /Users/shyam/sve/connectedhomeip/examples/darwin-framework-tool/out/debug/macos_framework_output/Matter.framework/Versions/A/Matter (0x10510d3a0) and /Users/shyam/sve/connectedhomeip/examples/darwin-framework-tool/out/debug/./darwin-framework-tool (0x1038f3fb8). One of the two will be used. Which one is undefined. [1657664324799] [4817:199081] CHIP: [TOO] Running Command [1657664324800] [4817:199081] CHIP: [DMG] AccessControl: initializing [1657664324800] [4817:199081] CHIP: [DL] _Init [1657664324801] [4817:199081] CHIP: [IN] UDP::Init bind&listen port=5541 [1657664324801] [4817:199081] CHIP: [IN] UDP::Init bound to port=5541 [1657664324801] [4817:199081] CHIP: [IN] UDP::Init bind&listen port=5541 [1657664324801] [4817:199081] CHIP: [IN] UDP::Init bound to port=5541 [1657664324801] [4817:199081] CHIP: [IN] BLEBase::Init - setting/overriding transport [1657664324801] [4817:199081] CHIP: [IN] TransportMgr initialized [1657664324801] [4817:199081] CHIP: [FP] Initializing FabricTable from persistent storage 2022-07-12 15:18:44.801 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/lkgt 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/lkgt, value {length = 8, bytes = 0x15260087d85e2a18} [1657664324804] [4817:199081] CHIP: [TS] Last Known Good Time: 2022-07-11T12:48:07 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/fidx 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/fidx, value {length = 14, bytes = 0x1524000436010401040204031818} 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/n 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/n, value {length = 258, bytes = 0x15300101 01240201 37032714 3067df8a ... 74497bf2 47cd7d18 } 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/r 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/r, value {length = 251, bytes = 0x15300101 00240201 37032714 3067df8a ... 6e847978 72e57718 } 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/m 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324804] [4817:199081] CHIP: [FP] Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x244EA62AE8692CC3, FabricId 0x0000000000000001, NodeId 0x6D40E8B39C5958B8, VendorId 0xFFF1 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/n 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/n, value {length = 258, bytes = 0x15300101 01240201 37032714 cef86fdf ... a0b38016 b5d72618 } 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/r 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/r, value {length = 251, bytes = 0x15300101 00240201 37032714 cef86fdf ... 262280db 63d92618 } 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/m 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324804] [4817:199081] CHIP: [FP] Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x6806DF83AE4F8BB7, FabricId 0x0000000000000002, NodeId 0x7A5B349C507DDAB1, VendorId 0xFFF1 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/n 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/n, value {length = 258, bytes = 0x15300101 01240201 37032714 e146d973 ... 13f94462 9bd77618 } 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/r 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/r, value {length = 251, bytes = 0x15300101 00240201 37032714 e146d973 ... 320190dc 10c5d018 } 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/m 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324804] [4817:199081] CHIP: [FP] Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x9FB726CEE5C3FF2C, FabricId 0x0000000000000003, NodeId 0x39CC07393D9F29A6, VendorId 0xFFF1 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/fs/c 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/fs/c, value (null) 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/gcc 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/gcc, value {length = 4, bytes = 0x98ab0200} 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/gdc 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/gdc, value {length = 4, bytes = 0x98ab0200} 2022-07-12 15:18:44.804 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key g/gcc 2022-07-12 15:18:44.805 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key g/gdc [1657664324805] [4817:199081] CHIP: [IN] CASE Server enabling CASE session setups [1657664324805] [4817:199081] CHIP: [IN] SecureSession[0x7fc2d38dc2d0]: Allocated Type:2 LSID:5489 [1657664324805] [4817:199081] CHIP: [SC] Allocated SecureSession (0x7fc2d38dc2d0) - waiting for Sigma1 msg [1657664324805] [4817:199081] CHIP: [DIS] Updating services using commissioning mode 0 [1657664324805] [4817:199081] CHIP: [DL] Using wifi MAC for hostname [1657664324805] [4817:199081] CHIP: [DIS] Advertise operational node 244EA62AE8692CC3-6D40E8B39C5958B8 [1657664324805] [4817:199081] CHIP: [DL] Publishing service 244EA62AE8692CC3-6D40E8B39C5958B8 on port 5541 with type: _matter._tcp,_I244EA62AE8692CC3 on interface id: 0 [1657664324806] [4817:199081] CHIP: [DL] Using wifi MAC for hostname [1657664324806] [4817:199081] CHIP: [DIS] Advertise operational node 6806DF83AE4F8BB7-7A5B349C507DDAB1 [1657664324806] [4817:199081] CHIP: [DL] Publishing service 6806DF83AE4F8BB7-7A5B349C507DDAB1 on port 5541 with type: _matter._tcp,_I6806DF83AE4F8BB7 on interface id: 0 [1657664324806] [4817:199081] CHIP: [DL] Using wifi MAC for hostname [1657664324806] [4817:199081] CHIP: [DIS] Advertise operational node 9FB726CEE5C3FF2C-39CC07393D9F29A6 [1657664324806] [4817:199081] CHIP: [DL] Publishing service 9FB726CEE5C3FF2C-39CC07393D9F29A6 on port 5541 with type: _matter._tcp,_I9FB726CEE5C3FF2C on interface id: 0 [1657664324806] [4817:199081] CHIP: [CTL] System State Initialized... [1657664324806] [4817:199085] CHIP: [DL] _OnPlatformEvent [1657664324806] [4817:199085] CHIP: [DIS] Updating services using commissioning mode 0 [1657664324806] [4817:199085] CHIP: [DL] Using wifi MAC for hostname [1657664324806] [4817:199085] CHIP: [DIS] Advertise operational node 244EA62AE8692CC3-6D40E8B39C5958B8 [1657664324806] [4817:199085] CHIP: [DL] Publishing service 244EA62AE8692CC3-6D40E8B39C5958B8 on port 5541 with type: _matter._tcp,_I244EA62AE8692CC3 on interface id: 0 [1657664324807] [4817:199085] CHIP: [DL] Using wifi MAC for hostname [1657664324807] [4817:199085] CHIP: [DIS] Advertise operational node 6806DF83AE4F8BB7-7A5B349C507DDAB1 [1657664324807] [4817:199085] CHIP: [DL] Publishing service 6806DF83AE4F8BB7-7A5B349C507DDAB1 on port 5541 with type: _matter._tcp,_I6806DF83AE4F8BB7 on interface id: 0 [1657664324807] [4817:199085] CHIP: [DL] Using wifi MAC for hostname [1657664324807] [4817:199085] CHIP: [DIS] Advertise operational node 9FB726CEE5C3FF2C-39CC07393D9F29A6 [1657664324807] [4817:199085] CHIP: [DL] Publishing service 9FB726CEE5C3FF2C-39CC07393D9F29A6 on port 5541 with type: _matter._tcp,_I9FB726CEE5C3FF2C on interface id: 0 2022-07-12 15:18:44.807 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: ChipToolOpCredsCAKey, value {length = 97, bytes = 0x043a5a7d 05ef324b b19c93de de91ec12 ... bcbb127d 2109cf1c } 2022-07-12 15:18:44.807 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: ChipToolOpCredsIPK, value {length = 16, bytes = 0x2a63852f0240cccfa584d062c608a5ef} [1657664324808] [4817:199081] CHIP: [FP] Initializing FabricTable from persistent storage 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/lkgt 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/lkgt, value {length = 8, bytes = 0x15260087d85e2a18} [1657664324808] [4817:199081] CHIP: [TS] Last Known Good Time: 2022-07-11T12:48:07 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/fidx 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/fidx, value {length = 14, bytes = 0x1524000436010401040204031818} 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/n 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/n, value {length = 258, bytes = 0x15300101 01240201 37032714 3067df8a ... 74497bf2 47cd7d18 } 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/r 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/r, value {length = 251, bytes = 0x15300101 00240201 37032714 3067df8a ... 6e847978 72e57718 } 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/m 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324808] [4817:199081] CHIP: [FP] Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x244EA62AE8692CC3, FabricId 0x0000000000000001, NodeId 0x6D40E8B39C5958B8, VendorId 0xFFF1 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/n 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/n, value {length = 258, bytes = 0x15300101 01240201 37032714 cef86fdf ... a0b38016 b5d72618 } 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/r 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/r, value {length = 251, bytes = 0x15300101 00240201 37032714 cef86fdf ... 262280db 63d92618 } 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/m 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324808] [4817:199081] CHIP: [FP] Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x6806DF83AE4F8BB7, FabricId 0x0000000000000002, NodeId 0x7A5B349C507DDAB1, VendorId 0xFFF1 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/n 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/n, value {length = 258, bytes = 0x15300101 01240201 37032714 e146d973 ... 13f94462 9bd77618 } 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/r 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/r, value {length = 251, bytes = 0x15300101 00240201 37032714 e146d973 ... 320190dc 10c5d018 } 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/m 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324808] [4817:199081] CHIP: [FP] Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x9FB726CEE5C3FF2C, FabricId 0x0000000000000003, NodeId 0x39CC07393D9F29A6, VendorId 0xFFF1 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/fs/c 2022-07-12 15:18:44.808 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/fs/c, value (null) 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/n 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/n, value {length = 258, bytes = 0x15300101 01240201 37032714 3067df8a ... 74497bf2 47cd7d18 } 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/o 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/o, value {length = 105, bytes = 0x15240001 30016104 809975eb 803cd78d ... c311c5bf ba945a18 } 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/i 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/i, value (null) 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/n 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/n, value {length = 258, bytes = 0x15300101 01240201 37032714 3067df8a ... 74497bf2 47cd7d18 } 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/r 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/r, value {length = 251, bytes = 0x15300101 00240201 37032714 3067df8a ... 6e847978 72e57718 } 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/o 2022-07-12 15:18:44.810 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/o, value {length = 105, bytes = 0x15240001 30016104 809975eb 803cd78d ... c311c5bf ba945a18 } [1657664324810] [4817:199081] CHIP: [CTL] Stopping commissioning discovery over DNS-SD [1657664324810] [4817:199081] CHIP: [CTL] Setting attestation nonce to random value [1657664324810] [4817:199081] CHIP: [CTL] Setting CSR nonce to random value [1657664324810] [4817:199081] CHIP: [CTL] Intermediate CA is not needed 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/o 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/o, value {length = 105, bytes = 0x15240001 30016104 809975eb 803cd78d ... c311c5bf ba945a18 } 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/o 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/o, value {length = 105, bytes = 0x15240001 30016104 809975eb 803cd78d ... c311c5bf ba945a18 } 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/r 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/r, value {length = 251, bytes = 0x15300101 00240201 37032714 3067df8a ... 6e847978 72e57718 } 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/r 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/r, value {length = 251, bytes = 0x15300101 00240201 37032714 3067df8a ... 6e847978 72e57718 } 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/n 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/n, value {length = 258, bytes = 0x15300101 01240201 37032714 3067df8a ... 74497bf2 47cd7d18 } 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/r 2022-07-12 15:18:44.811 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/r, value {length = 251, bytes = 0x15300101 00240201 37032714 3067df8a ... 6e847978 72e57718 } [1657664324811] [4817:199081] CHIP: [FP] Validating NOC chain [1657664324817] [4817:199081] CHIP: [FP] NOC chain validation successful 2022-07-12 15:18:44.817 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/o 2022-07-12 15:18:44.817 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/o, value {length = 105, bytes = 0x15240001 30016104 809975eb 803cd78d ... c311c5bf ba945a18 } [1657664324817] [4817:199081] CHIP: [FP] Updated fabric at index: 0x1, Node ID: 0x6D40E8B39C5958B8 [1657664324817] [4817:199081] CHIP: [TS] Last Known Good Time: 2022-07-11T12:48:07 [1657664324817] [4817:199081] CHIP: [TS] New proposed Last Known Good Time: 2022-07-11T12:48:07 [1657664324817] [4817:199081] CHIP: [TS] Retaining current Last Known Good Time 2022-07-12 15:18:44.817 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/sri 2022-07-12 15:18:44.818 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/sri, value {length = 10, bytes = 0x16152401012402011818} 2022-07-12 15:18:44.818 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/s/0000000000000001 2022-07-12 15:18:44.818 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/s/0000000000000001, value {length = 71, bytes = 0x15300310 c4f34657 8de49dc0 b994121b ... 00000000 00000018 } 2022-07-12 15:18:44.818 darwin-framework-tool[4817:199081] PersistentStorageDelegate Delete Key: g/s/xPNGV43kncC5lBIb+5z2tw== 2022-07-12 15:18:44.818 darwin-framework-tool[4817:199081] PersistentStorageDelegate Delete Key: f/1/s/0000000000000001 2022-07-12 15:18:44.818 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key g/sri 2022-07-12 15:18:44.819 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/o 2022-07-12 15:18:44.819 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/o, value {length = 105, bytes = 0x15240001 30016104 809975eb 803cd78d ... c311c5bf ba945a18 } 2022-07-12 15:18:44.819 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key g/fs/c 2022-07-12 15:18:44.819 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key f/1/m [1657664324819] [4817:199081] CHIP: [FP] Metadata for Fabric 0x1 persisted to storage. 2022-07-12 15:18:44.819 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/o 2022-07-12 15:18:44.819 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/o, value {length = 105, bytes = 0x15240001 30016104 809975eb 803cd78d ... c311c5bf ba945a18 } 2022-07-12 15:18:44.819 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key f/1/n 2022-07-12 15:18:44.819 darwin-framework-tool[4817:199081] PersistentStorageDelegate Delete Key: f/1/i [1657664324819] [4817:199081] CHIP: [TS] Committing Last Known Good Time to storage: 2022-07-11T12:48:07 2022-07-12 15:18:44.819 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key g/lkgt 2022-07-12 15:18:44.819 darwin-framework-tool[4817:199081] PersistentStorageDelegate Delete Key: g/fs/c [1657664324819] [4817:199081] CHIP: [CTL] Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000 [1657664324819] [4817:199081] CHIP: [FP] Initializing FabricTable from persistent storage 2022-07-12 15:18:44.819 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/lkgt 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/lkgt, value {length = 8, bytes = 0x15260087d85e2a18} [1657664324820] [4817:199081] CHIP: [TS] Last Known Good Time: 2022-07-11T12:48:07 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/fidx 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/fidx, value {length = 14, bytes = 0x1524000436010401040204031818} 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/n 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/n, value {length = 258, bytes = 0x15300101 01240201 37032714 3067df8a ... 74497bf2 47cd7d18 } 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/r 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/r, value {length = 251, bytes = 0x15300101 00240201 37032714 3067df8a ... 6e847978 72e57718 } 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/m 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324820] [4817:199081] CHIP: [FP] Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x244EA62AE8692CC3, FabricId 0x0000000000000001, NodeId 0x6D40E8B39C5958B8, VendorId 0xFFF1 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/n 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/n, value {length = 258, bytes = 0x15300101 01240201 37032714 cef86fdf ... a0b38016 b5d72618 } 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/r 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/r, value {length = 251, bytes = 0x15300101 00240201 37032714 cef86fdf ... 262280db 63d92618 } 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/m 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324820] [4817:199081] CHIP: [FP] Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x6806DF83AE4F8BB7, FabricId 0x0000000000000002, NodeId 0x7A5B349C507DDAB1, VendorId 0xFFF1 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/n 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/n, value {length = 258, bytes = 0x15300101 01240201 37032714 e146d973 ... 13f94462 9bd77618 } 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/r 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/r, value {length = 251, bytes = 0x15300101 00240201 37032714 e146d973 ... 320190dc 10c5d018 } 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/m 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324820] [4817:199081] CHIP: [FP] Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x9FB726CEE5C3FF2C, FabricId 0x0000000000000003, NodeId 0x39CC07393D9F29A6, VendorId 0xFFF1 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/fs/c 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/fs/c, value (null) 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/n 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/n, value {length = 258, bytes = 0x15300101 01240201 37032714 cef86fdf ... a0b38016 b5d72618 } 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/o 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/o, value {length = 105, bytes = 0x15240001 30016104 517b6664 e722eb00 ... ffcce7d0 07ec2e18 } 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/i 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/i, value (null) 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/n 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/n, value {length = 258, bytes = 0x15300101 01240201 37032714 cef86fdf ... a0b38016 b5d72618 } 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/r 2022-07-12 15:18:44.820 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/r, value {length = 251, bytes = 0x15300101 00240201 37032714 cef86fdf ... 262280db 63d92618 } 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/o 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/o, value {length = 105, bytes = 0x15240001 30016104 517b6664 e722eb00 ... ffcce7d0 07ec2e18 } [1657664324821] [4817:199081] CHIP: [CTL] Stopping commissioning discovery over DNS-SD [1657664324821] [4817:199081] CHIP: [CTL] Setting attestation nonce to random value [1657664324821] [4817:199081] CHIP: [CTL] Setting CSR nonce to random value [1657664324821] [4817:199081] CHIP: [CTL] Intermediate CA is not needed 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/o 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/o, value {length = 105, bytes = 0x15240001 30016104 517b6664 e722eb00 ... ffcce7d0 07ec2e18 } 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/o 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/o, value {length = 105, bytes = 0x15240001 30016104 517b6664 e722eb00 ... ffcce7d0 07ec2e18 } 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/r 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/r, value {length = 251, bytes = 0x15300101 00240201 37032714 cef86fdf ... 262280db 63d92618 } 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/r 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/r, value {length = 251, bytes = 0x15300101 00240201 37032714 cef86fdf ... 262280db 63d92618 } 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/n 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/n, value {length = 258, bytes = 0x15300101 01240201 37032714 cef86fdf ... a0b38016 b5d72618 } 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/r 2022-07-12 15:18:44.821 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/r, value {length = 251, bytes = 0x15300101 00240201 37032714 cef86fdf ... 262280db 63d92618 } [1657664324821] [4817:199081] CHIP: [FP] Validating NOC chain [1657664324828] [4817:199081] CHIP: [FP] NOC chain validation successful 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/o 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/o, value {length = 105, bytes = 0x15240001 30016104 517b6664 e722eb00 ... ffcce7d0 07ec2e18 } [1657664324828] [4817:199081] CHIP: [FP] Updated fabric at index: 0x2, Node ID: 0x7A5B349C507DDAB1 [1657664324828] [4817:199081] CHIP: [TS] Last Known Good Time: 2022-07-11T12:48:07 [1657664324828] [4817:199081] CHIP: [TS] New proposed Last Known Good Time: 2022-07-11T12:48:07 [1657664324828] [4817:199081] CHIP: [TS] Retaining current Last Known Good Time 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/sri 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/sri, value {length = 2, bytes = 0x1618} 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/o 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/o, value {length = 105, bytes = 0x15240001 30016104 517b6664 e722eb00 ... ffcce7d0 07ec2e18 } 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key g/fs/c 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key f/2/m [1657664324828] [4817:199081] CHIP: [FP] Metadata for Fabric 0x2 persisted to storage. 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/o 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/o, value {length = 105, bytes = 0x15240001 30016104 517b6664 e722eb00 ... ffcce7d0 07ec2e18 } 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key f/2/n 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] PersistentStorageDelegate Delete Key: f/2/i [1657664324828] [4817:199081] CHIP: [TS] Committing Last Known Good Time to storage: 2022-07-11T12:48:07 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key g/lkgt 2022-07-12 15:18:44.828 darwin-framework-tool[4817:199081] PersistentStorageDelegate Delete Key: g/fs/c [1657664324829] [4817:199081] CHIP: [CTL] Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000 [1657664324829] [4817:199081] CHIP: [FP] Initializing FabricTable from persistent storage 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/lkgt 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/lkgt, value {length = 8, bytes = 0x15260087d85e2a18} [1657664324829] [4817:199081] CHIP: [TS] Last Known Good Time: 2022-07-11T12:48:07 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/fidx 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/fidx, value {length = 14, bytes = 0x1524000436010401040204031818} 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/n 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/n, value {length = 258, bytes = 0x15300101 01240201 37032714 3067df8a ... 74497bf2 47cd7d18 } 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/r 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/r, value {length = 251, bytes = 0x15300101 00240201 37032714 3067df8a ... 6e847978 72e57718 } 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/1/m 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/1/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324829] [4817:199081] CHIP: [FP] Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x244EA62AE8692CC3, FabricId 0x0000000000000001, NodeId 0x6D40E8B39C5958B8, VendorId 0xFFF1 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/n 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/n, value {length = 258, bytes = 0x15300101 01240201 37032714 cef86fdf ... a0b38016 b5d72618 } 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/r 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/r, value {length = 251, bytes = 0x15300101 00240201 37032714 cef86fdf ... 262280db 63d92618 } 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/2/m 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/2/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324829] [4817:199081] CHIP: [FP] Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x6806DF83AE4F8BB7, FabricId 0x0000000000000002, NodeId 0x7A5B349C507DDAB1, VendorId 0xFFF1 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/n 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/n, value {length = 258, bytes = 0x15300101 01240201 37032714 e146d973 ... 13f94462 9bd77618 } 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/r 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/r, value {length = 251, bytes = 0x15300101 00240201 37032714 e146d973 ... 320190dc 10c5d018 } 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/m 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/m, value {length = 9, bytes = 0x152500f1ff2c010018} [1657664324829] [4817:199081] CHIP: [FP] Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x9FB726CEE5C3FF2C, FabricId 0x0000000000000003, NodeId 0x39CC07393D9F29A6, VendorId 0xFFF1 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/fs/c 2022-07-12 15:18:44.829 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/fs/c, value (null) 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/n 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/n, value {length = 258, bytes = 0x15300101 01240201 37032714 e146d973 ... 13f94462 9bd77618 } 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/o 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/o, value {length = 105, bytes = 0x15240001 30016104 8d5e65f0 a98b1657 ... 51e888f4 c2933918 } 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/i 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/i, value (null) 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/n 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/n, value {length = 258, bytes = 0x15300101 01240201 37032714 e146d973 ... 13f94462 9bd77618 } 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/r 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/r, value {length = 251, bytes = 0x15300101 00240201 37032714 e146d973 ... 320190dc 10c5d018 } 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/o 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/o, value {length = 105, bytes = 0x15240001 30016104 8d5e65f0 a98b1657 ... 51e888f4 c2933918 } [1657664324830] [4817:199081] CHIP: [CTL] Stopping commissioning discovery over DNS-SD [1657664324830] [4817:199081] CHIP: [CTL] Setting attestation nonce to random value [1657664324830] [4817:199081] CHIP: [CTL] Setting CSR nonce to random value [1657664324830] [4817:199081] CHIP: [CTL] Intermediate CA is not needed 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/o 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/o, value {length = 105, bytes = 0x15240001 30016104 8d5e65f0 a98b1657 ... 51e888f4 c2933918 } 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/o 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/o, value {length = 105, bytes = 0x15240001 30016104 8d5e65f0 a98b1657 ... 51e888f4 c2933918 } 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/r 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/r, value {length = 251, bytes = 0x15300101 00240201 37032714 e146d973 ... 320190dc 10c5d018 } 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/r 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/r, value {length = 251, bytes = 0x15300101 00240201 37032714 e146d973 ... 320190dc 10c5d018 } 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/n 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/n, value {length = 258, bytes = 0x15300101 01240201 37032714 e146d973 ... 13f94462 9bd77618 } 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/r 2022-07-12 15:18:44.830 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/r, value {length = 251, bytes = 0x15300101 00240201 37032714 e146d973 ... 320190dc 10c5d018 } [1657664324830] [4817:199081] CHIP: [FP] Validating NOC chain [1657664324837] [4817:199081] CHIP: [FP] NOC chain validation successful 2022-07-12 15:18:44.837 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/o 2022-07-12 15:18:44.837 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/o, value {length = 105, bytes = 0x15240001 30016104 8d5e65f0 a98b1657 ... 51e888f4 c2933918 } [1657664324837] [4817:199081] CHIP: [FP] Updated fabric at index: 0x3, Node ID: 0x39CC07393D9F29A6 [1657664324837] [4817:199081] CHIP: [TS] Last Known Good Time: 2022-07-11T12:48:07 [1657664324837] [4817:199081] CHIP: [TS] New proposed Last Known Good Time: 2022-07-11T12:48:07 [1657664324837] [4817:199081] CHIP: [TS] Retaining current Last Known Good Time 2022-07-12 15:18:44.837 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/sri 2022-07-12 15:18:44.837 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/sri, value {length = 2, bytes = 0x1618} 2022-07-12 15:18:44.837 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/o 2022-07-12 15:18:44.837 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/o, value {length = 105, bytes = 0x15240001 30016104 8d5e65f0 a98b1657 ... 51e888f4 c2933918 } 2022-07-12 15:18:44.837 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key g/fs/c 2022-07-12 15:18:44.837 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key f/3/m [1657664324837] [4817:199081] CHIP: [FP] Metadata for Fabric 0x3 persisted to storage. 2022-07-12 15:18:44.838 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: f/3/o 2022-07-12 15:18:44.838 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: f/3/o, value {length = 105, bytes = 0x15240001 30016104 8d5e65f0 a98b1657 ... 51e888f4 c2933918 } 2022-07-12 15:18:44.838 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key f/3/n 2022-07-12 15:18:44.838 darwin-framework-tool[4817:199081] PersistentStorageDelegate Delete Key: f/3/i [1657664324838] [4817:199081] CHIP: [TS] Committing Last Known Good Time to storage: 2022-07-11T12:48:07 2022-07-12 15:18:44.838 darwin-framework-tool[4817:199081] PersistentStorageDelegate Set Key g/lkgt 2022-07-12 15:18:44.838 darwin-framework-tool[4817:199081] PersistentStorageDelegate Delete Key: g/fs/c [1657664324838] [4817:199081] CHIP: [CTL] Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000 [1657664324851] [4817:199081] CHIP: [CSM] FindOrEstablishSession: PeerId = 244EA62AE8692CC3:0000000000000001 [1657664324852] [4817:199081] CHIP: [CSM] FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1657664324852] [4817:199081] CHIP: [CTL] OperationalDeviceProxy[244EA62AE8692CC3:0000000000000001]: State change 1 --> 2 [1657664324852] [4817:199081] CHIP: [DIS] Resolving 244EA62AE8692CC3:0000000000000001 ... [1657664324852] [4817:199081] CHIP: [DL] Resolve type=_matter._tcp name=244EA62AE8692CC3-0000000000000001 interface=0 [1657664324852] [4817:199081] CHIP: [SPL] Failed encoding invalid payload [1657664324852] [4817:199085] CHIP: [DL] Mdns : OnNewInterface hostname:E45F012EEC9F0000.local. fullname:244EA62AE8692CC3-0000000000000001._matter._tcp.local. interface: 8 [1657664324853] [4817:199085] CHIP: [DL] Mdns: OnNewAddress interface: 8 ip:fd96:352e:e7bb:0:e65f:1ff:fe2e:ec9f [1657664324853] [4817:199085] CHIP: [DL] Mdns: OnNewAddress interface: 8 ip:fe80::e65f:1ff:fe2e:ec9f [1657664324853] [4817:199085] CHIP: [DIS] Node ID resolved for 244EA62AE8692CC3:0000000000000001 [1657664324853] [4817:199085] CHIP: [DIS] Hostname: E45F012EEC9F0000 [1657664324853] [4817:199085] CHIP: [DIS] IP Address #1: fd96:352e:e7bb:0:e65f:1ff:fe2e:ec9f [1657664324853] [4817:199085] CHIP: [DIS] IP Address #2: fe80::e65f:1ff:fe2e:ec9f [1657664324853] [4817:199085] CHIP: [DIS] Port: 5540 [1657664324853] [4817:199085] CHIP: [DIS] Mrp Interval idle: 5000 ms [1657664324853] [4817:199085] CHIP: [DIS] Mrp Interval active: 300 ms [1657664324853] [4817:199085] CHIP: [DIS] Lookup clearing interface for non LL address [1657664324853] [4817:199085] CHIP: [DIS] UDP:[fd96:352e:e7bb:0:e65f:1ff:fe2e:ec9f%en0]:5540: new best score: 6 [1657664324853] [4817:199085] CHIP: [DIS] UDP:[fe80::e65f:1ff:fe2e:ec9f%en0]:5540: score has not improved: 3 [1657664324853] [4817:199085] CHIP: [DIS] Checking node lookup status after 2 ms [1657664324853] [4817:199085] CHIP: [DIS] Keeping DNSSD lookup active [1657664325052] [4817:199085] CHIP: [DIS] Checking node lookup status after 201 ms [1657664325052] [4817:199085] CHIP: [CTL] Updating device address to UDP:[fd96:352e:e7bb:0:e65f:1ff:fe2e:ec9f]:5540 while in state 2 [1657664325052] [4817:199085] CHIP: [CTL] OperationalDeviceProxy[244EA62AE8692CC3:0000000000000001]: State change 2 --> 3 [1657664325052] [4817:199085] CHIP: [IN] SecureSession[0x7fc2c2407970]: Allocated Type:2 LSID:5490 [1657664325052] [4817:199085] CHIP: [SC] Initiating session on local FabricIndex 1 from 0x6D40E8B39C5958B8 -> 0x0000000000000001 [1657664325055] [4817:199085] CHIP: [SC] Including MRP parameters 2022-07-12 15:18:45.055 darwin-framework-tool[4817:199085] PersistentStorageDelegate Sync Get Value for Key: f/1/s/0000000000000001 2022-07-12 15:18:45.055 darwin-framework-tool[4817:199085] CHIPPersistentStorageDelegate Get Value for Key: f/1/s/0000000000000001, value (null) [1657664325055] [4817:199085] CHIP: [IN] Prepared unauthenticated message 0x7fc2c2407de8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 49039i with MessageCounter:208117927. [1657664325055] [4817:199085] CHIP: [IN] Sending unauthenticated msg 0x7fc2c2407de8 with MessageCounter:208117927 to 0x0000000000000000 at monotonic time: 0000000000C63F28 msec [1657664325055] [4817:199085] CHIP: [SC] Sent Sigma1 msg [1657664325055] [4817:199085] CHIP: [CTL] OperationalDeviceProxy[244EA62AE8692CC3:0000000000000001]: State change 3 --> 4 [1657664325060] [4817:199086] CHIP: [EM] Received message of type 0x31 with protocolId (0, 0) and MessageCounter:10058168 on exchange 49039i [1657664325061] [4817:199086] CHIP: [EM] Found matching exchange: 49039i, Delegate: 0x7fc2c24076f0 [1657664325061] [4817:199086] CHIP: [EM] Rxd Ack; Removing MessageCounter:208117927 from Retrans Table on exchange 49039i [1657664325061] [4817:199086] CHIP: [EM] Removed CHIP MessageCounter:208117927 from RetransTable on exchange 49039i [1657664325061] [4817:199086] CHIP: [SC] Received Sigma2 msg [1657664325061] [4817:199086] CHIP: [SC] Peer assigned session session ID 40205 2022-07-12 15:18:45.063 darwin-framework-tool[4817:199086] PersistentStorageDelegate Sync Get Value for Key: f/1/r 2022-07-12 15:18:45.063 darwin-framework-tool[4817:199086] CHIPPersistentStorageDelegate Get Value for Key: f/1/r, value {length = 251, bytes = 0x15300101 00240201 37032714 3067df8a ... 6e847978 72e57718 } [1657664325074] [4817:199086] CHIP: [SC] Found MRP parameters in the message [1657664325074] [4817:199086] CHIP: [SC] Sending Sigma3 2022-07-12 15:18:45.074 darwin-framework-tool[4817:199086] PersistentStorageDelegate Sync Get Value for Key: f/1/i 2022-07-12 15:18:45.074 darwin-framework-tool[4817:199086] CHIPPersistentStorageDelegate Get Value for Key: f/1/i, value (null) 2022-07-12 15:18:45.074 darwin-framework-tool[4817:199086] PersistentStorageDelegate Sync Get Value for Key: f/1/n 2022-07-12 15:18:45.074 darwin-framework-tool[4817:199086] CHIPPersistentStorageDelegate Get Value for Key: f/1/n, value {length = 258, bytes = 0x15300101 01240201 37032714 3067df8a ... 74497bf2 47cd7d18 } 2022-07-12 15:18:45.074 darwin-framework-tool[4817:199086] PersistentStorageDelegate Sync Get Value for Key: f/1/n 2022-07-12 15:18:45.074 darwin-framework-tool[4817:199086] CHIPPersistentStorageDelegate Get Value for Key: f/1/n, value {length = 258, bytes = 0x15300101 01240201 37032714 3067df8a ... 74497bf2 47cd7d18 } 2022-07-12 15:18:45.074 darwin-framework-tool[4817:199086] PersistentStorageDelegate Sync Get Value for Key: f/1/o 2022-07-12 15:18:45.074 darwin-framework-tool[4817:199086] CHIPPersistentStorageDelegate Get Value for Key: f/1/o, value {length = 105, bytes = 0x15240001 30016104 809975eb 803cd78d ... c311c5bf ba945a18 } [1657664325077] [4817:199086] CHIP: [EM] Piggybacking Ack for MessageCounter:10058168 on exchange: 49039i [1657664325077] [4817:199086] CHIP: [IN] Prepared unauthenticated message 0x7fc2b2407348 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 49039i with MessageCounter:208117928. [1657664325077] [4817:199086] CHIP: [IN] Sending unauthenticated msg 0x7fc2b2407348 with MessageCounter:208117928 to 0x0000000000000000 at monotonic time: 0000000000C63F3D msec [1657664325077] [4817:199086] CHIP: [SC] Sent Sigma3 msg [1657664325089] [4817:199086] CHIP: [EM] Received message of type 0x40 with protocolId (0, 0) and MessageCounter:10058169 on exchange 49039i [1657664325089] [4817:199086] CHIP: [EM] Found matching exchange: 49039i, Delegate: 0x7fc2c24076f0 [1657664325089] [4817:199086] CHIP: [EM] Rxd Ack; Removing MessageCounter:208117928 from Retrans Table on exchange 49039i [1657664325089] [4817:199086] CHIP: [EM] Removed CHIP MessageCounter:208117928 from RetransTable on exchange 49039i [1657664325089] [4817:199086] CHIP: [SC] Success status report received. Session was established 2022-07-12 15:18:45.089 darwin-framework-tool[4817:199086] PersistentStorageDelegate Sync Get Value for Key: g/sri 2022-07-12 15:18:45.089 darwin-framework-tool[4817:199086] CHIPPersistentStorageDelegate Get Value for Key: g/sri, value {length = 2, bytes = 0x1618} 2022-07-12 15:18:45.089 darwin-framework-tool[4817:199086] PersistentStorageDelegate Set Key f/1/s/0000000000000001 2022-07-12 15:18:45.089 darwin-framework-tool[4817:199086] PersistentStorageDelegate Set Key g/s/bX2kbXn5V5WKuavGijeKew== 2022-07-12 15:18:45.090 darwin-framework-tool[4817:199086] PersistentStorageDelegate Set Key g/sri [1657664325090] [4817:199086] CHIP: [SC] SecureSession[0x7fc2c2407970]: Moving from state 'kEstablishing' --> 'kActive' [1657664325090] [4817:199086] CHIP: [IN] SecureSession[0x7fc2c2407970]: Activated - Type:2 LSID:5490 [1657664325090] [4817:199086] CHIP: [IN] New secure session activated for device <0000000000000001, 1>, LSID:5490 PSID:40205! [1657664325090] [4817:199086] CHIP: [CTL] OperationalDeviceProxy[244EA62AE8692CC3:0000000000000001]: State change 4 --> 5 [1657664325090] [4817:199086] CHIP: [CTL] OpenCommissioningWindow for device ID 1 [1657664325090] [4817:199086] CHIP: [DMG] ICR moving to [AddingComm] [1657664325090] [4817:199086] CHIP: [DMG] ICR moving to [AddedComma] [1657664325090] [4817:199086] CHIP: [IN] Prepared secure message 0x7fc2d258f338 to 0x0000000000000001 (1) of type 0xa and protocolId (0, 1) on exchange 49040i with MessageCounter:176217008. [1657664325090] [4817:199086] CHIP: [IN] Sending encrypted msg 0x7fc2d258f338 with MessageCounter:176217008 to 0x0000000000000001 (1) at monotonic time: 0000000000C63F4B msec [1657664325090] [4817:199086] CHIP: [DMG] ICR moving to [AwaitingTi] [1657664325090] [4817:199086] CHIP: [EM] Sending Standalone Ack for MessageCounter:10058169 on exchange 49039i [1657664325090] [4817:199086] CHIP: [IN] Prepared unauthenticated message 0x700003b10490 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 49039i with MessageCounter:208117929. [1657664325090] [4817:199086] CHIP: [IN] Sending unauthenticated msg 0x700003b10490 with MessageCounter:208117929 to 0x0000000000000000 at monotonic time: 0000000000C63F4B msec [1657664325090] [4817:199086] CHIP: [EM] Flushed pending ack for MessageCounter:10058169 on exchange 49039i [1657664325094] [4817:199086] CHIP: [EM] Received message of type 0x1 with protocolId (0, 1) and MessageCounter:191568767 on exchange 49040i [1657664325094] [4817:199086] CHIP: [EM] Found matching exchange: 49040i, Delegate: 0x7fc2d38dc790 [1657664325094] [4817:199086] CHIP: [EM] Rxd Ack; Removing MessageCounter:176217008 from Retrans Table on exchange 49040i [1657664325094] [4817:199086] CHIP: [EM] Removed CHIP MessageCounter:176217008 from RetransTable on exchange 49040i [1657664325094] [4817:199086] CHIP: [DMG] StatusResponseMessage = [1657664325094] [4817:199086] CHIP: [DMG] { [1657664325094] [4817:199086] CHIP: [DMG] Status = 0x00 (SUCCESS), [1657664325094] [4817:199086] CHIP: [DMG] InteractionModelRevision = 1 [1657664325094] [4817:199086] CHIP: [DMG] } [1657664325094] [4817:199086] CHIP: [IM] Received status response, status is 0x00 (SUCCESS) [1657664325094] [4817:199086] CHIP: [EM] Piggybacking Ack for MessageCounter:191568767 on exchange: 49040i [1657664325094] [4817:199086] CHIP: [IN] Prepared secure message 0x7fc2d2750db8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 49040i with MessageCounter:176217009. [1657664325094] [4817:199086] CHIP: [IN] Sending encrypted msg 0x7fc2d2750db8 with MessageCounter:176217009 to 0x0000000000000001 (1) at monotonic time: 0000000000C63F4E msec [1657664325094] [4817:199086] CHIP: [DMG] ICR moving to [CommandSen] [1657664325241] [4817:199086] CHIP: [EM] Received message of type 0x9 with protocolId (0, 1) and MessageCounter:191568768 on exchange 49040i [1657664325241] [4817:199086] CHIP: [EM] Found matching exchange: 49040i, Delegate: 0x7fc2d38dc790 [1657664325241] [4817:199086] CHIP: [EM] Rxd Ack; Removing MessageCounter:176217009 from Retrans Table on exchange 49040i [1657664325241] [4817:199086] CHIP: [EM] Removed CHIP MessageCounter:176217009 from RetransTable on exchange 49040i [1657664325241] [4817:199086] CHIP: [DMG] ICR moving to [ResponseRe] [1657664325241] [4817:199086] CHIP: [DMG] InvokeResponseMessage = [1657664325241] [4817:199086] CHIP: [DMG] { [1657664325241] [4817:199086] CHIP: [DMG] suppressResponse = false, [1657664325241] [4817:199086] CHIP: [DMG] InvokeResponseIBs = [1657664325241] [4817:199086] CHIP: [DMG] [ [1657664325241] [4817:199086] CHIP: [DMG] InvokeResponseIB = [1657664325241] [4817:199086] CHIP: [DMG] { [1657664325241] [4817:199086] CHIP: [DMG] CommandStatusIB = [1657664325241] [4817:199086] CHIP: [DMG] { [1657664325241] [4817:199086] CHIP: [DMG] CommandPathIB = [1657664325241] [4817:199086] CHIP: [DMG] { [1657664325241] [4817:199086] CHIP: [DMG] EndpointId = 0x0, [1657664325241] [4817:199086] CHIP: [DMG] ClusterId = 0x3c, [1657664325241] [4817:199086] CHIP: [DMG] CommandId = 0x0, [1657664325241] [4817:199086] CHIP: [DMG] }, [1657664325241] [4817:199086] CHIP: [DMG] [1657664325241] [4817:199086] CHIP: [DMG] StatusIB = [1657664325241] [4817:199086] CHIP: [DMG] { [1657664325241] [4817:199086] CHIP: [DMG] status = 0x00 (SUCCESS), [1657664325241] [4817:199086] CHIP: [DMG] }, [1657664325241] [4817:199086] CHIP: [DMG] [1657664325241] [4817:199086] CHIP: [DMG] }, [1657664325241] [4817:199086] CHIP: [DMG] [1657664325241] [4817:199086] CHIP: [DMG] }, [1657664325241] [4817:199086] CHIP: [DMG] [1657664325241] [4817:199086] CHIP: [DMG] ], [1657664325241] [4817:199086] CHIP: [DMG] [1657664325241] [4817:199086] CHIP: [DMG] InteractionModelRevision = 1 [1657664325241] [4817:199086] CHIP: [DMG] }, [1657664325241] [4817:199086] CHIP: [DMG] Received Command Response Status for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000 Status=0x0 [1657664325241] [4817:199086] CHIP: [CTL] Successfully opened pairing window on the device [1657664325241] [4817:199086] CHIP: [SPL] Failed encoding invalid payload [1657664325241] [4817:199086] CHIP: [CTL] Unable to generate manual code for setup payload: ../../../../../../../../src/setup_payload/ManualSetupPayloadGenerator.cpp:115: CHIP Error 0x0000002F: Invalid argument [1657664325241] [4817:199086] CHIP: [CTL] Unable to generate QR code for setup payload: ../../../../../../../../src/setup_payload/QRCodeSetupPayloadGenerator.cpp:283: CHIP Error 0x0000002F: Invalid argument [1657664325241] [4817:199086] CHIP: [DMG] ICR moving to [AwaitingDe] [1657664325241] [4817:199086] CHIP: [EM] Sending Standalone Ack for MessageCounter:191568768 on exchange 49040i [1657664325241] [4817:199086] CHIP: [IN] Prepared secure message 0x700003b104b0 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 49040i with MessageCounter:176217010. [1657664325241] [4817:199086] CHIP: [IN] Sending encrypted msg 0x700003b104b0 with MessageCounter:176217010 to 0x0000000000000001 (1) at monotonic time: 0000000000C63FE1 msec [1657664325241] [4817:199086] CHIP: [EM] Flushed pending ack for MessageCounter:191568768 on exchange 49040i [1657664325538] [4817:199085] CHIP: [DL] Mdns: OnRegister name: 244EA62AE8692CC3-6D40E8B39C5958B8, type: _matter._tcp., domain: local., flags: 2 [1657664325538] [4817:199085] CHIP: [DIS] mDNS service published: _matter._tcp [1657664325538] [4817:199085] CHIP: [DL] Mdns: OnRegister name: 6806DF83AE4F8BB7-7A5B349C507DDAB1, type: _matter._tcp., domain: local., flags: 2 [1657664325538] [4817:199085] CHIP: [DIS] mDNS service published: _matter._tcp [1657664325538] [4817:199085] CHIP: [DL] Mdns: OnRegister name: 9FB726CEE5C3FF2C-39CC07393D9F29A6, type: _matter._tcp., domain: local., flags: 2 [1657664325538] [4817:199085] CHIP: [DIS] mDNS service published: _matter._tcp [1657664342853] [4817:199081] CHIP: [TOO] Shutting down controller [1657664342853] [4817:199081] CHIP: [CTL] Shutting down the commissioner [1657664342853] [4817:199081] CHIP: [CTL] Shutting down the controller [1657664342853] [4817:199081] CHIP: [IN] Expiring all sessions for fabric 0x1!! [1657664342853] [4817:199081] CHIP: [IN] SecureSession[0x7fc2c2407970]: MarkForEviction Type:2 LSID:5490 [1657664342853] [4817:199081] CHIP: [SC] SecureSession[0x7fc2c2407970]: Moving from state 'kActive' --> 'kPendingEviction' [1657664342853] [4817:199081] CHIP: [IN] SecureSession[0x7fc2c2407970]: Released - Type:2 LSID:5490 [1657664342853] [4817:199081] CHIP: [FP] Forgetting fabric 0x1 [1657664342853] [4817:199081] CHIP: [TS] Pending Last Known Good Time: 2022-07-11T12:48:07 2022-07-12 15:19:02.853 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/lkgt 2022-07-12 15:19:02.853 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/lkgt, value {length = 8, bytes = 0x15260087d85e2a18} [1657664342853] [4817:199081] CHIP: [TS] Previous Last Known Good Time: 2022-07-11T12:48:07 [1657664342853] [4817:199081] CHIP: [TS] Reverted Last Known Good Time to previous value [1657664342853] [4817:199081] CHIP: [CTL] Shutting down the commissioner [1657664342853] [4817:199081] CHIP: [CTL] Shutting down the controller [1657664342853] [4817:199081] CHIP: [IN] Expiring all sessions for fabric 0x2!! [1657664342853] [4817:199081] CHIP: [FP] Forgetting fabric 0x2 [1657664342853] [4817:199081] CHIP: [TS] Pending Last Known Good Time: 2022-07-11T12:48:07 2022-07-12 15:19:02.853 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/lkgt 2022-07-12 15:19:02.854 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/lkgt, value {length = 8, bytes = 0x15260087d85e2a18} [1657664342854] [4817:199081] CHIP: [TS] Previous Last Known Good Time: 2022-07-11T12:48:07 [1657664342854] [4817:199081] CHIP: [TS] Reverted Last Known Good Time to previous value [1657664342854] [4817:199081] CHIP: [CTL] Shutting down the commissioner [1657664342854] [4817:199081] CHIP: [CTL] Shutting down the controller [1657664342854] [4817:199081] CHIP: [IN] Expiring all sessions for fabric 0x3!! [1657664342854] [4817:199081] CHIP: [FP] Forgetting fabric 0x3 [1657664342854] [4817:199081] CHIP: [TS] Pending Last Known Good Time: 2022-07-11T12:48:07 2022-07-12 15:19:02.854 darwin-framework-tool[4817:199081] PersistentStorageDelegate Sync Get Value for Key: g/lkgt 2022-07-12 15:19:02.854 darwin-framework-tool[4817:199081] CHIPPersistentStorageDelegate Get Value for Key: g/lkgt, value {length = 8, bytes = 0x15260087d85e2a18} [1657664342854] [4817:199081] CHIP: [TS] Previous Last Known Good Time: 2022-07-11T12:48:07 [1657664342854] [4817:199081] CHIP: [TS] Reverted Last Known Good Time to previous value [1657664342854] [4817:199081] CHIP: [CTL] Shutting down the System State, this will teardown the CHIP Stack [1657664342854] [4817:199081] CHIP: [IN] SecureSession[0x7fc2d38dc2d0]: Released - Type:2 LSID:5489 [1657664342854] [4817:199081] CHIP: [DMG] IM WH moving to [Uninitialized] [1657664342854] [4817:199081] CHIP: [DMG] IM WH moving to [Uninitialized] [1657664342854] [4817:199081] CHIP: [DMG] IM WH moving to [Uninitialized] [1657664342854] [4817:199081] CHIP: [DMG] IM WH moving to [Uninitialized] [1657664342854] [4817:199081] CHIP: [DMG] All ReadHandler-s are clean, clear GlobalDirtySet [1657664342854] [4817:199081] CHIP: [BLE] CancelConnection [1657664342854] [4817:199081] CHIP: [DL] Inet Layer shutdown [1657664342854] [4817:199081] CHIP: [DL] BLE shutdown [1657664342854] [4817:199081] CHIP: [DL] System Layer shutdown ```
bzbarsky-apple commented 2 years ago

Relevant log bits:

[1657664325241] [4817:199086] CHIP: [CTL] Unable to generate manual code for setup payload: ../../../../../../../../src/setup_payload/ManualSetupPayloadGenerator.cpp:115: CHIP Error 0x0000002F: Invalid argument
[1657664325241] [4817:199086] CHIP: [CTL] Unable to generate QR code for setup payload: ../../../../../../../../src/setup_payload/QRCodeSetupPayloadGenerator.cpp:283: CHIP Error 0x0000002F: Invalid argument

The code in question does the following:

  1. Generate a random 32-bit number.
  2. Pass it to an API as a passcode value to use.
  3. That API uses the low 27 bits of that number.

That means we get values in the range 0 to 2^27 - 1, or 0 to 134217728.

But valid passcodes have to be 8 digits, and there are some excluded values. The important part for the purposes of this issue is that the value range (not counting the small number of excluded things) is 1 to 99999998.

99999998/134217728 = 0.745 so the above procedure has a 25%+ chance of producing an invalid (out of range) passcode.

I think we need to make two changes here:

  1. Ensure that we don't try to open a commissioning window with an invalid passcode.
  2. Provide a simpler way to generate a valid random passcode.