./chip-tool accesscontrol write acl '[{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects": [112233], "targets": [{"cluster": null, "endpoint": 0, "deviceType": null}]}, {"fabricIndex": 1, "privilege": 3, "authMode": 3, "subjects": null, "targets": [{"cluster": null, "endpoint": 1, "deviceType": null}]}]' 1 0 [1655273487.823005][3455:3455] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655273487.823583][3455:3455] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655273487.823764][3455:3455] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655273487.823888][3455:3455] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655273487.824214][3455:3455] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-8iV58w) [1655273487.824906][3455:3455] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655273487.824963][3455:3455] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2) [1655273487.825827][3455:3455] CHIP:DL: Got Ethernet interface: eth0 [1655273487.826574][3455:3455] CHIP:DL: Found the primary Ethernet interface:eth0 [1655273487.827272][3455:3455] CHIP:DL: Got WiFi interface: wlan0 [1655273487.827357][3455:3455] CHIP:DL: Failed to reset WiFi statistic counts [1655273487.827416][3455:3455] CHIP:IN: UDP::Init bind&listen port=0 [1655273487.827571][3455:3455] CHIP:IN: UDP::Init bound to port=35713 [1655273487.827601][3455:3455] CHIP:IN: BLEBase::Init - setting/overriding transport [1655273487.827626][3455:3455] CHIP:IN: TransportMgr initialized [1655273487.827705][3455:3455] CHIP:FP: Initializing FabricTable from persistent storage [1655273487.827861][3455:3455] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273487.827955][3455:3455] CHIP:FP: Loading from storage for fabric index 0x1 [1655273487.828477][3455:3455] CHIP:FP: Loading from storage for fabric index 0x2 [1655273487.828866][3455:3455] CHIP:FP: Loading from storage for fabric index 0x3 [1655273487.832389][3455:3455] CHIP:ZCL: Using ZAP configuration... [1655273487.837052][3455:3455] CHIP:DL: Avahi client registered [1655273487.838388][3455:3455] CHIP:CTL: System State Initialized... [1655273487.838535][3455:3455] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273487.838591][3455:3455] CHIP:CTL: Setting attestation nonce to random value [1655273487.838644][3455:3455] CHIP:CTL: Setting CSR nonce to random value [1655273487.838758][3455:3455] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273487.838789][3455:3455] CHIP:CTL: Setting attestation nonce to random value [1655273487.838837][3455:3455] CHIP:CTL: Setting CSR nonce to random value [1655273487.841906][3455:3455] CHIP:CTL: Generating NOC [1655273487.842836][3455:3455] CHIP:FP: Validating NOC chain [1655273487.844763][3455:3455] CHIP:FP: NOC chain validation successful [1655273487.844937][3455:3455] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655273487.844966][3455:3455] CHIP:FP: Assigned compressed fabric ID: 0x4C449E0C3C685A46, node ID: 0x000000000001B669 [1655273487.851679][3455:3455] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655273487.851732][3455:3455] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273487.851757][3455:3455] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273487.851780][3455:3455] CHIP:TS: Retaining current Last Known Good Time [1655273487.853408][3455:3455] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x4C449E0C3C685A46 [1655273487.853522][3455:3455] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273487.853565][3455:3455] CHIP:CTL: Setting attestation nonce to random value [1655273487.853629][3455:3455] CHIP:CTL: Setting CSR nonce to random value [1655273487.854817][3455:3455] CHIP:CTL: Generating NOC [1655273487.855695][3455:3455] CHIP:FP: Validating NOC chain [1655273487.857547][3455:3455] CHIP:FP: NOC chain validation successful [1655273487.857757][3455:3455] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655273487.857786][3455:3455] CHIP:FP: Assigned compressed fabric ID: 0x35FCBE60CC390180, node ID: 0x000000000001B669 [1655273487.866639][3455:3455] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655273487.866697][3455:3455] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273487.866723][3455:3455] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273487.866746][3455:3455] CHIP:TS: Retaining current Last Known Good Time [1655273487.868140][3455:3455] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x35FCBE60CC390180 [1655273487.868277][3455:3455] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273487.868319][3455:3455] CHIP:CTL: Setting attestation nonce to random value [1655273487.868384][3455:3455] CHIP:CTL: Setting CSR nonce to random value [1655273487.869292][3455:3455] CHIP:CTL: Generating NOC [1655273487.870402][3455:3455] CHIP:FP: Validating NOC chain [1655273487.872601][3455:3455] CHIP:FP: NOC chain validation successful [1655273487.872796][3455:3455] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655273487.872830][3455:3455] CHIP:FP: Assigned compressed fabric ID: 0x082FA62E6A09E1D6, node ID: 0x000000000001B669 [1655273487.879093][3455:3455] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655273487.879155][3455:3455] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273487.879185][3455:3455] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273487.879212][3455:3455] CHIP:TS: Retaining current Last Known Good Time [1655273487.880985][3455:3455] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x082FA62E6A09E1D6 [1655273487.923221][3455:3460] CHIP:DL: CHIP task running [1655273487.923484][3455:3460] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655273487.923527][3455:3460] CHIP:TOO: Sending command to node 0x1 [1655273487.923566][3455:3460] CHIP:CSM: FindOrEstablishSession: PeerId = 4C449E0C3C685A46:0000000000000001 [1655273487.923598][3455:3460] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655273487.923646][3455:3460] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 1 --> 2 [1655273487.923682][3455:3460] CHIP:DIS: Resolving 4C449E0C3C685A46:0000000000000001 ... [1655273487.925988][3455:3460] CHIP:DL: Avahi resolve found [1655273487.926072][3455:3460] CHIP:DIS: Node ID resolved for 4C449E0C3C685A46:0000000000000001 [1655273487.926100][3455:3460] CHIP:DIS: Hostname: E45F01312CE50000 [1655273487.926139][3455:3460] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce6 [1655273487.926165][3455:3460] CHIP:DIS: Port: 5540 [1655273487.926189][3455:3460] CHIP:DIS: Mrp Interval idle: 5000 ms [1655273487.926212][3455:3460] CHIP:DIS: Mrp Interval active: 300 ms [1655273487.926513][3455:3460] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce6%eth0]:5540: new best score: 3 [1655273487.926543][3455:3460] CHIP:DIS: Checking node lookup status after 3 ms [1655273487.926566][3455:3460] CHIP:DIS: Keeping DNSSD lookup active [1655273488.123892][3455:3460] CHIP:DIS: Checking node lookup status after 200 ms [1655273488.124071][3455:3460] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce6%eth0]:5540 while in state 2 [1655273488.124098][3455:3460] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 2 --> 3 [1655273488.124296][3455:3460] CHIP:IN: SecureSession[0xaaaad3ad3850]: Allocated Type:2 LSID:3261 [1655273488.124336][3455:3460] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655273488.125087][3455:3460] CHIP:SC: Including MRP parameters [1655273488.125421][3455:3460] CHIP:IN: Prepared unauthenticated message 0xaaaad3adad08 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 22749i with MessageCounter:60618558. [1655273488.125472][3455:3460] CHIP:IN: Sending unauthenticated msg 0xaaaad3adad08 with MessageCounter:60618558 to 0x0000000000000000 at monotonic time: 000000000088D55F msec [1655273488.125653][3455:3460] CHIP:SC: Sent Sigma1 msg [1655273488.125683][3455:3460] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 3 --> 4 [1655273488.125710][3455:3460] CHIP:DIS: Discovery does not require any more timeouts [1655273488.186180][3455:3460] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:108588697 on exchange 22749i [1655273488.186274][3455:3460] CHIP:EM: Found matching exchange: 22749i, Delegate: 0xffff980011a0 [1655273488.186363][3455:3460] CHIP:EM: Rxd Ack; Removing MessageCounter:60618558 from Retrans Table on exchange 22749i [1655273488.186422][3455:3460] CHIP:EM: Removed CHIP MessageCounter:60618558 from RetransTable on exchange 22749i [1655273488.186556][3455:3460] CHIP:SC: Received Sigma2Resume msg [1655273488.186730][3455:3460] CHIP:SC: Found MRP parameters in the message [1655273488.186800][3455:3460] CHIP:SC: Peer assigned session session ID 36295 [1655273488.195892][3455:3460] CHIP:SC: Sending status report. Protocol code 0, exchange 22749 [1655273488.196021][3455:3460] CHIP:EM: Piggybacking Ack for MessageCounter:108588697 on exchange: 22749i [1655273488.196115][3455:3460] CHIP:IN: Prepared unauthenticated message 0xaaaad3adad08 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 22749i with MessageCounter:60618559. [1655273488.196210][3455:3460] CHIP:IN: Sending unauthenticated msg 0xaaaad3adad08 with MessageCounter:60618559 to 0x0000000000000000 at monotonic time: 000000000088D5A5 msec [1655273488.196579][3455:3460] CHIP:IN: SecureSession[0xaaaad3ad3850]: Activated - Type:2 LSID:3261 [1655273488.196615][3455:3460] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:3261 PSID:36295! [1655273488.196646][3455:3460] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 4 --> 5 [1655273488.196702][3455:3460] CHIP:TOO: Sending WriteAttribute to cluster 0x0000_001F on endpoint 0 [1655273488.196795][3455:3460] CHIP:DMG: WriteClient moving to [AddAttribu] [1655273488.196873][3455:3460] CHIP:DMG: WriteClient moving to [AddAttribu] [1655273488.196908][3455:3460] CHIP:DMG: WriteClient moving to [AddAttribu] [1655273488.197013][3455:3460] CHIP:IN: Prepared secure message 0xaaaad3adad28 to 0x0000000000000001 (1) of type 0x6 and protocolId (0, 1) on exchange 22750i with MessageCounter:39578044. [1655273488.197057][3455:3460] CHIP:IN: Sending encrypted msg 0xaaaad3adad28 with MessageCounter:39578044 to 0x0000000000000001 (1) at monotonic time: 000000000088D5A6 msec [1655273488.197203][3455:3460] CHIP:DMG: WriteClient moving to [AwaitingRe] [1655273488.209159][3455:3460] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:108588698 on exchange 22749i [1655273488.209224][3455:3460] CHIP:EM: Found matching exchange: 22749i, Delegate: (nil) [1655273488.209298][3455:3460] CHIP:EM: Rxd Ack; Removing MessageCounter:60618559 from Retrans Table on exchange 22749i [1655273488.209344][3455:3460] CHIP:EM: Removed CHIP MessageCounter:60618559 from RetransTable on exchange 22749i [1655273488.216945][3455:3460] CHIP:EM: Received message of type 0x7 with protocolId (0, 1) and MessageCounter:237106230 on exchange 22750i [1655273488.217002][3455:3460] CHIP:EM: Found matching exchange: 22750i, Delegate: 0xffff98004b20 [1655273488.217065][3455:3460] CHIP:EM: Rxd Ack; Removing MessageCounter:39578044 from Retrans Table on exchange 22750i [1655273488.217109][3455:3460] CHIP:EM: Removed CHIP MessageCounter:39578044 from RetransTable on exchange 22750i [1655273488.217169][3455:3460] CHIP:DMG: WriteClient moving to [ResponseRe] [1655273488.217263][3455:3460] CHIP:DMG: WriteResponseMessage = [1655273488.217308][3455:3460] CHIP:DMG: { [1655273488.217348][3455:3460] CHIP:DMG: AttributeStatusIBs = [1655273488.217405][3455:3460] CHIP:DMG: [ [1655273488.217451][3455:3460] CHIP:DMG: AttributeStatusIB = [1655273488.217500][3455:3460] CHIP:DMG: { [1655273488.217547][3455:3460] CHIP:DMG: AttributePathIB = [1655273488.217606][3455:3460] CHIP:DMG: { [1655273488.217664][3455:3460] CHIP:DMG: Endpoint = 0x0, [1655273488.217731][3455:3460] CHIP:DMG: Cluster = 0x1f, [1655273488.217794][3455:3460] CHIP:DMG: Attribute = 0x0000_0000, [1655273488.217851][3455:3460] CHIP:DMG: } [1655273488.217915][3455:3460] CHIP:DMG: [1655273488.217963][3455:3460] CHIP:DMG: StatusIB = [1655273488.218019][3455:3460] CHIP:DMG: { [1655273488.218077][3455:3460] CHIP:DMG: status = 0x00 (SUCCESS), [1655273488.218134][3455:3460] CHIP:DMG: }, [1655273488.218191][3455:3460] CHIP:DMG: [1655273488.218242][3455:3460] CHIP:DMG: }, [1655273488.218315][3455:3460] CHIP:DMG: [1655273488.218373][3455:3460] CHIP:DMG: AttributeStatusIB = [1655273488.218449][3455:3460] CHIP:DMG: { [1655273488.218506][3455:3460] CHIP:DMG: AttributePathIB = [1655273488.218571][3455:3460] CHIP:DMG: { [1655273488.218637][3455:3460] CHIP:DMG: Endpoint = 0x0, [1655273488.218706][3455:3460] CHIP:DMG: Cluster = 0x1f, [1655273488.218776][3455:3460] CHIP:DMG: Attribute = 0x0000_0000, [1655273488.218844][3455:3460] CHIP:DMG: ListIndex = Null, [1655273488.218909][3455:3460] CHIP:DMG: } [1655273488.218979][3455:3460] CHIP:DMG: [1655273488.219041][3455:3460] CHIP:DMG: StatusIB = [1655273488.219103][3455:3460] CHIP:DMG: { [1655273488.219166][3455:3460] CHIP:DMG: status = 0x00 (SUCCESS), [1655273488.219232][3455:3460] CHIP:DMG: }, [1655273488.219296][3455:3460] CHIP:DMG: [1655273488.219349][3455:3460] CHIP:DMG: }, [1655273488.219421][3455:3460] CHIP:DMG: [1655273488.219472][3455:3460] CHIP:DMG: AttributeStatusIB = [1655273488.219526][3455:3460] CHIP:DMG: { [1655273488.219579][3455:3460] CHIP:DMG: AttributePathIB = [1655273488.219640][3455:3460] CHIP:DMG: { [1655273488.219703][3455:3460] CHIP:DMG: Endpoint = 0x0, [1655273488.219772][3455:3460] CHIP:DMG: Cluster = 0x1f, [1655273488.219835][3455:3460] CHIP:DMG: Attribute = 0x0000_0000, [1655273488.219902][3455:3460] CHIP:DMG: ListIndex = Null, [1655273488.219966][3455:3460] CHIP:DMG: } [1655273488.220036][3455:3460] CHIP:DMG: [1655273488.220096][3455:3460] CHIP:DMG: StatusIB = [1655273488.220157][3455:3460] CHIP:DMG: { [1655273488.220221][3455:3460] CHIP:DMG: status = 0x00 (SUCCESS), [1655273488.220286][3455:3460] CHIP:DMG: }, [1655273488.220349][3455:3460] CHIP:DMG: [1655273488.220402][3455:3460] CHIP:DMG: }, [1655273488.220463][3455:3460] CHIP:DMG: [1655273488.220512][3455:3460] CHIP:DMG: ], [1655273488.220588][3455:3460] CHIP:DMG: [1655273488.220638][3455:3460] CHIP:DMG: InteractionModelRevision = 1 [1655273488.220687][3455:3460] CHIP:DMG: } [1655273488.220950][3455:3460] CHIP:DMG: WriteClient moving to [AwaitingDe] [1655273488.221052][3455:3460] CHIP:EM: Sending Standalone Ack for MessageCounter:237106230 on exchange 22750i [1655273488.221164][3455:3460] CHIP:IN: Prepared secure message 0xffffae23e958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 22750i with MessageCounter:39578045. [1655273488.221241][3455:3460] CHIP:IN: Sending encrypted msg 0xffffae23e958 with MessageCounter:39578045 to 0x0000000000000001 (1) at monotonic time: 000000000088D5BE msec [1655273488.221425][3455:3460] CHIP:EM: Flushed pending ack for MessageCounter:237106230 on exchange 22750i [1655273488.221738][3455:3455] CHIP:CTL: Shutting down the commissioner [1655273488.221799][3455:3455] CHIP:CTL: Shutting down the controller [1655273488.221854][3455:3455] CHIP:CTL: Shutting down the commissioner [1655273488.221899][3455:3455] CHIP:CTL: Shutting down the controller [1655273488.221952][3455:3455] CHIP:IN: Expiring all connections for fabric 1!! [1655273488.222000][3455:3455] CHIP:IN: SecureSession[0xaaaad3ad3850]: MarkForRemoval Type:2 LSID:3261 [1655273488.222046][3455:3455] CHIP:IN: SecureSession[0xaaaad3ad3850]: Released - Type:2 LSID:3261 [1655273488.222127][3455:3455] CHIP:CTL: Shutting down the commissioner [1655273488.222177][3455:3455] CHIP:CTL: Shutting down the controller [1655273488.222221][3455:3455] CHIP:IN: Expiring all connections for fabric 2!! [1655273488.222289][3455:3455] CHIP:CTL: Shutting down the commissioner [1655273488.222335][3455:3455] CHIP:CTL: Shutting down the controller [1655273488.222377][3455:3455] CHIP:IN: Expiring all connections for fabric 3!! [1655273488.222466][3455:3455] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655273488.224440][3455:3455] CHIP:DMG: IM WH moving to [Uninitialized] [1655273488.224523][3455:3455] CHIP:DMG: IM WH moving to [Uninitialized] [1655273488.224562][3455:3455] CHIP:DMG: IM WH moving to [Uninitialized] [1655273488.224608][3455:3455] CHIP:DMG: IM WH moving to [Uninitialized] [1655273488.224656][3455:3455] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655273488.224793][3455:3455] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655273488.225229][3455:3455] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-KXwcju) [1655273488.226307][3455:3455] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655273488.226411][3455:3455] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655273488.226518][3455:3455] CHIP:DL: Inet Layer shutdown [1655273488.226564][3455:3455] CHIP:DL: BLE shutdown [1655273488.226609][3455:3455] CHIP:DL: System Layer shutdown ./chip-tool groupkeymanagement key-set-write '{"groupKeySetID": 42, "groupKeySecurityPolicy": 0, "epochKey0": "d0d1d2d3d4d5d6d7d8d9dadbdcdddedf", "epochStartTime0": 2220000,"epochKey1": "d1d1d2d3d4d5d6d7d8d9dadbdcdddedf", "epochStartTime1": 2220001,"epochKey2": "d2d1d2d3d4d5d6d7d8d9dadbdcdddedf", "epochStartTime2": 2220002 }' 1 0 [1655273656.359478][3469:3469] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655273656.360012][3469:3469] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655273656.360177][3469:3469] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655273656.360292][3469:3469] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655273656.360654][3469:3469] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-AKdvFH) [1655273656.361310][3469:3469] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655273656.361362][3469:3469] CHIP:DL: NVS set: chip-counters/reboot-count = 3 (0x3) [1655273656.362234][3469:3469] CHIP:DL: Got Ethernet interface: eth0 [1655273656.362961][3469:3469] CHIP:DL: Found the primary Ethernet interface:eth0 [1655273656.363582][3469:3469] CHIP:DL: Got WiFi interface: wlan0 [1655273656.363658][3469:3469] CHIP:DL: Failed to reset WiFi statistic counts [1655273656.363716][3469:3469] CHIP:IN: UDP::Init bind&listen port=0 [1655273656.363865][3469:3469] CHIP:IN: UDP::Init bound to port=36996 [1655273656.363890][3469:3469] CHIP:IN: BLEBase::Init - setting/overriding transport [1655273656.363912][3469:3469] CHIP:IN: TransportMgr initialized [1655273656.363983][3469:3469] CHIP:FP: Initializing FabricTable from persistent storage [1655273656.364127][3469:3469] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273656.364210][3469:3469] CHIP:FP: Loading from storage for fabric index 0x1 [1655273656.364662][3469:3469] CHIP:FP: Loading from storage for fabric index 0x2 [1655273656.365003][3469:3469] CHIP:FP: Loading from storage for fabric index 0x3 [1655273656.368404][3469:3469] CHIP:ZCL: Using ZAP configuration... [1655273656.372693][3469:3469] CHIP:DL: Avahi client registered [1655273656.374045][3469:3469] CHIP:CTL: System State Initialized... [1655273656.374156][3469:3469] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273656.374212][3469:3469] CHIP:CTL: Setting attestation nonce to random value [1655273656.374265][3469:3469] CHIP:CTL: Setting CSR nonce to random value [1655273656.374380][3469:3469] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273656.374412][3469:3469] CHIP:CTL: Setting attestation nonce to random value [1655273656.374476][3469:3469] CHIP:CTL: Setting CSR nonce to random value [1655273656.377372][3469:3469] CHIP:CTL: Generating NOC [1655273656.378226][3469:3469] CHIP:FP: Validating NOC chain [1655273656.380421][3469:3469] CHIP:FP: NOC chain validation successful [1655273656.380629][3469:3469] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655273656.380663][3469:3469] CHIP:FP: Assigned compressed fabric ID: 0x4C449E0C3C685A46, node ID: 0x000000000001B669 [1655273656.387225][3469:3469] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655273656.387285][3469:3469] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273656.387315][3469:3469] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273656.387342][3469:3469] CHIP:TS: Retaining current Last Known Good Time [1655273656.389042][3469:3469] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x4C449E0C3C685A46 [1655273656.389192][3469:3469] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273656.389239][3469:3469] CHIP:CTL: Setting attestation nonce to random value [1655273656.389314][3469:3469] CHIP:CTL: Setting CSR nonce to random value [1655273656.390404][3469:3469] CHIP:CTL: Generating NOC [1655273656.391380][3469:3469] CHIP:FP: Validating NOC chain [1655273656.393085][3469:3469] CHIP:FP: NOC chain validation successful [1655273656.393244][3469:3469] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655273656.393270][3469:3469] CHIP:FP: Assigned compressed fabric ID: 0x35FCBE60CC390180, node ID: 0x000000000001B669 [1655273656.400136][3469:3469] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655273656.400192][3469:3469] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273656.400217][3469:3469] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273656.400240][3469:3469] CHIP:TS: Retaining current Last Known Good Time [1655273656.401885][3469:3469] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x35FCBE60CC390180 [1655273656.402000][3469:3469] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273656.402045][3469:3469] CHIP:CTL: Setting attestation nonce to random value [1655273656.402113][3469:3469] CHIP:CTL: Setting CSR nonce to random value [1655273656.403031][3469:3469] CHIP:CTL: Generating NOC [1655273656.403913][3469:3469] CHIP:FP: Validating NOC chain [1655273656.405751][3469:3469] CHIP:FP: NOC chain validation successful [1655273656.405915][3469:3469] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655273656.405943][3469:3469] CHIP:FP: Assigned compressed fabric ID: 0x082FA62E6A09E1D6, node ID: 0x000000000001B669 [1655273656.411867][3469:3469] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655273656.411922][3469:3469] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273656.411948][3469:3469] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273656.411971][3469:3469] CHIP:TS: Retaining current Last Known Good Time [1655273656.413415][3469:3469] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x082FA62E6A09E1D6 [1655273656.457006][3469:3474] CHIP:DL: CHIP task running [1655273656.457245][3469:3474] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655273656.457304][3469:3474] CHIP:TOO: Sending command to node 0x1 [1655273656.457340][3469:3474] CHIP:CSM: FindOrEstablishSession: PeerId = 4C449E0C3C685A46:0000000000000001 [1655273656.457367][3469:3474] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655273656.457408][3469:3474] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 1 --> 2 [1655273656.457449][3469:3474] CHIP:DIS: Resolving 4C449E0C3C685A46:0000000000000001 ... [1655273656.567244][3469:3474] CHIP:DL: Avahi resolve found [1655273656.567340][3469:3474] CHIP:DIS: Node ID resolved for 4C449E0C3C685A46:0000000000000001 [1655273656.567370][3469:3474] CHIP:DIS: Hostname: E45F01312CE50000 [1655273656.567401][3469:3474] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655273656.567425][3469:3474] CHIP:DIS: Port: 5540 [1655273656.567447][3469:3474] CHIP:DIS: Mrp Interval idle: 5000 ms [1655273656.567470][3469:3474] CHIP:DIS: Mrp Interval active: 300 ms [1655273656.567729][3469:3474] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655273656.567766][3469:3474] CHIP:DIS: Checking node lookup status after 110 ms [1655273656.567788][3469:3474] CHIP:DIS: Keeping DNSSD lookup active [1655273656.657957][3469:3474] CHIP:DIS: Checking node lookup status after 200 ms [1655273656.658236][3469:3474] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655273656.658300][3469:3474] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 2 --> 3 [1655273656.658754][3469:3474] CHIP:IN: SecureSession[0xaaaad3ce2100]: Allocated Type:2 LSID:50335 [1655273656.658840][3469:3474] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655273656.660278][3469:3474] CHIP:SC: Including MRP parameters [1655273656.660753][3469:3474] CHIP:IN: Prepared unauthenticated message 0xaaaad3ce95b8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 2209i with MessageCounter:138139510. [1655273656.660858][3469:3474] CHIP:IN: Sending unauthenticated msg 0xaaaad3ce95b8 with MessageCounter:138139510 to 0x0000000000000000 at monotonic time: 00000000008B67B6 msec [1655273656.661203][3469:3474] CHIP:SC: Sent Sigma1 msg [1655273656.661274][3469:3474] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 3 --> 4 [1655273656.661338][3469:3474] CHIP:DIS: Discovery does not require any more timeouts [1655273656.662760][3469:3474] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:108588699 on exchange 2209i [1655273656.662837][3469:3474] CHIP:EM: Found matching exchange: 2209i, Delegate: 0xffff780011a0 [1655273656.662922][3469:3474] CHIP:EM: Rxd Ack; Removing MessageCounter:138139510 from Retrans Table on exchange 2209i [1655273656.662982][3469:3474] CHIP:EM: Removed CHIP MessageCounter:138139510 from RetransTable on exchange 2209i [1655273656.663065][3469:3474] CHIP:SC: Received Sigma2Resume msg [1655273656.663227][3469:3474] CHIP:SC: Found MRP parameters in the message [1655273656.663293][3469:3474] CHIP:SC: Peer assigned session session ID 36296 [1655273656.672091][3469:3474] CHIP:SC: Sending status report. Protocol code 0, exchange 2209 [1655273656.672166][3469:3474] CHIP:EM: Piggybacking Ack for MessageCounter:108588699 on exchange: 2209i [1655273656.672217][3469:3474] CHIP:IN: Prepared unauthenticated message 0xaaaad3ce95b8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 2209i with MessageCounter:138139511. [1655273656.672266][3469:3474] CHIP:IN: Sending unauthenticated msg 0xaaaad3ce95b8 with MessageCounter:138139511 to 0x0000000000000000 at monotonic time: 00000000008B67C1 msec [1655273656.672530][3469:3474] CHIP:IN: SecureSession[0xaaaad3ce2100]: Activated - Type:2 LSID:50335 [1655273656.672566][3469:3474] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:50335 PSID:36296! [1655273656.672596][3469:3474] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 4 --> 5 [1655273656.672648][3469:3474] CHIP:TOO: Sending cluster (0x0000003F) command (0x00000000) on endpoint 0 [1655273656.672728][3469:3474] CHIP:DMG: ICR moving to [AddingComm] [1655273656.672796][3469:3474] CHIP:DMG: ICR moving to [AddedComma] [1655273656.672897][3469:3474] CHIP:IN: Prepared secure message 0xaaaad3ce95d8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 2210i with MessageCounter:211930106. [1655273656.672938][3469:3474] CHIP:IN: Sending encrypted msg 0xaaaad3ce95d8 with MessageCounter:211930106 to 0x0000000000000001 (1) at monotonic time: 00000000008B67C2 msec [1655273656.673069][3469:3474] CHIP:DMG: ICR moving to [CommandSen] [1655273656.677675][3469:3474] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:108588700 on exchange 2209i [1655273656.677716][3469:3474] CHIP:EM: Found matching exchange: 2209i, Delegate: (nil) [1655273656.677759][3469:3474] CHIP:EM: Rxd Ack; Removing MessageCounter:138139511 from Retrans Table on exchange 2209i [1655273656.677787][3469:3474] CHIP:EM: Removed CHIP MessageCounter:138139511 from RetransTable on exchange 2209i [1655273656.682825][3469:3474] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:205325721 on exchange 2210i [1655273656.682859][3469:3474] CHIP:EM: Found matching exchange: 2210i, Delegate: 0xffff78004350 [1655273656.682896][3469:3474] CHIP:EM: Rxd Ack; Removing MessageCounter:211930106 from Retrans Table on exchange 2210i [1655273656.682920][3469:3474] CHIP:EM: Removed CHIP MessageCounter:211930106 from RetransTable on exchange 2210i [1655273656.682955][3469:3474] CHIP:DMG: ICR moving to [ResponseRe] [1655273656.683008][3469:3474] CHIP:DMG: InvokeResponseMessage = [1655273656.683034][3469:3474] CHIP:DMG: { [1655273656.683059][3469:3474] CHIP:DMG: suppressResponse = false, [1655273656.683086][3469:3474] CHIP:DMG: InvokeResponseIBs = [1655273656.683118][3469:3474] CHIP:DMG: [ [1655273656.683144][3469:3474] CHIP:DMG: InvokeResponseIB = [1655273656.683179][3469:3474] CHIP:DMG: { [1655273656.683206][3469:3474] CHIP:DMG: CommandStatusIB = [1655273656.683240][3469:3474] CHIP:DMG: { [1655273656.683270][3469:3474] CHIP:DMG: CommandPathIB = [1655273656.683309][3469:3474] CHIP:DMG: { [1655273656.683345][3469:3474] CHIP:DMG: EndpointId = 0x0, [1655273656.683382][3469:3474] CHIP:DMG: ClusterId = 0x3f, [1655273656.683417][3469:3474] CHIP:DMG: CommandId = 0x0, [1655273656.683452][3469:3474] CHIP:DMG: }, [1655273656.683491][3469:3474] CHIP:DMG: [1655273656.683521][3469:3474] CHIP:DMG: StatusIB = [1655273656.683557][3469:3474] CHIP:DMG: { [1655273656.683592][3469:3474] CHIP:DMG: status = 0x00 (SUCCESS), [1655273656.683627][3469:3474] CHIP:DMG: }, [1655273656.683661][3469:3474] CHIP:DMG: [1655273656.683692][3469:3474] CHIP:DMG: }, [1655273656.683727][3469:3474] CHIP:DMG: [1655273656.683754][3469:3474] CHIP:DMG: }, [1655273656.683786][3469:3474] CHIP:DMG: [1655273656.683811][3469:3474] CHIP:DMG: ], [1655273656.683842][3469:3474] CHIP:DMG: [1655273656.683867][3469:3474] CHIP:DMG: InteractionModelRevision = 1 [1655273656.683899][3469:3474] CHIP:DMG: }, [1655273656.684066][3469:3474] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003F Command=0x0000_0000 Status=0x0 [1655273656.684135][3469:3474] CHIP:DMG: ICR moving to [AwaitingDe] [1655273656.684217][3469:3474] CHIP:EM: Sending Standalone Ack for MessageCounter:205325721 on exchange 2210i [1655273656.684308][3469:3474] CHIP:IN: Prepared secure message 0xffff8dd00958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 2210i with MessageCounter:211930107. [1655273656.684367][3469:3474] CHIP:IN: Sending encrypted msg 0xffff8dd00958 with MessageCounter:211930107 to 0x0000000000000001 (1) at monotonic time: 00000000008B67CD msec [1655273656.684516][3469:3474] CHIP:EM: Flushed pending ack for MessageCounter:205325721 on exchange 2210i [1655273656.684778][3469:3469] CHIP:CTL: Shutting down the commissioner [1655273656.684829][3469:3469] CHIP:CTL: Shutting down the controller [1655273656.684874][3469:3469] CHIP:CTL: Shutting down the commissioner [1655273656.684909][3469:3469] CHIP:CTL: Shutting down the controller [1655273656.684953][3469:3469] CHIP:IN: Expiring all connections for fabric 1!! [1655273656.684990][3469:3469] CHIP:IN: SecureSession[0xaaaad3ce2100]: MarkForRemoval Type:2 LSID:50335 [1655273656.685026][3469:3469] CHIP:IN: SecureSession[0xaaaad3ce2100]: Released - Type:2 LSID:50335 [1655273656.685092][3469:3469] CHIP:CTL: Shutting down the commissioner [1655273656.685132][3469:3469] CHIP:CTL: Shutting down the controller [1655273656.685165][3469:3469] CHIP:IN: Expiring all connections for fabric 2!! [1655273656.685218][3469:3469] CHIP:CTL: Shutting down the commissioner [1655273656.685254][3469:3469] CHIP:CTL: Shutting down the controller [1655273656.685286][3469:3469] CHIP:IN: Expiring all connections for fabric 3!! [1655273656.685334][3469:3469] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655273656.686685][3469:3469] CHIP:DMG: IM WH moving to [Uninitialized] [1655273656.686744][3469:3469] CHIP:DMG: IM WH moving to [Uninitialized] [1655273656.686784][3469:3469] CHIP:DMG: IM WH moving to [Uninitialized] [1655273656.686818][3469:3469] CHIP:DMG: IM WH moving to [Uninitialized] [1655273656.686854][3469:3469] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655273656.686963][3469:3469] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655273656.687336][3469:3469] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-nXSEQE) [1655273656.688262][3469:3469] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655273656.688357][3469:3469] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655273656.688401][3469:3469] CHIP:DL: Inet Layer shutdown [1655273656.688437][3469:3469] CHIP:DL: BLE shutdown [1655273656.688473][3469:3469] CHIP:DL: System Layer shutdown ./chip-tool groups add-group 0x0001 grp1 1 0 [1655273771.706001][3480:3480] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655273771.706592][3480:3480] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655273771.706765][3480:3480] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655273771.706875][3480:3480] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655273771.707238][3480:3480] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-UfAE3L) [1655273771.707866][3480:3480] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655273771.707921][3480:3480] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4) [1655273771.708777][3480:3480] CHIP:DL: Got Ethernet interface: eth0 [1655273771.709346][3480:3480] CHIP:DL: Found the primary Ethernet interface:eth0 [1655273771.709962][3480:3480] CHIP:DL: Got WiFi interface: wlan0 [1655273771.710041][3480:3480] CHIP:DL: Failed to reset WiFi statistic counts [1655273771.710096][3480:3480] CHIP:IN: UDP::Init bind&listen port=0 [1655273771.710239][3480:3480] CHIP:IN: UDP::Init bound to port=39421 [1655273771.710265][3480:3480] CHIP:IN: BLEBase::Init - setting/overriding transport [1655273771.710292][3480:3480] CHIP:IN: TransportMgr initialized [1655273771.710370][3480:3480] CHIP:FP: Initializing FabricTable from persistent storage [1655273771.710604][3480:3480] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273771.710713][3480:3480] CHIP:FP: Loading from storage for fabric index 0x1 [1655273771.711249][3480:3480] CHIP:FP: Loading from storage for fabric index 0x2 [1655273771.711674][3480:3480] CHIP:FP: Loading from storage for fabric index 0x3 [1655273771.715586][3480:3480] CHIP:ZCL: Using ZAP configuration... [1655273771.720461][3480:3480] CHIP:DL: Avahi client registered [1655273771.721916][3480:3480] CHIP:CTL: System State Initialized... [1655273771.722029][3480:3480] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273771.722087][3480:3480] CHIP:CTL: Setting attestation nonce to random value [1655273771.722143][3480:3480] CHIP:CTL: Setting CSR nonce to random value [1655273771.722264][3480:3480] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273771.722299][3480:3480] CHIP:CTL: Setting attestation nonce to random value [1655273771.722351][3480:3480] CHIP:CTL: Setting CSR nonce to random value [1655273771.725422][3480:3480] CHIP:CTL: Generating NOC [1655273771.726326][3480:3480] CHIP:FP: Validating NOC chain [1655273771.728474][3480:3480] CHIP:FP: NOC chain validation successful [1655273771.728659][3480:3480] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655273771.728691][3480:3480] CHIP:FP: Assigned compressed fabric ID: 0x4C449E0C3C685A46, node ID: 0x000000000001B669 [1655273771.734759][3480:3480] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655273771.734817][3480:3480] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273771.734843][3480:3480] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273771.734865][3480:3480] CHIP:TS: Retaining current Last Known Good Time [1655273771.736308][3480:3480] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x4C449E0C3C685A46 [1655273771.736447][3480:3480] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273771.736488][3480:3480] CHIP:CTL: Setting attestation nonce to random value [1655273771.736555][3480:3480] CHIP:CTL: Setting CSR nonce to random value [1655273771.737559][3480:3480] CHIP:CTL: Generating NOC [1655273771.738507][3480:3480] CHIP:FP: Validating NOC chain [1655273771.740484][3480:3480] CHIP:FP: NOC chain validation successful [1655273771.740739][3480:3480] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655273771.740770][3480:3480] CHIP:FP: Assigned compressed fabric ID: 0x35FCBE60CC390180, node ID: 0x000000000001B669 [1655273771.747696][3480:3480] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655273771.747748][3480:3480] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273771.747774][3480:3480] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273771.747795][3480:3480] CHIP:TS: Retaining current Last Known Good Time [1655273771.749462][3480:3480] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x35FCBE60CC390180 [1655273771.749576][3480:3480] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273771.749619][3480:3480] CHIP:CTL: Setting attestation nonce to random value [1655273771.749683][3480:3480] CHIP:CTL: Setting CSR nonce to random value [1655273771.750625][3480:3480] CHIP:CTL: Generating NOC [1655273771.751558][3480:3480] CHIP:FP: Validating NOC chain [1655273771.753590][3480:3480] CHIP:FP: NOC chain validation successful [1655273771.753770][3480:3480] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655273771.753802][3480:3480] CHIP:FP: Assigned compressed fabric ID: 0x082FA62E6A09E1D6, node ID: 0x000000000001B669 [1655273771.759729][3480:3480] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655273771.759787][3480:3480] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273771.759814][3480:3480] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273771.759838][3480:3480] CHIP:TS: Retaining current Last Known Good Time [1655273771.761310][3480:3480] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x082FA62E6A09E1D6 [1655273771.803529][3480:3485] CHIP:DL: CHIP task running [1655273771.803770][3480:3485] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655273771.803804][3480:3485] CHIP:TOO: Sending command to node 0x1 [1655273771.803841][3480:3485] CHIP:CSM: FindOrEstablishSession: PeerId = 4C449E0C3C685A46:0000000000000001 [1655273771.803868][3480:3485] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655273771.803910][3480:3485] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 1 --> 2 [1655273771.803940][3480:3485] CHIP:DIS: Resolving 4C449E0C3C685A46:0000000000000001 ... [1655273771.805894][3480:3485] CHIP:DL: Avahi resolve found [1655273771.805984][3480:3485] CHIP:DIS: Node ID resolved for 4C449E0C3C685A46:0000000000000001 [1655273771.806018][3480:3485] CHIP:DIS: Hostname: E45F01312CE50000 [1655273771.806058][3480:3485] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655273771.806087][3480:3485] CHIP:DIS: Port: 5540 [1655273771.806115][3480:3485] CHIP:DIS: Mrp Interval idle: 5000 ms [1655273771.806143][3480:3485] CHIP:DIS: Mrp Interval active: 300 ms [1655273771.806476][3480:3485] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655273771.806515][3480:3485] CHIP:DIS: Checking node lookup status after 3 ms [1655273771.806542][3480:3485] CHIP:DIS: Keeping DNSSD lookup active [1655273772.004052][3480:3485] CHIP:DIS: Checking node lookup status after 200 ms [1655273772.004344][3480:3485] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655273772.004409][3480:3485] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 2 --> 3 [1655273772.004800][3480:3485] CHIP:IN: SecureSession[0xaaaaeb796320]: Allocated Type:2 LSID:19670 [1655273772.004886][3480:3485] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655273772.006350][3480:3485] CHIP:SC: Including MRP parameters [1655273772.006929][3480:3485] CHIP:IN: Prepared unauthenticated message 0xaaaaeb79d7d8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 36686i with MessageCounter:181526316. [1655273772.007037][3480:3485] CHIP:IN: Sending unauthenticated msg 0xaaaaeb79d7d8 with MessageCounter:181526316 to 0x0000000000000000 at monotonic time: 00000000008D2A48 msec [1655273772.007387][3480:3485] CHIP:SC: Sent Sigma1 msg [1655273772.007459][3480:3485] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 3 --> 4 [1655273772.007526][3480:3485] CHIP:DIS: Discovery does not require any more timeouts [1655273772.009332][3480:3485] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:108588701 on exchange 36686i [1655273772.009408][3480:3485] CHIP:EM: Found matching exchange: 36686i, Delegate: 0xffff7c0011a0 [1655273772.009493][3480:3485] CHIP:EM: Rxd Ack; Removing MessageCounter:181526316 from Retrans Table on exchange 36686i [1655273772.009555][3480:3485] CHIP:EM: Removed CHIP MessageCounter:181526316 from RetransTable on exchange 36686i [1655273772.009635][3480:3485] CHIP:SC: Received Sigma2Resume msg [1655273772.009791][3480:3485] CHIP:SC: Found MRP parameters in the message [1655273772.009860][3480:3485] CHIP:SC: Peer assigned session session ID 36297 [1655273772.017830][3480:3485] CHIP:SC: Sending status report. Protocol code 0, exchange 36686 [1655273772.017906][3480:3485] CHIP:EM: Piggybacking Ack for MessageCounter:108588701 on exchange: 36686i [1655273772.017956][3480:3485] CHIP:IN: Prepared unauthenticated message 0xaaaaeb79d7d8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 36686i with MessageCounter:181526317. [1655273772.018006][3480:3485] CHIP:IN: Sending unauthenticated msg 0xaaaaeb79d7d8 with MessageCounter:181526317 to 0x0000000000000000 at monotonic time: 00000000008D2A53 msec [1655273772.018270][3480:3485] CHIP:IN: SecureSession[0xaaaaeb796320]: Activated - Type:2 LSID:19670 [1655273772.018305][3480:3485] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:19670 PSID:36297! [1655273772.018334][3480:3485] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 4 --> 5 [1655273772.018388][3480:3485] CHIP:TOO: Sending cluster (0x00000004) command (0x00000000) on endpoint 0 [1655273772.018483][3480:3485] CHIP:DMG: ICR moving to [AddingComm] [1655273772.018519][3480:3485] CHIP:DMG: ICR moving to [AddedComma] [1655273772.018615][3480:3485] CHIP:IN: Prepared secure message 0xaaaaeb79d7f8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 36687i with MessageCounter:26003801. [1655273772.018656][3480:3485] CHIP:IN: Sending encrypted msg 0xaaaaeb79d7f8 with MessageCounter:26003801 to 0x0000000000000001 (1) at monotonic time: 00000000008D2A54 msec [1655273772.018796][3480:3485] CHIP:DMG: ICR moving to [CommandSen] [1655273772.023835][3480:3485] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:108588702 on exchange 36686i [1655273772.023873][3480:3485] CHIP:EM: Found matching exchange: 36686i, Delegate: (nil) [1655273772.023917][3480:3485] CHIP:EM: Rxd Ack; Removing MessageCounter:181526317 from Retrans Table on exchange 36686i [1655273772.023944][3480:3485] CHIP:EM: Removed CHIP MessageCounter:181526317 from RetransTable on exchange 36686i [1655273772.033440][3480:3485] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:163261359 on exchange 36687i [1655273772.033499][3480:3485] CHIP:EM: Found matching exchange: 36687i, Delegate: 0xffff7c003f10 [1655273772.033558][3480:3485] CHIP:EM: Rxd Ack; Removing MessageCounter:26003801 from Retrans Table on exchange 36687i [1655273772.033596][3480:3485] CHIP:EM: Removed CHIP MessageCounter:26003801 from RetransTable on exchange 36687i [1655273772.033649][3480:3485] CHIP:DMG: ICR moving to [ResponseRe] [1655273772.033724][3480:3485] CHIP:DMG: InvokeResponseMessage = [1655273772.033765][3480:3485] CHIP:DMG: { [1655273772.033803][3480:3485] CHIP:DMG: suppressResponse = false, [1655273772.033844][3480:3485] CHIP:DMG: InvokeResponseIBs = [1655273772.033896][3480:3485] CHIP:DMG: [ [1655273772.033936][3480:3485] CHIP:DMG: InvokeResponseIB = [1655273772.033989][3480:3485] CHIP:DMG: { [1655273772.034031][3480:3485] CHIP:DMG: CommandDataIB = [1655273772.034083][3480:3485] CHIP:DMG: { [1655273772.034131][3480:3485] CHIP:DMG: CommandPathIB = [1655273772.034186][3480:3485] CHIP:DMG: { [1655273772.034242][3480:3485] CHIP:DMG: EndpointId = 0x0, [1655273772.034299][3480:3485] CHIP:DMG: ClusterId = 0x4, [1655273772.034361][3480:3485] CHIP:DMG: CommandId = 0x0, [1655273772.034415][3480:3485] CHIP:DMG: }, [1655273772.034505][3480:3485] CHIP:DMG: [1655273772.034555][3480:3485] CHIP:DMG: CommandFields = [1655273772.034609][3480:3485] CHIP:DMG: { [1655273772.034695][3480:3485] CHIP:DMG: 0x0 = 0, [1655273772.034752][3480:3485] CHIP:DMG: 0x1 = 1, [1655273772.034813][3480:3485] CHIP:DMG: }, [1655273772.034863][3480:3485] CHIP:DMG: }, [1655273772.034918][3480:3485] CHIP:DMG: [1655273772.034963][3480:3485] CHIP:DMG: }, [1655273772.035014][3480:3485] CHIP:DMG: [1655273772.035053][3480:3485] CHIP:DMG: ], [1655273772.035103][3480:3485] CHIP:DMG: [1655273772.035142][3480:3485] CHIP:DMG: InteractionModelRevision = 1 [1655273772.035180][3480:3485] CHIP:DMG: }, [1655273772.035275][3480:3485] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0004 Command=0x0000_0000 [1655273772.035345][3480:3485] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0004 Command 0x0000_0000 [1655273772.035423][3480:3485] CHIP:TOO: AddGroupResponse: { [1655273772.035476][3480:3485] CHIP:TOO: status: 0 [1655273772.035517][3480:3485] CHIP:TOO: groupId: 1 [1655273772.035555][3480:3485] CHIP:TOO: } [1655273772.035613][3480:3485] CHIP:DMG: ICR moving to [AwaitingDe] [1655273772.035697][3480:3485] CHIP:EM: Sending Standalone Ack for MessageCounter:163261359 on exchange 36687i [1655273772.035797][3480:3485] CHIP:IN: Prepared secure message 0xffff83ffd958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 36687i with MessageCounter:26003802. [1655273772.035860][3480:3485] CHIP:IN: Sending encrypted msg 0xffff83ffd958 with MessageCounter:26003802 to 0x0000000000000001 (1) at monotonic time: 00000000008D2A65 msec [1655273772.036022][3480:3485] CHIP:EM: Flushed pending ack for MessageCounter:163261359 on exchange 36687i [1655273772.036262][3480:3480] CHIP:CTL: Shutting down the commissioner [1655273772.036310][3480:3480] CHIP:CTL: Shutting down the controller [1655273772.036356][3480:3480] CHIP:CTL: Shutting down the commissioner [1655273772.036392][3480:3480] CHIP:CTL: Shutting down the controller [1655273772.036436][3480:3480] CHIP:IN: Expiring all connections for fabric 1!! [1655273772.036473][3480:3480] CHIP:IN: SecureSession[0xaaaaeb796320]: MarkForRemoval Type:2 LSID:19670 [1655273772.036510][3480:3480] CHIP:IN: SecureSession[0xaaaaeb796320]: Released - Type:2 LSID:19670 [1655273772.036577][3480:3480] CHIP:CTL: Shutting down the commissioner [1655273772.036616][3480:3480] CHIP:CTL: Shutting down the controller [1655273772.036647][3480:3480] CHIP:IN: Expiring all connections for fabric 2!! [1655273772.036701][3480:3480] CHIP:CTL: Shutting down the commissioner [1655273772.036737][3480:3480] CHIP:CTL: Shutting down the controller [1655273772.036770][3480:3480] CHIP:IN: Expiring all connections for fabric 3!! [1655273772.036818][3480:3480] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655273772.038127][3480:3480] CHIP:DMG: IM WH moving to [Uninitialized] [1655273772.038187][3480:3480] CHIP:DMG: IM WH moving to [Uninitialized] [1655273772.038222][3480:3480] CHIP:DMG: IM WH moving to [Uninitialized] [1655273772.038255][3480:3480] CHIP:DMG: IM WH moving to [Uninitialized] [1655273772.038290][3480:3480] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655273772.038394][3480:3480] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655273772.038810][3480:3480] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-vRN8DV) [1655273772.039737][3480:3480] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655273772.039829][3480:3480] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655273772.039871][3480:3480] CHIP:DL: Inet Layer shutdown [1655273772.039906][3480:3480] CHIP:DL: BLE shutdown [1655273772.039942][3480:3480] CHIP:DL: System Layer shutdown ./chip-tool groupkeymanagement write group-key-map '[{"groupId": 1, "groupKeySetID": 42, "fabricIndex": 1}]' 1 0 [1655273906.308667][3495:3495] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655273906.309214][3495:3495] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655273906.309376][3495:3495] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655273906.309487][3495:3495] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655273906.309850][3495:3495] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-LIbro7) [1655273906.310516][3495:3495] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655273906.310573][3495:3495] CHIP:DL: NVS set: chip-counters/reboot-count = 5 (0x5) [1655273906.311449][3495:3495] CHIP:DL: Got Ethernet interface: eth0 [1655273906.312032][3495:3495] CHIP:DL: Found the primary Ethernet interface:eth0 [1655273906.312628][3495:3495] CHIP:DL: Got WiFi interface: wlan0 [1655273906.312701][3495:3495] CHIP:DL: Failed to reset WiFi statistic counts [1655273906.312758][3495:3495] CHIP:IN: UDP::Init bind&listen port=0 [1655273906.312898][3495:3495] CHIP:IN: UDP::Init bound to port=40162 [1655273906.312923][3495:3495] CHIP:IN: BLEBase::Init - setting/overriding transport [1655273906.312945][3495:3495] CHIP:IN: TransportMgr initialized [1655273906.313014][3495:3495] CHIP:FP: Initializing FabricTable from persistent storage [1655273906.313185][3495:3495] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273906.313272][3495:3495] CHIP:FP: Loading from storage for fabric index 0x1 [1655273906.313708][3495:3495] CHIP:FP: Loading from storage for fabric index 0x2 [1655273906.314072][3495:3495] CHIP:FP: Loading from storage for fabric index 0x3 [1655273906.317803][3495:3495] CHIP:ZCL: Using ZAP configuration... [1655273906.322716][3495:3495] CHIP:DL: Avahi client registered [1655273906.324207][3495:3495] CHIP:CTL: System State Initialized... [1655273906.324313][3495:3495] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273906.324374][3495:3495] CHIP:CTL: Setting attestation nonce to random value [1655273906.324435][3495:3495] CHIP:CTL: Setting CSR nonce to random value [1655273906.324563][3495:3495] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273906.324599][3495:3495] CHIP:CTL: Setting attestation nonce to random value [1655273906.324656][3495:3495] CHIP:CTL: Setting CSR nonce to random value [1655273906.328294][3495:3495] CHIP:CTL: Generating NOC [1655273906.329342][3495:3495] CHIP:FP: Validating NOC chain [1655273906.331811][3495:3495] CHIP:FP: NOC chain validation successful [1655273906.332028][3495:3495] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655273906.332067][3495:3495] CHIP:FP: Assigned compressed fabric ID: 0x4C449E0C3C685A46, node ID: 0x000000000001B669 [1655273906.339483][3495:3495] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655273906.339537][3495:3495] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273906.339561][3495:3495] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273906.339582][3495:3495] CHIP:TS: Retaining current Last Known Good Time [1655273906.341244][3495:3495] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x4C449E0C3C685A46 [1655273906.341358][3495:3495] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273906.341400][3495:3495] CHIP:CTL: Setting attestation nonce to random value [1655273906.341463][3495:3495] CHIP:CTL: Setting CSR nonce to random value [1655273906.342302][3495:3495] CHIP:CTL: Generating NOC [1655273906.343137][3495:3495] CHIP:FP: Validating NOC chain [1655273906.344919][3495:3495] CHIP:FP: NOC chain validation successful [1655273906.345078][3495:3495] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655273906.345106][3495:3495] CHIP:FP: Assigned compressed fabric ID: 0x35FCBE60CC390180, node ID: 0x000000000001B669 [1655273906.350575][3495:3495] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655273906.350633][3495:3495] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273906.350658][3495:3495] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273906.350681][3495:3495] CHIP:TS: Retaining current Last Known Good Time [1655273906.352097][3495:3495] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x35FCBE60CC390180 [1655273906.352235][3495:3495] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655273906.352276][3495:3495] CHIP:CTL: Setting attestation nonce to random value [1655273906.352340][3495:3495] CHIP:CTL: Setting CSR nonce to random value [1655273906.353209][3495:3495] CHIP:CTL: Generating NOC [1655273906.354200][3495:3495] CHIP:FP: Validating NOC chain [1655273906.356088][3495:3495] CHIP:FP: NOC chain validation successful [1655273906.356341][3495:3495] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655273906.356372][3495:3495] CHIP:FP: Assigned compressed fabric ID: 0x082FA62E6A09E1D6, node ID: 0x000000000001B669 [1655273906.362575][3495:3495] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655273906.362629][3495:3495] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655273906.362653][3495:3495] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655273906.362674][3495:3495] CHIP:TS: Retaining current Last Known Good Time [1655273906.364178][3495:3495] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x082FA62E6A09E1D6 [1655273906.406527][3495:3500] CHIP:DL: CHIP task running [1655273906.406784][3495:3500] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655273906.406825][3495:3500] CHIP:TOO: Sending command to node 0x1 [1655273906.406863][3495:3500] CHIP:CSM: FindOrEstablishSession: PeerId = 4C449E0C3C685A46:0000000000000001 [1655273906.406892][3495:3500] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655273906.406933][3495:3500] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 1 --> 2 [1655273906.406963][3495:3500] CHIP:DIS: Resolving 4C449E0C3C685A46:0000000000000001 ... [1655273906.518902][3495:3500] CHIP:DL: Avahi resolve found [1655273906.519053][3495:3500] CHIP:DIS: Node ID resolved for 4C449E0C3C685A46:0000000000000001 [1655273906.519120][3495:3500] CHIP:DIS: Hostname: E45F01312CE50000 [1655273906.519189][3495:3500] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655273906.519246][3495:3500] CHIP:DIS: Port: 5540 [1655273906.519301][3495:3500] CHIP:DIS: Mrp Interval idle: 5000 ms [1655273906.519358][3495:3500] CHIP:DIS: Mrp Interval active: 300 ms [1655273906.519837][3495:3500] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655273906.519904][3495:3500] CHIP:DIS: Checking node lookup status after 113 ms [1655273906.519956][3495:3500] CHIP:DIS: Keeping DNSSD lookup active [1655273906.607362][3495:3500] CHIP:DIS: Checking node lookup status after 200 ms [1655273906.607629][3495:3500] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655273906.607692][3495:3500] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 2 --> 3 [1655273906.608074][3495:3500] CHIP:IN: SecureSession[0xaaaad9c93850]: Allocated Type:2 LSID:12143 [1655273906.608159][3495:3500] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655273906.609613][3495:3500] CHIP:SC: Including MRP parameters [1655273906.610089][3495:3500] CHIP:IN: Prepared unauthenticated message 0xaaaad9c9ad08 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 10501i with MessageCounter:26487287. [1655273906.610195][3495:3500] CHIP:IN: Sending unauthenticated msg 0xaaaad9c9ad08 with MessageCounter:26487287 to 0x0000000000000000 at monotonic time: 00000000008F3813 msec [1655273906.610623][3495:3500] CHIP:SC: Sent Sigma1 msg [1655273906.610695][3495:3500] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 3 --> 4 [1655273906.610761][3495:3500] CHIP:DIS: Discovery does not require any more timeouts [1655273906.612705][3495:3500] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:108588703 on exchange 10501i [1655273906.612782][3495:3500] CHIP:EM: Found matching exchange: 10501i, Delegate: 0xffff840011a0 [1655273906.612869][3495:3500] CHIP:EM: Rxd Ack; Removing MessageCounter:26487287 from Retrans Table on exchange 10501i [1655273906.612928][3495:3500] CHIP:EM: Removed CHIP MessageCounter:26487287 from RetransTable on exchange 10501i [1655273906.613009][3495:3500] CHIP:SC: Received Sigma2Resume msg [1655273906.613171][3495:3500] CHIP:SC: Found MRP parameters in the message [1655273906.613241][3495:3500] CHIP:SC: Peer assigned session session ID 36298 [1655273906.621662][3495:3500] CHIP:SC: Sending status report. Protocol code 0, exchange 10501 [1655273906.621739][3495:3500] CHIP:EM: Piggybacking Ack for MessageCounter:108588703 on exchange: 10501i [1655273906.621790][3495:3500] CHIP:IN: Prepared unauthenticated message 0xaaaad9c9ad08 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 10501i with MessageCounter:26487288. [1655273906.621840][3495:3500] CHIP:IN: Sending unauthenticated msg 0xaaaad9c9ad08 with MessageCounter:26487288 to 0x0000000000000000 at monotonic time: 00000000008F381F msec [1655273906.622105][3495:3500] CHIP:IN: SecureSession[0xaaaad9c93850]: Activated - Type:2 LSID:12143 [1655273906.622139][3495:3500] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:12143 PSID:36298! [1655273906.622168][3495:3500] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 4 --> 5 [1655273906.622221][3495:3500] CHIP:TOO: Sending WriteAttribute to cluster 0x0000_003F on endpoint 0 [1655273906.622286][3495:3500] CHIP:DMG: WriteClient moving to [AddAttribu] [1655273906.622370][3495:3500] CHIP:DMG: WriteClient moving to [AddAttribu] [1655273906.622514][3495:3500] CHIP:IN: Prepared secure message 0xaaaad9c9ad28 to 0x0000000000000001 (1) of type 0x6 and protocolId (0, 1) on exchange 10502i with MessageCounter:41706702. [1655273906.622559][3495:3500] CHIP:IN: Sending encrypted msg 0xaaaad9c9ad28 with MessageCounter:41706702 to 0x0000000000000001 (1) at monotonic time: 00000000008F3820 msec [1655273906.622700][3495:3500] CHIP:DMG: WriteClient moving to [AwaitingRe] [1655273906.627539][3495:3500] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:108588704 on exchange 10501i [1655273906.627578][3495:3500] CHIP:EM: Found matching exchange: 10501i, Delegate: (nil) [1655273906.627623][3495:3500] CHIP:EM: Rxd Ack; Removing MessageCounter:26487288 from Retrans Table on exchange 10501i [1655273906.627650][3495:3500] CHIP:EM: Removed CHIP MessageCounter:26487288 from RetransTable on exchange 10501i [1655273906.634607][3495:3500] CHIP:EM: Received message of type 0x7 with protocolId (0, 1) and MessageCounter:72818120 on exchange 10502i [1655273906.634646][3495:3500] CHIP:EM: Found matching exchange: 10502i, Delegate: 0xffff84003f80 [1655273906.634685][3495:3500] CHIP:EM: Rxd Ack; Removing MessageCounter:41706702 from Retrans Table on exchange 10502i [1655273906.634710][3495:3500] CHIP:EM: Removed CHIP MessageCounter:41706702 from RetransTable on exchange 10502i [1655273906.634747][3495:3500] CHIP:DMG: WriteClient moving to [ResponseRe] [1655273906.634804][3495:3500] CHIP:DMG: WriteResponseMessage = [1655273906.634831][3495:3500] CHIP:DMG: { [1655273906.634854][3495:3500] CHIP:DMG: AttributeStatusIBs = [1655273906.634887][3495:3500] CHIP:DMG: [ [1655273906.634913][3495:3500] CHIP:DMG: AttributeStatusIB = [1655273906.634949][3495:3500] CHIP:DMG: { [1655273906.634979][3495:3500] CHIP:DMG: AttributePathIB = [1655273906.635012][3495:3500] CHIP:DMG: { [1655273906.635047][3495:3500] CHIP:DMG: Endpoint = 0x0, [1655273906.635082][3495:3500] CHIP:DMG: Cluster = 0x3f, [1655273906.635121][3495:3500] CHIP:DMG: Attribute = 0x0000_0000, [1655273906.635154][3495:3500] CHIP:DMG: } [1655273906.635193][3495:3500] CHIP:DMG: [1655273906.635228][3495:3500] CHIP:DMG: StatusIB = [1655273906.635263][3495:3500] CHIP:DMG: { [1655273906.635297][3495:3500] CHIP:DMG: status = 0x00 (SUCCESS), [1655273906.635333][3495:3500] CHIP:DMG: }, [1655273906.635366][3495:3500] CHIP:DMG: [1655273906.635394][3495:3500] CHIP:DMG: }, [1655273906.635432][3495:3500] CHIP:DMG: [1655273906.635457][3495:3500] CHIP:DMG: AttributeStatusIB = [1655273906.635484][3495:3500] CHIP:DMG: { [1655273906.635511][3495:3500] CHIP:DMG: AttributePathIB = [1655273906.635542][3495:3500] CHIP:DMG: { [1655273906.635578][3495:3500] CHIP:DMG: Endpoint = 0x0, [1655273906.635615][3495:3500] CHIP:DMG: Cluster = 0x3f, [1655273906.635653][3495:3500] CHIP:DMG: Attribute = 0x0000_0000, [1655273906.635687][3495:3500] CHIP:DMG: ListIndex = Null, [1655273906.635719][3495:3500] CHIP:DMG: } [1655273906.635758][3495:3500] CHIP:DMG: [1655273906.635790][3495:3500] CHIP:DMG: StatusIB = [1655273906.635822][3495:3500] CHIP:DMG: { [1655273906.635854][3495:3500] CHIP:DMG: status = 0x00 (SUCCESS), [1655273906.635887][3495:3500] CHIP:DMG: }, [1655273906.635934][3495:3500] CHIP:DMG: [1655273906.635975][3495:3500] CHIP:DMG: }, [1655273906.636024][3495:3500] CHIP:DMG: [1655273906.636062][3495:3500] CHIP:DMG: ], [1655273906.636115][3495:3500] CHIP:DMG: [1655273906.636154][3495:3500] CHIP:DMG: InteractionModelRevision = 1 [1655273906.636191][3495:3500] CHIP:DMG: } [1655273906.636343][3495:3500] CHIP:DMG: WriteClient moving to [AwaitingDe] [1655273906.636431][3495:3500] CHIP:EM: Sending Standalone Ack for MessageCounter:72818120 on exchange 10502i [1655273906.636523][3495:3500] CHIP:IN: Prepared secure message 0xffff977ed958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 10502i with MessageCounter:41706703. [1655273906.636587][3495:3500] CHIP:IN: Sending encrypted msg 0xffff977ed958 with MessageCounter:41706703 to 0x0000000000000001 (1) at monotonic time: 00000000008F382E msec [1655273906.636757][3495:3500] CHIP:EM: Flushed pending ack for MessageCounter:72818120 on exchange 10502i [1655273906.636993][3495:3495] CHIP:CTL: Shutting down the commissioner [1655273906.637041][3495:3495] CHIP:CTL: Shutting down the controller [1655273906.637087][3495:3495] CHIP:CTL: Shutting down the commissioner [1655273906.637123][3495:3495] CHIP:CTL: Shutting down the controller [1655273906.637166][3495:3495] CHIP:IN: Expiring all connections for fabric 1!! [1655273906.637203][3495:3495] CHIP:IN: SecureSession[0xaaaad9c93850]: MarkForRemoval Type:2 LSID:12143 [1655273906.637239][3495:3495] CHIP:IN: SecureSession[0xaaaad9c93850]: Released - Type:2 LSID:12143 [1655273906.637307][3495:3495] CHIP:CTL: Shutting down the commissioner [1655273906.637347][3495:3495] CHIP:CTL: Shutting down the controller [1655273906.637381][3495:3495] CHIP:IN: Expiring all connections for fabric 2!! [1655273906.637436][3495:3495] CHIP:CTL: Shutting down the commissioner [1655273906.637472][3495:3495] CHIP:CTL: Shutting down the controller [1655273906.637504][3495:3495] CHIP:IN: Expiring all connections for fabric 3!! [1655273906.637554][3495:3495] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655273906.638939][3495:3495] CHIP:DMG: IM WH moving to [Uninitialized] [1655273906.638994][3495:3495] CHIP:DMG: IM WH moving to [Uninitialized] [1655273906.639026][3495:3495] CHIP:DMG: IM WH moving to [Uninitialized] [1655273906.639058][3495:3495] CHIP:DMG: IM WH moving to [Uninitialized] [1655273906.639093][3495:3495] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655273906.639198][3495:3495] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655273906.639586][3495:3495] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-iAYgSY) [1655273906.640502][3495:3495] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655273906.640595][3495:3495] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655273906.640631][3495:3495] CHIP:DL: Inet Layer shutdown [1655273906.640661][3495:3495] CHIP:DL: BLE shutdown [1655273906.640690][3495:3495] CHIP:DL: System Layer shutdown ./chip-tool groups view-group 0x0001 1 0 [1655274037.004708][3507:3507] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655274037.005259][3507:3507] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655274037.005422][3507:3507] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655274037.005536][3507:3507] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655274037.005885][3507:3507] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-je3S47) [1655274037.006552][3507:3507] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655274037.006612][3507:3507] CHIP:DL: NVS set: chip-counters/reboot-count = 6 (0x6) [1655274037.007536][3507:3507] CHIP:DL: Got Ethernet interface: eth0 [1655274037.008164][3507:3507] CHIP:DL: Found the primary Ethernet interface:eth0 [1655274037.008797][3507:3507] CHIP:DL: Got WiFi interface: wlan0 [1655274037.008875][3507:3507] CHIP:DL: Failed to reset WiFi statistic counts [1655274037.008934][3507:3507] CHIP:IN: UDP::Init bind&listen port=0 [1655274037.009085][3507:3507] CHIP:IN: UDP::Init bound to port=41591 [1655274037.009113][3507:3507] CHIP:IN: BLEBase::Init - setting/overriding transport [1655274037.009136][3507:3507] CHIP:IN: TransportMgr initialized [1655274037.009212][3507:3507] CHIP:FP: Initializing FabricTable from persistent storage [1655274037.009385][3507:3507] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274037.009474][3507:3507] CHIP:FP: Loading from storage for fabric index 0x1 [1655274037.009972][3507:3507] CHIP:FP: Loading from storage for fabric index 0x2 [1655274037.010344][3507:3507] CHIP:FP: Loading from storage for fabric index 0x3 [1655274037.013868][3507:3507] CHIP:ZCL: Using ZAP configuration... [1655274037.018060][3507:3507] CHIP:DL: Avahi client registered [1655274037.019412][3507:3507] CHIP:CTL: System State Initialized... [1655274037.019528][3507:3507] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274037.019580][3507:3507] CHIP:CTL: Setting attestation nonce to random value [1655274037.019629][3507:3507] CHIP:CTL: Setting CSR nonce to random value [1655274037.019768][3507:3507] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274037.019807][3507:3507] CHIP:CTL: Setting attestation nonce to random value [1655274037.019854][3507:3507] CHIP:CTL: Setting CSR nonce to random value [1655274037.022632][3507:3507] CHIP:CTL: Generating NOC [1655274037.023487][3507:3507] CHIP:FP: Validating NOC chain [1655274037.025228][3507:3507] CHIP:FP: NOC chain validation successful [1655274037.025501][3507:3507] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655274037.025531][3507:3507] CHIP:FP: Assigned compressed fabric ID: 0x4C449E0C3C685A46, node ID: 0x000000000001B669 [1655274037.032726][3507:3507] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655274037.032783][3507:3507] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274037.032811][3507:3507] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655274037.032836][3507:3507] CHIP:TS: Retaining current Last Known Good Time [1655274037.034518][3507:3507] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x4C449E0C3C685A46 [1655274037.034665][3507:3507] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274037.034710][3507:3507] CHIP:CTL: Setting attestation nonce to random value [1655274037.034796][3507:3507] CHIP:CTL: Setting CSR nonce to random value [1655274037.035755][3507:3507] CHIP:CTL: Generating NOC [1655274037.036791][3507:3507] CHIP:FP: Validating NOC chain [1655274037.038801][3507:3507] CHIP:FP: NOC chain validation successful [1655274037.038984][3507:3507] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655274037.039020][3507:3507] CHIP:FP: Assigned compressed fabric ID: 0x35FCBE60CC390180, node ID: 0x000000000001B669 [1655274037.044584][3507:3507] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655274037.044639][3507:3507] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274037.044666][3507:3507] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655274037.044689][3507:3507] CHIP:TS: Retaining current Last Known Good Time [1655274037.046155][3507:3507] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x35FCBE60CC390180 [1655274037.046276][3507:3507] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274037.046319][3507:3507] CHIP:CTL: Setting attestation nonce to random value [1655274037.046400][3507:3507] CHIP:CTL: Setting CSR nonce to random value [1655274037.047347][3507:3507] CHIP:CTL: Generating NOC [1655274037.048227][3507:3507] CHIP:FP: Validating NOC chain [1655274037.049944][3507:3507] CHIP:FP: NOC chain validation successful [1655274037.050108][3507:3507] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655274037.050136][3507:3507] CHIP:FP: Assigned compressed fabric ID: 0x082FA62E6A09E1D6, node ID: 0x000000000001B669 [1655274037.056226][3507:3507] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655274037.056286][3507:3507] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274037.056311][3507:3507] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655274037.056334][3507:3507] CHIP:TS: Retaining current Last Known Good Time [1655274037.057941][3507:3507] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x082FA62E6A09E1D6 [1655274037.105752][3507:3512] CHIP:DL: CHIP task running [1655274037.105980][3507:3512] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655274037.106012][3507:3512] CHIP:TOO: Sending command to node 0x1 [1655274037.106048][3507:3512] CHIP:CSM: FindOrEstablishSession: PeerId = 4C449E0C3C685A46:0000000000000001 [1655274037.106074][3507:3512] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655274037.106115][3507:3512] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 1 --> 2 [1655274037.106146][3507:3512] CHIP:DIS: Resolving 4C449E0C3C685A46:0000000000000001 ... [1655274037.216008][3507:3512] CHIP:DL: Avahi resolve found [1655274037.216155][3507:3512] CHIP:DIS: Node ID resolved for 4C449E0C3C685A46:0000000000000001 [1655274037.216220][3507:3512] CHIP:DIS: Hostname: E45F01312CE50000 [1655274037.216289][3507:3512] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655274037.216347][3507:3512] CHIP:DIS: Port: 5540 [1655274037.216402][3507:3512] CHIP:DIS: Mrp Interval idle: 5000 ms [1655274037.216458][3507:3512] CHIP:DIS: Mrp Interval active: 300 ms [1655274037.216943][3507:3512] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655274037.217010][3507:3512] CHIP:DIS: Checking node lookup status after 111 ms [1655274037.217064][3507:3512] CHIP:DIS: Keeping DNSSD lookup active [1655274037.306520][3507:3512] CHIP:DIS: Checking node lookup status after 201 ms [1655274037.306783][3507:3512] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655274037.306847][3507:3512] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 2 --> 3 [1655274037.307230][3507:3512] CHIP:IN: SecureSession[0xaaaadb7fd420]: Allocated Type:2 LSID:56754 [1655274037.307315][3507:3512] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655274037.308770][3507:3512] CHIP:SC: Including MRP parameters [1655274037.309367][3507:3512] CHIP:IN: Prepared unauthenticated message 0xaaaadb8048d8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 63943i with MessageCounter:181770560. [1655274037.309472][3507:3512] CHIP:IN: Sending unauthenticated msg 0xaaaadb8048d8 with MessageCounter:181770560 to 0x0000000000000000 at monotonic time: 000000000091369F msec [1655274037.309810][3507:3512] CHIP:SC: Sent Sigma1 msg [1655274037.309880][3507:3512] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 3 --> 4 [1655274037.309947][3507:3512] CHIP:DIS: Discovery does not require any more timeouts [1655274037.311279][3507:3512] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:108588705 on exchange 63943i [1655274037.311358][3507:3512] CHIP:EM: Found matching exchange: 63943i, Delegate: 0xffff9c0011d0 [1655274037.311446][3507:3512] CHIP:EM: Rxd Ack; Removing MessageCounter:181770560 from Retrans Table on exchange 63943i [1655274037.311505][3507:3512] CHIP:EM: Removed CHIP MessageCounter:181770560 from RetransTable on exchange 63943i [1655274037.311586][3507:3512] CHIP:SC: Received Sigma2Resume msg [1655274037.311748][3507:3512] CHIP:SC: Found MRP parameters in the message [1655274037.311817][3507:3512] CHIP:SC: Peer assigned session session ID 36299 [1655274037.320255][3507:3512] CHIP:SC: Sending status report. Protocol code 0, exchange 63943 [1655274037.320332][3507:3512] CHIP:EM: Piggybacking Ack for MessageCounter:108588705 on exchange: 63943i [1655274037.320384][3507:3512] CHIP:IN: Prepared unauthenticated message 0xaaaadb8048d8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 63943i with MessageCounter:181770561. [1655274037.320433][3507:3512] CHIP:IN: Sending unauthenticated msg 0xaaaadb8048d8 with MessageCounter:181770561 to 0x0000000000000000 at monotonic time: 00000000009136AA msec [1655274037.320698][3507:3512] CHIP:IN: SecureSession[0xaaaadb7fd420]: Activated - Type:2 LSID:56754 [1655274037.320734][3507:3512] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:56754 PSID:36299! [1655274037.320765][3507:3512] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 4 --> 5 [1655274037.320819][3507:3512] CHIP:TOO: Sending cluster (0x00000004) command (0x00000001) on endpoint 0 [1655274037.320874][3507:3512] CHIP:DMG: ICR moving to [AddingComm] [1655274037.320906][3507:3512] CHIP:DMG: ICR moving to [AddedComma] [1655274037.320995][3507:3512] CHIP:IN: Prepared secure message 0xaaaadb8048f8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 63944i with MessageCounter:134682193. [1655274037.321035][3507:3512] CHIP:IN: Sending encrypted msg 0xaaaadb8048f8 with MessageCounter:134682193 to 0x0000000000000001 (1) at monotonic time: 00000000009136AA msec [1655274037.321168][3507:3512] CHIP:DMG: ICR moving to [CommandSen] [1655274037.328588][3507:3512] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:108588706 on exchange 63943i [1655274037.328632][3507:3512] CHIP:EM: Found matching exchange: 63943i, Delegate: (nil) [1655274037.328679][3507:3512] CHIP:EM: Rxd Ack; Removing MessageCounter:181770561 from Retrans Table on exchange 63943i [1655274037.328705][3507:3512] CHIP:EM: Removed CHIP MessageCounter:181770561 from RetransTable on exchange 63943i [1655274037.332140][3507:3512] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:258602592 on exchange 63944i [1655274037.332194][3507:3512] CHIP:EM: Found matching exchange: 63944i, Delegate: 0xffff9c003ed0 [1655274037.332249][3507:3512] CHIP:EM: Rxd Ack; Removing MessageCounter:134682193 from Retrans Table on exchange 63944i [1655274037.332288][3507:3512] CHIP:EM: Removed CHIP MessageCounter:134682193 from RetransTable on exchange 63944i [1655274037.332340][3507:3512] CHIP:DMG: ICR moving to [ResponseRe] [1655274037.332415][3507:3512] CHIP:DMG: InvokeResponseMessage = [1655274037.332455][3507:3512] CHIP:DMG: { [1655274037.332495][3507:3512] CHIP:DMG: suppressResponse = false, [1655274037.332536][3507:3512] CHIP:DMG: InvokeResponseIBs = [1655274037.332588][3507:3512] CHIP:DMG: [ [1655274037.332629][3507:3512] CHIP:DMG: InvokeResponseIB = [1655274037.332683][3507:3512] CHIP:DMG: { [1655274037.332726][3507:3512] CHIP:DMG: CommandDataIB = [1655274037.332779][3507:3512] CHIP:DMG: { [1655274037.332829][3507:3512] CHIP:DMG: CommandPathIB = [1655274037.332884][3507:3512] CHIP:DMG: { [1655274037.332939][3507:3512] CHIP:DMG: EndpointId = 0x0, [1655274037.332998][3507:3512] CHIP:DMG: ClusterId = 0x4, [1655274037.333054][3507:3512] CHIP:DMG: CommandId = 0x1, [1655274037.333108][3507:3512] CHIP:DMG: }, [1655274037.333163][3507:3512] CHIP:DMG: [1655274037.333213][3507:3512] CHIP:DMG: CommandFields = [1655274037.333267][3507:3512] CHIP:DMG: { [1655274037.333354][3507:3512] CHIP:DMG: 0x0 = 0, [1655274037.333418][3507:3512] CHIP:DMG: 0x1 = 1, [1655274037.333484][3507:3512] CHIP:DMG: 0x2 = "grp1", [1655274037.333542][3507:3512] CHIP:DMG: }, [1655274037.333593][3507:3512] CHIP:DMG: }, [1655274037.333650][3507:3512] CHIP:DMG: [1655274037.333696][3507:3512] CHIP:DMG: }, [1655274037.333747][3507:3512] CHIP:DMG: [1655274037.333787][3507:3512] CHIP:DMG: ], [1655274037.333838][3507:3512] CHIP:DMG: [1655274037.333878][3507:3512] CHIP:DMG: InteractionModelRevision = 1 [1655274037.333917][3507:3512] CHIP:DMG: }, [1655274037.334014][3507:3512] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0004 Command=0x0000_0001 [1655274037.334087][3507:3512] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0004 Command 0x0000_0001 [1655274037.334168][3507:3512] CHIP:TOO: ViewGroupResponse: { [1655274037.334222][3507:3512] CHIP:TOO: status: 0 [1655274037.334261][3507:3512] CHIP:TOO: groupId: 1 [1655274037.334299][3507:3512] CHIP:TOO: groupName: grp1 [1655274037.334336][3507:3512] CHIP:TOO: } [1655274037.334397][3507:3512] CHIP:DMG: ICR moving to [AwaitingDe] [1655274037.334511][3507:3512] CHIP:EM: Sending Standalone Ack for MessageCounter:258602592 on exchange 63944i [1655274037.334610][3507:3512] CHIP:IN: Prepared secure message 0xffffb09ac958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 63944i with MessageCounter:134682194. [1655274037.334671][3507:3512] CHIP:IN: Sending encrypted msg 0xffffb09ac958 with MessageCounter:134682194 to 0x0000000000000001 (1) at monotonic time: 00000000009136B8 msec [1655274037.334824][3507:3512] CHIP:EM: Flushed pending ack for MessageCounter:258602592 on exchange 63944i [1655274037.335062][3507:3507] CHIP:CTL: Shutting down the commissioner [1655274037.335114][3507:3507] CHIP:CTL: Shutting down the controller [1655274037.335159][3507:3507] CHIP:CTL: Shutting down the commissioner [1655274037.335195][3507:3507] CHIP:CTL: Shutting down the controller [1655274037.335238][3507:3507] CHIP:IN: Expiring all connections for fabric 1!! [1655274037.335276][3507:3507] CHIP:IN: SecureSession[0xaaaadb7fd420]: MarkForRemoval Type:2 LSID:56754 [1655274037.335314][3507:3507] CHIP:IN: SecureSession[0xaaaadb7fd420]: Released - Type:2 LSID:56754 [1655274037.335382][3507:3507] CHIP:CTL: Shutting down the commissioner [1655274037.335419][3507:3507] CHIP:CTL: Shutting down the controller [1655274037.335452][3507:3507] CHIP:IN: Expiring all connections for fabric 2!! [1655274037.335505][3507:3507] CHIP:CTL: Shutting down the commissioner [1655274037.335541][3507:3507] CHIP:CTL: Shutting down the controller [1655274037.335573][3507:3507] CHIP:IN: Expiring all connections for fabric 3!! [1655274037.335622][3507:3507] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655274037.336957][3507:3507] CHIP:DMG: IM WH moving to [Uninitialized] [1655274037.337014][3507:3507] CHIP:DMG: IM WH moving to [Uninitialized] [1655274037.337047][3507:3507] CHIP:DMG: IM WH moving to [Uninitialized] [1655274037.337080][3507:3507] CHIP:DMG: IM WH moving to [Uninitialized] [1655274037.337116][3507:3507] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655274037.337222][3507:3507] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655274037.337586][3507:3507] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-DZcrWL) [1655274037.338548][3507:3507] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655274037.338644][3507:3507] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655274037.338687][3507:3507] CHIP:DL: Inet Layer shutdown [1655274037.338723][3507:3507] CHIP:DL: BLE shutdown [1655274037.338759][3507:3507] CHIP:DL: System Layer shutdown ./chip-tool groupkeymanagement key-set-read 42 1 0 [1655274192.417392][3523:3523] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655274192.417936][3523:3523] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655274192.418099][3523:3523] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655274192.418212][3523:3523] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655274192.418611][3523:3523] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-gChOml) [1655274192.419256][3523:3523] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655274192.419308][3523:3523] CHIP:DL: NVS set: chip-counters/reboot-count = 7 (0x7) [1655274192.420190][3523:3523] CHIP:DL: Got Ethernet interface: eth0 [1655274192.420877][3523:3523] CHIP:DL: Found the primary Ethernet interface:eth0 [1655274192.421490][3523:3523] CHIP:DL: Got WiFi interface: wlan0 [1655274192.421562][3523:3523] CHIP:DL: Failed to reset WiFi statistic counts [1655274192.421620][3523:3523] CHIP:IN: UDP::Init bind&listen port=0 [1655274192.421764][3523:3523] CHIP:IN: UDP::Init bound to port=38609 [1655274192.421790][3523:3523] CHIP:IN: BLEBase::Init - setting/overriding transport [1655274192.421812][3523:3523] CHIP:IN: TransportMgr initialized [1655274192.421889][3523:3523] CHIP:FP: Initializing FabricTable from persistent storage [1655274192.422050][3523:3523] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274192.422137][3523:3523] CHIP:FP: Loading from storage for fabric index 0x1 [1655274192.422643][3523:3523] CHIP:FP: Loading from storage for fabric index 0x2 [1655274192.422994][3523:3523] CHIP:FP: Loading from storage for fabric index 0x3 [1655274192.426800][3523:3523] CHIP:ZCL: Using ZAP configuration... [1655274192.431691][3523:3523] CHIP:DL: Avahi client registered [1655274192.433233][3523:3523] CHIP:CTL: System State Initialized... [1655274192.433390][3523:3523] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274192.433469][3523:3523] CHIP:CTL: Setting attestation nonce to random value [1655274192.433531][3523:3523] CHIP:CTL: Setting CSR nonce to random value [1655274192.433677][3523:3523] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274192.433728][3523:3523] CHIP:CTL: Setting attestation nonce to random value [1655274192.433797][3523:3523] CHIP:CTL: Setting CSR nonce to random value [1655274192.437144][3523:3523] CHIP:CTL: Generating NOC [1655274192.438124][3523:3523] CHIP:FP: Validating NOC chain [1655274192.440331][3523:3523] CHIP:FP: NOC chain validation successful [1655274192.440540][3523:3523] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655274192.440573][3523:3523] CHIP:FP: Assigned compressed fabric ID: 0x4C449E0C3C685A46, node ID: 0x000000000001B669 [1655274192.447914][3523:3523] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655274192.447968][3523:3523] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274192.447991][3523:3523] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655274192.448013][3523:3523] CHIP:TS: Retaining current Last Known Good Time [1655274192.449666][3523:3523] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x4C449E0C3C685A46 [1655274192.449795][3523:3523] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274192.449838][3523:3523] CHIP:CTL: Setting attestation nonce to random value [1655274192.449920][3523:3523] CHIP:CTL: Setting CSR nonce to random value [1655274192.450847][3523:3523] CHIP:CTL: Generating NOC [1655274192.451683][3523:3523] CHIP:FP: Validating NOC chain [1655274192.453396][3523:3523] CHIP:FP: NOC chain validation successful [1655274192.453566][3523:3523] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655274192.453594][3523:3523] CHIP:FP: Assigned compressed fabric ID: 0x35FCBE60CC390180, node ID: 0x000000000001B669 [1655274192.459134][3523:3523] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655274192.459190][3523:3523] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274192.459215][3523:3523] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655274192.459238][3523:3523] CHIP:TS: Retaining current Last Known Good Time [1655274192.460648][3523:3523] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x35FCBE60CC390180 [1655274192.460780][3523:3523] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274192.460821][3523:3523] CHIP:CTL: Setting attestation nonce to random value [1655274192.460903][3523:3523] CHIP:CTL: Setting CSR nonce to random value [1655274192.461804][3523:3523] CHIP:CTL: Generating NOC [1655274192.462775][3523:3523] CHIP:FP: Validating NOC chain [1655274192.464605][3523:3523] CHIP:FP: NOC chain validation successful [1655274192.464882][3523:3523] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655274192.464912][3523:3523] CHIP:FP: Assigned compressed fabric ID: 0x082FA62E6A09E1D6, node ID: 0x000000000001B669 [1655274192.471143][3523:3523] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655274192.471194][3523:3523] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274192.471217][3523:3523] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655274192.471238][3523:3523] CHIP:TS: Retaining current Last Known Good Time [1655274192.472858][3523:3523] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x082FA62E6A09E1D6 [1655274192.514771][3523:3528] CHIP:DL: CHIP task running [1655274192.515027][3523:3528] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655274192.515067][3523:3528] CHIP:TOO: Sending command to node 0x1 [1655274192.515105][3523:3528] CHIP:CSM: FindOrEstablishSession: PeerId = 4C449E0C3C685A46:0000000000000001 [1655274192.515131][3523:3528] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655274192.515175][3523:3528] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 1 --> 2 [1655274192.515206][3523:3528] CHIP:DIS: Resolving 4C449E0C3C685A46:0000000000000001 ... [1655274192.626012][3523:3528] CHIP:DL: Avahi resolve found [1655274192.626141][3523:3528] CHIP:DIS: Node ID resolved for 4C449E0C3C685A46:0000000000000001 [1655274192.626191][3523:3528] CHIP:DIS: Hostname: E45F01312CE50000 [1655274192.626244][3523:3528] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655274192.626288][3523:3528] CHIP:DIS: Port: 5540 [1655274192.626330][3523:3528] CHIP:DIS: Mrp Interval idle: 5000 ms [1655274192.626372][3523:3528] CHIP:DIS: Mrp Interval active: 300 ms [1655274192.626864][3523:3528] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655274192.626916][3523:3528] CHIP:DIS: Checking node lookup status after 112 ms [1655274192.626956][3523:3528] CHIP:DIS: Keeping DNSSD lookup active [1655274192.715432][3523:3528] CHIP:DIS: Checking node lookup status after 201 ms [1655274192.715714][3523:3528] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655274192.715778][3523:3528] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 2 --> 3 [1655274192.716220][3523:3528] CHIP:IN: SecureSession[0xaaab1bb39880]: Allocated Type:2 LSID:65109 [1655274192.716304][3523:3528] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655274192.717800][3523:3528] CHIP:SC: Including MRP parameters [1655274192.718314][3523:3528] CHIP:IN: Prepared unauthenticated message 0xaaab1bb40d38 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 35222i with MessageCounter:41247666. [1655274192.718420][3523:3528] CHIP:IN: Sending unauthenticated msg 0xaaab1bb40d38 with MessageCounter:41247666 to 0x0000000000000000 at monotonic time: 00000000009395AF msec [1655274192.718863][3523:3528] CHIP:SC: Sent Sigma1 msg [1655274192.718934][3523:3528] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 3 --> 4 [1655274192.718999][3523:3528] CHIP:DIS: Discovery does not require any more timeouts [1655274192.721167][3523:3528] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:108588707 on exchange 35222i [1655274192.721245][3523:3528] CHIP:EM: Found matching exchange: 35222i, Delegate: 0xffff840011a0 [1655274192.721331][3523:3528] CHIP:EM: Rxd Ack; Removing MessageCounter:41247666 from Retrans Table on exchange 35222i [1655274192.721390][3523:3528] CHIP:EM: Removed CHIP MessageCounter:41247666 from RetransTable on exchange 35222i [1655274192.721470][3523:3528] CHIP:SC: Received Sigma2Resume msg [1655274192.721681][3523:3528] CHIP:SC: Found MRP parameters in the message [1655274192.721748][3523:3528] CHIP:SC: Peer assigned session session ID 36300 [1655274192.728793][3523:3528] CHIP:SC: Sending status report. Protocol code 0, exchange 35222 [1655274192.728880][3523:3528] CHIP:EM: Piggybacking Ack for MessageCounter:108588707 on exchange: 35222i [1655274192.728939][3523:3528] CHIP:IN: Prepared unauthenticated message 0xaaab1bb40d38 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 35222i with MessageCounter:41247667. [1655274192.728996][3523:3528] CHIP:IN: Sending unauthenticated msg 0xaaab1bb40d38 with MessageCounter:41247667 to 0x0000000000000000 at monotonic time: 00000000009395BA msec [1655274192.729353][3523:3528] CHIP:IN: SecureSession[0xaaab1bb39880]: Activated - Type:2 LSID:65109 [1655274192.729394][3523:3528] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:65109 PSID:36300! [1655274192.729431][3523:3528] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 4 --> 5 [1655274192.729494][3523:3528] CHIP:TOO: Sending cluster (0x0000003F) command (0x00000001) on endpoint 0 [1655274192.729601][3523:3528] CHIP:DMG: ICR moving to [AddingComm] [1655274192.729672][3523:3528] CHIP:DMG: ICR moving to [AddedComma] [1655274192.729791][3523:3528] CHIP:IN: Prepared secure message 0xaaab1bb40d58 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 35223i with MessageCounter:267608930. [1655274192.729857][3523:3528] CHIP:IN: Sending encrypted msg 0xaaab1bb40d58 with MessageCounter:267608930 to 0x0000000000000001 (1) at monotonic time: 00000000009395BB msec [1655274192.730054][3523:3528] CHIP:DMG: ICR moving to [CommandSen] [1655274192.736736][3523:3528] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:108588708 on exchange 35222i [1655274192.736782][3523:3528] CHIP:EM: Found matching exchange: 35222i, Delegate: (nil) [1655274192.736833][3523:3528] CHIP:EM: Rxd Ack; Removing MessageCounter:41247667 from Retrans Table on exchange 35222i [1655274192.736864][3523:3528] CHIP:EM: Removed CHIP MessageCounter:41247667 from RetransTable on exchange 35222i [1655274192.740102][3523:3528] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:103575047 on exchange 35223i [1655274192.740140][3523:3528] CHIP:EM: Found matching exchange: 35223i, Delegate: 0xffff84005570 [1655274192.740180][3523:3528] CHIP:EM: Rxd Ack; Removing MessageCounter:267608930 from Retrans Table on exchange 35223i [1655274192.740209][3523:3528] CHIP:EM: Removed CHIP MessageCounter:267608930 from RetransTable on exchange 35223i [1655274192.740248][3523:3528] CHIP:DMG: ICR moving to [ResponseRe] [1655274192.740322][3523:3528] CHIP:DMG: InvokeResponseMessage = [1655274192.740354][3523:3528] CHIP:DMG: { [1655274192.740395][3523:3528] CHIP:DMG: suppressResponse = false, [1655274192.740426][3523:3528] CHIP:DMG: InvokeResponseIBs = [1655274192.740479][3523:3528] CHIP:DMG: [ [1655274192.740520][3523:3528] CHIP:DMG: InvokeResponseIB = [1655274192.740565][3523:3528] CHIP:DMG: { [1655274192.740609][3523:3528] CHIP:DMG: CommandDataIB = [1655274192.740655][3523:3528] CHIP:DMG: { [1655274192.740703][3523:3528] CHIP:DMG: CommandPathIB = [1655274192.740755][3523:3528] CHIP:DMG: { [1655274192.740797][3523:3528] CHIP:DMG: EndpointId = 0x0, [1655274192.740853][3523:3528] CHIP:DMG: ClusterId = 0x3f, [1655274192.740905][3523:3528] CHIP:DMG: CommandId = 0x2, [1655274192.740947][3523:3528] CHIP:DMG: }, [1655274192.740998][3523:3528] CHIP:DMG: [1655274192.741034][3523:3528] CHIP:DMG: CommandFields = [1655274192.741086][3523:3528] CHIP:DMG: { [1655274192.741159][3523:3528] CHIP:DMG: 0x0 = [1655274192.741211][3523:3528] CHIP:DMG: { [1655274192.741258][3523:3528] CHIP:DMG: 0x0 = 42, [1655274192.741319][3523:3528] CHIP:DMG: 0x1 = 0, [1655274192.741383][3523:3528] CHIP:DMG: 0x2 = NULL [1655274192.741430][3523:3528] CHIP:DMG: 0x3 = 2220000, [1655274192.741490][3523:3528] CHIP:DMG: 0x4 = NULL [1655274192.741552][3523:3528] CHIP:DMG: 0x5 = 2220001, [1655274192.741611][3523:3528] CHIP:DMG: 0x6 = NULL [1655274192.741657][3523:3528] CHIP:DMG: 0x7 = 2220002, [1655274192.741712][3523:3528] CHIP:DMG: }, [1655274192.741762][3523:3528] CHIP:DMG: }, [1655274192.741800][3523:3528] CHIP:DMG: }, [1655274192.741856][3523:3528] CHIP:DMG: [1655274192.741900][3523:3528] CHIP:DMG: }, [1655274192.741942][3523:3528] CHIP:DMG: [1655274192.741984][3523:3528] CHIP:DMG: ], [1655274192.742027][3523:3528] CHIP:DMG: [1655274192.742068][3523:3528] CHIP:DMG: InteractionModelRevision = 1 [1655274192.742097][3523:3528] CHIP:DMG: }, [1655274192.742191][3523:3528] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003F Command=0x0000_0002 [1655274192.742246][3523:3528] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_003F Command 0x0000_0002 [1655274192.742330][3523:3528] CHIP:TOO: KeySetReadResponse: { [1655274192.742363][3523:3528] CHIP:TOO: groupKeySet: { [1655274192.742404][3523:3528] CHIP:TOO: GroupKeySetID: 42 [1655274192.742458][3523:3528] CHIP:TOO: GroupKeySecurityPolicy: 0 [1655274192.742489][3523:3528] CHIP:TOO: EpochKey0: null [1655274192.742520][3523:3528] CHIP:TOO: EpochStartTime0: 2220000 [1655274192.742549][3523:3528] CHIP:TOO: EpochKey1: null [1655274192.742577][3523:3528] CHIP:TOO: EpochStartTime1: 2220001 [1655274192.742606][3523:3528] CHIP:TOO: EpochKey2: null [1655274192.742635][3523:3528] CHIP:TOO: EpochStartTime2: 2220002 [1655274192.742664][3523:3528] CHIP:TOO: } [1655274192.742691][3523:3528] CHIP:TOO: } [1655274192.742744][3523:3528] CHIP:DMG: ICR moving to [AwaitingDe] [1655274192.742808][3523:3528] CHIP:EM: Sending Standalone Ack for MessageCounter:103575047 on exchange 35223i [1655274192.742883][3523:3528] CHIP:IN: Prepared secure message 0xffff98d6b958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 35223i with MessageCounter:267608931. [1655274192.742928][3523:3528] CHIP:IN: Sending encrypted msg 0xffff98d6b958 with MessageCounter:267608931 to 0x0000000000000001 (1) at monotonic time: 00000000009395C8 msec [1655274192.743075][3523:3528] CHIP:EM: Flushed pending ack for MessageCounter:103575047 on exchange 35223i [1655274192.743267][3523:3523] CHIP:CTL: Shutting down the commissioner [1655274192.743304][3523:3523] CHIP:CTL: Shutting down the controller [1655274192.743338][3523:3523] CHIP:CTL: Shutting down the commissioner [1655274192.743365][3523:3523] CHIP:CTL: Shutting down the controller [1655274192.743399][3523:3523] CHIP:IN: Expiring all connections for fabric 1!! [1655274192.743427][3523:3523] CHIP:IN: SecureSession[0xaaab1bb39880]: MarkForRemoval Type:2 LSID:65109 [1655274192.743455][3523:3523] CHIP:IN: SecureSession[0xaaab1bb39880]: Released - Type:2 LSID:65109 [1655274192.743509][3523:3523] CHIP:CTL: Shutting down the commissioner [1655274192.743538][3523:3523] CHIP:CTL: Shutting down the controller [1655274192.743562][3523:3523] CHIP:IN: Expiring all connections for fabric 2!! [1655274192.743605][3523:3523] CHIP:CTL: Shutting down the commissioner [1655274192.743632][3523:3523] CHIP:CTL: Shutting down the controller [1655274192.743657][3523:3523] CHIP:IN: Expiring all connections for fabric 3!! [1655274192.743695][3523:3523] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655274192.744766][3523:3523] CHIP:DMG: IM WH moving to [Uninitialized] [1655274192.744814][3523:3523] CHIP:DMG: IM WH moving to [Uninitialized] [1655274192.744839][3523:3523] CHIP:DMG: IM WH moving to [Uninitialized] [1655274192.744870][3523:3523] CHIP:DMG: IM WH moving to [Uninitialized] [1655274192.744895][3523:3523] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655274192.744982][3523:3523] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655274192.745313][3523:3523] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-fv4bqs) [1655274192.746150][3523:3523] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655274192.746241][3523:3523] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655274192.746284][3523:3523] CHIP:DL: Inet Layer shutdown [1655274192.746321][3523:3523] CHIP:DL: BLE shutdown [1655274192.746357][3523:3523] CHIP:DL: System Layer shutdown ./chip-tool groupkeymanagement read group-table 1 0 [1655274297.059244][3532:3532] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655274297.059802][3532:3532] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655274297.059988][3532:3532] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655274297.060103][3532:3532] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655274297.060464][3532:3532] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-XjZReF) [1655274297.061103][3532:3532] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655274297.061158][3532:3532] CHIP:DL: NVS set: chip-counters/reboot-count = 8 (0x8) [1655274297.062020][3532:3532] CHIP:DL: Got Ethernet interface: eth0 [1655274297.062667][3532:3532] CHIP:DL: Found the primary Ethernet interface:eth0 [1655274297.063277][3532:3532] CHIP:DL: Got WiFi interface: wlan0 [1655274297.063353][3532:3532] CHIP:DL: Failed to reset WiFi statistic counts [1655274297.063410][3532:3532] CHIP:IN: UDP::Init bind&listen port=0 [1655274297.063553][3532:3532] CHIP:IN: UDP::Init bound to port=33452 [1655274297.063578][3532:3532] CHIP:IN: BLEBase::Init - setting/overriding transport [1655274297.063600][3532:3532] CHIP:IN: TransportMgr initialized [1655274297.063661][3532:3532] CHIP:FP: Initializing FabricTable from persistent storage [1655274297.063838][3532:3532] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274297.063922][3532:3532] CHIP:FP: Loading from storage for fabric index 0x1 [1655274297.064385][3532:3532] CHIP:FP: Loading from storage for fabric index 0x2 [1655274297.064754][3532:3532] CHIP:FP: Loading from storage for fabric index 0x3 [1655274297.068146][3532:3532] CHIP:ZCL: Using ZAP configuration... [1655274297.072383][3532:3532] CHIP:DL: Avahi client registered [1655274297.073716][3532:3532] CHIP:CTL: System State Initialized... [1655274297.073827][3532:3532] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274297.073882][3532:3532] CHIP:CTL: Setting attestation nonce to random value [1655274297.073935][3532:3532] CHIP:CTL: Setting CSR nonce to random value [1655274297.074047][3532:3532] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274297.074079][3532:3532] CHIP:CTL: Setting attestation nonce to random value [1655274297.074129][3532:3532] CHIP:CTL: Setting CSR nonce to random value [1655274297.077031][3532:3532] CHIP:CTL: Generating NOC [1655274297.077913][3532:3532] CHIP:FP: Validating NOC chain [1655274297.080116][3532:3532] CHIP:FP: NOC chain validation successful [1655274297.080334][3532:3532] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655274297.080372][3532:3532] CHIP:FP: Assigned compressed fabric ID: 0x4C449E0C3C685A46, node ID: 0x000000000001B669 [1655274297.088316][3532:3532] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655274297.088385][3532:3532] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274297.088418][3532:3532] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655274297.088449][3532:3532] CHIP:TS: Retaining current Last Known Good Time [1655274297.090206][3532:3532] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x4C449E0C3C685A46 [1655274297.090323][3532:3532] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274297.090364][3532:3532] CHIP:CTL: Setting attestation nonce to random value [1655274297.090448][3532:3532] CHIP:CTL: Setting CSR nonce to random value [1655274297.091323][3532:3532] CHIP:CTL: Generating NOC [1655274297.092141][3532:3532] CHIP:FP: Validating NOC chain [1655274297.093867][3532:3532] CHIP:FP: NOC chain validation successful [1655274297.094023][3532:3532] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655274297.094051][3532:3532] CHIP:FP: Assigned compressed fabric ID: 0x35FCBE60CC390180, node ID: 0x000000000001B669 [1655274297.099760][3532:3532] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655274297.099814][3532:3532] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274297.099838][3532:3532] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655274297.099859][3532:3532] CHIP:TS: Retaining current Last Known Good Time [1655274297.101348][3532:3532] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x35FCBE60CC390180 [1655274297.101488][3532:3532] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655274297.101530][3532:3532] CHIP:CTL: Setting attestation nonce to random value [1655274297.101592][3532:3532] CHIP:CTL: Setting CSR nonce to random value [1655274297.102624][3532:3532] CHIP:CTL: Generating NOC [1655274297.103478][3532:3532] CHIP:FP: Validating NOC chain [1655274297.105183][3532:3532] CHIP:FP: NOC chain validation successful [1655274297.105335][3532:3532] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655274297.105363][3532:3532] CHIP:FP: Assigned compressed fabric ID: 0x082FA62E6A09E1D6, node ID: 0x000000000001B669 [1655274297.111489][3532:3532] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655274297.111542][3532:3532] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655274297.111566][3532:3532] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655274297.111587][3532:3532] CHIP:TS: Retaining current Last Known Good Time [1655274297.113196][3532:3532] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x082FA62E6A09E1D6 [1655274297.157536][3532:3538] CHIP:DL: CHIP task running [1655274297.157826][3532:3538] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655274297.157892][3532:3538] CHIP:TOO: Sending command to node 0x1 [1655274297.157935][3532:3538] CHIP:CSM: FindOrEstablishSession: PeerId = 4C449E0C3C685A46:0000000000000001 [1655274297.157969][3532:3538] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655274297.158017][3532:3538] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 1 --> 2 [1655274297.158066][3532:3538] CHIP:DIS: Resolving 4C449E0C3C685A46:0000000000000001 ... [1655274297.160190][3532:3538] CHIP:DL: Avahi resolve found [1655274297.160276][3532:3538] CHIP:DIS: Node ID resolved for 4C449E0C3C685A46:0000000000000001 [1655274297.160309][3532:3538] CHIP:DIS: Hostname: E45F01312CE50000 [1655274297.160349][3532:3538] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655274297.160379][3532:3538] CHIP:DIS: Port: 5540 [1655274297.160406][3532:3538] CHIP:DIS: Mrp Interval idle: 5000 ms [1655274297.160435][3532:3538] CHIP:DIS: Mrp Interval active: 300 ms [1655274297.160765][3532:3538] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655274297.160802][3532:3538] CHIP:DIS: Checking node lookup status after 3 ms [1655274297.160829][3532:3538] CHIP:DIS: Keeping DNSSD lookup active [1655274297.358283][3532:3538] CHIP:DIS: Checking node lookup status after 200 ms [1655274297.358487][3532:3538] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655274297.358515][3532:3538] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 2 --> 3 [1655274297.358740][3532:3538] CHIP:IN: SecureSession[0xaaaac71817e0]: Allocated Type:2 LSID:6260 [1655274297.358780][3532:3538] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655274297.359558][3532:3538] CHIP:SC: Including MRP parameters [1655274297.359939][3532:3538] CHIP:IN: Prepared unauthenticated message 0xaaaac7188c98 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 52471i with MessageCounter:44312799. [1655274297.360046][3532:3538] CHIP:IN: Sending unauthenticated msg 0xaaaac7188c98 with MessageCounter:44312799 to 0x0000000000000000 at monotonic time: 0000000000952E71 msec [1655274297.360565][3532:3538] CHIP:SC: Sent Sigma1 msg [1655274297.360635][3532:3538] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 3 --> 4 [1655274297.360702][3532:3538] CHIP:DIS: Discovery does not require any more timeouts [1655274297.363129][3532:3538] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:108588709 on exchange 52471i [1655274297.363208][3532:3538] CHIP:EM: Found matching exchange: 52471i, Delegate: 0xffff7c0011a0 [1655274297.363294][3532:3538] CHIP:EM: Rxd Ack; Removing MessageCounter:44312799 from Retrans Table on exchange 52471i [1655274297.363353][3532:3538] CHIP:EM: Removed CHIP MessageCounter:44312799 from RetransTable on exchange 52471i [1655274297.363435][3532:3538] CHIP:SC: Received Sigma2Resume msg [1655274297.363621][3532:3538] CHIP:SC: Found MRP parameters in the message [1655274297.363713][3532:3538] CHIP:SC: Peer assigned session session ID 36301 [1655274297.372180][3532:3538] CHIP:SC: Sending status report. Protocol code 0, exchange 52471 [1655274297.372260][3532:3538] CHIP:EM: Piggybacking Ack for MessageCounter:108588709 on exchange: 52471i [1655274297.372314][3532:3538] CHIP:IN: Prepared unauthenticated message 0xaaaac7188c98 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 52471i with MessageCounter:44312800. [1655274297.372366][3532:3538] CHIP:IN: Sending unauthenticated msg 0xaaaac7188c98 with MessageCounter:44312800 to 0x0000000000000000 at monotonic time: 0000000000952E7D msec [1655274297.372689][3532:3538] CHIP:IN: SecureSession[0xaaaac71817e0]: Activated - Type:2 LSID:6260 [1655274297.372724][3532:3538] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:6260 PSID:36301! [1655274297.372757][3532:3538] CHIP:CTL: OperationalDeviceProxy[4C449E0C3C685A46:0000000000000001]: State change 4 --> 5 [1655274297.372821][3532:3538] CHIP:TOO: Sending ReadAttribute to: [1655274297.372862][3532:3538] CHIP:TOO: cluster 0x0000_003F, attribute: 0x0000_0001, endpoint 0 [1655274297.372905][3532:3538] CHIP:DMG: SendReadRequest ReadClient[0xffff7c0055d0]: Sending Read Request [1655274297.373047][3532:3538] CHIP:IN: Prepared secure message 0xaaaac7188cb8 to 0x0000000000000001 (1) of type 0x2 and protocolId (0, 1) on exchange 52472i with MessageCounter:138720493. [1655274297.373102][3532:3538] CHIP:IN: Sending encrypted msg 0xaaaac7188cb8 with MessageCounter:138720493 to 0x0000000000000001 (1) at monotonic time: 0000000000952E7E msec [1655274297.373267][3532:3538] CHIP:DMG: MoveToState ReadClient[0xffff7c0055d0]: Moving to [AwaitingIn] [1655274297.380582][3532:3538] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:108588710 on exchange 52471i [1655274297.380627][3532:3538] CHIP:EM: Found matching exchange: 52471i, Delegate: (nil) [1655274297.380675][3532:3538] CHIP:EM: Rxd Ack; Removing MessageCounter:44312800 from Retrans Table on exchange 52471i [1655274297.380704][3532:3538] CHIP:EM: Removed CHIP MessageCounter:44312800 from RetransTable on exchange 52471i [1655274297.383940][3532:3538] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:158145773 on exchange 52472i [1655274297.383992][3532:3538] CHIP:EM: Found matching exchange: 52472i, Delegate: 0xffff7c0055d0 [1655274297.384048][3532:3538] CHIP:EM: Rxd Ack; Removing MessageCounter:138720493 from Retrans Table on exchange 52472i [1655274297.384087][3532:3538] CHIP:EM: Removed CHIP MessageCounter:138720493 from RetransTable on exchange 52472i [1655274297.384204][3532:3538] CHIP:DMG: ReportDataMessage = [1655274297.384248][3532:3538] CHIP:DMG: { [1655274297.384299][3532:3538] CHIP:DMG: AttributeReportIBs = [1655274297.384352][3532:3538] CHIP:DMG: [ [1655274297.384392][3532:3538] CHIP:DMG: AttributeReportIB = [1655274297.384460][3532:3538] CHIP:DMG: { [1655274297.384503][3532:3538] CHIP:DMG: AttributeDataIB = [1655274297.384566][3532:3538] CHIP:DMG: { [1655274297.384621][3532:3538] CHIP:DMG: DataVersion = 0xe9ccb6a, [1655274297.384688][3532:3538] CHIP:DMG: AttributePathIB = [1655274297.384758][3532:3538] CHIP:DMG: { [1655274297.384819][3532:3538] CHIP:DMG: Endpoint = 0x0, [1655274297.384891][3532:3538] CHIP:DMG: Cluster = 0x3f, [1655274297.384965][3532:3538] CHIP:DMG: Attribute = 0x0000_0001, [1655274297.385019][3532:3538] CHIP:DMG: } [1655274297.385095][3532:3538] CHIP:DMG: [1655274297.385167][3532:3538] CHIP:DMG: Data = [ [1655274297.385221][3532:3538] CHIP:DMG: [1655274297.385292][3532:3538] CHIP:DMG: ], [1655274297.385359][3532:3538] CHIP:DMG: }, [1655274297.385415][3532:3538] CHIP:DMG: [1655274297.385473][3532:3538] CHIP:DMG: }, [1655274297.385536][3532:3538] CHIP:DMG: [1655274297.385590][3532:3538] CHIP:DMG: AttributeReportIB = [1655274297.385647][3532:3538] CHIP:DMG: { [1655274297.385702][3532:3538] CHIP:DMG: AttributeDataIB = [1655274297.385755][3532:3538] CHIP:DMG: { [1655274297.385818][3532:3538] CHIP:DMG: DataVersion = 0xe9ccb6a, [1655274297.385875][3532:3538] CHIP:DMG: AttributePathIB = [1655274297.385946][3532:3538] CHIP:DMG: { [1655274297.386015][3532:3538] CHIP:DMG: Endpoint = 0x0, [1655274297.386073][3532:3538] CHIP:DMG: Cluster = 0x3f, [1655274297.386145][3532:3538] CHIP:DMG: Attribute = 0x0000_0001, [1655274297.386214][3532:3538] CHIP:DMG: ListIndex = Null, [1655274297.386270][3532:3538] CHIP:DMG: } [1655274297.386338][3532:3538] CHIP:DMG: [1655274297.386391][3532:3538] CHIP:DMG: Data = [1655274297.386482][3532:3538] CHIP:DMG: { [1655274297.386586][3532:3538] CHIP:DMG: 0xfe = 1, [1655274297.386652][3532:3538] CHIP:DMG: 0x1 = 1, [1655274297.386725][3532:3538] CHIP:DMG: 0x2 = [ [1655274297.386807][3532:3538] CHIP:DMG: 0, [1655274297.386892][3532:3538] CHIP:DMG: ], [1655274297.386957][3532:3538] CHIP:DMG: 0x3 = "grp1", [1655274297.387033][3532:3538] CHIP:DMG: }, [1655274297.387106][3532:3538] CHIP:DMG: }, [1655274297.387165][3532:3538] CHIP:DMG: [1655274297.387210][3532:3538] CHIP:DMG: }, [1655274297.387264][3532:3538] CHIP:DMG: [1655274297.387303][3532:3538] CHIP:DMG: ], [1655274297.387364][3532:3538] CHIP:DMG: [1655274297.387404][3532:3538] CHIP:DMG: SuppressResponse = true, [1655274297.387445][3532:3538] CHIP:DMG: InteractionModelRevision = 1 [1655274297.387484][3532:3538] CHIP:DMG: } [1655274297.387851][3532:3538] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_003F Attribute 0x0000_0001 DataVersion: 245156714 [1655274297.387974][3532:3538] CHIP:TOO: GroupTable: 1 entries [1655274297.388076][3532:3538] CHIP:TOO: [1]: { [1655274297.388118][3532:3538] CHIP:TOO: GroupId: 1 [1655274297.388163][3532:3538] CHIP:TOO: Endpoints: 1 entries [1655274297.388209][3532:3538] CHIP:TOO: [1]: 0 [1655274297.388253][3532:3538] CHIP:TOO: GroupName: grp1 [1655274297.388293][3532:3538] CHIP:TOO: FabricIndex: 1 [1655274297.388330][3532:3538] CHIP:TOO: } [1655274297.388463][3532:3538] CHIP:EM: Sending Standalone Ack for MessageCounter:158145773 on exchange 52472i [1655274297.388561][3532:3538] CHIP:IN: Prepared secure message 0xffff83ffd958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 52472i with MessageCounter:138720494. [1655274297.388623][3532:3538] CHIP:IN: Sending encrypted msg 0xffff83ffd958 with MessageCounter:138720494 to 0x0000000000000001 (1) at monotonic time: 0000000000952E8E msec [1655274297.388806][3532:3538] CHIP:EM: Flushed pending ack for MessageCounter:158145773 on exchange 52472i [1655274297.389069][3532:3532] CHIP:CTL: Shutting down the commissioner [1655274297.389118][3532:3532] CHIP:CTL: Shutting down the controller [1655274297.389163][3532:3532] CHIP:CTL: Shutting down the commissioner [1655274297.389199][3532:3532] CHIP:CTL: Shutting down the controller [1655274297.389242][3532:3532] CHIP:IN: Expiring all connections for fabric 1!! [1655274297.389279][3532:3532] CHIP:IN: SecureSession[0xaaaac71817e0]: MarkForRemoval Type:2 LSID:6260 [1655274297.389316][3532:3532] CHIP:IN: SecureSession[0xaaaac71817e0]: Released - Type:2 LSID:6260 [1655274297.389382][3532:3532] CHIP:CTL: Shutting down the commissioner [1655274297.389420][3532:3532] CHIP:CTL: Shutting down the controller [1655274297.389453][3532:3532] CHIP:IN: Expiring all connections for fabric 2!! [1655274297.389505][3532:3532] CHIP:CTL: Shutting down the commissioner [1655274297.389541][3532:3532] CHIP:CTL: Shutting down the controller [1655274297.389574][3532:3532] CHIP:IN: Expiring all connections for fabric 3!! [1655274297.389621][3532:3532] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655274297.390997][3532:3532] CHIP:DMG: IM WH moving to [Uninitialized] [1655274297.391060][3532:3532] CHIP:DMG: IM WH moving to [Uninitialized] [1655274297.391093][3532:3532] CHIP:DMG: IM WH moving to [Uninitialized] [1655274297.391127][3532:3532] CHIP:DMG: IM WH moving to [Uninitialized] [1655274297.391163][3532:3532] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655274297.391268][3532:3532] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655274297.391639][3532:3532] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-19T9tP) [1655274297.392573][3532:3532] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655274297.392651][3532:3532] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655274297.392686][3532:3532] CHIP:DL: Inet Layer shutdown [1655274297.392715][3532:3532] CHIP:DL: BLE shutdown [1655274297.392746][3532:3532] CHIP:DL: System Layer shutdown ./chip-tool groupsettings add-group grp1 0x0001 [1654234949.881596][2577:2577] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1654234949.882133][2577:2577] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1654234949.882386][2577:2577] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1654234949.882499][2577:2577] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1654234949.882863][2577:2577] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-40NNF1) [1654234949.883491][2577:2577] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1654234949.883542][2577:2577] CHIP:DL: NVS set: chip-counters/reboot-count = 10 (0xA) [1654234949.884692][2577:2577] CHIP:DL: Got Ethernet interface: eth0 [1654234949.885312][2577:2577] CHIP:DL: Found the primary Ethernet interface:eth0 [1654234949.885925][2577:2577] CHIP:DL: Got WiFi interface: wlan0 [1654234949.886003][2577:2577] CHIP:DL: Failed to reset WiFi statistic counts [1654234949.886086][2577:2577] CHIP:IN: UDP::Init bind&listen port=0 [1654234949.886222][2577:2577] CHIP:IN: UDP::Init bound to port=38873 [1654234949.886251][2577:2577] CHIP:IN: BLEBase::Init - setting/overriding transport [1654234949.886273][2577:2577] CHIP:IN: TransportMgr initialized [1654234949.886326][2577:2577] CHIP:DIS: Init fabric pairing table with server storage [1654234949.886476][2577:2577] CHIP:IN: Loading from storage for fabric index 0x1 [1654234949.889308][2577:2577] CHIP:IN: Loading from storage for fabric index 0x2 [1654234949.889976][2577:2577] CHIP:IN: Loading from storage for fabric index 0x3 [1654234949.890591][2577:2577] CHIP:DIS: Add fabric pairing table delegate [1654234949.895352][2577:2577] CHIP:ZCL: Using ZAP configuration... [1654234949.899550][2577:2577] CHIP:DL: Avahi client registered [1654234949.900907][2577:2577] CHIP:CTL: System State Initialized... [1654234949.901007][2577:2577] CHIP:CTL: Setting attestation nonce to random value [1654234949.901057][2577:2577] CHIP:CTL: Setting CSR nonce to random value [1654234949.901171][2577:2577] CHIP:CTL: Setting attestation nonce to random value [1654234949.901222][2577:2577] CHIP:CTL: Setting CSR nonce to random value [1654234949.902159][2577:2577] CHIP:CTL: Generating NOC [1654234949.903046][2577:2577] CHIP:DIS: Verifying the received credentials [1654234949.905242][2577:2577] CHIP:DIS: Added new fabric at index: 0x1, Initialized: 1 [1654234949.905305][2577:2577] CHIP:DIS: Assigned compressed fabric ID: 0x5AF9D8FE8E9D355C, node ID: 0x000000000001B669 [1654234949.905340][2577:2577] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x5AF9D8FE8E9D355C [1654234949.905477][2577:2577] CHIP:CTL: Setting attestation nonce to random value [1654234949.905565][2577:2577] CHIP:CTL: Setting CSR nonce to random value [1654234949.906716][2577:2577] CHIP:CTL: Generating NOC [1654234949.908012][2577:2577] CHIP:DIS: Verifying the received credentials [1654234949.910569][2577:2577] CHIP:DIS: Added new fabric at index: 0x2, Initialized: 1 [1654234949.910619][2577:2577] CHIP:DIS: Assigned compressed fabric ID: 0x8D0B8E47AF82F747, node ID: 0x000000000001B669 [1654234949.910655][2577:2577] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x8D0B8E47AF82F747 [1654234949.910761][2577:2577] CHIP:CTL: Setting attestation nonce to random value [1654234949.910843][2577:2577] CHIP:CTL: Setting CSR nonce to random value [1654234949.911985][2577:2577] CHIP:CTL: Generating NOC [1654234949.913248][2577:2577] CHIP:DIS: Verifying the received credentials [1654234949.915594][2577:2577] CHIP:DIS: Added new fabric at index: 0x3, Initialized: 1 [1654234949.915632][2577:2577] CHIP:DIS: Assigned compressed fabric ID: 0xB555A2E50144819D, node ID: 0x000000000001B669 [1654234949.915657][2577:2577] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xB555A2E50144819D [1654234949.950586][2577:2582] CHIP:DL: CHIP task running [1654234949.950833][2577:2582] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1654234949.957487][2577:2577] CHIP:CTL: Shutting down the commissioner [1654234949.957547][2577:2577] CHIP:CTL: Shutting down the controller [1654234949.957585][2577:2577] CHIP:CTL: Shutting down the commissioner [1654234949.957616][2577:2577] CHIP:CTL: Shutting down the controller [1654234949.957645][2577:2577] CHIP:IN: Expiring all connections for fabric 1!! [1654234949.957702][2577:2577] CHIP:CTL: Shutting down the commissioner [1654234949.957735][2577:2577] CHIP:CTL: Shutting down the controller [1654234949.957761][2577:2577] CHIP:IN: Expiring all connections for fabric 2!! [1654234949.957811][2577:2577] CHIP:CTL: Shutting down the commissioner [1654234949.957843][2577:2577] CHIP:CTL: Shutting down the controller [1654234949.957871][2577:2577] CHIP:IN: Expiring all connections for fabric 3!! [1654234949.957908][2577:2577] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1654234949.959074][2577:2577] CHIP:DMG: IM WH moving to [Uninitialized] [1654234949.959128][2577:2577] CHIP:DMG: IM WH moving to [Uninitialized] [1654234949.959159][2577:2577] CHIP:DMG: IM WH moving to [Uninitialized] [1654234949.959187][2577:2577] CHIP:DMG: IM WH moving to [Uninitialized] [1654234949.959215][2577:2577] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1654234949.959305][2577:2577] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1654234949.959635][2577:2577] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-TvG4te) [1654234949.960498][2577:2577] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1654234949.960577][2577:2577] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1654234949.960611][2577:2577] CHIP:DL: Inet Layer shutdown [1654234949.960640][2577:2577] CHIP:DL: BLE shutdown [1654234949.960669][2577:2577] CHIP:DL: System Layer shutdown ./chip-tool groupsettings add-keysets 0x42 0 0x000000000021dfe hex:d0d1d2d3d4d5d6d7d8d9dadbdcdddedf [1654234981.910681][2584:2584] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1654234981.911228][2584:2584] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1654234981.911397][2584:2584] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1654234981.911508][2584:2584] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1654234981.911902][2584:2584] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Ndse6d) [1654234981.912526][2584:2584] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1654234981.912579][2584:2584] CHIP:DL: NVS set: chip-counters/reboot-count = 11 (0xB) [1654234981.913436][2584:2584] CHIP:DL: Got Ethernet interface: eth0 [1654234981.913997][2584:2584] CHIP:DL: Found the primary Ethernet interface:eth0 [1654234981.914571][2584:2584] CHIP:DL: Got WiFi interface: wlan0 [1654234981.914642][2584:2584] CHIP:DL: Failed to reset WiFi statistic counts [1654234981.914715][2584:2584] CHIP:IN: UDP::Init bind&listen port=0 [1654234981.914848][2584:2584] CHIP:IN: UDP::Init bound to port=36873 [1654234981.914874][2584:2584] CHIP:IN: BLEBase::Init - setting/overriding transport [1654234981.914896][2584:2584] CHIP:IN: TransportMgr initialized [1654234981.914954][2584:2584] CHIP:DIS: Init fabric pairing table with server storage [1654234981.915116][2584:2584] CHIP:IN: Loading from storage for fabric index 0x1 [1654234981.917674][2584:2584] CHIP:IN: Loading from storage for fabric index 0x2 [1654234981.918389][2584:2584] CHIP:IN: Loading from storage for fabric index 0x3 [1654234981.918977][2584:2584] CHIP:DIS: Add fabric pairing table delegate [1654234981.922470][2584:2584] CHIP:ZCL: Using ZAP configuration... [1654234981.927031][2584:2584] CHIP:DL: Avahi client registered [1654234981.928508][2584:2584] CHIP:CTL: System State Initialized... [1654234981.928624][2584:2584] CHIP:CTL: Setting attestation nonce to random value [1654234981.928683][2584:2584] CHIP:CTL: Setting CSR nonce to random value [1654234981.928804][2584:2584] CHIP:CTL: Setting attestation nonce to random value [1654234981.928861][2584:2584] CHIP:CTL: Setting CSR nonce to random value [1654234981.929965][2584:2584] CHIP:CTL: Generating NOC [1654234981.931061][2584:2584] CHIP:DIS: Verifying the received credentials [1654234981.933238][2584:2584] CHIP:DIS: Added new fabric at index: 0x1, Initialized: 1 [1654234981.933281][2584:2584] CHIP:DIS: Assigned compressed fabric ID: 0x5AF9D8FE8E9D355C, node ID: 0x000000000001B669 [1654234981.933312][2584:2584] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x5AF9D8FE8E9D355C [1654234981.933422][2584:2584] CHIP:CTL: Setting attestation nonce to random value [1654234981.933493][2584:2584] CHIP:CTL: Setting CSR nonce to random value [1654234981.934425][2584:2584] CHIP:CTL: Generating NOC [1654234981.935435][2584:2584] CHIP:DIS: Verifying the received credentials [1654234981.937590][2584:2584] CHIP:DIS: Added new fabric at index: 0x2, Initialized: 1 [1654234981.937631][2584:2584] CHIP:DIS: Assigned compressed fabric ID: 0x8D0B8E47AF82F747, node ID: 0x000000000001B669 [1654234981.937661][2584:2584] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x8D0B8E47AF82F747 [1654234981.937748][2584:2584] CHIP:CTL: Setting attestation nonce to random value [1654234981.937814][2584:2584] CHIP:CTL: Setting CSR nonce to random value [1654234981.938745][2584:2584] CHIP:CTL: Generating NOC [1654234981.939734][2584:2584] CHIP:DIS: Verifying the received credentials [1654234981.941447][2584:2584] CHIP:DIS: Added new fabric at index: 0x3, Initialized: 1 [1654234981.941480][2584:2584] CHIP:DIS: Assigned compressed fabric ID: 0xB555A2E50144819D, node ID: 0x000000000001B669 [1654234981.941504][2584:2584] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xB555A2E50144819D [1654234981.978161][2584:2589] CHIP:DL: CHIP task running [1654234981.978431][2584:2589] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1654234981.982658][2584:2584] CHIP:CTL: Shutting down the commissioner [1654234981.982713][2584:2584] CHIP:CTL: Shutting down the controller [1654234981.982744][2584:2584] CHIP:CTL: Shutting down the commissioner [1654234981.982769][2584:2584] CHIP:CTL: Shutting down the controller [1654234981.982792][2584:2584] CHIP:IN: Expiring all connections for fabric 1!! [1654234981.982842][2584:2584] CHIP:CTL: Shutting down the commissioner [1654234981.982867][2584:2584] CHIP:CTL: Shutting down the controller [1654234981.982889][2584:2584] CHIP:IN: Expiring all connections for fabric 2!! [1654234981.982925][2584:2584] CHIP:CTL: Shutting down the commissioner [1654234981.982949][2584:2584] CHIP:CTL: Shutting down the controller [1654234981.982971][2584:2584] CHIP:IN: Expiring all connections for fabric 3!! [1654234981.983003][2584:2584] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1654234981.984040][2584:2584] CHIP:DMG: IM WH moving to [Uninitialized] [1654234981.984093][2584:2584] CHIP:DMG: IM WH moving to [Uninitialized] [1654234981.984114][2584:2584] CHIP:DMG: IM WH moving to [Uninitialized] [1654234981.984137][2584:2584] CHIP:DMG: IM WH moving to [Uninitialized] [1654234981.984163][2584:2584] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1654234981.984243][2584:2584] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1654234981.984524][2584:2584] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-J6vM85) [1654234981.985389][2584:2584] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1654234981.985472][2584:2584] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1654234981.985502][2584:2584] CHIP:DL: Inet Layer shutdown [1654234981.985526][2584:2584] CHIP:DL: BLE shutdown [1654234981.985551][2584:2584] CHIP:DL: System Layer shutdown ./chip-tool groupsettings bind-keyset 0x0001 0x42 [1654235016.128069][2592:2592] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1654235016.128630][2592:2592] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1654235016.128823][2592:2592] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1654235016.128951][2592:2592] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1654235016.129345][2592:2592] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-vmSkku) [1654235016.130024][2592:2592] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1654235016.130093][2592:2592] CHIP:DL: NVS set: chip-counters/reboot-count = 12 (0xC) [1654235016.131108][2592:2592] CHIP:DL: Got Ethernet interface: eth0 [1654235016.131896][2592:2592] CHIP:DL: Found the primary Ethernet interface:eth0 [1654235016.132590][2592:2592] CHIP:DL: Got WiFi interface: wlan0 [1654235016.132677][2592:2592] CHIP:DL: Failed to reset WiFi statistic counts [1654235016.132765][2592:2592] CHIP:IN: UDP::Init bind&listen port=0 [1654235016.132902][2592:2592] CHIP:IN: UDP::Init bound to port=46393 [1654235016.132931][2592:2592] CHIP:IN: BLEBase::Init - setting/overriding transport [1654235016.132952][2592:2592] CHIP:IN: TransportMgr initialized [1654235016.133016][2592:2592] CHIP:DIS: Init fabric pairing table with server storage [1654235016.133190][2592:2592] CHIP:IN: Loading from storage for fabric index 0x1 [1654235016.136011][2592:2592] CHIP:IN: Loading from storage for fabric index 0x2 [1654235016.136771][2592:2592] CHIP:IN: Loading from storage for fabric index 0x3 [1654235016.137421][2592:2592] CHIP:DIS: Add fabric pairing table delegate [1654235016.140997][2592:2592] CHIP:ZCL: Using ZAP configuration... [1654235016.145879][2592:2592] CHIP:DL: Avahi client registered [1654235016.147434][2592:2592] CHIP:CTL: System State Initialized... [1654235016.147547][2592:2592] CHIP:CTL: Setting attestation nonce to random value [1654235016.147606][2592:2592] CHIP:CTL: Setting CSR nonce to random value [1654235016.147813][2592:2592] CHIP:CTL: Setting attestation nonce to random value [1654235016.147887][2592:2592] CHIP:CTL: Setting CSR nonce to random value [1654235016.148893][2592:2592] CHIP:CTL: Generating NOC [1654235016.149911][2592:2592] CHIP:DIS: Verifying the received credentials [1654235016.151799][2592:2592] CHIP:DIS: Added new fabric at index: 0x1, Initialized: 1 [1654235016.151843][2592:2592] CHIP:DIS: Assigned compressed fabric ID: 0x5AF9D8FE8E9D355C, node ID: 0x000000000001B669 [1654235016.151868][2592:2592] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x5AF9D8FE8E9D355C [1654235016.151985][2592:2592] CHIP:CTL: Setting attestation nonce to random value [1654235016.152074][2592:2592] CHIP:CTL: Setting CSR nonce to random value [1654235016.152979][2592:2592] CHIP:CTL: Generating NOC [1654235016.153976][2592:2592] CHIP:DIS: Verifying the received credentials [1654235016.155855][2592:2592] CHIP:DIS: Added new fabric at index: 0x2, Initialized: 1 [1654235016.155913][2592:2592] CHIP:DIS: Assigned compressed fabric ID: 0x8D0B8E47AF82F747, node ID: 0x000000000001B669 [1654235016.155937][2592:2592] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x8D0B8E47AF82F747 [1654235016.156059][2592:2592] CHIP:CTL: Setting attestation nonce to random value [1654235016.156140][2592:2592] CHIP:CTL: Setting CSR nonce to random value [1654235016.156999][2592:2592] CHIP:CTL: Generating NOC [1654235016.157980][2592:2592] CHIP:DIS: Verifying the received credentials [1654235016.159709][2592:2592] CHIP:DIS: Added new fabric at index: 0x3, Initialized: 1 [1654235016.159757][2592:2592] CHIP:DIS: Assigned compressed fabric ID: 0xB555A2E50144819D, node ID: 0x000000000001B669 [1654235016.159805][2592:2592] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xB555A2E50144819D [1654235016.202210][2592:2597] CHIP:DL: CHIP task running [1654235016.202454][2592:2597] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1654235016.207566][2592:2592] CHIP:CTL: Shutting down the commissioner [1654235016.207616][2592:2592] CHIP:CTL: Shutting down the controller [1654235016.207645][2592:2592] CHIP:CTL: Shutting down the commissioner [1654235016.207669][2592:2592] CHIP:CTL: Shutting down the controller [1654235016.207691][2592:2592] CHIP:IN: Expiring all connections for fabric 1!! [1654235016.207760][2592:2592] CHIP:CTL: Shutting down the commissioner [1654235016.207786][2592:2592] CHIP:CTL: Shutting down the controller [1654235016.207807][2592:2592] CHIP:IN: Expiring all connections for fabric 2!! [1654235016.207859][2592:2592] CHIP:CTL: Shutting down the commissioner [1654235016.207883][2592:2592] CHIP:CTL: Shutting down the controller [1654235016.207903][2592:2592] CHIP:IN: Expiring all connections for fabric 3!! [1654235016.207944][2592:2592] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1654235016.208901][2592:2592] CHIP:DMG: IM WH moving to [Uninitialized] [1654235016.208944][2592:2592] CHIP:DMG: IM WH moving to [Uninitialized] [1654235016.208966][2592:2592] CHIP:DMG: IM WH moving to [Uninitialized] [1654235016.208986][2592:2592] CHIP:DMG: IM WH moving to [Uninitialized] [1654235016.209008][2592:2592] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1654235016.209081][2592:2592] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1654235016.209414][2592:2592] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-JDQeTu) [1654235016.210183][2592:2592] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1654235016.210250][2592:2592] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1654235016.210278][2592:2592] CHIP:DL: Inet Layer shutdown [1654235016.210299][2592:2592] CHIP:DL: BLE shutdown [1654235016.210322][2592:2592] CHIP:DL: System Layer shutdown ./chip-tool groupsettings show-groups [1654235030.571559][2599:2599] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1654235030.572146][2599:2599] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1654235030.572308][2599:2599] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1654235030.572416][2599:2599] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1654235030.572790][2599:2599] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-k4VPgC) [1654235030.573409][2599:2599] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1654235030.573460][2599:2599] CHIP:DL: NVS set: chip-counters/reboot-count = 13 (0xD) [1654235030.574409][2599:2599] CHIP:DL: Got Ethernet interface: eth0 [1654235030.574987][2599:2599] CHIP:DL: Found the primary Ethernet interface:eth0 [1654235030.575559][2599:2599] CHIP:DL: Got WiFi interface: wlan0 [1654235030.575631][2599:2599] CHIP:DL: Failed to reset WiFi statistic counts [1654235030.575709][2599:2599] CHIP:IN: UDP::Init bind&listen port=0 [1654235030.575865][2599:2599] CHIP:IN: UDP::Init bound to port=49793 [1654235030.575890][2599:2599] CHIP:IN: BLEBase::Init - setting/overriding transport [1654235030.575911][2599:2599] CHIP:IN: TransportMgr initialized [1654235030.575964][2599:2599] CHIP:DIS: Init fabric pairing table with server storage [1654235030.576122][2599:2599] CHIP:IN: Loading from storage for fabric index 0x1 [1654235030.578836][2599:2599] CHIP:IN: Loading from storage for fabric index 0x2 [1654235030.579585][2599:2599] CHIP:IN: Loading from storage for fabric index 0x3 [1654235030.580224][2599:2599] CHIP:DIS: Add fabric pairing table delegate [1654235030.583707][2599:2599] CHIP:ZCL: Using ZAP configuration... [1654235030.588536][2599:2599] CHIP:DL: Avahi client registered [1654235030.590079][2599:2599] CHIP:CTL: System State Initialized... [1654235030.590184][2599:2599] CHIP:CTL: Setting attestation nonce to random value [1654235030.590241][2599:2599] CHIP:CTL: Setting CSR nonce to random value [1654235030.590369][2599:2599] CHIP:CTL: Setting attestation nonce to random value [1654235030.590426][2599:2599] CHIP:CTL: Setting CSR nonce to random value [1654235030.591468][2599:2599] CHIP:CTL: Generating NOC [1654235030.592615][2599:2599] CHIP:DIS: Verifying the received credentials [1654235030.594693][2599:2599] CHIP:DIS: Added new fabric at index: 0x1, Initialized: 1 [1654235030.594752][2599:2599] CHIP:DIS: Assigned compressed fabric ID: 0x5AF9D8FE8E9D355C, node ID: 0x000000000001B669 [1654235030.594779][2599:2599] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x5AF9D8FE8E9D355C [1654235030.594902][2599:2599] CHIP:CTL: Setting attestation nonce to random value [1654235030.594974][2599:2599] CHIP:CTL: Setting CSR nonce to random value [1654235030.595982][2599:2599] CHIP:CTL: Generating NOC [1654235030.597066][2599:2599] CHIP:DIS: Verifying the received credentials [1654235030.599148][2599:2599] CHIP:DIS: Added new fabric at index: 0x2, Initialized: 1 [1654235030.599303][2599:2599] CHIP:DIS: Assigned compressed fabric ID: 0x8D0B8E47AF82F747, node ID: 0x000000000001B669 [1654235030.599336][2599:2599] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x8D0B8E47AF82F747 [1654235030.599445][2599:2599] CHIP:CTL: Setting attestation nonce to random value [1654235030.599516][2599:2599] CHIP:CTL: Setting CSR nonce to random value [1654235030.600538][2599:2599] CHIP:CTL: Generating NOC [1654235030.601655][2599:2599] CHIP:DIS: Verifying the received credentials [1654235030.603521][2599:2599] CHIP:DIS: Added new fabric at index: 0x3, Initialized: 1 [1654235030.603576][2599:2599] CHIP:DIS: Assigned compressed fabric ID: 0xB555A2E50144819D, node ID: 0x000000000001B669 [1654235030.603600][2599:2599] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xB555A2E50144819D [1654235030.644437][2599:2604] CHIP:DL: CHIP task running [1654235030.644686][2599:2604] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 +-------------------------------------------------------------------------------------+ | Available Groups : | +-------------------------------------------------------------------------------------+ | Group Id | KeySet Id | Group Name | | 0x101 0x1a1 Group #1 | | 0x102 0x1a2 Group #2 | | 0x1 0x42 grp1 | +-------------------------------------------------------------------------------------+ [1654235030.645924][2599:2599] CHIP:CTL: Shutting down the commissioner [1654235030.645959][2599:2599] CHIP:CTL: Shutting down the controller [1654235030.645988][2599:2599] CHIP:CTL: Shutting down the commissioner [1654235030.646010][2599:2599] CHIP:CTL: Shutting down the controller [1654235030.646032][2599:2599] CHIP:IN: Expiring all connections for fabric 1!! [1654235030.646078][2599:2599] CHIP:CTL: Shutting down the commissioner [1654235030.646102][2599:2599] CHIP:CTL: Shutting down the controller [1654235030.646123][2599:2599] CHIP:IN: Expiring all connections for fabric 2!! [1654235030.646156][2599:2599] CHIP:CTL: Shutting down the commissioner [1654235030.646179][2599:2599] CHIP:CTL: Shutting down the controller [1654235030.646199][2599:2599] CHIP:IN: Expiring all connections for fabric 3!! [1654235030.646225][2599:2599] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1654235030.647155][2599:2599] CHIP:DMG: IM WH moving to [Uninitialized] [1654235030.647195][2599:2599] CHIP:DMG: IM WH moving to [Uninitialized] [1654235030.647246][2599:2599] CHIP:DMG: IM WH moving to [Uninitialized] [1654235030.647270][2599:2599] CHIP:DMG: IM WH moving to [Uninitialized] [1654235030.647294][2599:2599] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1654235030.647371][2599:2599] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1654235030.647658][2599:2599] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-YUB0FY) [1654235030.648396][2599:2599] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1654235030.648461][2599:2599] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1654235030.648487][2599:2599] CHIP:DL: Inet Layer shutdown [1654235030.648509][2599:2599] CHIP:DL: BLE shutdown [1654235030.648532][2599:2599] CHIP:DL: System Layer shutdown ./chip-tool onoff on 0xffffffffffff0001 1 [1655277451.684904][4042:4042] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655277451.685454][4042:4042] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655277451.685612][4042:4042] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655277451.685725][4042:4042] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655277451.686087][4042:4042] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-27gTuY) [1655277451.686767][4042:4042] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655277451.686821][4042:4042] CHIP:DL: NVS set: chip-counters/reboot-count = 20 (0x14) [1655277451.687704][4042:4042] CHIP:DL: Got Ethernet interface: eth0 [1655277451.688289][4042:4042] CHIP:DL: Found the primary Ethernet interface:eth0 [1655277451.688890][4042:4042] CHIP:DL: Got WiFi interface: wlan0 [1655277451.688964][4042:4042] CHIP:DL: Failed to reset WiFi statistic counts [1655277451.689020][4042:4042] CHIP:IN: UDP::Init bind&listen port=0 [1655277451.689162][4042:4042] CHIP:IN: UDP::Init bound to port=40033 [1655277451.689188][4042:4042] CHIP:IN: BLEBase::Init - setting/overriding transport [1655277451.689209][4042:4042] CHIP:IN: TransportMgr initialized [1655277451.689279][4042:4042] CHIP:FP: Initializing FabricTable from persistent storage [1655277451.689456][4042:4042] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655277451.689552][4042:4042] CHIP:FP: Loading from storage for fabric index 0x1 [1655277451.690068][4042:4042] CHIP:FP: Loading from storage for fabric index 0x2 [1655277451.690494][4042:4042] CHIP:FP: Loading from storage for fabric index 0x3 [1655277451.694564][4042:4042] CHIP:ZCL: Using ZAP configuration... [1655277451.699242][4042:4042] CHIP:DL: Avahi client registered [1655277451.700654][4042:4042] CHIP:CTL: System State Initialized... [1655277451.700752][4042:4042] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655277451.700809][4042:4042] CHIP:CTL: Setting attestation nonce to random value [1655277451.700866][4042:4042] CHIP:CTL: Setting CSR nonce to random value [1655277451.701026][4042:4042] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655277451.701060][4042:4042] CHIP:CTL: Setting attestation nonce to random value [1655277451.701113][4042:4042] CHIP:CTL: Setting CSR nonce to random value [1655277451.704283][4042:4042] CHIP:CTL: Generating NOC [1655277451.705315][4042:4042] CHIP:FP: Validating NOC chain [1655277451.707967][4042:4042] CHIP:FP: NOC chain validation successful [1655277451.708226][4042:4042] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655277451.708267][4042:4042] CHIP:FP: Assigned compressed fabric ID: 0xF108C463391241AB, node ID: 0x000000000001B669 [1655277451.718839][4042:4042] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655277451.718896][4042:4042] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655277451.718921][4042:4042] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655277451.718943][4042:4042] CHIP:TS: Retaining current Last Known Good Time [1655277451.720482][4042:4042] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0xF108C463391241AB [1655277451.720617][4042:4042] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655277451.720658][4042:4042] CHIP:CTL: Setting attestation nonce to random value [1655277451.720737][4042:4042] CHIP:CTL: Setting CSR nonce to random value [1655277451.721600][4042:4042] CHIP:CTL: Generating NOC [1655277451.722455][4042:4042] CHIP:FP: Validating NOC chain [1655277451.724173][4042:4042] CHIP:FP: NOC chain validation successful [1655277451.724338][4042:4042] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655277451.724365][4042:4042] CHIP:FP: Assigned compressed fabric ID: 0x2EE1BABB5D2E379C, node ID: 0x000000000001B669 [1655277451.730918][4042:4042] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655277451.730975][4042:4042] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655277451.731003][4042:4042] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655277451.731029][4042:4042] CHIP:TS: Retaining current Last Known Good Time [1655277451.732747][4042:4042] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x2EE1BABB5D2E379C [1655277451.732868][4042:4042] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655277451.732913][4042:4042] CHIP:CTL: Setting attestation nonce to random value [1655277451.732997][4042:4042] CHIP:CTL: Setting CSR nonce to random value [1655277451.733955][4042:4042] CHIP:CTL: Generating NOC [1655277451.734945][4042:4042] CHIP:FP: Validating NOC chain [1655277451.736914][4042:4042] CHIP:FP: NOC chain validation successful [1655277451.737203][4042:4042] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655277451.737234][4042:4042] CHIP:FP: Assigned compressed fabric ID: 0x984557A812960260, node ID: 0x000000000001B669 [1655277451.744222][4042:4042] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655277451.744276][4042:4042] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655277451.744300][4042:4042] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655277451.744321][4042:4042] CHIP:TS: Retaining current Last Known Good Time [1655277451.748556][4042:4042] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x984557A812960260 [1655277451.791493][4042:4047] CHIP:DL: CHIP task running [1655277451.791718][4042:4047] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655277451.791763][4042:4047] CHIP:TOO: Sending command to group 0x1 [1655277451.791786][4042:4047] CHIP:TOO: Sending cluster (0x00000006) command (0x00000001) on Group 1 [1655277451.791836][4042:4047] CHIP:DMG: ICR moving to [AddingComm] [1655277451.791885][4042:4047] CHIP:DMG: ICR moving to [AddedComma] [1655277451.792480][4042:4047] CHIP:IN: Prepared outgoing group message 0xffffb8afeff8 to 0x0000000000000000 (1) of type 0x8 and protocolId (0, 1) on exchange 50840i with MessageCounter:19000. [1655277451.792539][4042:4047] CHIP:IN: Sending encrypted group msg 0xffffb8afeff8 with MessageCounter:19000 to 1 at monotonic time: 0000000000C55072 msec to Multicast IPV6 address : UDP:[ff35:40:fd00::100:1]:5540 with GroupID of 1 and fabric index of 1 [1655277451.792676][4042:4047] CHIP:DMG: ICR moving to [CommandSen] [1655277451.792702][4042:4047] CHIP:DMG: ICR moving to [AwaitingDe] [1655277451.792937][4042:4042] CHIP:CTL: Shutting down the commissioner [1655277451.792974][4042:4042] CHIP:CTL: Shutting down the controller [1655277451.793004][4042:4042] CHIP:CTL: Shutting down the commissioner [1655277451.793026][4042:4042] CHIP:CTL: Shutting down the controller [1655277451.793049][4042:4042] CHIP:IN: Expiring all connections for fabric 1!! [1655277451.793096][4042:4042] CHIP:CTL: Shutting down the commissioner [1655277451.793120][4042:4042] CHIP:CTL: Shutting down the controller [1655277451.793141][4042:4042] CHIP:IN: Expiring all connections for fabric 2!! [1655277451.793176][4042:4042] CHIP:CTL: Shutting down the commissioner [1655277451.793198][4042:4042] CHIP:CTL: Shutting down the controller [1655277451.793217][4042:4042] CHIP:IN: Expiring all connections for fabric 3!! [1655277451.793247][4042:4042] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655277451.794178][4042:4042] CHIP:DMG: IM WH moving to [Uninitialized] [1655277451.794217][4042:4042] CHIP:DMG: IM WH moving to [Uninitialized] [1655277451.794237][4042:4042] CHIP:DMG: IM WH moving to [Uninitialized] [1655277451.794257][4042:4042] CHIP:DMG: IM WH moving to [Uninitialized] [1655277451.794279][4042:4042] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655277451.794354][4042:4042] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655277451.794697][4042:4042] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-YqtRCk) [1655277451.795411][4042:4042] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655277451.795476][4042:4042] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655277451.795504][4042:4042] CHIP:DL: Inet Layer shutdown [1655277451.795526][4042:4042] CHIP:DL: BLE shutdown [1655277451.795549][4042:4042] CHIP:DL: System Layer shutdown ./chip-tool accesscontrol write acl '[{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects": [112233], "targets": [{"cluster": null, "endpoint": 0, "deviceType": null}]}, {"fabricIndex": 1, "privilege": 3, "authMode": 2, "subjects": null, "targets": [{"cluster": null, "endpoint": 1, "deviceType": null}]}]' 1 0 [1655280383.891622][4375:4375] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655280383.892204][4375:4375] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655280383.892385][4375:4375] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655280383.892498][4375:4375] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655280383.892884][4375:4375] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-UXM2Lw) [1655280383.893527][4375:4375] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655280383.893580][4375:4375] CHIP:DL: NVS set: chip-counters/reboot-count = 13 (0xD) [1655280383.894494][4375:4375] CHIP:DL: Got Ethernet interface: eth0 [1655280383.895107][4375:4375] CHIP:DL: Found the primary Ethernet interface:eth0 [1655280383.895719][4375:4375] CHIP:DL: Got WiFi interface: wlan0 [1655280383.895793][4375:4375] CHIP:DL: Failed to reset WiFi statistic counts [1655280383.895860][4375:4375] CHIP:IN: UDP::Init bind&listen port=0 [1655280383.896005][4375:4375] CHIP:IN: UDP::Init bound to port=58358 [1655280383.896030][4375:4375] CHIP:IN: BLEBase::Init - setting/overriding transport [1655280383.896051][4375:4375] CHIP:IN: TransportMgr initialized [1655280383.896125][4375:4375] CHIP:FP: Initializing FabricTable from persistent storage [1655280383.896281][4375:4375] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655280383.896372][4375:4375] CHIP:FP: Loading from storage for fabric index 0x1 [1655280383.896829][4375:4375] CHIP:FP: Loading from storage for fabric index 0x2 [1655280383.897205][4375:4375] CHIP:FP: Loading from storage for fabric index 0x3 [1655280383.900829][4375:4375] CHIP:ZCL: Using ZAP configuration... [1655280383.905236][4375:4375] CHIP:DL: Avahi client registered [1655280383.906606][4375:4375] CHIP:CTL: System State Initialized... [1655280383.906689][4375:4375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655280383.906746][4375:4375] CHIP:CTL: Setting attestation nonce to random value [1655280383.906799][4375:4375] CHIP:CTL: Setting CSR nonce to random value [1655280383.906915][4375:4375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655280383.906946][4375:4375] CHIP:CTL: Setting attestation nonce to random value [1655280383.906996][4375:4375] CHIP:CTL: Setting CSR nonce to random value [1655280383.909879][4375:4375] CHIP:CTL: Generating NOC [1655280383.910885][4375:4375] CHIP:FP: Validating NOC chain [1655280383.913354][4375:4375] CHIP:FP: NOC chain validation successful [1655280383.913585][4375:4375] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655280383.913624][4375:4375] CHIP:FP: Assigned compressed fabric ID: 0x113253FC8ABC79A7, node ID: 0x000000000001B669 [1655280383.921778][4375:4375] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655280383.921849][4375:4375] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655280383.921884][4375:4375] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655280383.921917][4375:4375] CHIP:TS: Retaining current Last Known Good Time [1655280383.923674][4375:4375] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x113253FC8ABC79A7 [1655280383.923830][4375:4375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655280383.923872][4375:4375] CHIP:CTL: Setting attestation nonce to random value [1655280383.923933][4375:4375] CHIP:CTL: Setting CSR nonce to random value [1655280383.924813][4375:4375] CHIP:CTL: Generating NOC [1655280383.925699][4375:4375] CHIP:FP: Validating NOC chain [1655280383.927536][4375:4375] CHIP:FP: NOC chain validation successful [1655280383.927732][4375:4375] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655280383.927762][4375:4375] CHIP:FP: Assigned compressed fabric ID: 0x56E24F56E83DEB28, node ID: 0x000000000001B669 [1655280383.933672][4375:4375] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655280383.933732][4375:4375] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655280383.933755][4375:4375] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655280383.933776][4375:4375] CHIP:TS: Retaining current Last Known Good Time [1655280383.935313][4375:4375] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x56E24F56E83DEB28 [1655280383.935448][4375:4375] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655280383.935492][4375:4375] CHIP:CTL: Setting attestation nonce to random value [1655280383.935557][4375:4375] CHIP:CTL: Setting CSR nonce to random value [1655280383.936437][4375:4375] CHIP:CTL: Generating NOC [1655280383.937382][4375:4375] CHIP:FP: Validating NOC chain [1655280383.939307][4375:4375] CHIP:FP: NOC chain validation successful [1655280383.939527][4375:4375] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655280383.939561][4375:4375] CHIP:FP: Assigned compressed fabric ID: 0x999A17BE4981259E, node ID: 0x000000000001B669 [1655280383.946177][4375:4375] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655280383.946240][4375:4375] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655280383.946264][4375:4375] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655280383.946286][4375:4375] CHIP:TS: Retaining current Last Known Good Time [1655280383.947891][4375:4375] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x999A17BE4981259E [1655280383.991699][4375:4380] CHIP:DL: CHIP task running [1655280383.991962][4375:4380] CHIP:DL: HandlePlatformSpecificBLEEvent 32787[1655280383.992004][4375:4380] CHIP:TOO: Sending command to node 0x1 [1655280383.992047][4375:4380] CHIP:CSM: FindOrEstablishSession: PeerId = 113253FC8ABC79A7:0000000000000001 [1655280383.992080][4375:4380] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655280383.992127][4375:4380] CHIP:CTL: OperationalDeviceProxy[113253FC8ABC79A7:0000000000000001]: State change 1 --> 2 [1655280383.992163][4375:4380] CHIP:DIS: Resolving 113253FC8ABC79A7:0000000000000001 ... [1655280384.100938][4375:4380] CHIP:DL: Avahi resolve found [1655280384.101049][4375:4380] CHIP:DIS: Node ID resolved for 113253FC8ABC79A7:0000000000000001 [1655280384.101094][4375:4380] CHIP:DIS: Hostname: E45F01312CE50000 [1655280384.101140][4375:4380] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655280384.101179][4375:4380] CHIP:DIS: Port: 5540 [1655280384.101217][4375:4380] CHIP:DIS: Mrp Interval idle: 5000 ms [1655280384.101254][4375:4380] CHIP:DIS: Mrp Interval active: 300 ms [1655280384.101606][4375:4380] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655280384.101651][4375:4380] CHIP:DIS: Checking node lookup status after 110 ms [1655280384.101687][4375:4380] CHIP:DIS: Keeping DNSSD lookup active [1655280384.192079][4375:4380] CHIP:DIS: Checking node lookup status after 200 ms [1655280384.192343][4375:4380] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655280384.192407][4375:4380] CHIP:CTL: OperationalDeviceProxy[113253FC8ABC79A7:0000000000000001]: State change 2 --> 3 [1655280384.192790][4375:4380] CHIP:IN: SecureSession[0xaaaad6d3f410]: Allocated Type:2 LSID:17026 [1655280384.192876][4375:4380] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655280384.194639][4375:4380] CHIP:SC: Including MRP parameters [1655280384.195106][4375:4380] CHIP:IN: Prepared unauthenticated message 0xaaaad6d468c8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 38795i with MessageCounter:97515115. [1655280384.195216][4375:4380] CHIP:IN: Sending unauthenticated msg 0xaaaad6d468c8 with MessageCounter:97515115 to 0x0000000000000000 at monotonic time: 0000000000F20F24 msec [1655280384.195560][4375:4380] CHIP:SC: Sent Sigma1 msg [1655280384.195629][4375:4380] CHIP:CTL: OperationalDeviceProxy[113253FC8ABC79A7:0000000000000001]: State change 3 --> 4 [1655280384.195695][4375:4380] CHIP:DIS: Discovery does not require any more timeouts [1655280384.198062][4375:4380] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:151302212 on exchange 38795i [1655280384.198145][4375:4380] CHIP:EM: Found matching exchange: 38795i, Delegate: 0xffff880011a0 [1655280384.198226][4375:4380] CHIP:EM: Rxd Ack; Removing MessageCounter:97515115 from Retrans Table on exchange 38795i [1655280384.198285][4375:4380] CHIP:EM: Removed CHIP MessageCounter:97515115 from RetransTable on exchange 38795i [1655280384.198366][4375:4380] CHIP:SC: Received Sigma2Resume msg [1655280384.198575][4375:4380] CHIP:SC: Found MRP parameters in the message [1655280384.198645][4375:4380] CHIP:SC: Peer assigned session session ID 14260 [1655280384.206670][4375:4380] CHIP:SC: Sending status report. Protocol code 0, exchange 38795 [1655280384.206747][4375:4380] CHIP:EM: Piggybacking Ack for MessageCounter:151302212 on exchange: 38795i [1655280384.206802][4375:4380] CHIP:IN: Prepared unauthenticated message 0xaaaad6d468c8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 38795i with MessageCounter:97515116. [1655280384.206852][4375:4380] CHIP:IN: Sending unauthenticated msg 0xaaaad6d468c8 with MessageCounter:97515116 to 0x0000000000000000 at monotonic time: 0000000000F20F30 msec [1655280384.207132][4375:4380] CHIP:IN: SecureSession[0xaaaad6d3f410]: Activated - Type:2 LSID:17026 [1655280384.207168][4375:4380] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:17026 PSID:14260! [1655280384.207201][4375:4380] CHIP:CTL: OperationalDeviceProxy[113253FC8ABC79A7:0000000000000001]: State change 4 --> 5 [1655280384.207257][4375:4380] CHIP:TOO: Sending WriteAttribute to cluster 0x0000_001F on endpoint 0 [1655280384.207353][4375:4380] CHIP:DMG: WriteClient moving to [AddAttribu] [1655280384.207429][4375:4380] CHIP:DMG: WriteClient moving to [AddAttribu] [1655280384.207463][4375:4380] CHIP:DMG: WriteClient moving to [AddAttribu] [1655280384.207567][4375:4380] CHIP:IN: Prepared secure message 0xaaaad6d468e8 to 0x0000000000000001 (1) of type 0x6 and protocolId (0, 1) on exchange 38796i with MessageCounter:47326238. [1655280384.207611][4375:4380] CHIP:IN: Sending encrypted msg 0xaaaad6d468e8 with MessageCounter:47326238 to 0x0000000000000001 (1) at monotonic time: 0000000000F20F31 msec [1655280384.207755][4375:4380] CHIP:DMG: WriteClient moving to [AwaitingRe] [1655280384.214964][4375:4380] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:151302213 on exchange 38795i [1655280384.215007][4375:4380] CHIP:EM: Found matching exchange: 38795i, Delegate: (nil) [1655280384.215055][4375:4380] CHIP:EM: Rxd Ack; Removing MessageCounter:97515116 from Retrans Table on exchange 38795i [1655280384.215083][4375:4380] CHIP:EM: Removed CHIP MessageCounter:97515116 from RetransTable on exchange 38795i [1655280384.227272][4375:4380] CHIP:EM: Received message of type 0x7 with protocolId (0, 1) and MessageCounter:7864151 on exchange 38796i [1655280384.227338][4375:4380] CHIP:EM: Found matching exchange: 38796i, Delegate: 0xffff880057c0 [1655280384.227398][4375:4380] CHIP:EM: Rxd Ack; Removing MessageCounter:47326238 from Retrans Table on exchange 38796i [1655280384.227434][4375:4380] CHIP:EM: Removed CHIP MessageCounter:47326238 from RetransTable on exchange 38796i [1655280384.227488][4375:4380] CHIP:DMG: WriteClient moving to [ResponseRe] [1655280384.227567][4375:4380] CHIP:DMG: WriteResponseMessage = [1655280384.227605][4375:4380] CHIP:DMG: { [1655280384.227637][4375:4380] CHIP:DMG: AttributeStatusIBs = [1655280384.227683][4375:4380] CHIP:DMG: [ [1655280384.227720][4375:4380] CHIP:DMG: AttributeStatusIB = [1655280384.227761][4375:4380] CHIP:DMG: { [1655280384.227800][4375:4380] CHIP:DMG: AttributePathIB = [1655280384.227853][4375:4380] CHIP:DMG: { [1655280384.227905][4375:4380] CHIP:DMG: Endpoint = 0x0, [1655280384.227958][4375:4380] CHIP:DMG: Cluster = 0x1f, [1655280384.228009][4375:4380] CHIP:DMG: Attribute = 0x0000_0000, [1655280384.228073][4375:4380] CHIP:DMG: } [1655280384.228123][4375:4380] CHIP:DMG: [1655280384.228164][4375:4380] CHIP:DMG: StatusIB = [1655280384.228208][4375:4380] CHIP:DMG: { [1655280384.228252][4375:4380] CHIP:DMG: status = 0x00 (SUCCESS), [1655280384.228295][4375:4380] CHIP:DMG: }, [1655280384.228337][4375:4380] CHIP:DMG: [1655280384.228372][4375:4380] CHIP:DMG: }, [1655280384.228419][4375:4380] CHIP:DMG: [1655280384.228452][4375:4380] CHIP:DMG: AttributeStatusIB = [1655280384.228489][4375:4380] CHIP:DMG: { [1655280384.228524][4375:4380] CHIP:DMG: AttributePathIB = [1655280384.228565][4375:4380] CHIP:DMG: { [1655280384.228609][4375:4380] CHIP:DMG: Endpoint = 0x0, [1655280384.228659][4375:4380] CHIP:DMG: Cluster = 0x1f, [1655280384.228710][4375:4380] CHIP:DMG: Attribute = 0x0000_0000, [1655280384.228758][4375:4380] CHIP:DMG: ListIndex = Null, [1655280384.228805][4375:4380] CHIP:DMG: } [1655280384.228851][4375:4380] CHIP:DMG: [1655280384.228893][4375:4380] CHIP:DMG: StatusIB = [1655280384.228934][4375:4380] CHIP:DMG: { [1655280384.228976][4375:4380] CHIP:DMG: status = 0x00 (SUCCESS), [1655280384.229024][4375:4380] CHIP:DMG: }, [1655280384.229066][4375:4380] CHIP:DMG: [1655280384.229101][4375:4380] CHIP:DMG: }, [1655280384.229148][4375:4380] CHIP:DMG: [1655280384.229180][4375:4380] CHIP:DMG: AttributeStatusIB = [1655280384.229216][4375:4380] CHIP:DMG: { [1655280384.229251][4375:4380] CHIP:DMG: AttributePathIB = [1655280384.229292][4375:4380] CHIP:DMG: { [1655280384.229334][4375:4380] CHIP:DMG: Endpoint = 0x0, [1655280384.229379][4375:4380] CHIP:DMG: Cluster = 0x1f, [1655280384.229428][4375:4380] CHIP:DMG: Attribute = 0x0000_0000, [1655280384.229476][4375:4380] CHIP:DMG: ListIndex = Null, [1655280384.229524][4375:4380] CHIP:DMG: } [1655280384.229570][4375:4380] CHIP:DMG: [1655280384.229611][4375:4380] CHIP:DMG: StatusIB = [1655280384.229653][4375:4380] CHIP:DMG: { [1655280384.229695][4375:4380] CHIP:DMG: status = 0x00 (SUCCESS), [1655280384.229742][4375:4380] CHIP:DMG: }, [1655280384.229783][4375:4380] CHIP:DMG: [1655280384.229817][4375:4380] CHIP:DMG: }, [1655280384.229856][4375:4380] CHIP:DMG: [1655280384.229888][4375:4380] CHIP:DMG: ], [1655280384.229936][4375:4380] CHIP:DMG: [1655280384.229968][4375:4380] CHIP:DMG: InteractionModelRevision = 1[1655280384.230021][4375:4380] CHIP:DMG: } [1655280384.230194][4375:4380] CHIP:DMG: WriteClient moving to [AwaitingDe] [1655280384.230286][4375:4380] CHIP:EM: Sending Standalone Ack for MessageCounter:7864151 on exchange 38796i [1655280384.230392][4375:4380] CHIP:IN: Prepared secure message 0xffff9afdd958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 38796i with MessageCounter:47326239. [1655280384.230495][4375:4380] CHIP:IN: Sending encrypted msg 0xffff9afdd958 with MessageCounter:47326239 to 0x0000000000000001 (1) at monotonic time: 0000000000F20F48 msec [1655280384.230657][4375:4380] CHIP:EM: Flushed pending ack for MessageCounter:7864151 on exchange 38796i [1655280384.230905][4375:4375] CHIP:CTL: Shutting down the commissioner [1655280384.230951][4375:4375] CHIP:CTL: Shutting down the controller [1655280384.230987][4375:4375] CHIP:CTL: Shutting down the commissioner [1655280384.231017][4375:4375] CHIP:CTL: Shutting down the controller [1655280384.231056][4375:4375] CHIP:IN: Expiring all connections for fabric 1!! [1655280384.231087][4375:4375] CHIP:IN: SecureSession[0xaaaad6d3f410]: MarkForRemoval Type:2 LSID:17026 [1655280384.231118][4375:4375] CHIP:IN: SecureSession[0xaaaad6d3f410]: Released - Type:2 LSID:17026 [1655280384.231179][4375:4375] CHIP:CTL: Shutting down the commissioner [1655280384.231211][4375:4375] CHIP:CTL: Shutting down the controller [1655280384.231239][4375:4375] CHIP:IN: Expiring all connections for fabric 2!! [1655280384.231286][4375:4375] CHIP:CTL: Shutting down the commissioner [1655280384.231315][4375:4375] CHIP:CTL: Shutting down the controller [1655280384.231342][4375:4375] CHIP:IN: Expiring all connections for fabric 3!! [1655280384.231383][4375:4375] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655280384.232580][4375:4375] CHIP:DMG: IM WH moving to [Uninitialized] [1655280384.232636][4375:4375] CHIP:DMG: IM WH moving to [Uninitialized] [1655280384.232664][4375:4375] CHIP:DMG: IM WH moving to [Uninitialized] [1655280384.232691][4375:4375] CHIP:DMG: IM WH moving to [Uninitialized] [1655280384.232721][4375:4375] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655280384.232808][4375:4375] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655280384.233126][4375:4375] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-vFav8N) [1655280384.234570][4375:4375] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655280384.234668][4375:4375] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655280384.234707][4375:4375] CHIP:DL: Inet Layer shutdown [1655280384.234736][4375:4375] CHIP:DL: BLE shutdown [1655280384.234765][4375:4375] CHIP:DL: System Layer shutdown ./chip-tool onoff read on-off 1 1 [1655280422.252471][4382:4382] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655280422.253012][4382:4382] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655280422.253187][4382:4382] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655280422.253302][4382:4382] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655280422.253678][4382:4382] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-QRiN28) [1655280422.254364][4382:4382] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655280422.254459][4382:4382] CHIP:DL: NVS set: chip-counters/reboot-count = 14 (0xE) [1655280422.255369][4382:4382] CHIP:DL: Got Ethernet interface: eth0 [1655280422.256148][4382:4382] CHIP:DL: Found the primary Ethernet interface:eth0 [1655280422.256803][4382:4382] CHIP:DL: Got WiFi interface: wlan0 [1655280422.256888][4382:4382] CHIP:DL: Failed to reset WiFi statistic counts [1655280422.256947][4382:4382] CHIP:IN: UDP::Init bind&listen port=0 [1655280422.257100][4382:4382] CHIP:IN: UDP::Init bound to port=33472 [1655280422.257128][4382:4382] CHIP:IN: BLEBase::Init - setting/overriding transport [1655280422.257150][4382:4382] CHIP:IN: TransportMgr initialized [1655280422.257222][4382:4382] CHIP:FP: Initializing FabricTable from persistent storage [1655280422.257408][4382:4382] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655280422.257504][4382:4382] CHIP:FP: Loading from storage for fabric index 0x1 [1655280422.258017][4382:4382] CHIP:FP: Loading from storage for fabric index 0x2 [1655280422.258410][4382:4382] CHIP:FP: Loading from storage for fabric index 0x3 [1655280422.262470][4382:4382] CHIP:ZCL: Using ZAP configuration... [1655280422.267389][4382:4382] CHIP:DL: Avahi client registered [1655280422.268891][4382:4382] CHIP:CTL: System State Initialized... [1655280422.268987][4382:4382] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655280422.269041][4382:4382] CHIP:CTL: Setting attestation nonce to random value [1655280422.269096][4382:4382] CHIP:CTL: Setting CSR nonce to random value [1655280422.269225][4382:4382] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655280422.269261][4382:4382] CHIP:CTL: Setting attestation nonce to random value [1655280422.269310][4382:4382] CHIP:CTL: Setting CSR nonce to random value [1655280422.272227][4382:4382] CHIP:CTL: Generating NOC [1655280422.273145][4382:4382] CHIP:FP: Validating NOC chain [1655280422.275036][4382:4382] CHIP:FP: NOC chain validation successful [1655280422.275236][4382:4382] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655280422.275269][4382:4382] CHIP:FP: Assigned compressed fabric ID: 0x113253FC8ABC79A7, node ID: 0x000000000001B669 [1655280422.282573][4382:4382] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655280422.282644][4382:4382] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655280422.282668][4382:4382] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655280422.282691][4382:4382] CHIP:TS: Retaining current Last Known Good Time [1655280422.284292][4382:4382] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x113253FC8ABC79A7 [1655280422.284453][4382:4382] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655280422.284498][4382:4382] CHIP:CTL: Setting attestation nonce to random value [1655280422.284564][4382:4382] CHIP:CTL: Setting CSR nonce to random value [1655280422.285457][4382:4382] CHIP:CTL: Generating NOC [1655280422.286336][4382:4382] CHIP:FP: Validating NOC chain [1655280422.288205][4382:4382] CHIP:FP: NOC chain validation successful [1655280422.288403][4382:4382] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655280422.288435][4382:4382] CHIP:FP: Assigned compressed fabric ID: 0x56E24F56E83DEB28, node ID: 0x000000000001B669 [1655280422.294565][4382:4382] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655280422.294623][4382:4382] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655280422.294648][4382:4382] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655280422.294669][4382:4382] CHIP:TS: Retaining current Last Known Good Time [1655280422.296066][4382:4382] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x56E24F56E83DEB28 [1655280422.296186][4382:4382] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655280422.296227][4382:4382] CHIP:CTL: Setting attestation nonce to random value [1655280422.296291][4382:4382] CHIP:CTL: Setting CSR nonce to random value [1655280422.297133][4382:4382] CHIP:CTL: Generating NOC [1655280422.297993][4382:4382] CHIP:FP: Validating NOC chain [1655280422.299746][4382:4382] CHIP:FP: NOC chain validation successful [1655280422.299900][4382:4382] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655280422.299927][4382:4382] CHIP:FP: Assigned compressed fabric ID: 0x999A17BE4981259E, node ID: 0x000000000001B669 [1655280422.306189][4382:4382] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655280422.306240][4382:4382] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16 [1655280422.306264][4382:4382] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655280422.306286][4382:4382] CHIP:TS: Retaining current Last Known Good Time [1655280422.307915][4382:4382] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x999A17BE4981259E [1655280422.351252][4382:4387] CHIP:DL: CHIP task running [1655280422.351501][4382:4387] CHIP:DL: HandlePlatformSpecificBLEEvent 32787[1655280422.351543][4382:4387] CHIP:TOO: Sending command to node 0x1 [1655280422.351592][4382:4387] CHIP:CSM: FindOrEstablishSession: PeerId = 113253FC8ABC79A7:0000000000000001 [1655280422.351626][4382:4387] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655280422.351675][4382:4387] CHIP:CTL: OperationalDeviceProxy[113253FC8ABC79A7:0000000000000001]: State change 1 --> 2 [1655280422.351712][4382:4387] CHIP:DIS: Resolving 113253FC8ABC79A7:0000000000000001 ... [1655280422.353789][4382:4387] CHIP:DL: Avahi resolve found [1655280422.353875][4382:4387] CHIP:DIS: Node ID resolved for 113253FC8ABC79A7:0000000000000001 [1655280422.353909][4382:4387] CHIP:DIS: Hostname: E45F01312CE50000 [1655280422.353948][4382:4387] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655280422.353978][4382:4387] CHIP:DIS: Port: 5540 [1655280422.354005][4382:4387] CHIP:DIS: Mrp Interval idle: 5000 ms [1655280422.354033][4382:4387] CHIP:DIS: Mrp Interval active: 300 ms [1655280422.354319][4382:4387] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655280422.354355][4382:4387] CHIP:DIS: Checking node lookup status after 2 ms [1655280422.354381][4382:4387] CHIP:DIS: Keeping DNSSD lookup active [1655280422.551996][4382:4387] CHIP:DIS: Checking node lookup status after 200 ms [1655280422.552268][4382:4387] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655280422.552334][4382:4387] CHIP:CTL: OperationalDeviceProxy[113253FC8ABC79A7:0000000000000001]: State change 2 --> 3 [1655280422.552720][4382:4387] CHIP:IN: SecureSession[0xaaaac86a1130]: Allocated Type:2 LSID:13651 [1655280422.552809][4382:4387] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655280422.554151][4382:4387] CHIP:SC: Including MRP parameters [1655280422.554419][4382:4387] CHIP:IN: Prepared unauthenticated message 0xaaaac86a85e8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 50662i with MessageCounter:68370090. [1655280422.554508][4382:4387] CHIP:IN: Sending unauthenticated msg 0xaaaac86a85e8 with MessageCounter:68370090 to 0x0000000000000000 at monotonic time: 0000000000F2A4FC msec [1655280422.554704][4382:4387] CHIP:SC: Sent Sigma1 msg [1655280422.554740][4382:4387] CHIP:CTL: OperationalDeviceProxy[113253FC8ABC79A7:0000000000000001]: State change 3 --> 4 [1655280422.554769][4382:4387] CHIP:DIS: Discovery does not require any more timeouts [1655280422.557315][4382:4387] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:151302214 on exchange 50662i [1655280422.557357][4382:4387] CHIP:EM: Found matching exchange: 50662i, Delegate: 0xffff6c0011a0 [1655280422.557399][4382:4387] CHIP:EM: Rxd Ack; Removing MessageCounter:68370090 from Retrans Table on exchange 50662i [1655280422.557423][4382:4387] CHIP:EM: Removed CHIP MessageCounter:68370090 from RetransTable on exchange 50662i [1655280422.557460][4382:4387] CHIP:SC: Received Sigma2Resume msg [1655280422.557553][4382:4387] CHIP:SC: Found MRP parameters in the message [1655280422.557585][4382:4387] CHIP:SC: Peer assigned session session ID 14261 [1655280422.563205][4382:4387] CHIP:SC: Sending status report. Protocol code 0, exchange 50662 [1655280422.563290][4382:4387] CHIP:EM: Piggybacking Ack for MessageCounter:151302214 on exchange: 50662i [1655280422.563344][4382:4387] CHIP:IN: Prepared unauthenticated message 0xaaaac86a85e8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 50662i with MessageCounter:68370091. [1655280422.563394][4382:4387] CHIP:IN: Sending unauthenticated msg 0xaaaac86a85e8 with MessageCounter:68370091 to 0x0000000000000000 at monotonic time: 0000000000F2A504 msec [1655280422.563694][4382:4387] CHIP:IN: SecureSession[0xaaaac86a1130]: Activated - Type:2 LSID:13651 [1655280422.563734][4382:4387] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:13651 PSID:14261! [1655280422.563764][4382:4387] CHIP:CTL: OperationalDeviceProxy[113253FC8ABC79A7:0000000000000001]: State change 4 --> 5 [1655280422.563826][4382:4387] CHIP:TOO: Sending ReadAttribute to: [1655280422.563855][4382:4387] CHIP:TOO: cluster 0x0000_0006, attribute: 0x0000_0000, endpoint 1 [1655280422.563902][4382:4387] CHIP:DMG: SendReadRequest ReadClient[0xffff6c002de0]: Sending Read Request [1655280422.564061][4382:4387] CHIP:IN: Prepared secure message 0xaaaac86a8608 to 0x0000000000000001 (1) of type 0x2 and protocolId (0, 1) on exchange 50663i with MessageCounter:183931366. [1655280422.564111][4382:4387] CHIP:IN: Sending encrypted msg 0xaaaac86a8608 with MessageCounter:183931366 to 0x0000000000000001 (1) at monotonic time: 0000000000F2A505 msec [1655280422.564275][4382:4387] CHIP:DMG: MoveToState ReadClient[0xffff6c002de0]: Moving to [AwaitingIn] [1655280422.571836][4382:4387] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:151302215 on exchange 50662i [1655280422.571891][4382:4387] CHIP:EM: Found matching exchange: 50662i, Delegate: (nil) [1655280422.571944][4382:4387] CHIP:EM: Rxd Ack; Removing MessageCounter:68370091 from Retrans Table on exchange 50662i [1655280422.571969][4382:4387] CHIP:EM: Removed CHIP MessageCounter:68370091 from RetransTable on exchange 50662i [1655280422.574371][4382:4387] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:98926842 on exchange 50663i [1655280422.574421][4382:4387] CHIP:EM: Found matching exchange: 50663i, Delegate: 0xffff6c002de0 [1655280422.574497][4382:4387] CHIP:EM: Rxd Ack; Removing MessageCounter:183931366 from Retrans Table on exchange 50663i [1655280422.574521][4382:4387] CHIP:EM: Removed CHIP MessageCounter:183931366 from RetransTable on exchange 50663i [1655280422.574591][4382:4387] CHIP:DMG: ReportDataMessage = [1655280422.574621][4382:4387] CHIP:DMG: { [1655280422.574643][4382:4387] CHIP:DMG: AttributeReportIBs = [1655280422.574675][4382:4387] CHIP:DMG: [ [1655280422.574700][4382:4387] CHIP:DMG: AttributeReportIB = [1655280422.574732][4382:4387] CHIP:DMG: { [1655280422.574758][4382:4387] CHIP:DMG: AttributeDataIB = [1655280422.574794][4382:4387] CHIP:DMG: { [1655280422.574828][4382:4387] CHIP:DMG: DataVersion = 0x1c314b95, [1655280422.574864][4382:4387] CHIP:DMG: AttributePathIB = [1655280422.574902][4382:4387] CHIP:DMG: { [1655280422.574939][4382:4387] CHIP:DMG: Endpoint = 0x1, [1655280422.574979][4382:4387] CHIP:DMG: Cluster = 0x6, [1655280422.575018][4382:4387] CHIP:DMG: Attribute = 0x0000_0000, [1655280422.575055][4382:4387] CHIP:DMG: } [1655280422.575095][4382:4387] CHIP:DMG: [1655280422.575134][4382:4387] CHIP:DMG: Data = false, [1655280422.575169][4382:4387] CHIP:DMG: }, [1655280422.575203][4382:4387] CHIP:DMG: [1655280422.575228][4382:4387] CHIP:DMG: }, [1655280422.575258][4382:4387] CHIP:DMG: [1655280422.575282][4382:4387] CHIP:DMG: ], [1655280422.575312][4382:4387] CHIP:DMG: [1655280422.575337][4382:4387] CHIP:DMG: SuppressResponse = true, [1655280422.575363][4382:4387] CHIP:DMG: InteractionModelRevision = 1[1655280422.575386][4382:4387] CHIP:DMG: } [1655280422.575514][4382:4387] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0006 Attribute 0x0000_0000 DataVersion: 472992661 [1655280422.575565][4382:4387] CHIP:TOO: OnOff: FALSE [1655280422.575669][4382:4387] CHIP:EM: Sending Standalone Ack for MessageCounter:98926842 on exchange 50663i [1655280422.575759][4382:4387] CHIP:IN: Prepared secure message 0xffff7f7ed958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 50663i with MessageCounter:183931367. [1655280422.575804][4382:4387] CHIP:IN: Sending encrypted msg 0xffff7f7ed958 with MessageCounter:183931367 to 0x0000000000000001 (1) at monotonic time: 0000000000F2A511 msec [1655280422.575933][4382:4387] CHIP:EM: Flushed pending ack for MessageCounter:98926842 on exchange 50663i [1655280422.576123][4382:4382] CHIP:CTL: Shutting down the commissioner [1655280422.576163][4382:4382] CHIP:CTL: Shutting down the controller [1655280422.576196][4382:4382] CHIP:CTL: Shutting down the commissioner [1655280422.576218][4382:4382] CHIP:CTL: Shutting down the controller [1655280422.576248][4382:4382] CHIP:IN: Expiring all connections for fabric 1!! [1655280422.576272][4382:4382] CHIP:IN: SecureSession[0xaaaac86a1130]: MarkForRemoval Type:2 LSID:13651 [1655280422.576296][4382:4382] CHIP:IN: SecureSession[0xaaaac86a1130]: Released - Type:2 LSID:13651 [1655280422.576346][4382:4382] CHIP:CTL: Shutting down the commissioner [1655280422.576371][4382:4382] CHIP:CTL: Shutting down the controller [1655280422.576391][4382:4382] CHIP:IN: Expiring all connections for fabric 2!! [1655280422.576426][4382:4382] CHIP:CTL: Shutting down the commissioner [1655280422.576448][4382:4382] CHIP:CTL: Shutting down the controller [1655280422.576468][4382:4382] CHIP:IN: Expiring all connections for fabric 3!! [1655280422.576500][4382:4382] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655280422.577529][4382:4382] CHIP:DMG: IM WH moving to [Uninitialized] [1655280422.577581][4382:4382] CHIP:DMG: IM WH moving to [Uninitialized] [1655280422.577637][4382:4382] CHIP:DMG: IM WH moving to [Uninitialized] [1655280422.577682][4382:4382] CHIP:DMG: IM WH moving to [Uninitialized] [1655280422.577727][4382:4382] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655280422.577840][4382:4382] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655280422.578161][4382:4382] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-jnnlou) [1655280422.579151][4382:4382] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655280422.579240][4382:4382] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655280422.579268][4382:4382] CHIP:DL: Inet Layer shutdown [1655280422.579291][4382:4382] CHIP:DL: BLE shutdown [1655280422.579314][4382:4382] CHIP:DL: System Layer shutdown