text:
[ESP32] cannot find Discriminator: 3840 on all-cluster-app via chip-device-ctrl(python)

Problem

expected behavior

ble-scan on chip-device-ctrl can find discriminator:3840.

chip-device-ctrl > ble-scan
2022-07-08 09:28:10,520 ChipBLEMgr   INFO     scanning started
2022-07-08 09:28:11,044 ChipBLEMgr   INFO     Name            = None
2022-07-08 09:28:11,045 ChipBLEMgr   INFO     ID              = 12a18652-bbd8-41e5-ac1c-35067f35d0cb
2022-07-08 09:28:11,047 ChipBLEMgr   INFO     RSSI            = -59
2022-07-08 09:28:11,048 ChipBLEMgr   INFO     Address         = 7E:1E:1E:79:4F:F7
2022-07-08 09:28:11,053 ChipBLEMgr   INFO     Pairing State   = 0
2022-07-08 09:28:11,053 ChipBLEMgr   INFO     Discriminator   = 3840
2022-07-08 09:28:11,054 ChipBLEMgr   INFO     Vendor Id       = 9050
2022-07-08 09:28:11,054 ChipBLEMgr   INFO     Product Id      = 17729
2022-07-08 09:28:11,077 ChipBLEMgr   INFO     Adv UUID        = 0000fff6-0000-1000-8000-00805f9b34fb
2022-07-08 09:28:11,082 ChipBLEMgr   INFO     Adv Data        = 00000f5a234145
2022-07-08 09:28:11,083 ChipBLEMgr   INFO
2022-07-08 09:28:21,198 ChipBLEMgr   INFO     scanning stopped
chip-device-ctrl >

actual behavior

ble-scan on master branch cannot detect discriminator.
I guess the ESP32 for all-cluster-app on master branch did not set Discriminator, Vendor Id and Product Id.
chip-device-ctrl on master branch does not work.
therefore, I use chip-device-ctrl  on test_event_4_2021_07_06.

steps to reproduce

system configuration
Board : ESP32-C3-DevKitM-1

connectedhomeip version

