[1699019674.282266][1138:1138] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1699019674.309943][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-PFlQJ9) [1699019674.312371][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019674.326886][1138:1138] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1699019674.326943][1138:1138] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1699019674.356123][1138:1138] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1699019674.356493][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-BYzasY) [1699019674.356701][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1699019674.356873][1138:1138] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1699019674.357046][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_config.ini-Jnnd3Y) [1699019674.357192][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1699019674.357375][1138:1138] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1699019674.357500][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-twdB2K) [1699019674.357638][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1699019674.358309][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-l9uWmS) [1699019674.359675][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1699019674.359751][1138:1138] CHIP:DL: NVS set: chip-factory/unique-id = "925F14EF3B97F8B7" [1699019674.360005][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-ZeFj3e) [1699019674.360776][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1699019674.360867][1138:1138] CHIP:DL: NVS set: chip-factory/vendor-id = 65521 (0xFFF1) [1699019674.361085][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-fCMttt) [1699019674.361556][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1699019674.361619][1138:1138] CHIP:DL: NVS set: chip-factory/product-id = 32769 (0x8001) [1699019674.361791][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-NpECzt) [1699019674.362148][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1699019674.362318][1138:1138] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1) [1699019674.362563][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-8OTQ0Y) [1699019674.363468][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1699019674.363537][1138:1138] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1699019674.363746][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-TaXKdM) [1699019674.364650][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1699019674.364720][1138:1138] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0) [1699019674.364917][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_config.ini-rhIWgn) [1699019674.365247][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1699019674.365315][1138:1138] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1699019674.365513][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_config.ini-t1tKfZ) [1699019674.367027][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1699019674.367113][1138:1138] CHIP:DL: NVS set: chip-config/location-capability = 2 (0x2) [1699019674.372393][1138:1138] CHIP:DL: Got Ethernet interface: eth0 [1699019674.376347][1138:1138] CHIP:DL: Found the primary Ethernet interface:eth0 [1699019674.376829][1138:1138] CHIP:DL: Got WiFi interface: wlan0 [1699019674.376904][1138:1138] CHIP:DL: Failed to reset WiFi statistic counts [1699019674.376952][1138:1138] CHIP:SPT: *** WARNING: Using temporary passcode 20202021 due to no neither --passcode or --spake2p-verifier-base64 given on command line. This is temporary and will disappear. Please update your scripts to explicitly configure onboarding credentials. *** [1699019674.377012][1138:1138] CHIP:SPT: PASE PBKDF iterations set to 1000 [1699019674.377072][1138:1138] CHIP:SPT: LinuxCommissionableDataProvider didn't get a PASE salt, generating one. [1699019674.419173][1138:1138] CHIP:DL: Device Configuration: [1699019674.419338][1138:1138] CHIP:DL: Serial Number: TEST_SN [1699019674.419436][1138:1138] CHIP:DL: Vendor Id: 65521 (0xFFF1) [1699019674.419520][1138:1138] CHIP:DL: Product Id: 32769 (0x8001) [1699019674.419538][1138:1138] CHIP:DL: Product Name: TEST_PRODUCT [1699019674.419608][1138:1138] CHIP:DL: Hardware Version: 0 [1699019674.419628][1138:1138] CHIP:DL: Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 [1699019674.419643][1138:1138] CHIP:DL: Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 18 (0x12) [1699019674.419720][1138:1138] CHIP:DL: Manufacturing Date: (not set) [1699019674.419736][1138:1138] CHIP:DL: Device Type: 257 (0x101) [1699019674.419747][1138:1138] CHIP:-: ==== Onboarding payload for Standard Commissioning Flow ==== [1699019674.424102][1138:1138] CHIP:SVR: SetupQRCode: [MT:-24J0KQS02-Z.548G00] [1699019674.427743][1138:1138] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code: [1699019674.427767][1138:1138] CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J0KQS02-Z.548G00 [1699019674.427835][1138:1138] CHIP:SVR: Manual pairing code: [00054912336] [1699019674.428112][1138:1139] CHIP:DL: wpa_supplicant: Start WiFi management [1699019674.489915][1138:1139] CHIP:DL: wpa_supplicant: connected to wpa_supplicant proxy [1699019674.492204][1138:1139] CHIP:DL: wpa_supplicant: WiFi interface: /fi/w1/wpa_supplicant1/Interfaces/0 [1699019674.513519][1138:1139] CHIP:DL: wpa_supplicant: connected to wpa_supplicant interface proxy [1699019674.514198][1138:1139] CHIP:DL: wpa_supplicant: connected to wpa_supplicant bss proxy [1699019674.568411][1138:1138] CHIP:SVR: Initializing subscription resumption storage... [1699019674.568987][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-kLKfzX) [1699019674.569707][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019674.569867][1138:1138] CHIP:SVR: Server initializing... [1699019674.569994][1138:1138] CHIP:FP: Initializing FabricTable from persistent storage [1699019674.573272][1138:1138] CHIP:TS: Last Known Good Time: [unknown] [1699019674.573327][1138:1138] CHIP:TS: Setting Last Known Good Time to firmware build time 2023-10-14T01:16:48 [1699019674.573602][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-hQu3KH) [1699019674.574421][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019674.574657][1138:1138] CHIP:DMG: AccessControl: initializing [1699019674.579170][1138:1138] CHIP:DMG: Examples::AccessControlDelegate::Init [1699019674.579228][1138:1138] CHIP:DMG: AccessControl: setting [1699019674.579256][1138:1138] CHIP:DMG: DefaultAclStorage: initializing [1699019674.582616][1138:1138] CHIP:DMG: DefaultAclStorage: 0 entries loaded [1699019674.582721][1138:1138] CHIP:IN: UDP::Init bind&listen port=5540 [1699019674.582958][1138:1138] CHIP:IN: UDP::Init bound to port=5540 [1699019674.583023][1138:1138] CHIP:IN: UDP::Init bind&listen port=5540 [1699019674.583149][1138:1138] CHIP:IN: UDP::Init bound to port=5540 [1699019674.583175][1138:1138] CHIP:IN: BLEBase::Init - setting/overriding transport [1699019674.583602][1138:1138] CHIP:IN: TransportMgr initialized [1699019674.584253][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-oNjInL) [1699019674.585186][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019674.585550][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-FRcsCl) [1699019674.586764][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019674.593785][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-vhWU6W) [1699019674.594599][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019674.594732][1138:1138] CHIP:ZCL: Using ZAP configuration... [1699019674.603648][1138:1138] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.607362][1138:1138] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.607433][1138:1138] CHIP:DMG: Failed to read stored attribute (0, 0x0000_002B, 0x0000_0000: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.607524][1138:1138] CHIP:DMG: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0000: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.607570][1138:1138] CHIP:DMG: Failed to read stored attribute (0, 0x0000_002C, 0x0000_0001: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.607684][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0006, 0x0000_0000: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.607747][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0006, 0x0000_4003: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.607795][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0008, 0x0000_0000: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.607852][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0008, 0x0000_4000: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.607903][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_0000: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.607948][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_0001: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.607994][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_0003: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.608038][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_0004: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.608086][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_0007: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.608131][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_0008: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.608198][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_4000: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.608244][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_4001: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.608289][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_4002: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.608365][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_4003: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.608418][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_4004: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.608473][1138:1138] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0300, 0x0000_4010: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage [1699019674.608503][1138:1138] CHIP:DMG: AccessControlCluster: initializing [1699019674.612082][1138:1138] CHIP:ZCL: Initiating Admin Commissioning cluster. [1699019674.615657][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 373af31e [1699019674.619467][1138:1138] CHIP:ZCL: GeneralDiagnostics: OnDeviceReboot [1699019674.623065][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_0033 update version to bc952416 [1699019674.629104][1138:1138] CHIP:EVL: LogEvent event number: 0x0000000000000000 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0033 event id: 0x3 Epoch timestamp: 0x0000018B9576D3FF [1699019674.629342][1138:1138] CHIP:DMG: Endpoint 1, Cluster 0x0000_0005 update version to 3fea88e8 [1699019674.629376][1138:1138] CHIP:DMG: Endpoint 1, Cluster 0x0000_0005 update version to 3fea88e9 [1699019674.629396][1138:1138] CHIP:DMG: Endpoint 1, Cluster 0x0000_0005 update version to 3fea88ea [1699019674.633067][1138:1138] CHIP:DMG: Endpoint 1, Cluster 0x0000_0004 update version to 31eaf7cb [1699019674.633117][1138:1138] CHIP:DMG: Endpoint 1, Cluster 0x0000_0004 update version to 31eaf7cc [1699019674.633155][1138:1138] CHIP:ZCL: Endpoint 1 On/off already set to new value [1699019674.637173][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-s1CFnY) [1699019674.637971][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019674.638118][1138:1138] CHIP:DMG: Endpoint 1, Cluster 0x0000_0008 update version to df708da [1699019674.638417][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-JdRJl5) [1699019674.639796][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019674.639877][1138:1138] CHIP:DMG: Endpoint 1, Cluster 0x0000_0300 update version to a46dd320 [1699019674.640165][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-GONDCZ) [1699019674.641393][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019674.641495][1138:1138] CHIP:DMG: Endpoint 1, Cluster 0x0000_0300 update version to a46dd321 [1699019674.641763][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-bLN3VG) [1699019674.642973][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019674.643074][1138:1138] CHIP:DMG: Endpoint 1, Cluster 0x0000_0300 update version to a46dd322 [1699019674.643136][1138:1138] CHIP:DMG: Endpoint 1, Cluster 0x0000_0406 update version to 7c73aec3 [1699019674.643158][1138:1138] CHIP:DMG: Endpoint 1, Cluster 0x0000_0406 update version to 7c73aec4 [1699019674.643494][1138:1138] CHIP:IN: SecureSession[0xffffb130fb80]: Allocated Type:1 LSID:54336 [1699019674.643547][1138:1138] CHIP:SC: Assigned local session key ID 54336 [1699019674.643583][1138:1138] CHIP:SC: Waiting for PBKDF param request [1699019674.643623][1138:1138] CHIP:DIS: Updating services using commissioning mode 1 [1699019674.649816][1138:1138] CHIP:DIS: CHIP minimal mDNS started advertising. [1699019674.657039][1138:1138] CHIP:DL: Using wifi MAC for hostname [1699019674.657324][1138:1138] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=0018/00 cm=1 [1699019674.657458][1138:1138] CHIP:DIS: Responding with _matterc._udp.local [1699019674.657488][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019674.657507][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019674.657535][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019674.657578][1138:1138] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1699019674.657621][1138:1138] CHIP:DIS: Responding with _T257._sub._matterc._udp.local [1699019674.657646][1138:1138] CHIP:DIS: Responding with _S0._sub._matterc._udp.local [1699019674.657670][1138:1138] CHIP:DIS: Responding with _L18._sub._matterc._udp.local [1699019674.657692][1138:1138] CHIP:DIS: Responding with _CM._sub._matterc._udp.local [1699019674.657752][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019674.657767][1138:1138] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 1C38831F578D63AF. [1699019674.659429][1138:1138] CHIP:DIS: mDNS service published: _matterc._udp [1699019674.659485][1138:1138] CHIP:DIS: Updating services using commissioning mode 1 [1699019674.660877][1138:1138] CHIP:DIS: CHIP minimal mDNS started advertising. [1699019674.664263][1138:1138] CHIP:DL: Using wifi MAC for hostname [1699019674.664538][1138:1138] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=0018/00 cm=1 [1699019674.664656][1138:1138] CHIP:DIS: Responding with _matterc._udp.local [1699019674.664701][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019674.664718][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019674.664733][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019674.664774][1138:1138] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1699019674.664805][1138:1138] CHIP:DIS: Responding with _T257._sub._matterc._udp.local [1699019674.664830][1138:1138] CHIP:DIS: Responding with _S0._sub._matterc._udp.local [1699019674.664853][1138:1138] CHIP:DIS: Responding with _L18._sub._matterc._udp.local [1699019674.664876][1138:1138] CHIP:DIS: Responding with _CM._sub._matterc._udp.local [1699019674.664934][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019674.664948][1138:1138] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 1C38831F578D63AF. [1699019674.666602][1138:1138] CHIP:DIS: mDNS service published: _matterc._udp [1699019674.666681][1138:1138] CHIP:IN: CASE Server enabling CASE session setups [1699019674.669091][1138:1138] CHIP:IN: SecureSession[0xffffb130fa40]: Allocated Type:2 LSID:54337 [1699019674.669204][1138:1138] CHIP:SC: Allocated SecureSession (0xffffb130fa40) - waiting for Sigma1 msg [1699019674.669248][1138:1138] CHIP:SVR: Joining Multicast groups [1699019674.669303][1138:1138] CHIP:ZCL: Emitting StartUp event [1699019674.673154][1138:1138] CHIP:EVL: LogEvent event number: 0x0000000000000001 priority: 2, endpoint id: 0x0 cluster id: 0x0000_0028 event id: 0x0 Epoch timestamp: 0x0000018B9576D430 [1699019674.673220][1138:1138] CHIP:SVR: Server Listening... [1699019674.673239][1138:1138] CHIP:DL: Device Configuration: [1699019674.673382][1138:1138] CHIP:DL: Serial Number: TEST_SN [1699019674.673452][1138:1138] CHIP:DL: Vendor Id: 65521 (0xFFF1) [1699019674.673557][1138:1138] CHIP:DL: Product Id: 32769 (0x8001) [1699019674.673575][1138:1138] CHIP:DL: Product Name: TEST_PRODUCT [1699019674.673635][1138:1138] CHIP:DL: Hardware Version: 0 [1699019674.673653][1138:1138] CHIP:DL: Setup Pin Code (0 for UNKNOWN/ERROR): 20202021 [1699019674.673667][1138:1138] CHIP:DL: Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 18 (0x12) [1699019674.673724][1138:1138] CHIP:DL: Manufacturing Date: (not set) [1699019674.673741][1138:1138] CHIP:DL: Device Type: 257 (0x101) [1699019674.673812][1138:1138] CHIP:SVR: SetupQRCode: [MT:-24J0KQS02-Z.548G00] [1699019674.673848][1138:1138] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code: [1699019674.673859][1138:1138] CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J0KQS02-Z.548G00 [1699019674.673900][1138:1138] CHIP:SVR: Manual pairing code: [00054912336] [1699019674.682343][1138:1139] CHIP:DL: TRACE: Bus acquired for name MATTER-0018 [1699019674.683471][1138:1139] CHIP:DL: CREATE service object at /chipoble/0472/service [1699019674.686558][1138:1139] CHIP:DL: Create characteristic object at /chipoble/0472/service/c1 [1699019674.688611][1138:1139] CHIP:DL: Create characteristic object at /chipoble/0472/service/c2 [1699019674.689754][1138:1139] CHIP:DL: CHIP BTP C1 /chipoble/0472/service [1699019674.689792][1138:1139] CHIP:DL: CHIP BTP C2 /chipoble/0472/service [1699019674.689804][1138:1139] CHIP:DL: CHIP_ENABLE_ADDITIONAL_DATA_ADVERTISING is FALSE [1699019674.705942][1138:1138] CHIP:DL: PlatformBlueZInit init success [1699019674.707628][1138:1138] CHIP:DL: wpa_supplicant: disabling auto scan [1699019674.715540][1138:1139] CHIP:DL: BluezPeripheralRegisterAppDone done [1699019674.715695][1138:1138] CHIP:DL: HandlePlatformSpecificBLEEvent 16392 [1699019674.715863][1138:1139] CHIP:DL: Create adv object at /chipoble/0472/advertising [1699019674.724798][1138:1139] CHIP:DL: SET service data to {'0xFFF6': <[byte 0x00, 0x12, 0x00, 0xf1, 0xff, 0x01, 0x80, 0x00]>} [1699019674.726599][1138:1138] CHIP:DL: HandlePlatformSpecificBLEEvent 16393 [1699019674.726643][1138:1138] CHIP:DL: CHIPoBLE advertising config complete [1699019674.738119][1138:1139] CHIP:DL: RegisterAdvertisement complete [1699019674.738339][1138:1138] CHIP:DL: HandlePlatformSpecificBLEEvent 16394 [1699019681.168036][1138:1139] CHIP:DL: BLE device connected: conn 0xffffb2508de0, device E4:5F:01:0A:DA:38, path /org/bluez/hci0/dev_E4_5F_01_0A_DA_38 [1699019682.951263][1138:1139] CHIP:DL: BluezCharacteristicAcquireWrite is called, conn: 0xffffb2508de0 [1699019682.960968][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019682.961273][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019682.961627][1138:1138] CHIP:BLE: local and remote recv window sizes = 6 [1699019682.961665][1138:1138] CHIP:BLE: selected BTP version 4 [1699019682.961686][1138:1138] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244. [1699019683.099167][1138:1139] CHIP:DL: CHIPoBLE subscribe received [1699019683.100643][1138:1138] CHIP:IN: BLE EndPoint 0xaaaae610bb00 Connection Complete [1699019683.100773][1138:1138] CHIP:DL: HandlePlatformSpecificBLEEvent 32775 [1699019683.102164][1138:1138] CHIP:DL: Receive kCHIPoBLEConnectionEstablished [1699019683.195670][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019683.195905][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019683.197478][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019683.204736][1138:1138] CHIP:EM: >>> [E:2443r S:0 M:236165707] (U) Msg RX from 0:52FA4627EB740A72 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [1699019683.204949][1138:1138] CHIP:EM: Handling via exchange: 2443r, Delegate: 0xaaaae610a390 [1699019683.208179][1138:1138] CHIP:SC: Received PBKDF param request [1699019683.208739][1138:1138] CHIP:SC: Peer assigned session ID 34653 [1699019683.209860][1138:1138] CHIP:EM: <<< [E:2443r S:0 M:147505730] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [1699019683.210497][1138:1138] CHIP:SC: Sent PBKDF param response [1699019683.210544][1138:1138] CHIP:SVR: Commissioning session establishment step started [1699019683.293132][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019683.293470][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019683.296161][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019683.299707][1138:1138] CHIP:EM: >>> [E:2443r S:0 M:236165708] (U) Msg RX from 0:52FA4627EB740A72 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) [1699019683.299829][1138:1138] CHIP:EM: Found matching exchange: 2443r, Delegate: 0xaaaae610a390 [1699019683.299992][1138:1138] CHIP:SC: Received spake2p msg1 [1699019683.305433][1138:1138] CHIP:EM: <<< [E:2443r S:0 M:147505731] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:23 (SecureChannel:PASE_Pake2) [1699019683.306030][1138:1138] CHIP:SC: Sent spake2p msg2 [1699019683.389869][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019683.390740][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019683.393354][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019683.393942][1138:1138] CHIP:EM: >>> [E:2443r S:0 M:236165709] (U) Msg RX from 0:52FA4627EB740A72 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) [1699019683.394033][1138:1138] CHIP:EM: Found matching exchange: 2443r, Delegate: 0xaaaae610a390 [1699019683.394208][1138:1138] CHIP:SC: Received spake2p msg3 [1699019683.394585][1138:1138] CHIP:SC: Sending status report. Protocol code 0, exchange 2443 [1699019683.394760][1138:1138] CHIP:EM: <<< [E:2443r S:0 M:147505732] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:40 (SecureChannel:StatusReport) [1699019683.398511][1138:1138] CHIP:SC: SecureSession[0xffffb130fb80, LSID:54336]: State change 'kEstablishing' --> 'kActive' [1699019683.398599][1138:1138] CHIP:IN: SecureSession[0xffffb130fb80]: Activated - Type:1 LSID:54336 [1699019683.398639][1138:1138] CHIP:IN: New secure session activated for device , LSID:54336 PSID:34653! [1699019683.398727][1138:1138] CHIP:SVR: Commissioning completed session establishment step [1699019683.399257][1138:1138] CHIP:DIS: Updating services using commissioning mode 0 [1699019683.401861][1138:1138] CHIP:DIS: CHIP minimal mDNS started advertising. [1699019683.405396][1138:1138] CHIP:DL: Using wifi MAC for hostname [1699019683.405680][1138:1138] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=0018/00 cm=0 [1699019683.405772][1138:1138] CHIP:DIS: Responding with _matterc._udp.local [1699019683.405801][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019683.405821][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019683.405840][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019683.405873][1138:1138] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1699019683.405901][1138:1138] CHIP:DIS: Responding with _T257._sub._matterc._udp.local [1699019683.405940][1138:1138] CHIP:DIS: Responding with _S0._sub._matterc._udp.local [1699019683.405969][1138:1138] CHIP:DIS: Responding with _L18._sub._matterc._udp.local [1699019683.406037][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019683.406053][1138:1138] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 1C38831F578D63AF. [1699019683.407683][1138:1138] CHIP:DIS: mDNS service published: _matterc._udp [1699019683.407724][1138:1138] CHIP:DIS: Scheduling extended discovery timeout in 900s [1699019683.407858][1138:1138] CHIP:SVR: Device completed Rendezvous process [1699019683.411217][1138:1139] CHIP:DL: UnregisterAdvertisement complete [1699019683.411433][1138:1138] CHIP:DL: HandlePlatformSpecificBLEEvent 16395 [1699019683.411454][1138:1138] CHIP:DL: CHIPoBLE advertising stopped [1699019683.488208][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019683.488901][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019683.491330][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019683.492442][1138:1138] CHIP:EM: >>> [E:2444r S:54336 M:208478989] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) [1699019683.492570][1138:1138] CHIP:EM: Handling via exchange: 2444r, Delegate: 0xaaaae60ff308 [1699019683.496308][1138:1138] CHIP:IM: Received Read request [1699019683.500203][1138:1138] CHIP:DMG: ReadRequestMessage = [1699019683.500282][1138:1138] CHIP:DMG: { [1699019683.500305][1138:1138] CHIP:DMG: AttributePathIBs = [1699019683.500327][1138:1138] CHIP:DMG: [ [1699019683.502503][1138:1138] CHIP:DMG: AttributePathIB = [1699019683.502553][1138:1138] CHIP:DMG: { [1699019683.502576][1138:1138] CHIP:DMG: Cluster = 0x31, [1699019683.502595][1138:1138] CHIP:DMG: Attribute = 0x0000_FFFC, [1699019683.502609][1138:1138] CHIP:DMG: } [1699019683.502645][1138:1138] CHIP:DMG: [1699019683.502659][1138:1138] CHIP:DMG: AttributePathIB = [1699019683.502680][1138:1138] CHIP:DMG: { [1699019683.502697][1138:1138] CHIP:DMG: Endpoint = 0x0, [1699019683.502715][1138:1138] CHIP:DMG: Cluster = 0x30, [1699019683.502733][1138:1138] CHIP:DMG: Attribute = 0x0000_0000, [1699019683.502745][1138:1138] CHIP:DMG: } [1699019683.502766][1138:1138] CHIP:DMG: [1699019683.502780][1138:1138] CHIP:DMG: AttributePathIB = [1699019683.502796][1138:1138] CHIP:DMG: { [1699019683.502813][1138:1138] CHIP:DMG: Endpoint = 0x0, [1699019683.502831][1138:1138] CHIP:DMG: Cluster = 0x30, [1699019683.502848][1138:1138] CHIP:DMG: Attribute = 0x0000_0001, [1699019683.502860][1138:1138] CHIP:DMG: } [1699019683.502881][1138:1138] CHIP:DMG: [1699019683.502895][1138:1138] CHIP:DMG: AttributePathIB = [1699019683.502911][1138:1138] CHIP:DMG: { [1699019683.502928][1138:1138] CHIP:DMG: Endpoint = 0x0, [1699019683.502946][1138:1138] CHIP:DMG: Cluster = 0x30, [1699019683.502962][1138:1138] CHIP:DMG: Attribute = 0x0000_0002, [1699019683.502975][1138:1138] CHIP:DMG: } [1699019683.502996][1138:1138] CHIP:DMG: [1699019683.503010][1138:1138] CHIP:DMG: AttributePathIB = [1699019683.503026][1138:1138] CHIP:DMG: { [1699019683.503043][1138:1138] CHIP:DMG: Endpoint = 0x0, [1699019683.503061][1138:1138] CHIP:DMG: Cluster = 0x30, [1699019683.503077][1138:1138] CHIP:DMG: Attribute = 0x0000_0003, [1699019683.503090][1138:1138] CHIP:DMG: } [1699019683.503111][1138:1138] CHIP:DMG: [1699019683.503124][1138:1138] CHIP:DMG: AttributePathIB = [1699019683.503140][1138:1138] CHIP:DMG: { [1699019683.503158][1138:1138] CHIP:DMG: Endpoint = 0x0, [1699019683.503175][1138:1138] CHIP:DMG: Cluster = 0x28, [1699019683.503191][1138:1138] CHIP:DMG: Attribute = 0x0000_0002, [1699019683.503203][1138:1138] CHIP:DMG: } [1699019683.503223][1138:1138] CHIP:DMG: [1699019683.503238][1138:1138] CHIP:DMG: AttributePathIB = [1699019683.503254][1138:1138] CHIP:DMG: { [1699019683.503270][1138:1138] CHIP:DMG: Endpoint = 0x0, [1699019683.503286][1138:1138] CHIP:DMG: Cluster = 0x28, [1699019683.503304][1138:1138] CHIP:DMG: Attribute = 0x0000_0004, [1699019683.503316][1138:1138] CHIP:DMG: } [1699019683.503335][1138:1138] CHIP:DMG: [1699019683.503349][1138:1138] CHIP:DMG: AttributePathIB = [1699019683.503365][1138:1138] CHIP:DMG: { [1699019683.503382][1138:1138] CHIP:DMG: Cluster = 0x31, [1699019683.503399][1138:1138] CHIP:DMG: Attribute = 0x0000_0003, [1699019683.503411][1138:1138] CHIP:DMG: } [1699019683.503431][1138:1138] CHIP:DMG: [1699019683.503445][1138:1138] CHIP:DMG: AttributePathIB = [1699019683.503461][1138:1138] CHIP:DMG: { [1699019683.503478][1138:1138] CHIP:DMG: Endpoint = 0x0, [1699019683.503495][1138:1138] CHIP:DMG: Cluster = 0x38, [1699019683.503507][1138:1138] CHIP:DMG: } [1699019683.503526][1138:1138] CHIP:DMG: [1699019683.503539][1138:1138] CHIP:DMG: ], [1699019683.503596][1138:1138] CHIP:DMG: [1699019683.503619][1138:1138] CHIP:DMG: isFabricFiltered = false, [1699019683.503636][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019683.503649][1138:1138] CHIP:DMG: }, [1699019683.504454][1138:1138] CHIP:DMG: IM RH moving to [CanStartReporting] [1699019683.504760][1138:1138] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 [1699019683.504805][1138:1138] CHIP:DMG: Cluster 31, Attribute 3 is dirty [1699019683.504824][1138:1138] CHIP:DMG: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1) [1699019683.511500][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v [1699019683.511567][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019683.511922][1138:1138] CHIP:DMG: Cluster 28, Attribute 4 is dirty [1699019683.511949][1138:1138] CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) [1699019683.511986][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v [1699019683.512001][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019683.512228][1138:1138] CHIP:DMG: Cluster 28, Attribute 2 is dirty [1699019683.512247][1138:1138] CHIP:DMG: Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) [1699019683.512265][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0028 e=0 p=v [1699019683.512282][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019683.512376][1138:1138] CHIP:DMG: Cluster 30, Attribute 3 is dirty [1699019683.512393][1138:1138] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0) [1699019683.512409][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v [1699019683.512424][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019683.512535][1138:1138] CHIP:DMG: Cluster 30, Attribute 2 is dirty [1699019683.512551][1138:1138] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0) [1699019683.512567][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v [1699019683.512581][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019683.512671][1138:1138] CHIP:DMG: Cluster 30, Attribute 1 is dirty [1699019683.512687][1138:1138] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0) [1699019683.512703][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v [1699019683.512718][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019683.512793][1138:1138] CHIP:DMG: Cluster 30, Attribute 0 is dirty [1699019683.512808][1138:1138] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0) [1699019683.512824][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v [1699019683.512838][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019683.512897][1138:1138] CHIP:DMG: Cluster 31, Attribute fffc is dirty [1699019683.512912][1138:1138] CHIP:DMG: Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1) [1699019683.512928][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=v [1699019683.512943][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019683.513021][1138:1138] CHIP:DMG: Sending report (payload has 228 bytes)... [1699019683.513315][1138:1138] CHIP:EM: <<< [E:2444r S:54336 M:115124572] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) [1699019683.513902][1138:1138] CHIP:DMG: OnReportConfirm: NumReports = 0 [1699019683.513939][1138:1138] CHIP:DMG: ReportsInFlight = 0 with readHandler 0, RE has no more messages [1699019683.513960][1138:1138] CHIP:DMG: IM RH moving to [AwaitingDestruction] [1699019683.516637][1138:1138] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1699019683.632596][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019683.731154][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019683.731383][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019683.734372][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019683.735133][1138:1138] CHIP:EM: >>> [E:2445r S:54336 M:208478990] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) [1699019683.735272][1138:1138] CHIP:EM: Handling via exchange: 2445r, Delegate: 0xaaaae60ff308 [1699019683.735344][1138:1138] CHIP:IM: Received Read request [1699019683.735494][1138:1138] CHIP:DMG: ReadRequestMessage = [1699019683.735556][1138:1138] CHIP:DMG: { [1699019683.735599][1138:1138] CHIP:DMG: AttributePathIBs = [1699019683.735654][1138:1138] CHIP:DMG: [ [1699019683.735696][1138:1138] CHIP:DMG: AttributePathIB = [1699019683.735745][1138:1138] CHIP:DMG: { [1699019683.735801][1138:1138] CHIP:DMG: Endpoint = 0x0, [1699019683.735856][1138:1138] CHIP:DMG: Cluster = 0x30, [1699019683.735909][1138:1138] CHIP:DMG: Attribute = 0x0000_0004, [1699019683.735948][1138:1138] CHIP:DMG: } [1699019683.736009][1138:1138] CHIP:DMG: [1699019683.736049][1138:1138] CHIP:DMG: ], [1699019683.736115][1138:1138] CHIP:DMG: [1699019683.736168][1138:1138] CHIP:DMG: isFabricFiltered = false, [1699019683.736212][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019683.736249][1138:1138] CHIP:DMG: }, [1699019683.736726][1138:1138] CHIP:DMG: IM RH moving to [CanStartReporting] [1699019683.737048][1138:1138] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0 [1699019683.737117][1138:1138] CHIP:DMG: Cluster 30, Attribute 4 is dirty [1699019683.737158][1138:1138] CHIP:DMG: Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0004 (expanded=0) [1699019683.737224][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=v [1699019683.737273][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019683.737466][1138:1138] CHIP:DMG: Sending report (payload has 35 bytes)... [1699019683.737782][1138:1138] CHIP:EM: <<< [E:2445r S:54336 M:115124573] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:05 (IM:ReportData) [1699019683.739888][1138:1138] CHIP:DMG: OnReportConfirm: NumReports = 0 [1699019683.739977][1138:1138] CHIP:DMG: ReportsInFlight = 0 with readHandler 0, RE has no more messages [1699019683.740023][1138:1138] CHIP:DMG: IM RH moving to [AwaitingDestruction] [1699019683.744733][1138:1138] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1699019683.828219][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019683.829073][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019683.829964][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019683.830510][1138:1138] CHIP:EM: >>> [E:2446r S:54336 M:208478991] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019683.830599][1138:1138] CHIP:EM: Handling via exchange: 2446r, Delegate: 0xaaaae60ff308 [1699019683.830764][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019683.830790][1138:1138] CHIP:DMG: { [1699019683.830807][1138:1138] CHIP:DMG: suppressResponse = false, [1699019683.830830][1138:1138] CHIP:DMG: timedRequest = false, [1699019683.830847][1138:1138] CHIP:DMG: InvokeRequests = [1699019683.830880][1138:1138] CHIP:DMG: [ [1699019683.830896][1138:1138] CHIP:DMG: CommandDataIB = [1699019683.830917][1138:1138] CHIP:DMG: { [1699019683.830931][1138:1138] CHIP:DMG: CommandPathIB = [1699019683.830953][1138:1138] CHIP:DMG: { [1699019683.830975][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019683.830996][1138:1138] CHIP:DMG: ClusterId = 0x30, [1699019683.831012][1138:1138] CHIP:DMG: CommandId = 0x0, [1699019683.831025][1138:1138] CHIP:DMG: }, [1699019683.831051][1138:1138] CHIP:DMG: [1699019683.831068][1138:1138] CHIP:DMG: CommandFields = [1699019683.831090][1138:1138] CHIP:DMG: { [1699019683.831144][1138:1138] CHIP:DMG: 0x0 = 60, [1699019683.831163][1138:1138] CHIP:DMG: 0x1 = 4, [1699019683.831181][1138:1138] CHIP:DMG: }, [1699019683.831194][1138:1138] CHIP:DMG: }, [1699019683.831224][1138:1138] CHIP:DMG: [1699019683.831238][1138:1138] CHIP:DMG: ], [1699019683.831271][1138:1138] CHIP:DMG: [1699019683.831289][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019683.831302][1138:1138] CHIP:DMG: }, [1699019683.831482][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a [1699019683.831510][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019683.831543][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 [1699019683.831751][1138:1138] CHIP:FS: GeneralCommissioning: Received ArmFailSafe (60s) [1699019683.835710][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 373af31f [1699019683.835823][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019683.835878][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019683.835937][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019683.836046][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019683.836341][1138:1138] CHIP:EM: <<< [E:2446r S:54336 M:115124574] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019683.836939][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019683.836963][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019683.926169][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019683.926762][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019683.928236][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019683.928853][1138:1138] CHIP:EM: >>> [E:2447r S:54336 M:208478992] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019683.928949][1138:1138] CHIP:EM: Handling via exchange: 2447r, Delegate: 0xaaaae60ff308 [1699019683.929118][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019683.929153][1138:1138] CHIP:DMG: { [1699019683.929183][1138:1138] CHIP:DMG: suppressResponse = false, [1699019683.929217][1138:1138] CHIP:DMG: timedRequest = false, [1699019683.929243][1138:1138] CHIP:DMG: InvokeRequests = [1699019683.929298][1138:1138] CHIP:DMG: [ [1699019683.929325][1138:1138] CHIP:DMG: CommandDataIB = [1699019683.929358][1138:1138] CHIP:DMG: { [1699019683.929383][1138:1138] CHIP:DMG: CommandPathIB = [1699019683.929416][1138:1138] CHIP:DMG: { [1699019683.929450][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019683.929484][1138:1138] CHIP:DMG: ClusterId = 0x30, [1699019683.929513][1138:1138] CHIP:DMG: CommandId = 0x2, [1699019683.929537][1138:1138] CHIP:DMG: }, [1699019683.929578][1138:1138] CHIP:DMG: [1699019683.929606][1138:1138] CHIP:DMG: CommandFields = [1699019683.929638][1138:1138] CHIP:DMG: { [1699019683.929677][1138:1138] CHIP:DMG: 0x0 = 0, [1699019683.929720][1138:1138] CHIP:DMG: 0x1 = "XX" (2 chars), [1699019683.929753][1138:1138] CHIP:DMG: 0x2 = 5, [1699019683.929784][1138:1138] CHIP:DMG: }, [1699019683.929808][1138:1138] CHIP:DMG: }, [1699019683.929855][1138:1138] CHIP:DMG: [1699019683.929879][1138:1138] CHIP:DMG: ], [1699019683.929933][1138:1138] CHIP:DMG: [1699019683.929963][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019683.929985][1138:1138] CHIP:DMG: }, [1699019683.930210][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a [1699019683.930263][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019683.930318][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002 [1699019683.931011][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_config.ini-sjyVIv) [1699019683.931977][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1699019683.932101][1138:1138] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1699019683.932365][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_config.ini-49Rhpf) [1699019683.933167][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1699019683.933277][1138:1138] CHIP:DL: NVS set: chip-config/country-code = "XX" [1699019683.933369][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 373af320 [1699019683.933497][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019683.933558][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019683.933625][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019683.933769][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019683.934065][1138:1138] CHIP:EM: <<< [E:2447r S:54336 M:115124575] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019683.934657][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019683.934690][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019684.023098][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019684.024000][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019684.024955][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019684.025484][1138:1138] CHIP:EM: >>> [E:2448r S:54336 M:208478993] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019684.025549][1138:1138] CHIP:EM: Handling via exchange: 2448r, Delegate: 0xaaaae60ff308 [1699019684.025685][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019684.025711][1138:1138] CHIP:DMG: { [1699019684.025729][1138:1138] CHIP:DMG: suppressResponse = false, [1699019684.025749][1138:1138] CHIP:DMG: timedRequest = false, [1699019684.025766][1138:1138] CHIP:DMG: InvokeRequests = [1699019684.025799][1138:1138] CHIP:DMG: [ [1699019684.025815][1138:1138] CHIP:DMG: CommandDataIB = [1699019684.025835][1138:1138] CHIP:DMG: { [1699019684.025849][1138:1138] CHIP:DMG: CommandPathIB = [1699019684.025874][1138:1138] CHIP:DMG: { [1699019684.025895][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019684.025915][1138:1138] CHIP:DMG: ClusterId = 0x3e, [1699019684.025932][1138:1138] CHIP:DMG: CommandId = 0x2, [1699019684.025945][1138:1138] CHIP:DMG: }, [1699019684.025972][1138:1138] CHIP:DMG: [1699019684.025990][1138:1138] CHIP:DMG: CommandFields = [1699019684.026011][1138:1138] CHIP:DMG: { [1699019684.026034][1138:1138] CHIP:DMG: 0x0 = 2, [1699019684.026052][1138:1138] CHIP:DMG: }, [1699019684.026065][1138:1138] CHIP:DMG: }, [1699019684.026141][1138:1138] CHIP:DMG: [1699019684.026154][1138:1138] CHIP:DMG: ], [1699019684.026189][1138:1138] CHIP:DMG: [1699019684.026208][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019684.026222][1138:1138] CHIP:DMG: }, [1699019684.026387][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1699019684.026413][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019684.026449][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [1699019684.026564][1138:1138] CHIP:ZCL: OpCreds: Certificate Chain request received for PAI [1699019684.026698][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019684.026752][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019684.026810][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019684.026889][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019684.027153][1138:1138] CHIP:EM: <<< [E:2448r S:54336 M:115124576] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019684.027604][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019684.027626][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019684.169937][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019684.267470][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019684.364275][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019684.364768][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019684.366036][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019684.366732][1138:1138] CHIP:EM: >>> [E:2449r S:54336 M:208478994] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019684.366825][1138:1138] CHIP:EM: Handling via exchange: 2449r, Delegate: 0xaaaae60ff308 [1699019684.367005][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019684.367037][1138:1138] CHIP:DMG: { [1699019684.367066][1138:1138] CHIP:DMG: suppressResponse = false, [1699019684.367098][1138:1138] CHIP:DMG: timedRequest = false, [1699019684.367121][1138:1138] CHIP:DMG: InvokeRequests = [1699019684.367168][1138:1138] CHIP:DMG: [ [1699019684.367192][1138:1138] CHIP:DMG: CommandDataIB = [1699019684.367223][1138:1138] CHIP:DMG: { [1699019684.367246][1138:1138] CHIP:DMG: CommandPathIB = [1699019684.367279][1138:1138] CHIP:DMG: { [1699019684.367310][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019684.367341][1138:1138] CHIP:DMG: ClusterId = 0x3e, [1699019684.367369][1138:1138] CHIP:DMG: CommandId = 0x2, [1699019684.367390][1138:1138] CHIP:DMG: }, [1699019684.367430][1138:1138] CHIP:DMG: [1699019684.367455][1138:1138] CHIP:DMG: CommandFields = [1699019684.367483][1138:1138] CHIP:DMG: { [1699019684.367516][1138:1138] CHIP:DMG: 0x0 = 1, [1699019684.367545][1138:1138] CHIP:DMG: }, [1699019684.367566][1138:1138] CHIP:DMG: }, [1699019684.367605][1138:1138] CHIP:DMG: [1699019684.367627][1138:1138] CHIP:DMG: ], [1699019684.367674][1138:1138] CHIP:DMG: [1699019684.367704][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019684.367725][1138:1138] CHIP:DMG: }, [1699019684.367908][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1699019684.367946][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019684.367992][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002 [1699019684.368079][1138:1138] CHIP:ZCL: OpCreds: Certificate Chain request received for DAC [1699019684.368231][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019684.368305][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019684.368379][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019684.368482][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019684.368810][1138:1138] CHIP:EM: <<< [E:2449r S:54336 M:115124577] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019684.369302][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019684.369334][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019684.511190][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019684.608655][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019684.706164][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019684.706746][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019684.709311][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019684.710155][1138:1138] CHIP:EM: >>> [E:2450r S:54336 M:208478995] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019684.710292][1138:1138] CHIP:EM: Handling via exchange: 2450r, Delegate: 0xaaaae60ff308 [1699019684.710514][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019684.710575][1138:1138] CHIP:DMG: { [1699019684.710626][1138:1138] CHIP:DMG: suppressResponse = false, [1699019684.710682][1138:1138] CHIP:DMG: timedRequest = false, [1699019684.710725][1138:1138] CHIP:DMG: InvokeRequests = [1699019684.710809][1138:1138] CHIP:DMG: [ [1699019684.710852][1138:1138] CHIP:DMG: CommandDataIB = [1699019684.710905][1138:1138] CHIP:DMG: { [1699019684.710947][1138:1138] CHIP:DMG: CommandPathIB = [1699019684.711000][1138:1138] CHIP:DMG: { [1699019684.711055][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019684.711110][1138:1138] CHIP:DMG: ClusterId = 0x3e, [1699019684.711161][1138:1138] CHIP:DMG: CommandId = 0x0, [1699019684.711200][1138:1138] CHIP:DMG: }, [1699019684.711264][1138:1138] CHIP:DMG: [1699019684.711309][1138:1138] CHIP:DMG: CommandFields = [1699019684.711361][1138:1138] CHIP:DMG: { [1699019684.711415][1138:1138] CHIP:DMG: 0x0 = [ [1699019684.711527][1138:1138] CHIP:DMG: 0xff, 0x42, 0x11, 0x12, 0xb9, 0xd1, 0xe3, 0xa5, 0xee, 0x88, 0xd7, 0x03, 0x7c, 0x0b, 0x3b, 0x8d, 0xaa, 0x66, 0x0c, 0x4b, 0x49, 0xf9, 0xba, 0xd0, 0x5d, 0xd9, 0xfc, 0x32, 0x27, 0x22, 0x8c, 0x8a, [1699019684.711587][1138:1138] CHIP:DMG: ] (32 bytes) [1699019684.711640][1138:1138] CHIP:DMG: }, [1699019684.711679][1138:1138] CHIP:DMG: }, [1699019684.711746][1138:1138] CHIP:DMG: [1699019684.711786][1138:1138] CHIP:DMG: ], [1699019684.711864][1138:1138] CHIP:DMG: [1699019684.711911][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019684.711946][1138:1138] CHIP:DMG: }, [1699019684.712210][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1699019684.712270][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019684.712341][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000 [1699019684.713177][1138:1138] CHIP:ZCL: OpCreds: Received an AttestationRequest command [1699019684.717062][1138:1138] CHIP:ZCL: OpCreds: AttestationRequest successful. [1699019684.717209][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019684.717262][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019684.717317][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019684.717457][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019684.717764][1138:1138] CHIP:EM: <<< [E:2450r S:54336 M:115124578] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019684.718284][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019684.718311][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019684.851323][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019684.949875][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019685.047481][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019685.144620][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019685.147752][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019685.148570][1138:1138] CHIP:EM: >>> [E:2451r S:54336 M:208478996] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019685.148709][1138:1138] CHIP:EM: Handling via exchange: 2451r, Delegate: 0xaaaae60ff308 [1699019685.148932][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019685.148991][1138:1138] CHIP:DMG: { [1699019685.149038][1138:1138] CHIP:DMG: suppressResponse = false, [1699019685.149094][1138:1138] CHIP:DMG: timedRequest = false, [1699019685.149137][1138:1138] CHIP:DMG: InvokeRequests = [1699019685.149223][1138:1138] CHIP:DMG: [ [1699019685.149268][1138:1138] CHIP:DMG: CommandDataIB = [1699019685.149321][1138:1138] CHIP:DMG: { [1699019685.149363][1138:1138] CHIP:DMG: CommandPathIB = [1699019685.149416][1138:1138] CHIP:DMG: { [1699019685.149472][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019685.149528][1138:1138] CHIP:DMG: ClusterId = 0x3e, [1699019685.149578][1138:1138] CHIP:DMG: CommandId = 0x4, [1699019685.149617][1138:1138] CHIP:DMG: }, [1699019685.149681][1138:1138] CHIP:DMG: [1699019685.149726][1138:1138] CHIP:DMG: CommandFields = [1699019685.149779][1138:1138] CHIP:DMG: { [1699019685.149831][1138:1138] CHIP:DMG: 0x0 = [ [1699019685.149941][1138:1138] CHIP:DMG: 0xb5, 0xb2, 0x1a, 0x56, 0xe4, 0x62, 0xcb, 0x99, 0xb5, 0x78, 0x6c, 0x42, 0x60, 0xd8, 0x12, 0x32, 0x9b, 0x9c, 0xbd, 0x52, 0xc9, 0x04, 0x7c, 0x10, 0xbc, 0x74, 0xe5, 0xd9, 0xcb, 0x2a, 0x35, 0xed, [1699019685.149992][1138:1138] CHIP:DMG: ] (32 bytes) [1699019685.150045][1138:1138] CHIP:DMG: }, [1699019685.150127][1138:1138] CHIP:DMG: }, [1699019685.150205][1138:1138] CHIP:DMG: [1699019685.150246][1138:1138] CHIP:DMG: ], [1699019685.150328][1138:1138] CHIP:DMG: [1699019685.150377][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019685.150414][1138:1138] CHIP:DMG: }, [1699019685.150685][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1699019685.150749][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019685.150818][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0004 [1699019685.150943][1138:1138] CHIP:ZCL: OpCreds: Received a CSRRequest command [1699019685.151000][1138:1138] CHIP:ZCL: OpCreds: Finding fabric with fabricIndex 0x0 [1699019685.158636][1138:1138] CHIP:ZCL: OpCreds: AllocatePendingOperationalKey succeeded [1699019685.160151][1138:1138] CHIP:ZCL: OpCreds: CSRRequest successful. [1699019685.160243][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019685.160303][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019685.160430][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019685.160544][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019685.160798][1138:1138] CHIP:EM: <<< [E:2451r S:54336 M:115124579] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019685.161351][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019685.161378][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019685.242333][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019685.339796][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019685.389933][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019685.394326][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019685.485670][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019685.490154][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019685.490882][1138:1138] CHIP:EM: >>> [E:2452r S:54336 M:208478997] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019685.491021][1138:1138] CHIP:EM: Handling via exchange: 2452r, Delegate: 0xaaaae60ff308 [1699019685.491243][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019685.491299][1138:1138] CHIP:DMG: { [1699019685.491346][1138:1138] CHIP:DMG: suppressResponse = false, [1699019685.491395][1138:1138] CHIP:DMG: timedRequest = false, [1699019685.491437][1138:1138] CHIP:DMG: InvokeRequests = [1699019685.491523][1138:1138] CHIP:DMG: [ [1699019685.491567][1138:1138] CHIP:DMG: CommandDataIB = [1699019685.491619][1138:1138] CHIP:DMG: { [1699019685.491661][1138:1138] CHIP:DMG: CommandPathIB = [1699019685.491715][1138:1138] CHIP:DMG: { [1699019685.491767][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019685.491818][1138:1138] CHIP:DMG: ClusterId = 0x3e, [1699019685.491864][1138:1138] CHIP:DMG: CommandId = 0xb, [1699019685.491904][1138:1138] CHIP:DMG: }, [1699019685.491969][1138:1138] CHIP:DMG: [1699019685.492014][1138:1138] CHIP:DMG: CommandFields = [1699019685.492066][1138:1138] CHIP:DMG: { [1699019685.492121][1138:1138] CHIP:DMG: 0x0 = [ [1699019685.492674][1138:1138] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x14, 0x01, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x14, 0x01, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0xb4, 0xe9, 0x16, 0x75, 0x1d, 0x80, 0x4a, 0xf8, 0x1f, 0x41, 0xd3, 0xdf, 0x30, 0xc8, 0xfb, 0x29, 0xbb, 0x44, 0x8c, 0x34, 0x84, 0xbd, 0x9f, 0x75, 0x2a, 0xf4, 0x01, 0xfb, 0xb3, 0xee, 0xa9, 0x26, 0xeb, 0x0c, 0x11, 0xf8, 0xf9, 0xe3, 0xa2, 0xa0, 0xe2, 0xdb, 0x72, 0xa6, 0x0f, 0x4c, 0xdf, 0xaa, 0x98, 0x3c, 0x6c, 0x7f, 0xe4, 0x7b, 0x49, 0xfc, 0x57, 0xc2, 0x50, 0x22, 0x4f, 0x86, 0x77, 0x42, 0x37, 0x0a, 0x35, 0x01, 0x29, 0x01, 0x18, 0x24, 0x02, 0x60, 0x30, 0x04, 0x14, 0x5f, 0xe5, 0x83, 0x90, 0x92, 0x25, 0x7d, 0x58, 0x72, 0x93, 0xa6, 0x3f, 0x4d, 0x1c, 0x8f, 0xe1, 0xad, 0xd2, 0x3f, 0x93, 0x30, 0x05, 0x14, 0x5f, 0xe5, 0x83, 0x90, 0x92, 0x25, 0x7d, 0x58, 0x72, 0x93, 0xa6, 0x3f, 0x4d, 0x1c, 0x8f, 0xe1, 0xad, 0xd2, 0x3f, 0x93, 0x18, 0x30, 0x0b, 0x40, 0x65, 0xc5, 0xf9, 0x2e, 0x21, 0xa1, 0xd9, 0x55, 0x09, 0x45, 0x07, 0x22, 0xf0, 0x97, 0xc1, 0x74, 0x7c, 0xac, 0x70, 0x06, 0xdb, 0x5c, 0xc5, 0x30, 0xde, 0x3a, 0x86, 0x0d, 0x33, 0x61, 0xd0, 0xbb, 0xd1, 0x90, 0x5b, 0xe9, 0x12, 0x1d, 0xb7, 0x5b, 0x55, 0x24, 0x03, 0xad, 0x88, 0x9a, 0x55, 0x82, 0xba, 0xb5, 0x98, 0x42, 0xbd, 0x0e, 0x50, 0x9f, 0xad, 0xa2, 0x32, 0x63, 0x6f, 0x9b, 0xc4, 0x32, 0x18, [1699019685.492734][1138:1138] CHIP:DMG: ] (231 bytes) [1699019685.492788][1138:1138] CHIP:DMG: }, [1699019685.492828][1138:1138] CHIP:DMG: }, [1699019685.492899][1138:1138] CHIP:DMG: [1699019685.492940][1138:1138] CHIP:DMG: ], [1699019685.493022][1138:1138] CHIP:DMG: [1699019685.493072][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019685.493108][1138:1138] CHIP:DMG: }, [1699019685.493369][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1699019685.493434][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019685.493500][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B [1699019685.493710][1138:1138] CHIP:ZCL: OpCreds: Received an AddTrustedRootCertificate command [1699019685.497618][1138:1138] CHIP:ZCL: OpCreds: AddTrustedRootCertificate successful. [1699019685.497733][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019685.497785][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019685.497823][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019685.497932][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019685.498214][1138:1138] CHIP:EM: <<< [E:2452r S:54336 M:115124580] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019685.498723][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019685.498749][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019685.583146][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019685.630688][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019685.634578][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019685.731696][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019685.738766][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019685.827144][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019685.832037][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019685.832788][1138:1138] CHIP:EM: >>> [E:2453r S:54336 M:208478998] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019685.832920][1138:1138] CHIP:EM: Handling via exchange: 2453r, Delegate: 0xaaaae60ff308 [1699019685.833154][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019685.833210][1138:1138] CHIP:DMG: { [1699019685.833262][1138:1138] CHIP:DMG: suppressResponse = false, [1699019685.833316][1138:1138] CHIP:DMG: timedRequest = false, [1699019685.833357][1138:1138] CHIP:DMG: InvokeRequests = [1699019685.833451][1138:1138] CHIP:DMG: [ [1699019685.833496][1138:1138] CHIP:DMG: CommandDataIB = [1699019685.833549][1138:1138] CHIP:DMG: { [1699019685.833591][1138:1138] CHIP:DMG: CommandPathIB = [1699019685.833643][1138:1138] CHIP:DMG: { [1699019685.833700][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019685.833756][1138:1138] CHIP:DMG: ClusterId = 0x3e, [1699019685.833806][1138:1138] CHIP:DMG: CommandId = 0x6, [1699019685.833845][1138:1138] CHIP:DMG: }, [1699019685.833910][1138:1138] CHIP:DMG: [1699019685.833955][1138:1138] CHIP:DMG: CommandFields = [1699019685.834008][1138:1138] CHIP:DMG: { [1699019685.834064][1138:1138] CHIP:DMG: 0x0 = [ [1699019685.834672][1138:1138] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x13, 0x02, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x15, 0x01, 0x25, 0x11, 0xce, 0x07, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0x25, 0xcb, 0x59, 0x42, 0x41, 0x04, 0x9e, 0x64, 0xf1, 0x94, 0x5c, 0x03, 0x5b, 0x00, 0x89, 0xdf, 0xc8, 0xe8, 0x61, 0xab, 0x01, 0x91, 0x84, 0x61, 0x0a, 0x2f, 0x89, 0x1d, 0x0a, 0xe8, 0x74, 0x1d, 0xbb, 0x5b, 0xce, 0x62, 0x2a, 0x5d, 0xf7, 0x19, 0x2a, 0xb3, 0xc6, 0x37, 0xf4, 0xe0, 0x53, 0x47, 0xbc, 0xcd, 0xdf, 0xa5, 0xfa, 0x75, 0x9a, 0xe2, 0x30, 0x03, 0x6d, 0x73, 0x26, 0xb2, 0x9b, 0x30, 0x37, 0x0a, 0x35, 0x01, 0x28, 0x01, 0x18, 0x24, 0x02, 0x01, 0x36, 0x03, 0x04, 0x02, 0x04, 0x01, 0x18, 0x30, 0x04, 0x14, 0x96, 0xb9, 0x18, 0x52, 0x00, 0xa9, 0x3e, 0x9a, 0x32, 0x9c, 0x0f, 0x00, 0x23, 0x53, 0xc7, 0x6c, 0x17, 0x44, 0x6b, 0x20, 0x30, 0x05, 0x14, 0x71, 0x7d, 0xab, 0x41, 0x37, 0x07, 0x0d, 0x8a, 0x0b, 0x43, 0xae, 0xde, 0x91, 0x80, 0x9e, 0x2b, 0xbb, 0xb5, 0xd6, 0xf7, 0x18, 0x30, 0x0b, 0x40, 0xab, 0x2b, 0x5c, 0x56, 0x44, 0xb6, 0x68, 0xc0, 0x1e, 0x56, 0x79, 0xf3, 0x98, 0xc1, 0x4d, 0x5d, 0x43, 0x80, 0xa3, 0xe5, 0x0d, 0x90, 0x17, 0x01, 0x08, 0xe5, 0xe4, 0xd9, 0x4d, 0x92, 0x58, 0x2d, 0x75, 0xdd, 0xa6, 0x6a, 0xa3, 0x8b, 0xf5, 0x70, 0x33, 0xdd, 0x8e, 0x8b, 0x4f, 0x47, 0x6c, 0xc1, 0x5d, 0xe7, 0x6d, 0x4f, 0x4c, 0xf4, 0xc0, 0x08, 0xa8, 0x49, 0x85, 0xac, 0x58, 0xfd, 0x86, 0x5b, 0x18, [1699019685.834742][1138:1138] CHIP:DMG: ] (242 bytes) [1699019685.834792][1138:1138] CHIP:DMG: 0x1 = [ [1699019685.835345][1138:1138] CHIP:DMG: 0x15, 0x30, 0x01, 0x01, 0x01, 0x24, 0x02, 0x01, 0x37, 0x03, 0x24, 0x14, 0x01, 0x18, 0x26, 0x04, 0x80, 0x22, 0x81, 0x27, 0x26, 0x05, 0x80, 0x25, 0x4d, 0x3a, 0x37, 0x06, 0x24, 0x13, 0x02, 0x18, 0x24, 0x07, 0x01, 0x24, 0x08, 0x01, 0x30, 0x09, 0x41, 0x04, 0x44, 0xfa, 0x2c, 0xe6, 0x1f, 0x0d, 0xda, 0x77, 0x18, 0x30, 0xef, 0x92, 0xb3, 0x55, 0x2c, 0xd0, 0x62, 0x63, 0x88, 0x07, 0xfa, 0x88, 0xe4, 0xc1, 0x18, 0xf5, 0x82, 0x47, 0x9a, 0x1f, 0xf9, 0xad, 0xd5, 0x1c, 0xc2, 0xbc, 0xd0, 0x91, 0x0e, 0xba, 0x47, 0xeb, 0x5a, 0xce, 0x6f, 0x8e, 0x09, 0xf2, 0x22, 0x49, 0x17, 0xa9, 0x0d, 0x80, 0xf1, 0xc3, 0xda, 0xad, 0x7c, 0x4c, 0x92, 0x54, 0xa7, 0xb1, 0x37, 0x0a, 0x35, 0x01, 0x29, 0x01, 0x18, 0x24, 0x02, 0x60, 0x30, 0x04, 0x14, 0x71, 0x7d, 0xab, 0x41, 0x37, 0x07, 0x0d, 0x8a, 0x0b, 0x43, 0xae, 0xde, 0x91, 0x80, 0x9e, 0x2b, 0xbb, 0xb5, 0xd6, 0xf7, 0x30, 0x05, 0x14, 0x5f, 0xe5, 0x83, 0x90, 0x92, 0x25, 0x7d, 0x58, 0x72, 0x93, 0xa6, 0x3f, 0x4d, 0x1c, 0x8f, 0xe1, 0xad, 0xd2, 0x3f, 0x93, 0x18, 0x30, 0x0b, 0x40, 0x45, 0xe7, 0xc1, 0x7a, 0x08, 0x8b, 0xa1, 0xc6, 0xc7, 0xbe, 0x57, 0x02, 0xc3, 0xf5, 0x83, 0x9a, 0x30, 0x97, 0x29, 0xf7, 0xe3, 0x7b, 0x01, 0x8a, 0x55, 0xa0, 0xc0, 0x6d, 0xc6, 0x7e, 0xc0, 0x1d, 0x33, 0x79, 0x34, 0x66, 0xe3, 0x90, 0xa9, 0x88, 0x3a, 0xfe, 0x98, 0x57, 0x14, 0xb4, 0xf2, 0xbe, 0x09, 0x12, 0xe1, 0x4a, 0x2d, 0xd1, 0x19, 0x60, 0xeb, 0xec, 0x27, 0x62, 0x08, 0x0e, 0x67, 0x1e, 0x18, [1699019685.835419][1138:1138] CHIP:DMG: ] (231 bytes) [1699019685.835469][1138:1138] CHIP:DMG: 0x2 = [ [1699019685.835543][1138:1138] CHIP:DMG: 0x74, 0x65, 0x6d, 0x70, 0x6f, 0x72, 0x61, 0x72, 0x79, 0x20, 0x69, 0x70, 0x6b, 0x20, 0x30, 0x31, [1699019685.835602][1138:1138] CHIP:DMG: ] (16 bytes) [1699019685.835661][1138:1138] CHIP:DMG: 0x3 = 112233, [1699019685.835717][1138:1138] CHIP:DMG: 0x4 = 65521, [1699019685.835770][1138:1138] CHIP:DMG: }, [1699019685.835809][1138:1138] CHIP:DMG: }, [1699019685.835894][1138:1138] CHIP:DMG: [1699019685.835935][1138:1138] CHIP:DMG: ], [1699019685.836030][1138:1138] CHIP:DMG: [1699019685.836081][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019685.836117][1138:1138] CHIP:DMG: }, [1699019685.836406][1138:1138] CHIP:DMG: AccessControl: checking f=0 a=p s=0xFFFFFFFB00000000 t= c=0x0000_003E e=0 p=a [1699019685.836466][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019685.836537][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0006 [1699019685.836781][1138:1138] CHIP:ZCL: OpCreds: Received an AddNOC command [1699019685.841799][1138:1138] CHIP:FP: Validating NOC chain [1699019685.846582][1138:1138] CHIP:FP: NOC chain validation successful [1699019685.846698][1138:1138] CHIP:FP: Added new fabric at index: 0x1 [1699019685.846714][1138:1138] CHIP:FP: Assigned compressed fabric ID: 0x027FBA21A63140CE, node ID: 0x00000000000007CE [1699019685.846753][1138:1138] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1699019685.846772][1138:1138] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1699019685.846786][1138:1138] CHIP:TS: Retaining current Last Known Good Time [1699019685.846830][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 128f7aae [1699019685.846855][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 128f7aaf [1699019685.848600][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-BhYf6f) [1699019685.849666][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019685.850214][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-XXme75) [1699019685.851033][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019685.851354][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-hUFT6S) [1699019685.852150][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019685.852309][1138:1138] CHIP:DMG: AccessControl: validating f=1 p=a a=c s=1 t=0 [1699019685.852331][1138:1138] CHIP:DMG: validating subject 0x000000000001B669 [1699019685.852711][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-McRLGl) [1699019685.853401][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019685.853767][1138:1138] CHIP:EVL: LogEvent event number: 0x0000000000000002 priority: 1, endpoint id: 0x0 cluster id: 0x0000_001F event id: 0x0 Epoch timestamp: 0x0000018B9576FFDD [1699019685.853803][1138:1138] CHIP:ZCL: OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x000000000001B669 [1699019685.854425][1138:1138] CHIP:DL: Using wifi MAC for hostname [1699019685.854507][1138:1138] CHIP:DIS: Advertise operational node 027FBA21A63140CE-00000000000007CE [1699019685.854638][1138:1138] CHIP:DIS: Responding with _matter._tcp.local [1699019685.854667][1138:1138] CHIP:DIS: Responding with 027FBA21A63140CE-00000000000007CE._matter._tcp.local [1699019685.854700][1138:1138] CHIP:DIS: Responding with 027FBA21A63140CE-00000000000007CE._matter._tcp.local [1699019685.854718][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019685.854736][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019685.854775][1138:1138] CHIP:DIS: Responding with _I027FBA21A63140CE._sub._matter._tcp.local [1699019685.854789][1138:1138] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: 027FBA21A63140CE-00000000000007CE. [1699019685.856357][1138:1138] CHIP:DIS: mDNS service published: _matter._tcp [1699019685.856419][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 128f7ab0 [1699019685.856444][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_003E update version to 128f7ab1 [1699019685.856530][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019685.856584][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019685.856640][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019685.856656][1138:1138] CHIP:ZCL: OpCreds: successfully created fabric index 0x1 via AddNOC [1699019685.856779][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019685.857073][1138:1138] CHIP:EM: <<< [E:2453r S:54336 M:115124581] (S) Msg TX to 1:FFFFFFFB00000000 [40CE] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019685.857573][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019685.857594][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019685.924750][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019685.925509][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019685.926668][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019685.927195][1138:1138] CHIP:EM: >>> [E:2454r S:54336 M:208478999] (S) Msg RX from 1:FFFFFFFB00000000 [40CE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019685.927279][1138:1138] CHIP:EM: Handling via exchange: 2454r, Delegate: 0xaaaae60ff308 [1699019685.927449][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019685.927471][1138:1138] CHIP:DMG: { [1699019685.927489][1138:1138] CHIP:DMG: suppressResponse = false, [1699019685.927509][1138:1138] CHIP:DMG: timedRequest = false, [1699019685.927525][1138:1138] CHIP:DMG: InvokeRequests = [1699019685.927560][1138:1138] CHIP:DMG: [ [1699019685.927575][1138:1138] CHIP:DMG: CommandDataIB = [1699019685.927597][1138:1138] CHIP:DMG: { [1699019685.927611][1138:1138] CHIP:DMG: CommandPathIB = [1699019685.927635][1138:1138] CHIP:DMG: { [1699019685.927657][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019685.927676][1138:1138] CHIP:DMG: ClusterId = 0x31, [1699019685.927692][1138:1138] CHIP:DMG: CommandId = 0x2, [1699019685.927706][1138:1138] CHIP:DMG: }, [1699019685.927730][1138:1138] CHIP:DMG: [1699019685.927749][1138:1138] CHIP:DMG: CommandFields = [1699019685.927770][1138:1138] CHIP:DMG: { [1699019685.927791][1138:1138] CHIP:DMG: 0x0 = [ [1699019685.927811][1138:1138] CHIP:DMG: 0x4d, 0x4d, 0x2d, 0x4c, 0x41, 0x42, [1699019685.927831][1138:1138] CHIP:DMG: ] (6 bytes) [1699019685.927848][1138:1138] CHIP:DMG: 0x1 = [ [1699019685.927869][1138:1138] CHIP:DMG: 0x4c, 0x61, 0x62, 0x43, 0x6f, 0x61, 0x74, 0x43, 0x6f, 0x64, 0x65, [1699019685.927888][1138:1138] CHIP:DMG: ] (11 bytes) [1699019685.927908][1138:1138] CHIP:DMG: 0x2 = 20, [1699019685.927927][1138:1138] CHIP:DMG: }, [1699019685.927941][1138:1138] CHIP:DMG: }, [1699019685.927969][1138:1138] CHIP:DMG: [1699019685.927984][1138:1138] CHIP:DMG: ], [1699019685.928019][1138:1138] CHIP:DMG: [1699019685.928037][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019685.928049][1138:1138] CHIP:DMG: }, [1699019685.932429][1138:1138] CHIP:DMG: AccessControl: checking f=1 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=a [1699019685.932511][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019685.932588][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0002 [1699019685.932833][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019685.932892][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019685.932940][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019685.932997][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 373af321 [1699019685.933082][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019685.933367][1138:1138] CHIP:EM: <<< [E:2454r S:54336 M:115124582] (S) Msg TX to 1:FFFFFFFB00000000 [40CE] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019685.933832][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019685.933853][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019686.022253][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019686.070418][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019686.072957][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019686.073695][1138:1138] CHIP:EM: >>> [E:2455r S:54336 M:208479000] (S) Msg RX from 1:FFFFFFFB00000000 [40CE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019686.073825][1138:1138] CHIP:EM: Handling via exchange: 2455r, Delegate: 0xaaaae60ff308 [1699019686.074041][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019686.074252][1138:1138] CHIP:DMG: { [1699019686.074302][1138:1138] CHIP:DMG: suppressResponse = false, [1699019686.074352][1138:1138] CHIP:DMG: timedRequest = false, [1699019686.074394][1138:1138] CHIP:DMG: InvokeRequests = [1699019686.074480][1138:1138] CHIP:DMG: [ [1699019686.074524][1138:1138] CHIP:DMG: CommandDataIB = [1699019686.074578][1138:1138] CHIP:DMG: { [1699019686.074620][1138:1138] CHIP:DMG: CommandPathIB = [1699019686.074670][1138:1138] CHIP:DMG: { [1699019686.074726][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019686.074777][1138:1138] CHIP:DMG: ClusterId = 0x30, [1699019686.074827][1138:1138] CHIP:DMG: CommandId = 0x0, [1699019686.074865][1138:1138] CHIP:DMG: }, [1699019686.074925][1138:1138] CHIP:DMG: [1699019686.074970][1138:1138] CHIP:DMG: CommandFields = [1699019686.075017][1138:1138] CHIP:DMG: { [1699019686.075073][1138:1138] CHIP:DMG: 0x0 = 66, [1699019686.075128][1138:1138] CHIP:DMG: 0x1 = 22, [1699019686.075180][1138:1138] CHIP:DMG: }, [1699019686.075220][1138:1138] CHIP:DMG: }, [1699019686.075289][1138:1138] CHIP:DMG: [1699019686.075327][1138:1138] CHIP:DMG: ], [1699019686.075405][1138:1138] CHIP:DMG: [1699019686.075454][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019686.075490][1138:1138] CHIP:DMG: }, [1699019686.075753][1138:1138] CHIP:DMG: AccessControl: checking f=1 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0030 e=0 p=a [1699019686.075812][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019686.075880][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000 [1699019686.076000][1138:1138] CHIP:FS: GeneralCommissioning: Received ArmFailSafe (66s) [1699019686.076190][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 373af322 [1699019686.076373][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019686.076462][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019686.076550][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019686.076729][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019686.077077][1138:1138] CHIP:EM: <<< [E:2455r S:54336 M:115124583] (S) Msg TX to 1:FFFFFFFB00000000 [40CE] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019686.077827][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019686.077880][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019686.168135][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019686.169124][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019686.170113][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019686.170601][1138:1138] CHIP:EM: >>> [E:2456r S:54336 M:208479001] (S) Msg RX from 1:FFFFFFFB00000000 [40CE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019686.170664][1138:1138] CHIP:EM: Handling via exchange: 2456r, Delegate: 0xaaaae60ff308 [1699019686.170815][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019686.170837][1138:1138] CHIP:DMG: { [1699019686.170855][1138:1138] CHIP:DMG: suppressResponse = false, [1699019686.170879][1138:1138] CHIP:DMG: timedRequest = false, [1699019686.170896][1138:1138] CHIP:DMG: InvokeRequests = [1699019686.170928][1138:1138] CHIP:DMG: [ [1699019686.170944][1138:1138] CHIP:DMG: CommandDataIB = [1699019686.170967][1138:1138] CHIP:DMG: { [1699019686.170981][1138:1138] CHIP:DMG: CommandPathIB = [1699019686.171006][1138:1138] CHIP:DMG: { [1699019686.171029][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019686.171048][1138:1138] CHIP:DMG: ClusterId = 0x31, [1699019686.171065][1138:1138] CHIP:DMG: CommandId = 0x6, [1699019686.171078][1138:1138] CHIP:DMG: }, [1699019686.171104][1138:1138] CHIP:DMG: [1699019686.171121][1138:1138] CHIP:DMG: CommandFields = [1699019686.171142][1138:1138] CHIP:DMG: { [1699019686.171165][1138:1138] CHIP:DMG: 0x0 = [ [1699019686.171185][1138:1138] CHIP:DMG: 0x4d, 0x4d, 0x2d, 0x4c, 0x41, 0x42, [1699019686.171206][1138:1138] CHIP:DMG: ] (6 bytes) [1699019686.171227][1138:1138] CHIP:DMG: 0x1 = 24, [1699019686.171246][1138:1138] CHIP:DMG: }, [1699019686.171260][1138:1138] CHIP:DMG: }, [1699019686.171287][1138:1138] CHIP:DMG: [1699019686.171301][1138:1138] CHIP:DMG: ], [1699019686.171334][1138:1138] CHIP:DMG: [1699019686.171353][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019686.171365][1138:1138] CHIP:DMG: }, [1699019686.171537][1138:1138] CHIP:DMG: AccessControl: checking f=1 a=p s=0xFFFFFFFB00000000 t= c=0x0000_0031 e=0 p=a [1699019686.171574][1138:1138] CHIP:DMG: AccessControl: implicit admin (PASE) [1699019686.171612][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0006 [1699019686.171724][1138:1138] CHIP:NP: LinuxWiFiDriver: SSID: MM-LAB [1699019686.188534][1138:1138] CHIP:DL: wpa_supplicant: added network: /fi/w1/wpa_supplicant1/Interfaces/0/Networks/0 [1699019686.189209][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 1 [1699019686.216548][1138:1139] CHIP:DL: wpa_supplicant:PropertiesChanged:key:State -> 'scanning' [1699019686.216607][1138:1139] CHIP:DL: wpa_supplicant:PropertiesChanged:key:Scanning -> true [1699019688.752543][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019689.045748][1138:1139] CHIP:DL: wpa_supplicant: network scan done [1699019689.046747][1138:1139] CHIP:DL: wpa_supplicant:PropertiesChanged:key:Scanning -> false [1699019689.047052][1138:1139] CHIP:DL: wpa_supplicant:PropertiesChanged:key:BSSs -> [objectpath '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/0', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/1', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/2', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/3', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/4', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/5', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/6', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/7', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/8', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/9', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/10', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/11', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/12', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/13', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/14', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/15', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/16', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/17', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/18', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/19', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/20', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/21', '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/22'] [1699019689.063281][1138:1139] CHIP:DL: wpa_supplicant:PropertiesChanged:key:State -> 'associating' [1699019691.237202][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019691.238519][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019692.026962][1138:1139] CHIP:DL: wpa_supplicant:PropertiesChanged:key:State -> 'completed' [1699019692.027096][1138:1139] CHIP:DL: wpa_supplicant:PropertiesChanged:key:CurrentBSS -> objectpath '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/0' [1699019692.027142][1138:1139] CHIP:DL: wpa_supplicant:PropertiesChanged:key:CurrentAuthMode -> 'WPA2-PSK+WPA-PSK' [1699019692.027306][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019692.027371][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019692.027428][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019692.027490][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 373af323 [1699019692.027524][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019692.027827][1138:1138] CHIP:EM: <<< [E:2456r S:54336 M:115124584] (S) Msg TX to 1:FFFFFFFB00000000 [40CE] [BLE] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019692.028511][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019692.028552][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019692.115605][1138:1139] CHIP:BLE: Indication confirmation, 0xffffb2508de0 [1699019692.214139][1138:1138] CHIP:DL: dhclient is running on the wlan0 interface. [1699019692.214225][1138:1138] CHIP:DL: Long dispatch time: 187 ms, for event type 3 [1699019692.214293][1138:1138] CHIP:DL: HandlePlatformSpecificBLEEvent 32785 [1699019692.214967][1138:1138] CHIP:DL: Using wifi MAC for hostname [1699019692.215044][1138:1138] CHIP:DIS: Advertise operational node 027FBA21A63140CE-00000000000007CE [1699019692.215205][1138:1138] CHIP:DIS: Responding with _matter._tcp.local [1699019692.215254][1138:1138] CHIP:DIS: Responding with 027FBA21A63140CE-00000000000007CE._matter._tcp.local [1699019692.215307][1138:1138] CHIP:DIS: Responding with 027FBA21A63140CE-00000000000007CE._matter._tcp.local [1699019692.215340][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019692.215369][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019692.215457][1138:1138] CHIP:DIS: Responding with _I027FBA21A63140CE._sub._matter._tcp.local [1699019692.215485][1138:1138] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: 027FBA21A63140CE-00000000000007CE. [1699019692.221110][1138:1138] CHIP:DIS: Failed to advertise records: src/lib/dnssd/minimal_mdns/Server.cpp:344: CHIP Error 0x00000046: No endpoint was available to send the message [1699019692.221193][1138:1138] CHIP:DIS: mDNS service published: _matter._tcp [1699019692.221232][1138:1138] CHIP:SVR: Operational advertising enabled [1699019692.269353][1138:1139] CHIP:DL: Got IP address on interface: wlan0 IP: 172.16.62.162 [1699019692.269620][1138:1138] CHIP:DL: HandlePlatformSpecificBLEEvent 32770 [1699019692.269673][1138:1138] CHIP:DL: EventHandler: DeviceEventType::kInternetConnectivityChange [1699019692.269702][1138:1138] CHIP:DL: EventHandler: posted kDnssdRestartNeeded [1699019692.269729][1138:1138] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1699019692.269751][1138:1138] CHIP:DIS: Updating services using commissioning mode 0 [1699019692.279729][1138:1138] CHIP:DIS: CHIP minimal mDNS started advertising. [1699019692.287359][1138:1138] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.287435][1138:1138] CHIP:DIS: mDNS broadcast full failed in 1 separate send attempts. [1699019692.287470][1138:1138] CHIP:DIS: Failed to advertise records: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.294618][1138:1138] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.294705][1138:1138] CHIP:DIS: mDNS broadcast full failed in 1 separate send attempts. [1699019692.294741][1138:1138] CHIP:DIS: Failed to advertise records: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.295472][1138:1138] CHIP:DL: Using wifi MAC for hostname [1699019692.295580][1138:1138] CHIP:DIS: Advertise operational node 027FBA21A63140CE-00000000000007CE [1699019692.295733][1138:1138] CHIP:DIS: Responding with _matter._tcp.local [1699019692.295767][1138:1138] CHIP:DIS: Responding with 027FBA21A63140CE-00000000000007CE._matter._tcp.local [1699019692.295802][1138:1138] CHIP:DIS: Responding with 027FBA21A63140CE-00000000000007CE._matter._tcp.local [1699019692.295819][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019692.295838][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019692.295874][1138:1138] CHIP:DIS: Responding with _I027FBA21A63140CE._sub._matter._tcp.local [1699019692.295889][1138:1138] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: 027FBA21A63140CE-00000000000007CE. [1699019692.301478][1138:1138] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.301524][1138:1138] CHIP:DIS: mDNS broadcast full failed in 1 separate send attempts. [1699019692.301550][1138:1138] CHIP:DIS: Failed to advertise records: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.301592][1138:1138] CHIP:DIS: mDNS service published: _matter._tcp [1699019692.302825][1138:1138] CHIP:DL: Using wifi MAC for hostname [1699019692.303098][1138:1138] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=0018/00 cm=0 [1699019692.303216][1138:1138] CHIP:DIS: Responding with _matterc._udp.local [1699019692.303254][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019692.303271][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019692.303287][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019692.303316][1138:1138] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1699019692.303342][1138:1138] CHIP:DIS: Responding with _T257._sub._matterc._udp.local [1699019692.303365][1138:1138] CHIP:DIS: Responding with _S0._sub._matterc._udp.local [1699019692.303387][1138:1138] CHIP:DIS: Responding with _L18._sub._matterc._udp.local [1699019692.303440][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019692.303455][1138:1138] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 1C38831F578D63AF. [1699019692.309561][1138:1138] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.309623][1138:1138] CHIP:DIS: mDNS broadcast full failed in 1 separate send attempts. [1699019692.309657][1138:1138] CHIP:DIS: Failed to advertise records: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.309712][1138:1138] CHIP:DIS: mDNS service published: _matterc._udp [1699019692.309792][1138:1138] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1699019692.309827][1138:1138] CHIP:SVR: Server initialization complete [1699019692.309880][1138:1138] CHIP:DIS: Updating services using commissioning mode 0 [1699019692.314456][1138:1138] CHIP:DIS: CHIP minimal mDNS started advertising. [1699019692.322525][1138:1138] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.322590][1138:1138] CHIP:DIS: mDNS broadcast full failed in 1 separate send attempts. [1699019692.322623][1138:1138] CHIP:DIS: Failed to advertise records: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.331154][1138:1138] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.331213][1138:1138] CHIP:DIS: mDNS broadcast full failed in 1 separate send attempts. [1699019692.331240][1138:1138] CHIP:DIS: Failed to advertise records: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.331825][1138:1138] CHIP:DL: Using wifi MAC for hostname [1699019692.331913][1138:1138] CHIP:DIS: Advertise operational node 027FBA21A63140CE-00000000000007CE [1699019692.332064][1138:1138] CHIP:DIS: Responding with _matter._tcp.local [1699019692.332107][1138:1138] CHIP:DIS: Responding with 027FBA21A63140CE-00000000000007CE._matter._tcp.local [1699019692.332145][1138:1138] CHIP:DIS: Responding with 027FBA21A63140CE-00000000000007CE._matter._tcp.local [1699019692.332163][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019692.332180][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019692.332221][1138:1138] CHIP:DIS: Responding with _I027FBA21A63140CE._sub._matter._tcp.local [1699019692.332235][1138:1138] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: 027FBA21A63140CE-00000000000007CE. [1699019692.337855][1138:1138] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.337904][1138:1138] CHIP:DIS: mDNS broadcast full failed in 1 separate send attempts. [1699019692.337931][1138:1138] CHIP:DIS: Failed to advertise records: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.337982][1138:1138] CHIP:DIS: mDNS service published: _matter._tcp [1699019692.338434][1138:1138] CHIP:DL: Using wifi MAC for hostname [1699019692.338762][1138:1138] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=0018/00 cm=0 [1699019692.338875][1138:1138] CHIP:DIS: Responding with _matterc._udp.local [1699019692.338911][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019692.338928][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019692.338945][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019692.338976][1138:1138] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1699019692.339004][1138:1138] CHIP:DIS: Responding with _T257._sub._matterc._udp.local [1699019692.339035][1138:1138] CHIP:DIS: Responding with _S0._sub._matterc._udp.local [1699019692.339060][1138:1138] CHIP:DIS: Responding with _L18._sub._matterc._udp.local [1699019692.339121][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019692.339137][1138:1138] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 1C38831F578D63AF. [1699019692.345452][1138:1138] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on wlan0: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.345497][1138:1138] CHIP:DIS: mDNS broadcast full failed in 1 separate send attempts. [1699019692.345526][1138:1138] CHIP:DIS: Failed to advertise records: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000063: Cannot assign requested address [1699019692.345573][1138:1138] CHIP:DIS: mDNS service published: _matterc._udp [1699019692.345648][1138:1138] CHIP:DL: HandlePlatformSpecificBLEEvent 32790 [1699019692.350314][1138:1138] CHIP:IM: No subscriptions to resume [1699019694.601040][1138:1139] CHIP:DL: C1 WriteHandlerCallback MTU: 517 [1699019694.601542][1138:1139] CHIP:BLE: Write request received debug 0xffffb2508de0 [1699019694.603717][1138:1138] CHIP:EM: >>> [E:2457r S:0 M:236165710] (U) Msg RX from 0:80A2B1FDA7D4A386 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1699019694.603880][1138:1138] CHIP:EM: Handling via exchange: 2457r, Delegate: 0xaaaae6108160 [1699019694.604017][1138:1138] CHIP:IN: CASE Server received Sigma1 message . Starting handshake. EC 0xffffb190e140 [1699019694.604310][1138:1138] CHIP:SC: Received Sigma1 msg [1699019694.604479][1138:1138] CHIP:SC: Peer assigned session key ID 34654 [1699019694.607701][1138:1138] CHIP:SC: CASE matched destination ID: fabricIndex 1, NodeID 0x00000000000007CE [1699019694.617564][1138:1138] CHIP:EM: <<< [E:2457r S:0 M:147505733 (Ack:236165710)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e65f:1ff:fe0a:da36%wlan0]:50381] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1699019694.618101][1138:1138] CHIP:SC: Sent Sigma2 msg [1699019694.643699][1138:1138] CHIP:EM: >>> [E:2457r S:0 M:236165711 (Ack:147505733)] (U) Msg RX from 0:80A2B1FDA7D4A386 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1699019694.643754][1138:1138] CHIP:EM: Found matching exchange: 2457r, Delegate: 0xaaaae6108198 [1699019694.643823][1138:1138] CHIP:EM: Rxd Ack; Removing MessageCounter:147505733 from Retrans Table on exchange 2457r [1699019694.643925][1138:1138] CHIP:SC: Received Sigma3 msg [1699019694.662834][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-m65eF9) [1699019694.663834][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.664237][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-8eue5q) [1699019694.665401][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.665760][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-3cIw2j) [1699019694.666616][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.666724][1138:1138] CHIP:SC: Sending status report. Protocol code 0, exchange 2457 [1699019694.667060][1138:1138] CHIP:EM: <<< [E:2457r S:0 M:147505734 (Ack:236165711)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e65f:1ff:fe0a:da36%wlan0]:50381] --- Type 0000:40 (SecureChannel:StatusReport) [1699019694.668073][1138:1138] CHIP:SC: SecureSession[0xffffb130fa40, LSID:54337]: State change 'kEstablishing' --> 'kActive' [1699019694.668124][1138:1138] CHIP:IN: SecureSession[0xffffb130fa40]: Activated - Type:2 LSID:54337 [1699019694.668138][1138:1138] CHIP:IN: New secure session activated for device <000000000001B669, 1>, LSID:54337 PSID:34654! [1699019694.668163][1138:1138] CHIP:IN: CASE Session established to peer: <000000000001B669, 1> [1699019694.668398][1138:1138] CHIP:IN: SecureSession[0xffffb1314900]: Allocated Type:2 LSID:54338 [1699019694.668444][1138:1138] CHIP:SC: Allocated SecureSession (0xffffb1314900) - waiting for Sigma1 msg [1699019694.682592][1138:1138] CHIP:EM: >>> [E:2458r S:54337 M:133313970] (S) Msg RX from 1:000000000001B669 [40CE] --- Type 0001:08 (IM:InvokeCommandRequest) [1699019694.682705][1138:1138] CHIP:EM: Handling via exchange: 2458r, Delegate: 0xaaaae60ff308 [1699019694.682914][1138:1138] CHIP:DMG: InvokeRequestMessage = [1699019694.682942][1138:1138] CHIP:DMG: { [1699019694.682962][1138:1138] CHIP:DMG: suppressResponse = false, [1699019694.682983][1138:1138] CHIP:DMG: timedRequest = false, [1699019694.682999][1138:1138] CHIP:DMG: InvokeRequests = [1699019694.683029][1138:1138] CHIP:DMG: [ [1699019694.683045][1138:1138] CHIP:DMG: CommandDataIB = [1699019694.683065][1138:1138] CHIP:DMG: { [1699019694.683079][1138:1138] CHIP:DMG: CommandPathIB = [1699019694.683103][1138:1138] CHIP:DMG: { [1699019694.683123][1138:1138] CHIP:DMG: EndpointId = 0x0, [1699019694.683142][1138:1138] CHIP:DMG: ClusterId = 0x30, [1699019694.683159][1138:1138] CHIP:DMG: CommandId = 0x4, [1699019694.683172][1138:1138] CHIP:DMG: }, [1699019694.683199][1138:1138] CHIP:DMG: [1699019694.683215][1138:1138] CHIP:DMG: CommandFields = [1699019694.683232][1138:1138] CHIP:DMG: { [1699019694.683251][1138:1138] CHIP:DMG: }, [1699019694.683264][1138:1138] CHIP:DMG: }, [1699019694.683288][1138:1138] CHIP:DMG: [1699019694.683302][1138:1138] CHIP:DMG: ], [1699019694.683334][1138:1138] CHIP:DMG: [1699019694.683351][1138:1138] CHIP:DMG: InteractionModelRevision = 11 [1699019694.683363][1138:1138] CHIP:DMG: }, [1699019694.683511][1138:1138] CHIP:DMG: AccessControl: checking f=1 a=c s=0x000000000001B669 t= c=0x0000_0030 e=0 p=a [1699019694.683572][1138:1138] CHIP:DMG: AccessControl: allowed [1699019694.683607][1138:1138] CHIP:DMG: Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004 [1699019694.683653][1138:1138] CHIP:FS: GeneralCommissioning: Received CommissioningComplete [1699019694.684055][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-1Bt22x) [1699019694.685103][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.685422][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-vTFsEc) [1699019694.686650][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.686759][1138:1138] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1699019694.687092][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-ILjkaN) [1699019694.688189][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.688625][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-5XwrJh) [1699019694.689778][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.690048][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-T3tBmM) [1699019694.691402][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.691738][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-qK6nDV) [1699019694.693025][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.693199][1138:1138] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1699019694.693456][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-hLTEr2) [1699019694.694610][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.694944][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-u8i0WJ) [1699019694.696230][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.696330][1138:1138] CHIP:ZCL: OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x027FBA21A63140CE, FabricId 0000000000000001, NodeId 00000000000007CE, VendorId 0xFFF1 [1699019694.696504][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-8lXVZk) [1699019694.699848][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.699968][1138:1138] CHIP:FS: GeneralCommissioning: Successfully commited pending fabric data [1699019694.700015][1138:1138] CHIP:FS: Fail-safe cleanly disarmed [1699019694.700088][1138:1138] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 373af324 [1699019694.700197][1138:1138] CHIP:DMG: Command handler moving to [ Preparing] [1699019694.700252][1138:1138] CHIP:DMG: Command handler moving to [AddingComm] [1699019694.700305][1138:1138] CHIP:DMG: Command handler moving to [AddedComma] [1699019694.700430][1138:1138] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1699019694.700875][1138:1138] CHIP:EM: <<< [E:2458r S:54337 M:108597018 (Ack:133313970)] (S) Msg TX to 1:000000000001B669 [40CE] [UDP:[fe80::e65f:1ff:fe0a:da36%wlan0]:50381] --- Type 0001:09 (IM:InvokeCommandResponse) [1699019694.701279][1138:1138] CHIP:DMG: Command handler moving to [CommandSen] [1699019694.701301][1138:1138] CHIP:DMG: Command handler moving to [AwaitingDe] [1699019694.701389][1138:1138] CHIP:DL: HandlePlatformSpecificBLEEvent 32783 [1699019694.701413][1138:1138] CHIP:SVR: Commissioning completed successfully [1699019694.701463][1138:1138] CHIP:DIS: Updating services using commissioning mode 0 [1699019694.705477][1138:1138] CHIP:DIS: CHIP minimal mDNS started advertising. [1699019694.717677][1138:1138] CHIP:DL: Using wifi MAC for hostname [1699019694.717765][1138:1138] CHIP:DIS: Advertise operational node 027FBA21A63140CE-00000000000007CE [1699019694.717884][1138:1138] CHIP:DIS: Responding with _matter._tcp.local [1699019694.717915][1138:1138] CHIP:DIS: Responding with 027FBA21A63140CE-00000000000007CE._matter._tcp.local [1699019694.717969][1138:1138] CHIP:DIS: Responding with 027FBA21A63140CE-00000000000007CE._matter._tcp.local [1699019694.717988][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019694.718005][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019694.718040][1138:1138] CHIP:DIS: Responding with _I027FBA21A63140CE._sub._matter._tcp.local [1699019694.718053][1138:1138] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: 027FBA21A63140CE-00000000000007CE. [1699019694.723366][1138:1138] CHIP:DIS: mDNS service published: _matter._tcp [1699019694.723832][1138:1138] CHIP:DL: Using wifi MAC for hostname [1699019694.724103][1138:1138] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=0018/00 cm=0 [1699019694.724186][1138:1138] CHIP:DIS: Responding with _matterc._udp.local [1699019694.724220][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019694.724235][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019694.724252][1138:1138] CHIP:DIS: Responding with E45F01C247AF0000.local [1699019694.724284][1138:1138] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local [1699019694.724310][1138:1138] CHIP:DIS: Responding with _T257._sub._matterc._udp.local [1699019694.724334][1138:1138] CHIP:DIS: Responding with _S0._sub._matterc._udp.local [1699019694.724357][1138:1138] CHIP:DIS: Responding with _L18._sub._matterc._udp.local [1699019694.724420][1138:1138] CHIP:DIS: Responding with 1C38831F578D63AF._matterc._udp.local [1699019694.724439][1138:1138] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 1C38831F578D63AF. [1699019694.730109][1138:1138] CHIP:DIS: mDNS service published: _matterc._udp [1699019694.730236][1138:1138] CHIP:IN: Expiring all PASE sessions [1699019694.730260][1138:1138] CHIP:IN: SecureSession[0xffffb130fb80]: MarkForEviction Type:1 LSID:54336 [1699019694.730278][1138:1138] CHIP:SC: SecureSession[0xffffb130fb80, LSID:54336]: State change 'kActive' --> 'kPendingEviction' [1699019694.730309][1138:1138] CHIP:IN: SecureSession[0xffffb130fb80]: Released - Type:1 LSID:54336 [1699019694.730408][1138:1138] CHIP:IN: Clearing BLE pending packets. [1699019694.730424][1138:1138] CHIP:BLE: Releasing end point's BLE connection back to application. [1699019694.730436][1138:1138] CHIP:BLE: Got notification regarding chip connection closure [1699019694.730473][1138:1138] CHIP:ZCL: Commissioning complete, notify platform driver to persist network credentials. [1699019694.730822][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-uNsJHW) [1699019694.731892][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.732151][1138:1138] CHIP:DL: writing settings to file (/tmp/chip_kvs-dOwpRn) [1699019694.732911][1138:1138] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1699019694.733012][1138:1138] CHIP:DL: wpa_supplicant: save config [1699019694.742635][1138:1138] CHIP:DL: wpa_supplicant: save config succeeded! [1699019694.743122][1138:1138] CHIP:EM: >>> [E:2457r S:0 M:236165712 (Ack:147505734)] (U) Msg RX from 0:80A2B1FDA7D4A386 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1699019694.743165][1138:1138] CHIP:EM: Found matching exchange: 2457r, Delegate: (nil) [1699019694.743278][1138:1138] CHIP:EM: Rxd Ack; Removing MessageCounter:147505734 from Retrans Table on exchange 2457r [1699019694.746368][1138:1138] CHIP:DIS: SRV record already actively processed. [1699019694.750342][1138:1138] CHIP:DIS: SRV record already actively processed. [1699019694.751102][1138:1138] CHIP:DIS: SRV record already actively processed. [1699019694.753789][1138:1138] CHIP:DIS: SRV record already actively processed. [1699019695.061219][1138:1138] CHIP:EM: Retransmitting MessageCounter:108597018 on exchange 2458r Send Cnt 1 [1699019695.467656][1138:1138] CHIP:EM: Retransmitting MessageCounter:108597018 on exchange 2458r Send Cnt 2 [1699019696.124183][1138:1138] CHIP:EM: Retransmitting MessageCounter:108597018 on exchange 2458r Send Cnt 3 [1699019697.061313][1138:1138] CHIP:EM: Retransmitting MessageCounter:108597018 on exchange 2458r Send Cnt 4 [1699019697.144451][1138:1138] CHIP:EM: >>> [E:2458r S:54337 M:133313971 (Ack:108597018)] (S) Msg RX from 1:000000000001B669 [40CE] --- Type 0000:10 (SecureChannel:StandaloneAck) [1699019697.144556][1138:1138] CHIP:EM: Found matching exchange: 2458r, Delegate: (nil) [1699019697.144681][1138:1138] CHIP:EM: Rxd Ack; Removing MessageCounter:108597018 from Retrans Table on exchange 2458r [1699019697.383482][1138:1139] CHIP:DL: Bluez disconnected [1699019697.383570][1138:1139] CHIP:DL: Bluez notify CHIPoBluez connection disconnected