$ git log -1
commit 126f6b2915fc26ee17342e1dc80f96f031938a6c (HEAD -> master, origin/master, origin/HEAD)
Author: Stefan Agner <stefan@agner.ch>
Date:   Wed Jul 6 15:04:20 2022 +0200

   [python] Move string encoding to ChipDeviceCtrl.py (#20306)

   * Encode strings in ChipDeviceCtrl.py

   * Fix Python tests

* ESP-IDF version

$ git log -1
commit 1329b19fe494500aeb79d19b27cfd99b40c37aec (HEAD, tag: v4.4.1)
Author: Michael (XIAO Xufeng) <xiaoxufeng@espressif.com>
Date:   Sat Apr 16 09:43:14 2022 +0800

    versions: Update version to 4.4.1

screenshots, images, logs, etc.

chip-device-ctrl > ble-scan
2022-07-08 08:08:54,980 ChipBLEMgr   INFO     scanning started
2022-07-08 08:08:55,225 ChipBLEMgr   INFO     Name            = None
2022-07-08 08:08:55,226 ChipBLEMgr   INFO     ID              = 4ab2afe7-351f-4c98-a74b-a9c565ca9dba
2022-07-08 08:08:55,228 ChipBLEMgr   INFO     RSSI            = -32
2022-07-08 08:08:55,230 ChipBLEMgr   INFO     Address         = C8:E8:F5:91:36:6F
2022-07-08 08:08:55,238 ChipBLEMgr   INFO     Adv UUID        = 0000fff6-0000-1000-8000-00805f9b34fb
2022-07-08 08:08:55,240 ChipBLEMgr   INFO     Adv Data        = 00000ff1ff008000
2022-07-08 08:08:55,240 ChipBLEMgr   INFO
2022-07-08 08:09:05,171 ChipBLEMgr   INFO     scanning stopped
chip-device-ctrl >

Proposed Solution
<suggested fix, suggested enhancement>

2022-07-08 08:08:55,240 ChipBLEMgr INFO Adv Data = 00000ff1ff008000

HI @tatsutaigu The "Adv Data" that you see above has the discriminator: 0xF00 (3840), VID: 0xFFF1 as well as PID: 0x8001 in the format as required by the specification.

Hi, @dhrishi
Thank you for your reply.
I use chip-tool and it can find ESP32.
However, chip-tool was stopped as Aborted (core dumped).
Below is log.

$ ./out/debug/chip-tool pairing ble-wifi 12344321 $SSID $PASSWORD 20202021 3840
[1657513261.977971][3087:3087] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1657513261.978251][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_kvs-pGJSPA)
[1657513261.978420][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1657513261.978737][3087:3087] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1657513261.978846][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-nGbQjC)
[1657513261.978979][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1657513261.979053][3087:3087] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1657513261.979155][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_config.ini-QyrBpC)
[1657513261.979263][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini)
[1657513261.979332][3087:3087] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1657513261.979424][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-l8xuPE)
[1657513261.979534][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657513261.979726][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-Anil0D)
[1657513261.980209][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1657513261.980256][3087:3087] CHIP:DL: NVS set: chip-factory/unique-id = "7F10F63AFCD34573"
[1657513261.980385][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-FXoI0B)
[1657513261.980784][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1657513261.980824][3087:3087] CHIP:DL: NVS set: chip-factory/vendor-id = 65521 (0xFFF1)
[1657513261.980943][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-jRMkvC)
[1657513261.981332][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini)
[1657513261.981370][3087:3087] CHIP:DL: NVS set: chip-factory/product-id = 32769 (0x8001)
[1657513261.981486][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-yupNVA)
[1657513261.982013][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657513261.982063][3087:3087] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1)
[1657513261.982196][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-1KXfJA)
[1657513261.982611][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657513261.982654][3087:3087] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1657513261.982798][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-EOeABD)
[1657513261.983190][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657513261.983231][3087:3087] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0)
[1657513261.983348][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_config.ini-JpTygE)
[1657513261.983684][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini)
[1657513261.983722][3087:3087] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0)
[1657513261.983841][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_config.ini-dtoKqE)
[1657513261.984210][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini)
[1657513261.984248][3087:3087] CHIP:DL: NVS set: chip-config/location-capability = 2 (0x2)
[1657513261.984676][3087:3087] CHIP:DL: Failed to get Ethernet interface
[1657513261.984958][3087:3087] CHIP:DL: Failed to reset Ethernet statistic counts
[1657513261.985126][3087:3087] CHIP:DL: Got WiFi interface: wlp1s0
[1657513261.990147][3087:3087] CHIP:DL: Found the primary WiFi interface:wlp1s0
[1657513261.990253][3087:3087] CHIP:IN: UDP::Init bind&listen port=0
[1657513261.990327][3087:3087] CHIP:IN: UDP::Init bound to port=50764
[1657513261.990344][3087:3087] CHIP:IN: UDP::Init bind&listen port=0
[1657513261.990385][3087:3087] CHIP:IN: UDP::Init bound to port=34728
[1657513261.990399][3087:3087] CHIP:IN: BLEBase::Init - setting/overriding transport
[1657513261.990408][3087:3087] CHIP:IN: TransportMgr initialized
[1657513261.990431][3087:3087] CHIP:FP: Initializing FabricTable from persistent storage
[1657513261.990471][3087:3087] CHIP:TS: Last Known Good Time: [unknown]
[1657513261.990488][3087:3087] CHIP:TS: Setting Last Known Good Time to firmware build time 2022-07-07T00:10:25
[1657513261.994195][3087:3087] CHIP:ZCL: Using ZAP configuration...
[1657513261.994877][3087:3087] CHIP:CTL: System State Initialized...
[1657513261.994932][3087:3087] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657513261.994960][3087:3087] CHIP:CTL: Setting attestation nonce to random value
[1657513261.994993][3087:3087] CHIP:CTL: Setting CSR nonce to random value
[1657513261.995047][3087:3087] CHIP:IN: UDP::Init bind&listen port=5550
[1657513261.995092][3087:3087] CHIP:IN: UDP::Init bound to port=5550
[1657513261.995110][3087:3087] CHIP:IN: UDP::Init bind&listen port=5550
[1657513261.995146][3087:3087] CHIP:IN: UDP::Init bound to port=5550
[1657513261.995162][3087:3087] CHIP:IN: TransportMgr initialized
[1657513261.995232][3087:3087] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657513261.995255][3087:3087] CHIP:CTL: Setting attestation nonce to random value
[1657513261.995281][3087:3087] CHIP:CTL: Setting CSR nonce to random value
[1657513261.995643][3087:3087] CHIP:CTL: Couldn't get ExampleOpCredsCAKey from storage: ../../config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage
[1657513262.002986][3087:3087] CHIP:CTL: Couldn't get ExampleOpCredsICAKey from storage: ../../config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage
[1657513262.004272][3087:3087] CHIP:CTL: Generating RCAC
[1657513262.005250][3087:3087] CHIP:CTL: Generating ICAC
[1657513262.009142][3087:3087] CHIP:CTL: Generating NOC
[1657513262.010160][3087:3087] CHIP:FP: Validating NOC chain
[1657513262.016094][3087:3087] CHIP:FP: NOC chain validation successful
[1657513262.016352][3087:3087] CHIP:FP: Added new fabric at index: 0x1
[1657513262.016372][3087:3087] CHIP:FP: Assigned compressed fabric ID: 0xC514CBA34B4E423E, node ID: 0x000000000001B669
[1657513262.016395][3087:3087] CHIP:TS: Last Known Good Time: 2022-07-07T00:10:25
[1657513262.016411][3087:3087] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657513262.016422][3087:3087] CHIP:TS: Retaining current Last Known Good Time
[1657513262.018419][3087:3087] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1657513262.020280][3087:3087] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-07T00:10:25
[1657513262.025490][3087:3087] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1657513262.025562][3087:3087] CHIP:IN: UDP::Init bind&listen port=5550
[1657513262.025640][3087:3087] CHIP:IN: UDP::Init bound to port=5550
[1657513262.025661][3087:3087] CHIP:IN: UDP::Init bind&listen port=5550
[1657513262.025704][3087:3087] CHIP:IN: UDP::Init bound to port=5550
[1657513262.029920][3087:3087] CHIP:IN: TransportMgr initialized
[1657513262.030051][3087:3087] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657513262.030081][3087:3087] CHIP:CTL: Setting attestation nonce to random value
[1657513262.030119][3087:3087] CHIP:CTL: Setting CSR nonce to random value
[1657513262.031556][3087:3087] CHIP:CTL: Generating NOC
[1657513262.032390][3087:3087] CHIP:FP: Validating NOC chain
[1657513262.034706][3087:3087] CHIP:FP: NOC chain validation successful
[1657513262.034898][3087:3087] CHIP:FP: Added new fabric at index: 0x2
[1657513262.034916][3087:3087] CHIP:FP: Assigned compressed fabric ID: 0xE9F8A4A0812BB2F3, node ID: 0x000000000001B669
[1657513262.034933][3087:3087] CHIP:TS: Last Known Good Time: 2022-07-07T00:10:25
[1657513262.034948][3087:3087] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657513262.034957][3087:3087] CHIP:TS: Retaining current Last Known Good Time
[1657513262.036477][3087:3087] CHIP:FP: Metadata for Fabric 0x2 persisted to storage.
[1657513262.046791][3087:3087] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-07T00:10:25
[1657513262.048582][3087:3087] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000
[1657513262.048627][3087:3087] CHIP:IN: UDP::Init bind&listen port=5550
[1657513262.048694][3087:3087] CHIP:IN: UDP::Init bound to port=5550
[1657513262.048714][3087:3087] CHIP:IN: UDP::Init bind&listen port=5550
[1657513262.048757][3087:3087] CHIP:IN: UDP::Init bound to port=5550
[1657513262.048773][3087:3087] CHIP:IN: TransportMgr initialized
[1657513262.048870][3087:3087] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657513262.048900][3087:3087] CHIP:CTL: Setting attestation nonce to random value
[1657513262.048941][3087:3087] CHIP:CTL: Setting CSR nonce to random value
[1657513262.050367][3087:3087] CHIP:CTL: Generating NOC
[1657513262.051227][3087:3087] CHIP:FP: Validating NOC chain
[1657513262.053470][3087:3087] CHIP:FP: NOC chain validation successful
[1657513262.053659][3087:3087] CHIP:FP: Added new fabric at index: 0x3
[1657513262.053677][3087:3087] CHIP:FP: Assigned compressed fabric ID: 0x8EB7D3E2000C9D1D, node ID: 0x000000000001B669
[1657513262.053694][3087:3087] CHIP:TS: Last Known Good Time: 2022-07-07T00:10:25
[1657513262.053709][3087:3087] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657513262.057266][3087:3087] CHIP:TS: Retaining current Last Known Good Time
[1657513262.062620][3087:3087] CHIP:FP: Metadata for Fabric 0x3 persisted to storage.
[1657513262.064665][3087:3087] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-07T00:10:25
[1657513262.066679][3087:3087] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000
[1657513262.066728][3087:3087] CHIP:IN: UDP::Init bind&listen port=5550
[1657513262.066798][3087:3087] CHIP:IN: UDP::Init bound to port=5550
[1657513262.066819][3087:3087] CHIP:IN: UDP::Init bind&listen port=5550
[1657513262.066863][3087:3087] CHIP:IN: UDP::Init bound to port=5550
[1657513262.066880][3087:3087] CHIP:IN: TransportMgr initialized
[1657513262.202449][3087:3121] CHIP:DL: CHIP task running
[1657513262.202831][3087:3121] CHIP:IN: SecureSession[0x7f9ea8001a30]: Allocated Type:1 LSID:17126
[1657513262.202866][3087:3121] CHIP:SC: Assigned local session key ID 17126
[1657513262.202923][3087:3121] CHIP:SC: Including MRP parameters in PBKDF param request
[1657513262.202982][3087:3121] CHIP:IN: Prepared unauthenticated message 0x7f9eafffe3f0 to 0x0000000000000000 (0)  of type 0x20 and protocolId (0, 0) on exchange 16147i with MessageCounter:51773991.
[1657513262.203018][3087:3121] CHIP:IN: Sending unauthenticated msg 0x7f9eafffe3f0 with MessageCounter:51773991 to 0x0000000000000000 at monotonic time: 000000000004D018 msec
[1657513262.203042][3087:3121] CHIP:IN: Message appended to BLE send queue
[1657513262.203056][3087:3121] CHIP:SC: Sent PBKDF param request
[1657513262.203073][3087:3121] CHIP:CTL: Setting wifi credentials from parameters
[1657513262.203083][3087:3121] CHIP:CTL: Setting attestation nonce to random value
[1657513262.203104][3087:3121] CHIP:CTL: Setting CSR nonce to random value
[1657513262.203127][3087:3121] CHIP:CTL: Commission called for node ID 0x0000000000BC5C01
[1657513262.203676][3087:3116] CHIP:DL: TRACE: Bus acquired for name C-0c0f
[1657513262.205195][3087:3122] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1657513262.242085][3087:3121] CHIP:DL: PlatformBlueZInit init success
[1657513262.260430][3087:3116] CHIP:BLE: BLE removing known devices.
[1657513262.266782][3087:3116] CHIP:BLE: BLE initiating scan.
[1657513262.907484][3087:3121] CHIP:DL: Long dispatch time: 704 ms, for event type 2
[1657513262.946572][3087:3116] CHIP:BLE: Device 10:02:1D:9A:A0:40 does not look like a CHIP device.
[1657513262.986130][3087:3116] CHIP:BLE: New device scanned: F4:4E:1E:26:0B:32
[1657513262.986175][3087:3116] CHIP:BLE: Device discriminator match. Attempting to connect.
[1657513263.003717][3087:3116] CHIP:BLE: Scan complete notification without an active scan.
[1657513264.071405][3087:3116] CHIP:DL: ConnectDevice complete
[1657513264.993904][3087:3116] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_4E_1E_26_0B_32/service000a
[1657513264.993946][3087:3116] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_4E_1E_26_0B_32/service000a
[1657513264.993970][3087:3116] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_4E_1E_26_0B_32/service000a
[1657513264.993984][3087:3116] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_4E_1E_26_0B_32/service000a
[1657513264.993999][3087:3116] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_4E_1E_26_0B_32/service000a
[1657513264.994009][3087:3116] CHIP:DL: Char1 /org/bluez/hci0/dev_F4_4E_1E_26_0B_32/service000a
[1657513264.994025][3087:3116] CHIP:DL: New BLE connection 0x7f9eb4031140, device F4:4E:1E:26:0B:32, path /org/bluez/hci0/dev_F4_4E_1E_26_0B_32
[1657513264.994142][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1657513264.994190][3087:3121] CHIP:IN: BleConnectionComplete: endPoint 0x558090b44260
[1657513265.369874][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657513265.473050][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513265.473312][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1657513265.473337][3087:3121] CHIP:BLE: subscribe complete, ep = 0x558090b44260
[1657513265.473360][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513265.473380][3087:3121] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1657513265.473394][3087:3121] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1657513265.473403][3087:3121] CHIP:BLE: local and remote recv window size = 5
[1657513265.473496][3087:3121] CHIP:IN: BLE EndPoint 0x558090b44260 Connection Complete
[1657513265.569793][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657513265.624228][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513265.624564][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513265.624714][3087:3121] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:191441026 on exchange 16147i
[1657513265.624740][3087:3121] CHIP:EM: Found matching exchange: 16147i, Delegate: 0x7f9ea8000bb0
[1657513265.624770][3087:3121] CHIP:SC: Received PBKDF param response
[1657513265.624806][3087:3121] CHIP:SC: Peer assigned session ID 62731
[1657513265.624832][3087:3121] CHIP:SC: Found MRP parameters in the message
[1657513265.631360][3087:3121] CHIP:IN: Prepared unauthenticated message 0x7f9eafffdfe0 to 0x0000000000000000 (0)  of type 0x22 and protocolId (0, 0) on exchange 16147i with MessageCounter:51773992.
[1657513265.631404][3087:3121] CHIP:IN: Sending unauthenticated msg 0x7f9eafffdfe0 with MessageCounter:51773992 to 0x0000000000000000 at monotonic time: 000000000004DD7D msec
[1657513265.631487][3087:3121] CHIP:SC: Sent spake2p msg1
[1657513265.719458][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657513266.574201][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513266.574379][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513266.574544][3087:3121] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:191441027 on exchange 16147i
[1657513266.574583][3087:3121] CHIP:EM: Found matching exchange: 16147i, Delegate: 0x7f9ea8000bb0
[1657513266.574626][3087:3121] CHIP:SC: Received spake2p msg2
[1657513266.576914][3087:3121] CHIP:IN: Prepared unauthenticated message 0x7f9eafffe0e0 to 0x0000000000000000 (0)  of type 0x24 and protocolId (0, 0) on exchange 16147i with MessageCounter:51773993.
[1657513266.576967][3087:3121] CHIP:IN: Sending unauthenticated msg 0x7f9eafffe0e0 with MessageCounter:51773993 to 0x0000000000000000 at monotonic time: 000000000004E12E msec
[1657513266.577060][3087:3121] CHIP:SC: Sent spake2p msg3
[1657513266.669711][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657513266.721039][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513266.721203][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513266.721345][3087:3121] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:191441028 on exchange 16147i
[1657513266.721379][3087:3121] CHIP:EM: Found matching exchange: 16147i, Delegate: 0x7f9ea8000bb0
[1657513266.721474][3087:3121] CHIP:SC: SecureSession[0x7f9ea8001a30]: Moving from state 'kEstablishing' --> 'kActive'
[1657513266.721497][3087:3121] CHIP:IN: SecureSession[0x7f9ea8001a30]: Activated - Type:1 LSID:17126
[1657513266.721514][3087:3121] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:17126 PSID:62731!
[1657513266.721539][3087:3121] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1657513266.721556][3087:3121] CHIP:TOO: Pairing Success
[1657513266.721568][3087:3121] CHIP:TOO: PASE establishment successful
[1657513266.721584][3087:3121] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1657513266.721605][3087:3121] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1657513266.721620][3087:3121] CHIP:CTL: Sending request for commissioning information
[1657513266.721654][3087:3121] CHIP:DMG: SendReadRequest ReadClient[0x7f9eb4031840]: Sending Read Request
[1657513266.721838][3087:3121] CHIP:IN: Prepared secure message 0x7f9eafffd960 to 0xFFFFFFFB00000000 (0)  of type 0x2 and protocolId (0, 1) on exchange 16148i with MessageCounter:131943875.
[1657513266.721908][3087:3121] CHIP:IN: Sending encrypted msg 0x7f9eafffd960 with MessageCounter:131943875 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000004E1BF msec
[1657513266.722007][3087:3121] CHIP:DMG: MoveToState ReadClient[0x7f9eb4031840]: Moving to [AwaitingIn]
[1657513266.819522][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657513266.876853][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513266.877019][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513266.920861][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513266.921017][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513266.921153][3087:3121] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:20565486 on exchange 16148i
[1657513266.921186][3087:3121] CHIP:EM: Found matching exchange: 16148i, Delegate: 0x7f9eb4031840
[1657513266.921300][3087:3121] CHIP:DMG: ReportDataMessage =
[1657513266.921322][3087:3121] CHIP:DMG: {
[1657513266.921338][3087:3121] CHIP:DMG: 	AttributeReportIBs =
[1657513266.921361][3087:3121] CHIP:DMG: 	[
[1657513266.921377][3087:3121] CHIP:DMG: 		AttributeReportIB =
[1657513266.921405][3087:3121] CHIP:DMG: 		{
[1657513266.921422][3087:3121] CHIP:DMG: 			AttributeDataIB =
[1657513266.921440][3087:3121] CHIP:DMG: 			{
[1657513266.921461][3087:3121] CHIP:DMG: 				DataVersion = 0xed2c6352,
[1657513266.921478][3087:3121] CHIP:DMG: 				AttributePathIB =
[1657513266.921497][3087:3121] CHIP:DMG: 				{
[1657513266.921517][3087:3121] CHIP:DMG: 					Endpoint = 0x0,
[1657513266.921533][3087:3121] CHIP:DMG: 					Cluster = 0x31,
[1657513266.921553][3087:3121] CHIP:DMG: 					Attribute = 0x0000_0003,
[1657513266.921570][3087:3121] CHIP:DMG: 				}
[1657513266.921591][3087:3121] CHIP:DMG:
[1657513266.921612][3087:3121] CHIP:DMG: 				Data = 30,
[1657513266.921629][3087:3121] CHIP:DMG: 			},
[1657513266.921650][3087:3121] CHIP:DMG:
[1657513266.921665][3087:3121] CHIP:DMG: 		},
[1657513266.921696][3087:3121] CHIP:DMG:
[1657513266.921712][3087:3121] CHIP:DMG: 		AttributeReportIB =
[1657513266.921798][3087:3121] CHIP:DMG: 		{
[1657513266.921818][3087:3121] CHIP:DMG: 			AttributeDataIB =
[1657513266.921835][3087:3121] CHIP:DMG: 			{
[1657513266.921854][3087:3121] CHIP:DMG: 				DataVersion = 0xb24b860d,
[1657513266.921872][3087:3121] CHIP:DMG: 				AttributePathIB =
[1657513266.921889][3087:3121] CHIP:DMG: 				{
[1657513266.921908][3087:3121] CHIP:DMG: 					Endpoint = 0x0,
[1657513266.921928][3087:3121] CHIP:DMG: 					Cluster = 0x28,
[1657513266.921947][3087:3121] CHIP:DMG: 					Attribute = 0x0000_0004,
[1657513266.921964][3087:3121] CHIP:DMG: 				}
[1657513266.921985][3087:3121] CHIP:DMG:
[1657513266.922005][3087:3121] CHIP:DMG: 				Data = 32768,
[1657513266.922021][3087:3121] CHIP:DMG: 			},
[1657513266.922042][3087:3121] CHIP:DMG:
[1657513266.922057][3087:3121] CHIP:DMG: 		},
[1657513266.922086][3087:3121] CHIP:DMG:
[1657513266.922101][3087:3121] CHIP:DMG: 		AttributeReportIB =
[1657513266.922126][3087:3121] CHIP:DMG: 		{
[1657513266.922141][3087:3121] CHIP:DMG: 			AttributeDataIB =
[1657513266.922159][3087:3121] CHIP:DMG: 			{
[1657513266.922178][3087:3121] CHIP:DMG: 				DataVersion = 0xb24b860d,
[1657513266.922204][3087:3121] CHIP:DMG: 				AttributePathIB =
[1657513266.922222][3087:3121] CHIP:DMG: 				{
[1657513266.922242][3087:3121] CHIP:DMG: 					Endpoint = 0x0,
[1657513266.922261][3087:3121] CHIP:DMG: 					Cluster = 0x28,
[1657513266.922281][3087:3121] CHIP:DMG: 					Attribute = 0x0000_0002,
[1657513266.922297][3087:3121] CHIP:DMG: 				}
[1657513266.922317][3087:3121] CHIP:DMG:
[1657513266.922338][3087:3121] CHIP:DMG: 				Data = 65521,
[1657513266.922354][3087:3121] CHIP:DMG: 			},
[1657513266.922374][3087:3121] CHIP:DMG:
[1657513266.922389][3087:3121] CHIP:DMG: 		},
[1657513266.922415][3087:3121] CHIP:DMG:
[1657513266.922431][3087:3121] CHIP:DMG: 		AttributeReportIB =
[1657513266.922451][3087:3121] CHIP:DMG: 		{
[1657513266.922466][3087:3121] CHIP:DMG: 			AttributeDataIB =
[1657513266.922482][3087:3121] CHIP:DMG: 			{
[1657513266.922501][3087:3121] CHIP:DMG: 				DataVersion = 0xaf3e74b,
[1657513266.922518][3087:3121] CHIP:DMG: 				AttributePathIB =
[1657513266.922535][3087:3121] CHIP:DMG: 				{
[1657513266.922554][3087:3121] CHIP:DMG: 					Endpoint = 0x0,
[1657513266.922573][3087:3121] CHIP:DMG: 					Cluster = 0x30,
[1657513266.922593][3087:3121] CHIP:DMG: 					Attribute = 0x0000_0003,
[1657513266.922608][3087:3121] CHIP:DMG: 				}
[1657513266.922628][3087:3121] CHIP:DMG:
[1657513266.922648][3087:3121] CHIP:DMG: 				Data = 0,
[1657513266.922664][3087:3121] CHIP:DMG: 			},
[1657513266.922684][3087:3121] CHIP:DMG:
[1657513266.922699][3087:3121] CHIP:DMG: 		},
[1657513266.922727][3087:3121] CHIP:DMG:
[1657513266.922742][3087:3121] CHIP:DMG: 		AttributeReportIB =
[1657513266.922765][3087:3121] CHIP:DMG: 		{
[1657513266.922781][3087:3121] CHIP:DMG: 			AttributeDataIB =
[1657513266.922798][3087:3121] CHIP:DMG: 			{
[1657513266.922817][3087:3121] CHIP:DMG: 				DataVersion = 0xaf3e74b,
[1657513266.922835][3087:3121] CHIP:DMG: 				AttributePathIB =
[1657513266.922853][3087:3121] CHIP:DMG: 				{
[1657513266.922872][3087:3121] CHIP:DMG: 					Endpoint = 0x0,
[1657513266.922891][3087:3121] CHIP:DMG: 					Cluster = 0x30,
[1657513266.922911][3087:3121] CHIP:DMG: 					Attribute = 0x0000_0002,
[1657513266.922927][3087:3121] CHIP:DMG: 				}
[1657513266.922947][3087:3121] CHIP:DMG:
[1657513266.922966][3087:3121] CHIP:DMG: 				Data = 0,
[1657513266.922983][3087:3121] CHIP:DMG: 			},
[1657513266.923004][3087:3121] CHIP:DMG:
[1657513266.923019][3087:3121] CHIP:DMG: 		},
[1657513266.923049][3087:3121] CHIP:DMG:
[1657513266.923065][3087:3121] CHIP:DMG: 		AttributeReportIB =
[1657513266.923091][3087:3121] CHIP:DMG: 		{
[1657513266.923107][3087:3121] CHIP:DMG: 			AttributeDataIB =
[1657513266.923123][3087:3121] CHIP:DMG: 			{
[1657513266.923141][3087:3121] CHIP:DMG: 				DataVersion = 0xaf3e74b,
[1657513266.923159][3087:3121] CHIP:DMG: 				AttributePathIB =
[1657513266.923176][3087:3121] CHIP:DMG: 				{
[1657513266.923195][3087:3121] CHIP:DMG: 					Endpoint = 0x0,
[1657513266.923215][3087:3121] CHIP:DMG: 					Cluster = 0x30,
[1657513266.923235][3087:3121] CHIP:DMG: 					Attribute = 0x0000_0001,
[1657513266.923251][3087:3121] CHIP:DMG: 				}
[1657513266.923270][3087:3121] CHIP:DMG:
[1657513266.923287][3087:3121] CHIP:DMG: 				Data =
[1657513266.923304][3087:3121] CHIP:DMG: 				{
[1657513266.923325][3087:3121] CHIP:DMG: 					0x0 = 60,
[1657513266.923345][3087:3121] CHIP:DMG: 					0x1 = 900,
[1657513266.923364][3087:3121] CHIP:DMG: 				},
[1657513266.923380][3087:3121] CHIP:DMG: 			},
[1657513266.923403][3087:3121] CHIP:DMG:
[1657513266.923418][3087:3121] CHIP:DMG: 		},
[1657513266.923448][3087:3121] CHIP:DMG:
[1657513266.923463][3087:3121] CHIP:DMG: 		AttributeReportIB =
[1657513266.923486][3087:3121] CHIP:DMG: 		{
[1657513266.923502][3087:3121] CHIP:DMG: 			AttributeDataIB =
[1657513266.923519][3087:3121] CHIP:DMG: 			{
[1657513266.923537][3087:3121] CHIP:DMG: 				DataVersion = 0xaf3e74b,
[1657513266.923554][3087:3121] CHIP:DMG: 				AttributePathIB =
[1657513266.923571][3087:3121] CHIP:DMG: 				{
[1657513266.923589][3087:3121] CHIP:DMG: 					Endpoint = 0x0,
[1657513266.923608][3087:3121] CHIP:DMG: 					Cluster = 0x30,
[1657513266.923627][3087:3121] CHIP:DMG: 					Attribute = 0x0000_0000,
[1657513266.923643][3087:3121] CHIP:DMG: 				}
[1657513266.923663][3087:3121] CHIP:DMG:
[1657513266.923684][3087:3121] CHIP:DMG: 				Data = 0,
[1657513266.923699][3087:3121] CHIP:DMG: 			},
[1657513266.923720][3087:3121] CHIP:DMG:
[1657513266.923735][3087:3121] CHIP:DMG: 		},
[1657513266.923765][3087:3121] CHIP:DMG:
[1657513266.923781][3087:3121] CHIP:DMG: 		AttributeReportIB =
[1657513266.923804][3087:3121] CHIP:DMG: 		{
[1657513266.923820][3087:3121] CHIP:DMG: 			AttributeDataIB =
[1657513266.923836][3087:3121] CHIP:DMG: 			{
[1657513266.923855][3087:3121] CHIP:DMG: 				DataVersion = 0xed2c6352,
[1657513266.923873][3087:3121] CHIP:DMG: 				AttributePathIB =
[1657513266.923889][3087:3121] CHIP:DMG: 				{
[1657513266.923908][3087:3121] CHIP:DMG: 					Endpoint = 0x0,
[1657513266.923928][3087:3121] CHIP:DMG: 					Cluster = 0x31,
[1657513266.923948][3087:3121] CHIP:DMG: 					Attribute = 0x0000_FFFC,
[1657513266.923964][3087:3121] CHIP:DMG: 				}
[1657513266.923984][3087:3121] CHIP:DMG:
[1657513266.924004][3087:3121] CHIP:DMG: 				Data = 1,
[1657513266.924020][3087:3121] CHIP:DMG: 			},
[1657513266.924040][3087:3121] CHIP:DMG:
[1657513266.924055][3087:3121] CHIP:DMG: 		},
[1657513266.924076][3087:3121] CHIP:DMG:
[1657513266.924091][3087:3121] CHIP:DMG: 	],
[1657513266.924161][3087:3121] CHIP:DMG:
[1657513266.924179][3087:3121] CHIP:DMG: 	SuppressResponse = true,
[1657513266.924193][3087:3121] CHIP:DMG: 	InteractionModelRevision = 1
[1657513266.924204][3087:3121] CHIP:DMG: }
[1657513266.925312][3087:3121] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1657513266.925343][3087:3121] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1657513266.925362][3087:3121] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1657513266.925373][3087:3121] CHIP:CTL: Arming failsafe (60 seconds)
[1657513266.925423][3087:3121] CHIP:DMG: ICR moving to [AddingComm]
[1657513266.925450][3087:3121] CHIP:DMG: ICR moving to [AddedComma]
[1657513266.925523][3087:3121] CHIP:IN: Prepared secure message 0x7f9eafffd6f0 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 16149i with MessageCounter:131943876.
[1657513266.925559][3087:3121] CHIP:IN: Sending encrypted msg 0x7f9eafffd6f0 with MessageCounter:131943876 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000004E28B msec
[1657513266.925649][3087:3121] CHIP:DMG: ICR moving to [CommandSen]
[1657513267.019524][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657513267.071742][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513267.071994][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513267.072178][3087:3121] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:20565487 on exchange 16149i
[1657513267.072208][3087:3121] CHIP:EM: Found matching exchange: 16149i, Delegate: 0x7f9ea800ea40
[1657513267.072236][3087:3121] CHIP:DMG: ICR moving to [ResponseRe]
[1657513267.072287][3087:3121] CHIP:DMG: InvokeResponseMessage =
[1657513267.072304][3087:3121] CHIP:DMG: {
[1657513267.072319][3087:3121] CHIP:DMG: 	suppressResponse = false,
[1657513267.072332][3087:3121] CHIP:DMG: 	InvokeResponseIBs =
[1657513267.072356][3087:3121] CHIP:DMG: 	[
[1657513267.072369][3087:3121] CHIP:DMG: 		InvokeResponseIB =
[1657513267.072393][3087:3121] CHIP:DMG: 		{
[1657513267.072408][3087:3121] CHIP:DMG: 			CommandDataIB =
[1657513267.072425][3087:3121] CHIP:DMG: 			{
[1657513267.072438][3087:3121] CHIP:DMG: 				CommandPathIB =
[1657513267.072455][3087:3121] CHIP:DMG: 				{
[1657513267.072473][3087:3121] CHIP:DMG: 					EndpointId = 0x0,
[1657513267.072491][3087:3121] CHIP:DMG: 					ClusterId = 0x30,
[1657513267.072508][3087:3121] CHIP:DMG: 					CommandId = 0x1,
[1657513267.072522][3087:3121] CHIP:DMG: 				},
[1657513267.072541][3087:3121] CHIP:DMG:
[1657513267.072556][3087:3121] CHIP:DMG: 				CommandFields =
[1657513267.072573][3087:3121] CHIP:DMG: 				{
[1657513267.072591][3087:3121] CHIP:DMG: 					0x0 = 0,
[1657513267.072611][3087:3121] CHIP:DMG: 					0x1 = "",
[1657513267.072629][3087:3121] CHIP:DMG: 				},
[1657513267.072642][3087:3121] CHIP:DMG: 			},
[1657513267.072664][3087:3121] CHIP:DMG:
[1657513267.072676][3087:3121] CHIP:DMG: 		},
[1657513267.072698][3087:3121] CHIP:DMG:
[1657513267.072710][3087:3121] CHIP:DMG: 	],
[1657513267.072734][3087:3121] CHIP:DMG:
[1657513267.072747][3087:3121] CHIP:DMG: 	InteractionModelRevision = 1
[1657513267.072759][3087:3121] CHIP:DMG: },
[1657513267.072826][3087:3121] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1657513267.072859][3087:3121] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1657513267.072885][3087:3121] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1657513267.072906][3087:3121] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1657513267.072929][3087:3121] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1657513267.072942][3087:3121] CHIP:CTL: Setting Regulatory Config
[1657513267.072951][3087:3121] CHIP:CTL: Device does not support configurable regulatory location
[1657513267.073011][3087:3121] CHIP:DMG: ICR moving to [AddingComm]
[1657513267.073068][3087:3121] CHIP:DMG: ICR moving to [AddedComma]
[1657513267.073147][3087:3121] CHIP:IN: Prepared secure message 0x7f9eafffd1e0 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 16150i with MessageCounter:131943877.
[1657513267.073187][3087:3121] CHIP:IN: Sending encrypted msg 0x7f9eafffd1e0 with MessageCounter:131943877 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000004E31F msec
[1657513267.073279][3087:3121] CHIP:DMG: ICR moving to [CommandSen]
[1657513267.073343][3087:3121] CHIP:DMG: ICR moving to [AwaitingDe]
[1657513267.169871][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657513267.222462][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513267.222731][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513267.222926][3087:3121] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:20565488 on exchange 16150i
[1657513267.222962][3087:3121] CHIP:EM: Found matching exchange: 16150i, Delegate: 0x7f9ea800eb90
[1657513267.222993][3087:3121] CHIP:DMG: ICR moving to [ResponseRe]
[1657513267.223049][3087:3121] CHIP:DMG: InvokeResponseMessage =
[1657513267.223072][3087:3121] CHIP:DMG: {
[1657513267.223093][3087:3121] CHIP:DMG: 	suppressResponse = false,
[1657513267.223113][3087:3121] CHIP:DMG: 	InvokeResponseIBs =
[1657513267.223144][3087:3121] CHIP:DMG: 	[
[1657513267.223165][3087:3121] CHIP:DMG: 		InvokeResponseIB =
[1657513267.223196][3087:3121] CHIP:DMG: 		{
[1657513267.223216][3087:3121] CHIP:DMG: 			CommandDataIB =
[1657513267.223238][3087:3121] CHIP:DMG: 			{
[1657513267.223257][3087:3121] CHIP:DMG: 				CommandPathIB =
[1657513267.223280][3087:3121] CHIP:DMG: 				{
[1657513267.223304][3087:3121] CHIP:DMG: 					EndpointId = 0x0,
[1657513267.223329][3087:3121] CHIP:DMG: 					ClusterId = 0x30,
[1657513267.223353][3087:3121] CHIP:DMG: 					CommandId = 0x3,
[1657513267.223376][3087:3121] CHIP:DMG: 				},
[1657513267.223401][3087:3121] CHIP:DMG:
[1657513267.223423][3087:3121] CHIP:DMG: 				CommandFields =
[1657513267.223445][3087:3121] CHIP:DMG: 				{
[1657513267.223470][3087:3121] CHIP:DMG: 					0x0 = 0,
[1657513267.223497][3087:3121] CHIP:DMG: 					0x1 = "",
[1657513267.223521][3087:3121] CHIP:DMG: 				},
[1657513267.223541][3087:3121] CHIP:DMG: 			},
[1657513267.223569][3087:3121] CHIP:DMG:
[1657513267.223588][3087:3121] CHIP:DMG: 		},
[1657513267.223615][3087:3121] CHIP:DMG:
[1657513267.223632][3087:3121] CHIP:DMG: 	],
[1657513267.223664][3087:3121] CHIP:DMG:
[1657513267.223686][3087:3121] CHIP:DMG: 	InteractionModelRevision = 1
[1657513267.223703][3087:3121] CHIP:DMG: },
[1657513267.223783][3087:3121] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1657513267.223827][3087:3121] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0
[1657513267.223859][3087:3121] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'
[1657513267.223880][3087:3121] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[1657513267.223904][3087:3121] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'
[1657513267.223922][3087:3121] CHIP:CTL: Sending request for PAI certificate
[1657513267.223937][3087:3121] CHIP:CTL: Sending Certificate Chain request to 0x7f9ea8000b60 device
[1657513267.224003][3087:3121] CHIP:DMG: ICR moving to [AddingComm]
[1657513267.224033][3087:3121] CHIP:DMG: ICR moving to [AddedComma]
[1657513267.224117][3087:3121] CHIP:IN: Prepared secure message 0x7f9eafffd110 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 16151i with MessageCounter:131943878.
[1657513267.224162][3087:3121] CHIP:IN: Sending encrypted msg 0x7f9eafffd110 with MessageCounter:131943878 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000004E3B6 msec
[1657513267.224263][3087:3121] CHIP:DMG: ICR moving to [CommandSen]
[1657513267.224332][3087:3121] CHIP:DMG: ICR moving to [AwaitingDe]
[1657513267.319612][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657513267.376538][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513267.377005][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513267.427756][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513267.428055][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513267.471648][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513267.471872][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513267.472025][3087:3121] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:20565489 on exchange 16151i
[1657513267.472051][3087:3121] CHIP:EM: Found matching exchange: 16151i, Delegate: 0x7f9ea800ea40
[1657513267.472084][3087:3121] CHIP:DMG: ICR moving to [ResponseRe]
[1657513267.472134][3087:3121] CHIP:DMG: InvokeResponseMessage =
[1657513267.472151][3087:3121] CHIP:DMG: {
[1657513267.472166][3087:3121] CHIP:DMG: 	suppressResponse = false,
[1657513267.472179][3087:3121] CHIP:DMG: 	InvokeResponseIBs =
[1657513267.472203][3087:3121] CHIP:DMG: 	[
[1657513267.472216][3087:3121] CHIP:DMG: 		InvokeResponseIB =
[1657513267.472239][3087:3121] CHIP:DMG: 		{
[1657513267.472253][3087:3121] CHIP:DMG: 			CommandDataIB =
[1657513267.472269][3087:3121] CHIP:DMG: 			{
[1657513267.472283][3087:3121] CHIP:DMG: 				CommandPathIB =
[1657513267.472299][3087:3121] CHIP:DMG: 				{
[1657513267.472317][3087:3121] CHIP:DMG: 					EndpointId = 0x0,
[1657513267.472335][3087:3121] CHIP:DMG: 					ClusterId = 0x3e,
[1657513267.472351][3087:3121] CHIP:DMG: 					CommandId = 0x3,
[1657513267.472366][3087:3121] CHIP:DMG: 				},
[1657513267.472383][3087:3121] CHIP:DMG:
[1657513267.472398][3087:3121] CHIP:DMG: 				CommandFields =
[1657513267.472414][3087:3121] CHIP:DMG: 				{
[1657513267.472431][3087:3121] CHIP:DMG: 					0x0 = [
[1657513267.472586][3087:3121] CHIP:DMG: 					0x30, 0x82, 0x1, 0xcb, 0x30, 0x82, 0x1, 0x71, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x8, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0xf, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0xc, 0x8c, 0x87, 0x6d, 0x3, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x5, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x9, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0xb, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x6, 0x3, 0x55, 0x1d, 0x13, 0x1, 0x1, 0xff, 0x4, 0x8, 0x30, 0x6, 0x1, 0x1, 0xff, 0x2, 0x1,
[1657513267.472649][3087:3121] CHIP:DMG: 					]
[1657513267.472666][3087:3121] CHIP:DMG: 				},
[1657513267.472679][3087:3121] CHIP:DMG: 			},
[1657513267.472700][3087:3121] CHIP:DMG:
[1657513267.472719][3087:3121] CHIP:DMG: 		},
[1657513267.472742][3087:3121] CHIP:DMG:
[1657513267.472758][3087:3121] CHIP:DMG: 	],
[1657513267.472782][3087:3121] CHIP:DMG:
[1657513267.472800][3087:3121] CHIP:DMG: 	InteractionModelRevision = 1
[1657513267.472816][3087:3121] CHIP:DMG: },
[1657513267.472885][3087:3121] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1657513267.472921][3087:3121] CHIP:CTL: Received certificate chain from the device
[1657513267.472950][3087:3121] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
[1657513267.472974][3087:3121] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[1657513267.472999][3087:3121] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'
[1657513267.473015][3087:3121] CHIP:CTL: Sending request for DAC certificate
[1657513267.473026][3087:3121] CHIP:CTL: Sending Certificate Chain request to 0x7f9ea8000b60 device
[1657513267.473087][3087:3121] CHIP:DMG: ICR moving to [AddingComm]
[1657513267.473115][3087:3121] CHIP:DMG: ICR moving to [AddedComma]
[1657513267.473192][3087:3121] CHIP:IN: Prepared secure message 0x7f9eafffd140 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 16152i with MessageCounter:131943879.
[1657513267.473232][3087:3121] CHIP:IN: Sending encrypted msg 0x7f9eafffd140 with MessageCounter:131943879 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000004E4AF msec
[1657513267.473323][3087:3121] CHIP:DMG: ICR moving to [CommandSen]
[1657513267.473381][3087:3121] CHIP:DMG: ICR moving to [AwaitingDe]
[1657513267.569476][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657513267.626604][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513267.626797][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513267.676835][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513267.677306][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513267.722561][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513267.722949][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513267.723108][3087:3121] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:20565490 on exchange 16152i
[1657513267.723136][3087:3121] CHIP:EM: Found matching exchange: 16152i, Delegate: 0x7f9ea800eb90
[1657513267.723168][3087:3121] CHIP:DMG: ICR moving to [ResponseRe]
[1657513267.723220][3087:3121] CHIP:DMG: InvokeResponseMessage =
[1657513267.723236][3087:3121] CHIP:DMG: {
[1657513267.723251][3087:3121] CHIP:DMG: 	suppressResponse = false,
[1657513267.723264][3087:3121] CHIP:DMG: 	InvokeResponseIBs =
[1657513267.723287][3087:3121] CHIP:DMG: 	[
[1657513267.723300][3087:3121] CHIP:DMG: 		InvokeResponseIB =
[1657513267.723324][3087:3121] CHIP:DMG: 		{
[1657513267.723338][3087:3121] CHIP:DMG: 			CommandDataIB =
[1657513267.723354][3087:3121] CHIP:DMG: 			{
[1657513267.723367][3087:3121] CHIP:DMG: 				CommandPathIB =
[1657513267.723385][3087:3121] CHIP:DMG: 				{
[1657513267.723403][3087:3121] CHIP:DMG: 					EndpointId = 0x0,
[1657513267.723421][3087:3121] CHIP:DMG: 					ClusterId = 0x3e,
[1657513267.723437][3087:3121] CHIP:DMG: 					CommandId = 0x3,
[1657513267.723451][3087:3121] CHIP:DMG: 				},
[1657513267.723469][3087:3121] CHIP:DMG:
[1657513267.723484][3087:3121] CHIP:DMG: 				CommandFields =
[1657513267.723500][3087:3121] CHIP:DMG: 				{
[1657513267.723517][3087:3121] CHIP:DMG: 					0x0 = [
[1657513267.723672][3087:3121] CHIP:DMG: 					0x30, 0x82, 0x1, 0xe9, 0x30, 0x82, 0x1, 0x8e, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x8, 0x23, 0x8a, 0x64, 0x7b, 0xbc, 0x4c, 0x30, 0xdd, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x44, 0x41, 0x43, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x2f, 0x30, 0x78, 0x38, 0x30, 0x30, 0x30, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x2, 0xc, 0x4, 0x38, 0x30, 0x30, 0x30, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x62, 0xdb, 0x16, 0xba, 0xde, 0xa3, 0x26, 0xa6, 0xdb, 0x84, 0x81, 0x4a, 0x6, 0x3f, 0xc6, 0xc7, 0xe9, 0xe2, 0xb1, 0x1, 0xb7, 0x21, 0x64, 0x8e, 0xba, 0x4e, 0x5a, 0xc8, 0x40, 0xf5, 0xda, 0x30, 0x1e, 0xe6, 0x18, 0x12, 0x4e, 0xb4, 0x18, 0xe, 0x2f, 0xc3, 0xa2, 0x4, 0x7a, 0x56, 0x4b, 0xa9, 0xbc, 0xfa, 0xb, 0xf
[1657513267.723735][3087:3121] CHIP:DMG: 					]
[1657513267.723752][3087:3121] CHIP:DMG: 				},
[1657513267.723765][3087:3121] CHIP:DMG: 			},
[1657513267.723786][3087:3121] CHIP:DMG:
[1657513267.723798][3087:3121] CHIP:DMG: 		},
[1657513267.723819][3087:3121] CHIP:DMG:
[1657513267.723830][3087:3121] CHIP:DMG: 	],
[1657513267.723852][3087:3121] CHIP:DMG:
[1657513267.723866][3087:3121] CHIP:DMG: 	InteractionModelRevision = 1
[1657513267.723878][3087:3121] CHIP:DMG: },
[1657513267.723944][3087:3121] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1657513267.723975][3087:3121] CHIP:CTL: Received certificate chain from the device
[1657513267.723999][3087:3121] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
[1657513267.724019][3087:3121] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[1657513267.724040][3087:3121] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'
[1657513267.724052][3087:3121] CHIP:CTL: Sending Attestation Request to the device.
[1657513267.724063][3087:3121] CHIP:CTL: Sending Attestation request to 0x7f9ea8000b60 device
[1657513267.724123][3087:3121] CHIP:DMG: ICR moving to [AddingComm]
[1657513267.724148][3087:3121] CHIP:DMG: ICR moving to [AddedComma]
[1657513267.724222][3087:3121] CHIP:IN: Prepared secure message 0x7f9eafffd120 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 16153i with MessageCounter:131943880.
[1657513267.724257][3087:3121] CHIP:IN: Sending encrypted msg 0x7f9eafffd120 with MessageCounter:131943880 to 0xFFFFFFFB00000000 (0) at monotonic time: 000000000004E5AA msec
[1657513267.724351][3087:3121] CHIP:DMG: ICR moving to [CommandSen]
[1657513267.724375][3087:3121] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information
[1657513267.724420][3087:3121] CHIP:DMG: ICR moving to [AwaitingDe]
[1657513267.819349][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1657513268.026409][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513268.027080][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513268.076286][3087:3116] CHIP:DL: Indication received, conn = 0x7f9eb4031140
[1657513268.076899][3087:3121] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1657513269.471013][3087:3116] CHIP:DL: Bluez disconnected
[1657513269.471066][3087:3116] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1657513269.471386][3087:3121] CHIP:IN: Clearing BLE pending packets.
[1657513297.745925][3087:3121] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 16153i
[1657513297.745999][3087:3121] CHIP:CTL: Device failed to receive the Attestation Information Response: ../../third_party/connectedhomeip/src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout
[1657513297.746030][3087:3121] CHIP:CTL: Error on commissioning step 'SendAttestationRequest': '../../third_party/connectedhomeip/src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout'
[1657513297.746045][3087:3121] CHIP:CTL: Failed to perform commissioning step 7
[1657513297.746060][3087:3121] CHIP:CTL: Going from commissioning step 'SendAttestationRequest' with lastErr = '../../third_party/connectedhomeip/src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout' -> 'Cleanup'
[1657513297.746098][3087:3121] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../third_party/connectedhomeip/src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout'
[1657513297.746118][3087:3121] CHIP:CTL: Expiring failsafe on proxy 0x7f9ea8000b60
[1657513297.746183][3087:3121] CHIP:DMG: ICR moving to [AddingComm]
[1657513297.746208][3087:3121] CHIP:DMG: ICR moving to [AddedComma]
[1657513297.746307][3087:3121] CHIP:IN: Prepared secure message 0x7f9eafffdd90 to 0xFFFFFFFB00000000 (0)  of type 0x8 and protocolId (0, 1) on exchange 16154i with MessageCounter:131943881.
[1657513297.746348][3087:3121] CHIP:IN: Sending encrypted msg 0x7f9eafffdd90 with MessageCounter:131943881 to 0xFFFFFFFB00000000 (0) at monotonic time: 0000000000055AF0 msec
[1657513297.746376][3087:3121] CHIP:IN: Message appended to BLE send queue
[1657513297.746395][3087:3121] CHIP:DMG: ICR moving to [CommandSen]
[1657513297.746417][3087:3121] CHIP:DMG: ICR moving to [AwaitingDe]
[1657513302.208279][3087:3121] CHIP:DIS: Closing all BLE connections
[1657513302.208407][3087:3121] CHIP:TOO: Pairing Failure: ../../third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1401: CHIP Error 0x00000032: Timeout
[1657513302.209054][3087:3087] CHIP:CTL: Shutting down the commissioner
[1657513302.209211][3087:3087] CHIP:CTL: Shutting down the controller
[1657513302.209244][3087:3087] CHIP:CTL: Shutting down the commissioner
[1657513302.209297][3087:3087] CHIP:CTL: Shutting down the controller
[1657513302.209321][3087:3087] CHIP:IN: Expiring all connections for fabric 1!!
[1657513302.209343][3087:3087] CHIP:FP: Forgetting fabric 0x1
[1657513302.209380][3087:3087] CHIP:TS: Pending Last Known Good Time: 2022-07-07T00:10:25
[1657513302.209653][3087:3087] CHIP:TS: Previous Last Known Good Time: 2022-07-07T00:10:25
[1657513302.209677][3087:3087] CHIP:TS: Reverted Last Known Good Time to previous value
[1657513302.209766][3087:3087] CHIP:CTL: Shutting down the commissioner
[1657513302.209832][3087:3087] CHIP:CTL: Shutting down the controller
[1657513302.209854][3087:3087] CHIP:IN: Expiring all connections for fabric 2!!
[1657513302.209867][3087:3087] CHIP:FP: Forgetting fabric 0x2
[1657513302.209890][3087:3087] CHIP:TS: Pending Last Known Good Time: 2022-07-07T00:10:25
[1657513302.210062][3087:3087] CHIP:TS: Previous Last Known Good Time: 2022-07-07T00:10:25
[1657513302.210084][3087:3087] CHIP:TS: Reverted Last Known Good Time to previous value
[1657513302.210116][3087:3087] CHIP:CTL: Shutting down the commissioner
[1657513302.210169][3087:3087] CHIP:CTL: Shutting down the controller
[1657513302.210190][3087:3087] CHIP:IN: Expiring all connections for fabric 3!!
[1657513302.210203][3087:3087] CHIP:FP: Forgetting fabric 0x3
[1657513302.210221][3087:3087] CHIP:TS: Pending Last Known Good Time: 2022-07-07T00:10:25
[1657513302.210383][3087:3087] CHIP:TS: Previous Last Known Good Time: 2022-07-07T00:10:25
[1657513302.210404][3087:3087] CHIP:TS: Reverted Last Known Good Time to previous value
[1657513302.210429][3087:3087] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1657513302.210539][3087:3087] CHIP:DMG: IM WH moving to [Uninitialized]
[1657513302.210561][3087:3087] CHIP:DMG: IM WH moving to [Uninitialized]
[1657513302.210572][3087:3087] CHIP:DMG: IM WH moving to [Uninitialized]
[1657513302.210581][3087:3087] CHIP:DMG: IM WH moving to [Uninitialized]
[1657513302.210593][3087:3087] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1657513302.210668][3087:3087] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1657513302.210988][3087:3087] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-elYp9B)
[1657513302.211695][3087:3087] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657513302.211795][3087:3087] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1657513302.211816][3087:3087] CHIP:DL: Inet Layer shutdown
[1657513302.211828][3087:3087] CHIP:DL: BLE shutdown
[1657513302.213383][3087:3087] CHIP:DL: System Layer shutdown
[1657513302.213497][3087:3087] CHIP:SPT: VerifyOrDie failure at ../../third_party/connectedhomeip/src/lib/support/Pool.h:317: Allocated() == 0
Aborted (core dumped)

@dhrishi

Does this happen everytime?
Yes, it happen everytime.
I will write logs next paragraph.

I tried all-clusters-app example.
I do below command for build.

$ cd $CONNECTEDHOMEIPPATH
$ source ./scripts/bootstrap.sh
$ source ./scripts/activate.sh
$ cd examples/all-clusters-app/esp32/
$ . ./$ESPIDFPATH/export.sh
$ mv sdkconfig.defaults sdkconfig_esp32.defaults
$ ln -s sdkconfig_c3devkit.defaults sdkconfig.defaults
$ idf.py set-target esp32c3
$ idf.py build
$ idf.py -p /dev/ttyUSB0 erase_flash flash

I'm using below branch/commit id for connectedhomeip and ESP-IDF.

connectedhomeip

$ git log -1
commit 126f6b2915fc26ee17342e1dc80f96f031938a6c (HEAD -> master, origin/master, origin/HEAD)
Author: Stefan Agner stefan@agner.ch
Date:   Wed Jul 6 15:04:20 2022 +0200
[python] Move string encoding to ChipDeviceCtrl.py (#20306)

Encode strings in ChipDeviceCtrl.py

Fix Python tests

ESP-IDF

$ git log -1
commit 1329b19fe494500aeb79d19b27cfd99b40c37aec (HEAD, tag: v4.4.1)
Author: Michael (XIAO Xufeng) xiaoxufeng@espressif.com
Date:   Sat Apr 16 09:43:14 2022 +0800
versions: Update version to 4.4.1

Logs

connectedhomeip

$ ./out/debug/chip-tool pairing ble-wifi 12344321 $SSID $PASSWORD 20202021 3840
[1657582567.584798][12762:12762] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1657582567.585477][12762:12762] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1657582567.585790][12762:12762] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1657582567.586047][12762:12762] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1657582567.586549][12762:12762] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-wHe3vd)
[1657582567.587260][12762:12762] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657582567.587572][12762:12762] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4)
[1657582567.588278][12762:12762] CHIP:DL: Failed to get Ethernet interface
[1657582567.588743][12762:12762] CHIP:DL: Failed to reset Ethernet statistic counts
[1657582567.589151][12762:12762] CHIP:DL: Got WiFi interface: wlp1s0
[1657582567.590417][12762:12762] CHIP:DL: Found the primary WiFi interface:wlp1s0
[1657582567.590795][12762:12762] CHIP:IN: UDP::Init bind&listen port=0
[1657582567.591074][12762:12762] CHIP:IN: UDP::Init bound to port=42583
[1657582567.591259][12762:12762] CHIP:IN: UDP::Init bind&listen port=0
[1657582567.591471][12762:12762] CHIP:IN: UDP::Init bound to port=56806
[1657582567.591651][12762:12762] CHIP:IN: BLEBase::Init - setting/overriding transport
[1657582567.591873][12762:12762] CHIP:IN: TransportMgr initialized
[1657582567.592071][12762:12762] CHIP:FP: Initializing FabricTable from persistent storage
[1657582567.592472][12762:12762] CHIP:TS: Last Known Good Time: 2022-07-07T00:10:25
[1657582567.593425][12762:12762] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xFDAA879C07F9EFE6, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657582567.594175][12762:12762] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0x1E5D8F19A53A5B5E, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657582567.594916][12762:12762] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0x087EA5B078BED830, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1
[1657582567.599367][12762:12762] CHIP:ZCL: Using ZAP configuration...
[1657582567.600396][12762:12762] CHIP:CTL: System State Initialized...
[1657582567.600653][12762:12762] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657582567.600828][12762:12762] CHIP:CTL: Setting attestation nonce to random value
[1657582567.601021][12762:12762] CHIP:CTL: Setting CSR nonce to random value
[1657582567.601226][12762:12762] CHIP:IN: UDP::Init bind&listen port=5550
[1657582567.601424][12762:12762] CHIP:IN: UDP::Init bound to port=5550
[1657582567.601590][12762:12762] CHIP:IN: UDP::Init bind&listen port=5550
[1657582567.601776][12762:12762] CHIP:IN: UDP::Init bound to port=5550
[1657582567.601939][12762:12762] CHIP:IN: TransportMgr initialized
[1657582567.602366][12762:12762] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657582567.602558][12762:12762] CHIP:CTL: Setting attestation nonce to random value
[1657582567.602734][12762:12762] CHIP:CTL: Setting CSR nonce to random value
[1657582567.606064][12762:12762] CHIP:CTL: Generating NOC
[1657582567.607668][12762:12762] CHIP:FP: Validating NOC chain
[1657582567.610263][12762:12762] CHIP:FP: NOC chain validation successful
[1657582567.616436][12762:12762] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1657582567.616639][12762:12762] CHIP:TS: Last Known Good Time: 2022-07-07T00:10:25
[1657582567.616807][12762:12762] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657582567.616965][12762:12762] CHIP:TS: Retaining current Last Known Good Time
[1657582567.619844][12762:12762] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1657582567.622669][12762:12762] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-07T00:10:25
[1657582567.625302][12762:12762] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1657582567.625353][12762:12762] CHIP:IN: UDP::Init bind&listen port=5550
[1657582567.625421][12762:12762] CHIP:IN: UDP::Init bound to port=5550
[1657582567.625436][12762:12762] CHIP:IN: UDP::Init bind&listen port=5550
[1657582567.625476][12762:12762] CHIP:IN: UDP::Init bound to port=5550
[1657582567.625488][12762:12762] CHIP:IN: TransportMgr initialized
[1657582567.625584][12762:12762] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657582567.625609][12762:12762] CHIP:CTL: Setting attestation nonce to random value
[1657582567.625645][12762:12762] CHIP:CTL: Setting CSR nonce to random value
[1657582567.626859][12762:12762] CHIP:CTL: Generating NOC
[1657582567.628302][12762:12762] CHIP:FP: Validating NOC chain
[1657582567.630817][12762:12762] CHIP:FP: NOC chain validation successful
[1657582567.631125][12762:12762] CHIP:FP: Updated fabric at index: 0x2, Node ID: 0x000000000001B669
[1657582567.631153][12762:12762] CHIP:TS: Last Known Good Time: 2022-07-07T00:10:25
[1657582567.631165][12762:12762] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657582567.631174][12762:12762] CHIP:TS: Retaining current Last Known Good Time
[1657582567.634384][12762:12762] CHIP:FP: Metadata for Fabric 0x2 persisted to storage.
[1657582567.637149][12762:12762] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-07T00:10:25
[1657582567.639674][12762:12762] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000
[1657582567.639958][12762:12762] CHIP:IN: UDP::Init bind&listen port=5550
[1657582567.640114][12762:12762] CHIP:IN: UDP::Init bound to port=5550
[1657582567.640136][12762:12762] CHIP:IN: UDP::Init bind&listen port=5550
[1657582567.640179][12762:12762] CHIP:IN: UDP::Init bound to port=5550
[1657582567.640191][12762:12762] CHIP:IN: TransportMgr initialized
[1657582567.640382][12762:12762] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1657582567.640413][12762:12762] CHIP:CTL: Setting attestation nonce to random value
[1657582567.640451][12762:12762] CHIP:CTL: Setting CSR nonce to random value
[1657582567.641576][12762:12762] CHIP:CTL: Generating NOC
[1657582567.651425][12762:12762] CHIP:FP: Validating NOC chain
[1657582567.653764][12762:12762] CHIP:FP: NOC chain validation successful
[1657582567.653958][12762:12762] CHIP:FP: Updated fabric at index: 0x3, Node ID: 0x000000000001B669
[1657582567.653986][12762:12762] CHIP:TS: Last Known Good Time: 2022-07-07T00:10:25
[1657582567.654001][12762:12762] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1657582567.654013][12762:12762] CHIP:TS: Retaining current Last Known Good Time
[1657582567.657059][12762:12762] CHIP:FP: Metadata for Fabric 0x3 persisted to storage.
[1657582567.659592][12762:12762] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-07T00:10:25
[1657582567.662144][12762:12762] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000
[1657582567.662423][12762:12762] CHIP:IN: UDP::Init bind&listen port=5550
[1657582567.662845][12762:12762] CHIP:IN: UDP::Init bound to port=5550
[1657582567.663032][12762:12762] CHIP:IN: UDP::Init bind&listen port=5550
[1657582567.663226][12762:12762] CHIP:IN: UDP::Init bound to port=5550
[1657582567.663389][12762:12762] CHIP:IN: TransportMgr initialized
[1657582567.709894][12762:12767] CHIP:DL: CHIP task running
[1657582567.710309][12762:12767] CHIP:IN: SecureSession[0x7fb358001a30]: Allocated Type:1 LSID:44141
[1657582567.710347][12762:12767] CHIP:SC: Assigned local session key ID 44141
[1657582567.710406][12762:12767] CHIP:SC: Including MRP parameters in PBKDF param request
[1657582567.710464][12762:12767] CHIP:IN: Prepared unauthenticated message 0x7fb35fffe3f0 to 0x0000000000000000 (0)  of type 0x20 and protocolId (0, 0) on exchange 54861i with MessageCounter:116153229.
[1657582567.710503][12762:12767] CHIP:IN: Sending unauthenticated msg 0x7fb35fffe3f0 with MessageCounter:116153229 to 0x0000000000000000 at monotonic time: 000000000029982F msec
[1657582567.710528][12762:12767] CHIP:IN: Message appended to BLE send queue
[1657582567.710542][12762:12767] CHIP:SC: Sent PBKDF param request
[1657582567.710573][12762:12767] CHIP:CTL: Setting wifi credentials from parameters
[1657582567.710589][12762:12767] CHIP:CTL: Setting attestation nonce to random value
[1657582567.710611][12762:12767] CHIP:CTL: Setting CSR nonce to random value
[1657582567.710635][12762:12767] CHIP:CTL: Commission called for node ID 0x0000000000BC5C01
[1657582567.710990][12762:12768] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1657582567.710994][12762:12765] CHIP:DL: TRACE: Bus acquired for name C-31da
[1657582567.723284][12762:12767] CHIP:DL: PlatformBlueZInit init success
[1657582567.733368][12762:12765] CHIP:BLE: BLE removing known devices.
[1657582567.745959][12762:12765] CHIP:BLE: BLE initiating scan.
[1657582567.897413][12762:12767] CHIP:DL: Long dispatch time: 187 ms, for event type 2
[1657582567.918421][12762:12765] CHIP:BLE: New device scanned: C4:75:1A:88:5D:48
[1657582567.918514][12762:12765] CHIP:BLE: Device discriminator match. Attempting to connect.
[1657582567.931628][12762:12765] CHIP:BLE: Scan complete notification without an active scan.
[1657582568.315032][12762:12765] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort (36)
[1657582568.465205][12762:12765] CHIP:DL: ConnectDevice complete
[1657582577.918757][12762:12767] CHIP:DL: HandlePlatformSpecificBLEEvent 16386
[1657582577.918823][12762:12767] CHIP:IN: Clearing BLE pending packets.
[1657582577.918854][12762:12767] CHIP:IN: BleConnection Error: ../../third_party/connectedhomeip/src/platform/Linux/BLEManagerImpl.cpp:63: CHIP Error 0x00000032: Timeout
[1657582597.724012][12762:12767] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
[1657582597.724069][12762:12767] CHIP:IN: SecureSession[0x7fb358001a30]: Released - Type:1 LSID:44141
[1657582597.724124][12762:12767] CHIP:TOO: Secure Pairing Failed
[1657582597.724188][12762:12767] CHIP:DIS: Closing all BLE connections
[1657582597.724221][12762:12767] CHIP:TOO: Pairing Failure: ../../third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:244: CHIP Error 0x00000032: Timeout
[1657582597.724467][12762:12762] CHIP:CTL: Shutting down the commissioner
[1657582597.724592][12762:12762] CHIP:CTL: Shutting down the controller
[1657582597.724620][12762:12762] CHIP:CTL: Shutting down the commissioner
[1657582597.724659][12762:12762] CHIP:CTL: Shutting down the controller
[1657582597.724674][12762:12762] CHIP:IN: Expiring all connections for fabric 1!!
[1657582597.724685][12762:12762] CHIP:FP: Forgetting fabric 0x1
[1657582597.724708][12762:12762] CHIP:TS: Pending Last Known Good Time: 2022-07-07T00:10:25
[1657582597.724890][12762:12762] CHIP:TS: Previous Last Known Good Time: 2022-07-07T00:10:25
[1657582597.724909][12762:12762] CHIP:TS: Reverted Last Known Good Time to previous value
[1657582597.724942][12762:12762] CHIP:CTL: Shutting down the commissioner
[1657582597.724987][12762:12762] CHIP:CTL: Shutting down the controller
[1657582597.725000][12762:12762] CHIP:IN: Expiring all connections for fabric 2!!
[1657582597.725008][12762:12762] CHIP:FP: Forgetting fabric 0x2
[1657582597.725021][12762:12762] CHIP:TS: Pending Last Known Good Time: 2022-07-07T00:10:25
[1657582597.725144][12762:12762] CHIP:TS: Previous Last Known Good Time: 2022-07-07T00:10:25
[1657582597.725160][12762:12762] CHIP:TS: Reverted Last Known Good Time to previous value
[1657582597.725191][12762:12762] CHIP:CTL: Shutting down the commissioner
[1657582597.725236][12762:12762] CHIP:CTL: Shutting down the controller
[1657582597.725252][12762:12762] CHIP:IN: Expiring all connections for fabric 3!!
[1657582597.725263][12762:12762] CHIP:FP: Forgetting fabric 0x3
[1657582597.725281][12762:12762] CHIP:TS: Pending Last Known Good Time: 2022-07-07T00:10:25
[1657582597.725403][12762:12762] CHIP:TS: Previous Last Known Good Time: 2022-07-07T00:10:25
[1657582597.725420][12762:12762] CHIP:TS: Reverted Last Known Good Time to previous value
[1657582597.725439][12762:12762] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1657582597.725525][12762:12762] CHIP:DMG: IM WH moving to [Uninitialized]
[1657582597.725542][12762:12762] CHIP:DMG: IM WH moving to [Uninitialized]
[1657582597.725551][12762:12762] CHIP:DMG: IM WH moving to [Uninitialized]
[1657582597.725561][12762:12762] CHIP:DMG: IM WH moving to [Uninitialized]
[1657582597.725575][12762:12762] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1657582597.725622][12762:12762] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1657582597.725872][12762:12762] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-6jD9cb)
[1657582597.726436][12762:12762] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1657582597.726505][12762:12762] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1657582597.726521][12762:12762] CHIP:DL: Inet Layer shutdown
[1657582597.726535][12762:12762] CHIP:DL: BLE shutdown
[1657582597.727071][12762:12762] CHIP:DL: System Layer shutdown
[1657582597.727173][12762:12762] CHIP:TOO: Run command failure: ../../third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:244: CHIP Error 0x00000032: Timeout

device side

ESP-ROM:esp32c3-api1-20210207
Build:Feb  7 2021
rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fcd6100,len:0x16b4
load:0x403ce000,len:0x930
load:0x403d0000,len:0x2d28
entry 0x403ce000
I (30) boot: ESP-IDF v4.4.1 2nd stage bootloader
I (30) boot: compile time 00:29:42
I (30) boot: chip revision: 3
I (32) boot.esp32c3: SPI Speed      : 80MHz
I (37) boot.esp32c3: SPI Mode       : DIO
I (41) boot.esp32c3: SPI Flash Size : 4MB
I (46) boot: Enabling RNG early entropy source...
I (52) boot: Partition Table:
I (55) boot: ## Label            Usage          Type ST Offset   Length
I (62) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (70) boot:  1 otadata          OTA data         01 00 0000f000 00002000
I (77) boot:  2 phy_init         RF data          01 01 00011000 00001000
I (85) boot:  3 ota_0            OTA app          00 10 00020000 00177000
I (92) boot:  4 ota_1            OTA app          00 11 001a0000 00177000
I (100) boot:  5 ot_storage       Unknown data     01 3a 00317000 00002000
I (107) boot: End of partition table
I (112) esp_image: segment 0: paddr=00020020 vaddr=3c100020 size=35410h (218128) map
I (154) esp_image: segment 1: paddr=00055438 vaddr=3fc8f600 size=03908h ( 14600) load
I (157) esp_image: segment 2: paddr=00058d48 vaddr=40380000 size=072d0h ( 29392) load
I (165) esp_image: segment 3: paddr=00060020 vaddr=42000020 size=f8de8h (1019368) map
I (328) esp_image: segment 4: paddr=00158e10 vaddr=403872d0 size=082e8h ( 33512) load
I (334) esp_image: segment 5: paddr=00161100 vaddr=50000010 size=00010h (    16) load
I (339) boot: Loaded app from partition at offset 0x20000
I (340) boot: Disabling RNG early entropy source...
I (357) cpu_start: Pro cpu up.
I (365) cpu_start: Pro cpu start user code
I (365) cpu_start: cpu freq: 160000000
I (365) cpu_start: Application information:
I (368) cpu_start: Project name:     chip-all-clusters-app
I (374) cpu_start: App version:      TE9-1048-g126f6b291-dirty
I (380) cpu_start: Compile time:     Jul 12 2022 07:56:50
I (387) cpu_start: ELF file SHA256:  d3b58a68968b94be...
I (393) cpu_start: ESP-IDF:          v4.4.1
I (397) heap_init: Initializing. RAM available for dynamic allocation:
I (405) heap_init: At 3FCA40D0 len 0001BF30 (111 KiB): DRAM
I (411) heap_init: At 3FCC0000 len 0001F060 (124 KiB): STACK/DRAM
I (418) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM
I (424) spi_flash: detected chip: generic
I (429) spi_flash: flash io: dio
I (434) sleep: Configure to isolate all GPIO pins in sleep state
I (439) sleep: Enable automatic switching of GPIO sleep configuration
I (447) coexist: coexist rom version 9387209
I (452) cpu_start: Starting scheduler.
I (463) all-clusters-app: ==================================================
I (463) all-clusters-app: chip-esp32-all-cluster-demo starting
I (473) all-clusters-app: ==================================================
I (483) pp: pp rom version: 9387209
I (483) net80211: net80211 rom version: 9387209
I (503) wifi:wifi driver task: 3fcad210, prio:23, stack:6656, core=0
I (503) system_api: Base MAC address is not set
I (503) system_api: read default base MAC address from EFUSE
I (513) wifi:wifi firmware version: 63017e0
I (513) wifi:wifi certification version: v7.0
I (513) wifi:config NVS flash: enabled
I (523) wifi:config nano formating: disabled
I (523) wifi:Init data frame dynamic rx buffer num: 32
I (523) wifi:Init management frame dynamic rx buffer num: 32
I (533) wifi:Init management short buffer num: 32
I (533) wifi:Init dynamic tx buffer num: 32
I (543) wifi:Init static tx FG buffer num: 2
I (543) wifi:Init static rx buffer size: 1600
I (553) wifi:Init static rx buffer num: 10
I (553) wifi:Init dynamic rx buffer num: 32
I (553) wifi_init: rx ba win: 6
I (563) wifi_init: tcpip mbox: 32
I (563) wifi_init: udp mbox: 6
I (573) wifi_init: tcp mbox: 6
I (573) wifi_init: tcp tx win: 5744
I (573) wifi_init: tcp rx win: 5744
I (583) wifi_init: tcp mss: 1440
I (583) wifi_init: WiFi IRAM OP enabled
I (593) wifi_init: WiFi RX IRAM OP enabled
I (603) chip[DL]: NVS set: chip-counters/reboot-count = 2 (0x2)
I (603) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (613) all-clusters-app: ------------------------Starting App Task---------------------------
W (613) BTDM_INIT: esp_bt_controller_mem_release not implemented, return OK
I (623) BTDM_INIT: BT controller compile version [d913766]
I (633) phy_init: phy_version 909,156dee4,Apr  7 2022,20:27:09
I (623) app-task: This is ESP32 chip with 1 CPU cores, WiFi/BLE,
I (643) app-task: silicon revision 3,
I (663) app-task: 4MB external flash
I (663) chip[SVR]: SetupQRCode: [MT:Y.K9042C00KA0648G00]
I (663) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code:
I (663) chip[SVR]: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3AY.K9042C00KA0648G00
I (683) chip[SVR]: Manual pairing code: [34970112332]
I (683) app-task: App Task started
I (783) BTDM_INIT: Bluetooth MAC: 84:f7:03:60:fb:e6
I (783) NimBLE: GAP procedure initiated: stop advertising.
I (783) CHIP[DL]: BLE host-controller synced
I (1283) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (1283) NimBLE: GAP procedure initiated: advertise;
I (1283) NimBLE: disc_mode=2
I (1283) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1293) NimBLE:
I (1303) chip[DL]: CHIPoBLE advertising started
E (1303) chip[DL]: Long dispatch time: 689 ms, for event type 2
I (1313) chip[DL]: Starting ESP WiFi layer
I (1323) wifi:mode : sta (84:f7:03:60:fb:e4)
I (1323) wifi:enable tsf
W (1323) wifi:Haven't to connect to a suitable AP now!
I (1333) chip[DL]: Done driving station state, nothing else to do...
I (1333) phy: chan:1,max_power:80
I (1343) phy: chan:2,max_power:80
I (1343) phy: chan:3,max_power:80
I (1343) phy: chan:4,max_power:80
I (1353) phy: chan:5,max_power:80
I (1353) phy: chan:6,max_power:80
I (1363) phy: chan:7,max_power:80
I (1363) phy: chan:8,max_power:80
I (1363) phy: chan:9,max_power:80
I (1373) phy: chan:10,max_power:80
I (1373) phy: chan:11,max_power:80
I (1383) phy: chan:12,max_power:80
I (1383) phy: chan:13,max_power:80
I (1383) phy: chan:14,max_power:80
W (1393) wifi:Haven't to connect to a suitable AP now!
I (1393) chip[DL]: Done driving station state, nothing else to do...
I (1403) phy: chan:1,max_power:80
I (1403) phy: chan:2,max_power:80
I (1413) phy: chan:3,max_power:80
I (1413) phy: chan:4,max_power:80
I (1423) phy: chan:5,max_power:80
I (1423) phy: chan:6,max_power:80
I (1423) phy: chan:7,max_power:80
I (1433) phy: chan:8,max_power:80
I (1433) phy: chan:9,max_power:80
I (1443) phy: chan:10,max_power:80
I (1443) phy: chan:11,max_power:80
I (1443) phy: chan:12,max_power:80
I (1453) phy: chan:13,max_power:80
I (1453) phy: chan:14,max_power:80
I (1463) chip[SVR]: Server initializing...
I (1463) chip[TS]: Last Known Good Time: 2022-07-12T08:11:45
I (1473) chip[DMG]: AccessControl: initializing
I (1473) chip[DMG]: Examples::AccessControlDelegate::Init
I (1483) chip[DMG]: AccessControl: setting
I (1483) chip[DMG]: DefaultAclStorage: initializing
I (1493) chip[DMG]: DefaultAclStorage: 0 entries loaded
I (1503) chip[ZCL]: Using ZAP configuration...
I (1513) chip[DMG]: AccessControlCluster: initializing
I (1513) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0030', EndPoint ID: '0x00', Attribute ID: '0x0000'
I (1523) app-devicecallbacks: Unhandled cluster ID: 48
I (1533) app-devicecallbacks: Current free heap: 125380
E (1533) chip[ZCL]: GeneralDiagnostics: Failed to record BootReason event: 3
I (1543) chip[ZCL]: Initiating Admin Commissioning cluster.
I (1553) chip[ZCL]: Door Lock server initialized
I (1553) chip[ZCL]: Initialize PCC Plugin Server Cluster.
I (1563) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001'
I (1573) app-devicecallbacks: Current free heap: 125344
I (1583) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000'
I (1593) app-devicecallbacks: Unhandled cluster ID: 4
I (1593) app-devicecallbacks: Current free heap: 125344
I (1603) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x002b', EndPoint ID: '0x00', Attribute ID: '0x0000'
I (1613) app-devicecallbacks: Unhandled cluster ID: 43
I (1623) app-devicecallbacks: Current free heap: 125344
I (1623) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (1643) app-devicecallbacks: Current free heap: 125344
I (1643) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (1653) app-devicecallbacks: Unhandled cluster ID: 4
I (1663) app-devicecallbacks: Current free heap: 125344
I (1673) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (1683) app-devicecallbacks: Unhandled cluster ID: 5
I (1683) app-devicecallbacks: Current free heap: 125344
I (1693) chip[ZCL]: On/Off set value: 1 0
I (1693) chip[ZCL]: On/off already set to new value
I (1703) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (1713) app-devicecallbacks: Current free heap: 125344
I (1723) chip[ZCL]: Window Covering Cluster init
I (1723) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0102', EndPoint ID: '0x01', Attribute ID: '0x0007'
I (1733) app-devicecallbacks: Unhandled cluster ID: 258
I (1743) app-devicecallbacks: Current free heap: 125344
I (1753) chip[ZCL]: WC POST ATTRIBUTE=7
I (1753) chip[ZCL]: ConfigStatus 0x1B Operational=1 OnlineReserved=1
I (1763) chip[ZCL]: Lift(PA=1 Encoder=0 Reversed=0) Tilt(PA=1 Encoder=0)
I (1773) chip[ZCL]: Initialize PCC Server Cluster [EP:1]
I (1773) chip[ZCL]: Constant Pressure Supported
I (1783) chip[ZCL]: PCC Server: Constant Proportional Pressure Supported
I (1783) chip[ZCL]: PCC Server: Constant Flow Supported
I (1793) chip[ZCL]: PCC Server: Constant Temperature Supported
I (1803) chip[ZCL]: PCC Server: Constant Speed Supported
I (1803) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007'
I (1813) app-devicecallbacks: Unhandled AttributeId ID: '0x0007
I (1823) app-devicecallbacks: Current free heap: 125344
I (1833) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008'
I (1843) app-devicecallbacks: Unhandled AttributeId ID: '0x0008
I (1853) app-devicecallbacks: Current free heap: 125344
I (1853) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001'
I (1863) app-devicecallbacks: Unhandled AttributeId ID: '0x4001
I (1873) app-devicecallbacks: Current free heap: 125344
I (1883) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (1893) app-devicecallbacks: Unhandled cluster ID: 1030
I (1893) app-devicecallbacks: Current free heap: 125344
I (1903) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (1913) app-devicecallbacks: Unhandled cluster ID: 1030
I (1923) app-devicecallbacks: Current free heap: 125344
I (1923) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000'
I (1943) app-devicecallbacks: Unhandled cluster ID: 4
I (1943) app-devicecallbacks: Current free heap: 125344
I (1953) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001'
I (1963) app-devicecallbacks: Unhandled cluster ID: 1030
I (1973) app-devicecallbacks: Current free heap: 125344
I (1973) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002'
I (1983) app-devicecallbacks: Unhandled cluster ID: 1030
I (1993) app-devicecallbacks: Current free heap: 125344
I (2013) chip[DIS]: Updating services using commissioning mode 1
I (2013) chip[DIS]: CHIP minimal mDNS started advertising.
I (2013) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=3840/15
I (2023) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (2033) chip[DIS]: mDNS service published: _matterc._udp
I (2043) chip[IN]: CASE Server enabling CASE session setups
I (2043) chip[SVR]: Joining Multicast groups
I (2053) chip[SVR]: Server Listening...
E (2053) chip[DL]: Long dispatch time: 597 ms, for event type 2
I (2063) app-devicecallbacks: Current free heap: 124384
I (2073) chip[DL]: WIFI_EVENT_STA_START
I (2073) phy: chan:1,max_power:80
I (2073) phy: chan:2,max_power:80
I (2083) phy: chan:3,max_power:80
I (2083) phy: chan:4,max_power:80
I (2093) phy: chan:5,max_power:80
I (2093) phy: chan:6,max_power:80
I (2093) phy: chan:7,max_power:80
I (2103) phy: chan:8,max_power:80
I (2103) phy: chan:9,max_power:80
I (2113) phy: chan:10,max_power:80
I (2113) phy: chan:11,max_power:80
I (2113) phy: chan:12,max_power:80
I (2123) phy: chan:13,max_power:80
I (2123) phy: chan:14,max_power:80
W (2133) wifi:Haven't to connect to a suitable AP now!
I (2133) chip[DL]: Done driving station state, nothing else to do...
I (2143) app-devicecallbacks: Current free heap: 124384
I (2153) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (2163) chip[DL]: Device already advertising, stop active advertisement and restart
I (2163) NimBLE: GAP procedure initiated: stop advertising.
I (2173) NimBLE: GAP procedure initiated: advertise;
I (2183) NimBLE: disc_mode=2
I (2183) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (2193) NimBLE:
I (2193) chip[SVR]: Cannot load binding table: a0
I (10633) chip[DL]: BLE GAP connection established (con 1)
I (10633) chip[DL]: CHIPoBLE advertising stopped
I (10633) app-devicecallbacks: Current free heap: 124392
I (42863) chip[DL]: BLE GAP connection terminated (con 1 reason 0x213)
I (42863) app-devicecallbacks: CHIPoBLE disconnected
I (42863) app-devicecallbacks: Current free heap: 124392
I (42873) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-3840)
I (42883) NimBLE: GAP procedure initiated: advertise;
I (42893) NimBLE: disc_mode=2
I (42893) NimBLE:  adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (42903) NimBLE:
I (42903) chip[DL]: CHIPoBLE advertising started
I (42913) app-devicecallbacks: Current free heap: 124384

$ ln -s sdkconfig_c3devkit.defaults sdkconfig.defaults

This is not required. When you do idf.py set-target esp32c3 the sdkconfig gets updated appropriately. Can you please try with the latest codebase. I am able to get this to work fine with it.

@tatsutaigu Please attach logs instead of pasting, or at least wrap them in <details> bits....

@dhrishi
I tried your suggestion.
However, Timeout occurred.
it may chip-tool issue?
for example, chip-tool has insufficient control of BLE controller?
@bzbarsky-apple
I change it.

Ohh, my bad. I am on the latest commit on my fork which is https://github.com/dhrishi/connectedhomeip/commit/8ebd7f0fd891dc745b2b2eb9fb5a7ea0b241342b (around 63 commits behind) and it works there. I will update to the latest codebase and try

@bzbarsky-apple I am able to perform commissioning and cluster control on the current latest commit on upstream connectedhomeip https://github.com/project-chip/connectedhomeip/commit/51e41f9dfb49727a90b9641621085e60f642a884
Please see attached logs
esp32c3_51e41f9.txt
chip-tool_51e41f9.txt

@dhrishi
Thank for your information.
I tried 51e41f9, but error occurred.
chip-tool-51e41f9.txt
esp32-c3-51e41f9.txt
My environment:
Ubuntu 20.04
Celeron N3350 ( ZBOX PI225 pico )
This environment successfully completed commissioning with test_event_4_2021_07_06.

@dhrishi
I tried
chip-device-ctrl on test_event_4_2021_07_06 and esp32-c3 all-cluster-app on 51e41f9.
NG_chip-device-ctrl-test_event_4_2021_07_06.txt
NG_esp32-c3-51e41f9.txt
chip-device-ctrl on 51e41f9 could not run, it aborted.
Therefore, I cannot test chip-device-ctrl on 51e41f9  and esp32-c3 all-cluster-app on test_event_4_2021_07_06.

@dhrishi
all-cluster-app example on ESP32-C3 is working.
root cause is relation chip-tool and bluetooth adapter.
I inserted bluetooth dongle to USB and I choose dongle via --ble-adapter option on chip-tool, then Timeout error does not occur.
current chip-tool is degradation from test_event_4_2021_07_06
python chip-device-ctrl.
should I change title [ESP32] to [chip-tool]?
and, moderator will change label esp32 to chip-tool?

hci0 : Timeout Error
esp32-c3-0718-hci0.txt
chiptool-0718-hci0.txt

[1658188151.168122][10375:10380] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 53514i
[1658188151.168195][10375:10380] CHIP:CTL: Device failed to receive the CSR request Response: ../../third_party/connectedhomeip/src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout
[1658188151.168231][10375:10380] CHIP:CTL: Error on commissioning step 'SendOpCertSigningRequest': '../../third_party/connectedhomeip/src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout'
[1658188151.168246][10375:10380] CHIP:CTL: Failed to perform commissioning step 9
[1658188151.168260][10375:10380] CHIP:CTL: Going from commissioning step 'SendOpCertSigningRequest' with lastErr = '../../third_party/connectedhomeip/src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout' -> 'Cleanup'
[1658188151.168285][10375:10380] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../third_party/connectedhomeip/src/app/CommandSender.cpp:214: CHIP Error 0x00000032: Timeout'

hic1 : No Error
esp32-c3-0718-hci1.txt
chiptool-0718-hci1.txt

connectedhomeip

$ git log -1
commit aa9457e6b94b735076dff6297176183bf9780177 (HEAD -> master, origin/sve, origin/master, origin/HEAD)
Author: manjunath-grl 102359958+manjunath-grl@users.noreply.github.com
Date:   Sun Jul 17 07:47:19 2022 +0530
Manual and modified script update (#20821)

bluetooth interface on PC

$ hciconfig --all
hci1:	Type: Primary  Bus: USB
BD Address: 00:1B:DC:FE:D1:61  ACL MTU: 310:10  SCO MTU: 64:8
UP RUNNING
RX bytes:6232 acl:171 sco:0 events:135 errors:0
TX bytes:6200 acl:33 sco:0 commands:90 errors:0
Features: 0xff 0xff 0x8f 0xfe 0xdb 0xff 0x5b 0x87
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy: RSWITCH HOLD SNIFF PARK
Link mode: SLAVE ACCEPT
Name: 'tatsutaigu-ZBOX-PI225'
Class: 0x0c0104
Service Classes: Rendering, Capturing
Device Class: Computer, Desktop workstation
HCI Version: 4.0 (0x6)  Revision: 0x22bb
LMP Version: 4.0 (0x6)  Subversion: 0x22bb
Manufacturer: Cambridge Silicon Radio (10)
hci0:	Type: Primary  Bus: USB
BD Address: F4:96:34:8F:7E:96  ACL MTU: 1021:5  SCO MTU: 96:6
UP RUNNING
RX bytes:2330 acl:0 sco:0 events:253 errors:0
TX bytes:41862 acl:0 sco:0 commands:252 errors:0
Features: 0xff 0xfe 0x0f 0xfe 0xdb 0xff 0x7b 0x87
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy: RSWITCH HOLD SNIFF
Link mode: SLAVE ACCEPT
Name: 'tatsutaigu-ZBOX-PI225 #1'
Class: 0x0c0104
Service Classes: Rendering, Capturing
Device Class: Computer, Desktop workstation
HCI Version: 4.2 (0x8)  Revision: 0x1000
LMP Version: 4.2 (0x8)  Subversion: 0x1000
Manufacturer: Intel Corp. (2)

Hi,
I use below commit ID, then It is resolved.
commit 513235823b2a1f6b5a299f71feef9e28c95dc1cf (HEAD -> master, origin/master, origin/HEAD)

authors: bzbarsky-apple dhrishi tatsutaigu


text:
Linux address iteration uses deprecated/temporary and other generally "no usable" Ip addresses

Problem
The API that linux uses for fetching IP addresses is not aware of interface flags.
As a result, addresses marked temporary (before Duplicate Address Detection/DAD) or deprecated addresses (from old routing advertisements) are still used and reported as DNSSD 'usable addresses'
Proposed Solution
Figure out a way to better filter usable addresses.
One step would be to have a linux-specific platform implementation that is more aware of address flags (e.g. using libnl).
Another step would be to allow for hooks in DNSSD (minmdns specifically) for better integration for applications to control IP address logic, like what interface to advertise on and which IP address(es) to allow for such advertisement.

Note that this is a potential improvement for #21736 - using deprecated addresses has the potential to saturate a network with more multicast data than expected.

source: gharchive/issue

repo: project-chip/connectedhomeip

license_type: permissive

license_source: github-api


text:
Convert if ZEPHYR to if defined(ZEPHYR)

Fix building with -Wundef on non-Zephyr platforms.

@rojer So we never have __ZEPHYR__ defined but set to 0?

i'm not using Zephyr myself but that would be... weird.

source: gharchive/pull-request


text:
Remove the MTR_PER_CONTROLLER_STORAGE_ENABLED define.

This is now enabled unconditionally.  Also allows us to remove the wrapper headers we had to allow us to use the per-controller storage bits internally.

Fast-tracking Darwin-only change.

authors: bzbarsky-apple ksperling-apple


text:
Make it possible to use lock-protected state in MTRDevice_Concrete's description.

We need _descriptionWhileLocked for use from places where the lock is already held.

Per conversation with @jtung-apple we came up with a less brittle approach: have any state description needs be stored separately, protected by a separate lock, and get updated while both that lock and the overall state lock are held.


text:
Give user choice whether they want to use Zigbee or Matter

(This bug probably depends on another bug within the same context: https://github.com/project-chip/zap/issues/554. They should probably be worked on together.)
When database is populated by BOTH Zigbee and Matter metadata, then when user does a "New Configuration", then they first have to choose which existing metadata they will use.
How to reproduce:
1.) Run npm run zapall, which starts up zap with both Matter and Zigbee loaded.
2.) Observe a printout: Multiple toplevel zcl.properties found. Using the first one from args: 2 which comes from util.initializeSessionPackage(). This is the spot where code detects this condition.
Goal:
we need to change this flow, so that if back-end can't create a new configuration, because there is MORE THAN ONE toplevel zcl file, it needs to stop there, and present the user with a dialog, that shows options, allows them to pick ONE and ONLY ONE, and then goes back to creating the session with the chosen option.

@Mehradml
Description how this would work...
CASE 1: user creates a "New Configuration", either because they fired up zap from scratch, or because they clicked "File -> New Configuration...". The flow is as follows:
1.) Logic should check "zcl-properties" packages types and "gen-templates-json" package types.
2.) Before a new configuration is created, a user needs to be presented with a DIALOG, that allows them to choose:
a.) ONE AND ONLY ONE of the zcl-properties package type.
b.) ZERO OR MORE of the gen-templates-json package types.
3.) User picks and once the valid data is selected, the new session is created and opened in the ui.
CASE 2: user opens a ".zap" file, and the session is about to be created. At this point, the correct packages need to be associated with the zap file. Note that ZAP file DOES ALREADY contain information about which packages it was created with.
1.) Logic should analyze the packages listed in .zap file, vs packages listed in the database.
2.) IF 100% matching packages are found (same paths, same versions, etc), then file is opened, NOTHING is shown to users.
3.) IF things don't match, then a similar DIALOG is shown as the one above for "new configuration". It shows and allows users to select:
a.) Which of the zcl-properties should be used.
b.) Which of the gen-templates-json should be used.
4.) This dialog should be aware of whether it's just a "version" or also "category" that is different. Opening a Zigbee file from 1.0 with Zigbee 2.0 is an EXPECTED operation. However, opening a Matter file with Zigbee package is more weird, and there should probably be a dialog.

repo: project-chip/zap

license_source: bigquery


text:
CLI Architecture Document

We need a document that details the desired architecture for the CodeFlare  SDK.
This task depends on #158 being complete.

https://docs.google.com/document/d/1f8b5jWhbatbhjuJaPKon56Hq_4R4-TK1Th7I9NN_hFg/edit

#253

authors: MichaelClifford carsonmh

repo: project-codeflare/codeflare-sdk


text:
Enable timeout when disconnecting a source thread

Enable timeout when disconnecting a source thread. This means that the thread that is either reading new events or managing Kafka consumers will be joinable if not stuck. If stuck the timer will expire without the thread being joined and will then be killed along with the application.

Closed by https://github.com/project-codeflare/rayvens/pull/53

repo: project-codeflare/rayvens


text:
fix: google distroless patching for libssl1.1

Match naming of libssl1.1 status.d control file to match libssl1 as provided by the distroless base image. This implementation truncates all package file names to the first period, which does not affect other existing packages in the base images seen in the distroless images test set, but may need to be revisited if that behavior changes.
Add test case for distroless libssl1.1 patching.
Fix failure to copy unpacked update files to target image if the tooling image already has the latest versions of the files. dpkg.go now unpacks the update files to a separate root and copies those into a layer for merge into the target image instead of relying of a diff layer after unpacking the update files into the tooling image.
Clarify in comments for rpm.go why the distroless patching behavior differs from dpkg.go.

Closes #37

Codecov Report
Base: 100.00% // Head: 100.00% // No change to project coverage :thumbsup:

Coverage data is based on head (588d8d7) compared to base (e28c02d).
Patch has no changes to coverable lines.

:exclamation: Current head 588d8d7 differs from pull request most recent head 534f291. Consider uploading reports for the commit 534f291 to get more accurate results

Additional details and impacted files
@@            Coverage Diff            @@
##              main       #41   +/-   ##
=========================================
  Coverage   100.00%   100.00%
=========================================
  Files            2         2
  Lines           27        27
=========================================
  Hits            27        27

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

:umbrella: View full report at Codecov.
:loudspeaker: Do you have feedback about the report comment? Let us know in this issue.

authors: CodeMonkeyLeet codecov-commenter

repo: project-copacetic/copacetic


text:
'Add a Source' empty state button no longer functions

Describe the bug
'Add a Source' empty state button no longer functions
To Reproduce
Steps to reproduce the behavior:

Go to Overview page (with no providers added)
Click on 'Add a Source' button in center of page
Button highlights but nothing happens

Expected behavior
Button should work correctly to load now modal
Screenshots

Desktop (please complete the following information):

OS: Fedora
Browser Chrome
Version 66

Additional context
Testing against CI insightsbeta

I think I know why.

repo: project-koku/koku-ui


text:
Fix intl mock for cost models table test

The recent PatternFly table upgrade is generating the test error below. The containerized build is failing, so new PRs are blocked from merging.

Codecov Report

Merging #2803 (00f54d9) into main (a197f42) will not change coverage.
The diff coverage is n/a.

@@           Coverage Diff           @@
##             main    #2803   +/-   ##
=======================================
  Coverage   65.74%   65.74%
=======================================
  Files         485      485
  Lines        9341     9341
  Branches     2158     2158
=======================================
  Hits         6141     6141
  Misses       3197     3197
  Partials        3        3

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update a197f42...00f54d9. Read the comment docs.

authors: codecov-commenter dlabrecq


text:
Full proofs of inverse_mix_columns

Resolves #295
This PR fills in the last two admits that were left in #504, which stated that modular multiplication in the AES byte field was associative and distributive.
The strategy here is very computational; after investigating a bit and determining that proving the properties we needed in full generality (i.e. for all polynomials) would likely be very time-consuming, I took advantage of the fact that the AES field has a fixed modulus to write explicit expressions in terms of the input for modular reduction, multiplication, and addition in terms of GF(2) (bit) operations, and then used Coq's ring tactic to prove these equivalent.
Because of the computational strategy (which results in pretty large expressions), the proofs are unfortunately pretty slow. Compiling MixColumns.v takes about a minute on my laptop. The proofs have few dependencies, though, so they should be highly parallelizable and hopefully won't do too much damage to our CI time.
CC @cipher1024 The explicit formulas for byte multiplication/modulo might be helpful for mix_columns proofs.

Looks like the CI does parallelize this well enough to avoid a major performance hit -- I ran the CI twice, and got one run on the high end of our recent CI runtimes and one on the low end.

repo: project-oak/silveroak