ubuntu@ubuntu:~/connectedhomeip/out/chip-tool$ ./chip-tool interactive start [1694587821.233403][19556:19556] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1694587821.235204][19556:19556] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1694587821.235235][19556:19556] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1694587821.235254][19556:19556] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1694587821.235434][19556:19556] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-JKV7eN) [1694587821.235905][19556:19556] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1694587821.235917][19556:19556] CHIP:DL: NVS set: chip-counters/reboot-count = 5 (0x5) [1694587821.236127][19556:19556] CHIP:DL: Got Ethernet interface: enp2s0 [1694587821.236256][19556:19556] CHIP:DL: Found the primary Ethernet interface:enp2s0 [1694587821.236397][19556:19556] CHIP:DL: Got WiFi interface: wlx30de4b67624e [1694587821.236621][19556:19556] CHIP:DL: Found the primary WiFi interface:wlx30de4b67624e [1694587821.236662][19556:19556] CHIP:IN: UDP::Init bind&listen port=0 [1694587821.236684][19556:19556] CHIP:IN: UDP::Init bound to port=45280 [1694587821.236701][19556:19556] CHIP:IN: UDP::Init bind&listen port=0 [1694587821.236729][19556:19556] CHIP:IN: UDP::Init bound to port=52551 [1694587821.236733][19556:19556] CHIP:IN: BLEBase::Init - setting/overriding transport [1694587821.236736][19556:19556] CHIP:IN: TransportMgr initialized [1694587821.236743][19556:19556] CHIP:FP: Initializing FabricTable from persistent storage [1694587821.236847][19556:19556] CHIP:TS: Last Known Good Time: 2023-09-13T14:10:46 [1694587821.237483][19556:19556] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x801790F0A5604F3E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1694587821.238012][19556:19556] CHIP:ZCL: Using ZAP configuration... [1694587821.238768][19556:19556] CHIP:IN: CASE Server enabling CASE session setups [1694587821.238786][19556:19556] CHIP:IN: SecureSession[0x55e7b9c35990]: Allocated Type:2 LSID:37831 [1694587821.238808][19556:19556] CHIP:SC: Allocated SecureSession (0x55e7b9c35990) - waiting for Sigma1 msg [1694587821.238826][19556:19556] CHIP:DIS: Updating services using commissioning mode 0 [1694587821.239539][19556:19556] CHIP:DIS: CHIP minimal mDNS started advertising. [1694587821.240486][19556:19556] CHIP:DL: Using wifi MAC for hostname [1694587821.240493][19556:19556] CHIP:DIS: Advertise operational node 801790F0A5604F3E-000000000001B669 [1694587821.240504][19556:19556] CHIP:DIS: Responding with _matter._tcp.local [1694587821.240507][19556:19556] CHIP:DIS: Responding with 801790F0A5604F3E-000000000001B669._matter._tcp.local [1694587821.240511][19556:19556] CHIP:DIS: Responding with 801790F0A5604F3E-000000000001B669._matter._tcp.local [1694587821.240514][19556:19556] CHIP:DIS: Responding with 1866DA2BAC0C0000.local [1694587821.240517][19556:19556] CHIP:DIS: Responding with 1866DA2BAC0C0000.local [1694587821.240521][19556:19556] CHIP:DIS: Responding with _I801790F0A5604F3E._sub._matter._tcp.local [1694587821.240524][19556:19556] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: 801790F0A5604F3E-000000000001B669. [1694587821.241833][19556:19556] CHIP:DIS: mDNS service published: _matter._tcp [1694587821.241939][19556:19556] CHIP:DL: Using wifi MAC for hostname [1694587821.241976][19556:19556] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=0000/00 cm=0 [1694587821.241998][19556:19556] CHIP:DIS: Responding with _matterd._udp.local [1694587821.242002][19556:19556] CHIP:DIS: Responding with CFA653B817F39375._matterd._udp.local [1694587821.242020][19556:19556] CHIP:DIS: Responding with 1866DA2BAC0C0000.local [1694587821.242023][19556:19556] CHIP:DIS: Responding with 1866DA2BAC0C0000.local [1694587821.242027][19556:19556] CHIP:DIS: Responding with _V65521._sub._matterd._udp.local [1694587821.242033][19556:19556] CHIP:DIS: Responding with CFA653B817F39375._matterd._udp.local [1694587821.242036][19556:19556] CHIP:DIS: CHIP minimal mDNS configured as 'Commissioner device'; instance name: CFA653B817F39375. [1694587821.243500][19556:19556] CHIP:DIS: mDNS service published: _matterd._udp [1694587821.243512][19556:19556] CHIP:CTL: System State Initialized... [1694587821.243542][19556:19556] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1694587821.243551][19556:19556] CHIP:CTL: Setting attestation nonce to random value [1694587821.243575][19556:19556] CHIP:CTL: Setting CSR nonce to random value [1694587821.243601][19556:19556] CHIP:IN: UDP::Init bind&listen port=5550 [1694587821.243616][19556:19556] CHIP:IN: UDP::Init bound to port=5550 [1694587821.243620][19556:19556] CHIP:IN: UDP::Init bind&listen port=5550 [1694587821.243630][19556:19556] CHIP:IN: UDP::Init bound to port=5550 [1694587821.243634][19556:19556] CHIP:IN: TransportMgr initialized [1694587821.243782][19556:19558] CHIP:DL: CHIP task running [1694587821.243898][19556:19558] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1694587821.243905][19556:19558] CHIP:DIS: Updating services using commissioning mode 0 [1694587821.244599][19556:19558] CHIP:DIS: CHIP minimal mDNS started advertising. [1694587821.248022][19556:19558] CHIP:DL: Using wifi MAC for hostname [1694587821.248039][19556:19558] CHIP:DIS: Advertise operational node 801790F0A5604F3E-000000000001B669 [1694587821.248082][19556:19558] CHIP:DIS: Responding with _matter._tcp.local [1694587821.248088][19556:19558] CHIP:DIS: Responding with 801790F0A5604F3E-000000000001B669._matter._tcp.local [1694587821.248109][19556:19558] CHIP:DIS: Responding with 801790F0A5604F3E-000000000001B669._matter._tcp.local [1694587821.248138][19556:19558] CHIP:DIS: Responding with 1866DA2BAC0C0000.local [1694587821.248141][19556:19558] CHIP:DIS: Responding with 1866DA2BAC0C0000.local [1694587821.248146][19556:19558] CHIP:DIS: Responding with _I801790F0A5604F3E._sub._matter._tcp.local [1694587821.248150][19556:19558] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: 801790F0A5604F3E-000000000001B669. [1694587821.249483][19556:19558] CHIP:DIS: mDNS service published: _matter._tcp [1694587821.249631][19556:19558] CHIP:DL: Using wifi MAC for hostname [1694587821.249724][19556:19558] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=0000/00 cm=0 [1694587821.249735][19556:19558] CHIP:DIS: Responding with _matterd._udp.local [1694587821.249738][19556:19558] CHIP:DIS: Responding with CFA653B817F39375._matterd._udp.local [1694587821.249741][19556:19558] CHIP:DIS: Responding with 1866DA2BAC0C0000.local [1694587821.249744][19556:19558] CHIP:DIS: Responding with 1866DA2BAC0C0000.local [1694587821.249760][19556:19558] CHIP:DIS: Responding with _V65521._sub._matterd._udp.local [1694587821.249768][19556:19558] CHIP:DIS: Responding with CFA653B817F39375._matterd._udp.local [1694587821.249772][19556:19558] CHIP:DIS: CHIP minimal mDNS configured as 'Commissioner device'; instance name: CFA653B817F39375. [1694587821.251456][19556:19558] CHIP:DIS: mDNS service published: _matterd._udp >>> accesscontrol write acl '[{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects":[1,112233], "targets": [{ "cluster":31, "endpoint":0, "deviceType":null }]}]' 2 0 [1694587831.009404][19556:19556] CHIP:TOO: Command: accesscontrol write acl [{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects":[1,112233], "targets": [{ "cluster":31, "endpoint":0, "deviceType":null }]}] 2 0 [1694587831.010280][19556:19558] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1694587831.010332][19556:19558] CHIP:CTL: Setting attestation nonce to random value [1694587831.010435][19556:19558] CHIP:CTL: Setting CSR nonce to random value [1694587831.011407][19556:19558] CHIP:CTL: Generating NOC [1694587831.012351][19556:19558] CHIP:FP: Validating NOC chain [1694587831.014026][19556:19558] CHIP:FP: NOC chain validation successful [1694587831.014192][19556:19558] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1694587831.014214][19556:19558] CHIP:TS: Last Known Good Time: 2023-09-13T14:10:46 [1694587831.014228][19556:19558] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1694587831.014240][19556:19558] CHIP:TS: Retaining current Last Known Good Time [1694587831.016010][19556:19558] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1694587831.016368][19556:19558] CHIP:TS: Committing Last Known Good Time to storage: 2023-09-13T14:10:46 [1694587831.016699][19556:19558] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 801790F0A5604F3E) [1694587831.016710][19556:19558] CHIP:IN: UDP::Init bind&listen port=5550 [1694587831.016734][19556:19558] CHIP:IN: UDP::Init bound to port=5550 [1694587831.016739][19556:19558] CHIP:IN: UDP::Init bind&listen port=5550 [1694587831.016754][19556:19558] CHIP:IN: UDP::Init bound to port=5550 [1694587831.016759][19556:19558] CHIP:IN: TransportMgr initialized [1694587831.020300][19556:19558] CHIP:TOO: Sending command to node 0x2 [1694587831.020403][19556:19558] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000002] [1694587831.020411][19556:19558] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1694587831.020421][19556:19558] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: State change 1 --> 2 [1694587831.021046][19556:19558] CHIP:DIS: Lookup clearing interface for non LL address [1694587831.021067][19556:19558] CHIP:DIS: UDP:[2002:ac19:1534:e472:a6e8:fbc2:9aed:dc6a%enp2s0]:5540: new best score: 6 [1694587831.021213][19556:19558] CHIP:DIS: UDP:[fe80::616d:a99b:8505:9b15%enp2s0]:5540: new best score: 7 [1694587831.021225][19556:19558] CHIP:DIS: UDP:192.168.76.37%enp2s0:5540: score has not improved: 2 [1694587831.021229][19556:19558] CHIP:DIS: Checking node lookup status after 1 ms [1694587831.021232][19556:19558] CHIP:DIS: Keeping DNSSD lookup active [1694587831.021420][19556:19558] CHIP:DIS: UDP:[2002:ac19:1534:e472:a6e8:fbc2:9aed:dc6a%enp2s0]:5540: score has not improved: 6 [1694587831.021434][19556:19558] CHIP:DIS: UDP:[fe80::616d:a99b:8505:9b15%enp2s0]:5540: score has not improved: 7 [1694587831.021445][19556:19558] CHIP:DIS: UDP:192.168.76.37%enp2s0:5540: score has not improved: 2 [1694587831.021450][19556:19558] CHIP:DIS: Checking node lookup status after 1 ms [1694587831.021454][19556:19558] CHIP:DIS: Keeping DNSSD lookup active [1694587831.021655][19556:19558] CHIP:DIS: UDP:172.17.0.1%docker0:5540: score has not improved: 2 [1694587831.021668][19556:19558] CHIP:DIS: Checking node lookup status after 1 ms [1694587831.021673][19556:19558] CHIP:DIS: Keeping DNSSD lookup active [1694587831.220994][19556:19558] CHIP:DIS: Checking node lookup status after 200 ms [1694587831.221124][19556:19558] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: Updating device address to UDP:[fe80::616d:a99b:8505:9b15%enp2s0]:5540 while in state 2 [1694587831.221136][19556:19558] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: State change 2 --> 3 [1694587831.221254][19556:19558] CHIP:IN: SecureSession[0x7fb9e000b600]: Allocated Type:2 LSID:37832 [1694587831.221271][19556:19558] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000002 [1694587831.221847][19556:19558] CHIP:EM: <<< [E:24053i S:0 M:145182555] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1694587831.221915][19556:19558] CHIP:IN: (U) Sending msg 145182555 to IP address 'UDP:[fe80::616d:a99b:8505:9b15%enp2s0]:5540' [1694587831.222086][19556:19558] CHIP:SC: Sent Sigma1 msg [1694587831.222095][19556:19558] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: State change 3 --> 4 [1694587831.223863][19556:19558] CHIP:EM: >>> [E:24053i S:0 M:9589639 (Ack:145182555)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1694587831.223881][19556:19558] CHIP:EM: Found matching exchange: 24053i, Delegate: 0x7fb9e000fa28 [1694587831.223893][19556:19558] CHIP:EM: Rxd Ack; Removing MessageCounter:145182555 from Retrans Table on exchange 24053i [1694587831.223908][19556:19558] CHIP:SC: Received Sigma2 msg [1694587831.223925][19556:19558] CHIP:SC: Peer assigned session session ID 26102 [1694587831.225446][19556:19558] CHIP:SC: Sending Sigma3 [1694587831.225660][19556:19558] CHIP:EM: <<< [E:24053i S:0 M:145182556 (Ack:9589639)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1694587831.225706][19556:19558] CHIP:IN: (U) Sending msg 145182556 to IP address 'UDP:[fe80::616d:a99b:8505:9b15%enp2s0]:5540' [1694587831.225771][19556:19558] CHIP:SC: Sent Sigma3 msg [1694587831.228182][19556:19558] CHIP:EM: >>> [E:24053i S:0 M:9589640 (Ack:145182556)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1694587831.228199][19556:19558] CHIP:EM: Found matching exchange: 24053i, Delegate: 0x7fb9e000fa28 [1694587831.228212][19556:19558] CHIP:EM: Rxd Ack; Removing MessageCounter:145182556 from Retrans Table on exchange 24053i [1694587831.228234][19556:19558] CHIP:SC: Success status report received. Session was established [1694587831.229075][19556:19558] CHIP:SC: SecureSession[0x7fb9e000b600, LSID:37832]: State change 'kEstablishing' --> 'kActive' [1694587831.229087][19556:19558] CHIP:IN: SecureSession[0x7fb9e000b600]: Activated - Type:2 LSID:37832 [1694587831.229093][19556:19558] CHIP:IN: New secure session activated for device <0000000000000002, 1>, LSID:37832 PSID:26102! [1694587831.229102][19556:19558] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: State change 4 --> 5 [1694587831.229132][19556:19558] CHIP:TOO: cluster 0x0000_001F, attribute: 0x0000_0000, endpoint 0 [1694587831.229153][19556:19558] CHIP:DMG: WriteClient moving to [AddAttribu] [1694587831.229177][19556:19558] CHIP:DMG: WriteClient moving to [AddAttribu] [1694587831.229215][19556:19558] CHIP:EM: <<< [E:24054i S:37832 M:42081504] (S) Msg TX to 1:0000000000000002 [4F3E] --- Type 0001:06 (IM:WriteRequest) [1694587831.229229][19556:19558] CHIP:IN: (S) Sending msg 42081504 on secure session with LSID: 37832 [1694587831.229277][19556:19558] CHIP:DMG: WriteClient moving to [AwaitingRe] [1694587831.229297][19556:19558] CHIP:EM: <<< [E:24053i S:0 M:145182557 (Ack:9589640)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1694587831.229326][19556:19558] CHIP:IN: (U) Sending msg 145182557 to IP address 'UDP:[fe80::616d:a99b:8505:9b15%enp2s0]:5540' [1694587831.229350][19556:19558] CHIP:EM: Flushed pending ack for MessageCounter:9589640 on exchange 24053i [1694587831.230625][19556:19558] CHIP:EM: >>> [E:24054i S:37832 M:247239269 (Ack:42081504)] (S) Msg RX from 1:0000000000000002 [4F3E] --- Type 0001:07 (IM:WriteResponse) [1694587831.230637][19556:19558] CHIP:EM: Found matching exchange: 24054i, Delegate: 0x7fb9e000a990 [1694587831.230647][19556:19558] CHIP:EM: Rxd Ack; Removing MessageCounter:42081504 from Retrans Table on exchange 24054i [1694587831.230657][19556:19558] CHIP:DMG: WriteClient moving to [ResponseRe] [1694587831.230676][19556:19558] CHIP:DMG: WriteResponseMessage = [1694587831.230683][19556:19558] CHIP:DMG: { [1694587831.230689][19556:19558] CHIP:DMG: AttributeStatusIBs = [1694587831.230698][19556:19558] CHIP:DMG: [ [1694587831.230704][19556:19558] CHIP:DMG: AttributeStatusIB = [1694587831.230710][19556:19558] CHIP:DMG: { [1694587831.230716][19556:19558] CHIP:DMG: AttributePathIB = [1694587831.230723][19556:19558] CHIP:DMG: { [1694587831.230730][19556:19558] CHIP:DMG: Endpoint = 0x0, [1694587831.230738][19556:19558] CHIP:DMG: Cluster = 0x1f, [1694587831.230745][19556:19558] CHIP:DMG: Attribute = 0x0000_0000, [1694587831.230751][19556:19558] CHIP:DMG: } [1694587831.230760][19556:19558] CHIP:DMG: [1694587831.230766][19556:19558] CHIP:DMG: StatusIB = [1694587831.230773][19556:19558] CHIP:DMG: { [1694587831.230779][19556:19558] CHIP:DMG: status = 0x00 (SUCCESS), [1694587831.230786][19556:19558] CHIP:DMG: }, [1694587831.230793][19556:19558] CHIP:DMG: [1694587831.230798][19556:19558] CHIP:DMG: }, [1694587831.230809][19556:19558] CHIP:DMG: [1694587831.230814][19556:19558] CHIP:DMG: AttributeStatusIB = [1694587831.230821][19556:19558] CHIP:DMG: { [1694587831.230826][19556:19558] CHIP:DMG: AttributePathIB = [1694587831.230833][19556:19558] CHIP:DMG: { [1694587831.230839][19556:19558] CHIP:DMG: Endpoint = 0x0, [1694587831.230846][19556:19558] CHIP:DMG: Cluster = 0x1f, [1694587831.230853][19556:19558] CHIP:DMG: Attribute = 0x0000_0000, [1694587831.230860][19556:19558] CHIP:DMG: ListIndex = Null, [1694587831.230866][19556:19558] CHIP:DMG: } [1694587831.230874][19556:19558] CHIP:DMG: [1694587831.230881][19556:19558] CHIP:DMG: StatusIB = [1694587831.230887][19556:19558] CHIP:DMG: { [1694587831.230894][19556:19558] CHIP:DMG: status = 0x00 (SUCCESS), [1694587831.230900][19556:19558] CHIP:DMG: }, [1694587831.230906][19556:19558] CHIP:DMG: [1694587831.230912][19556:19558] CHIP:DMG: }, [1694587831.230920][19556:19558] CHIP:DMG: [1694587831.230926][19556:19558] CHIP:DMG: ], [1694587831.230937][19556:19558] CHIP:DMG: [1694587831.230943][19556:19558] CHIP:DMG: InteractionModelRevision = 1 [1694587831.230949][19556:19558] CHIP:DMG: } [1694587831.230994][19556:19558] CHIP:DMG: WriteClient moving to [AwaitingDe] [1694587831.231028][19556:19558] CHIP:EM: <<< [E:24054i S:37832 M:42081505 (Ack:247239269)] (S) Msg TX to 1:0000000000000002 [4F3E] --- Type 0000:10 (SecureChannel:StandaloneAck) [1694587831.231040][19556:19558] CHIP:IN: (S) Sending msg 42081505 on secure session with LSID: 37832 [1694587831.231068][19556:19558] CHIP:EM: Flushed pending ack for MessageCounter:247239269 on exchange 24054i >>> basicinformation subscribe-event-by-id 0x000 100 1000 2 0 --keepSubscriptions true [1694587839.177489][19556:19556] CHIP:TOO: Command: basicinformation subscribe-event-by-id 0x000 100 1000 2 0 --keepSubscriptions true [1694587839.177898][19556:19558] CHIP:TOO: Sending command to node 0x2 [1694587839.178195][19556:19558] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000002] [1694587839.178221][19556:19558] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1694587839.178254][19556:19558] CHIP:DIS: Found an existing secure session to [1:0000000000000002]! [1694587839.178273][19556:19558] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: State change 1 --> 5 [1694587839.178310][19556:19558] CHIP:TOO: Sending SubscribeEvent to: [1694587839.178329][19556:19558] CHIP:TOO: cluster 0x0000_0028, event: 0x0000_0000, endpoint 0 [1694587839.178475][19556:19558] CHIP:EM: <<< [E:24055i S:37832 M:42081506] (S) Msg TX to 1:0000000000000002 [4F3E] --- Type 0001:03 (IM:SubscribeRequest) [1694587839.178513][19556:19558] CHIP:IN: (S) Sending msg 42081506 on secure session with LSID: 37832 [1694587839.178675][19556:19558] CHIP:DMG: MoveToState ReadClient[0x7fb9e000f670]: Moving to [AwaitingIn] [1694587839.179650][19556:19558] CHIP:EM: >>> [E:24055i S:37832 M:247239270 (Ack:42081506)] (S) Msg RX from 1:0000000000000002 [4F3E] --- Type 0001:01 (IM:StatusResponse) [1694587839.179689][19556:19558] CHIP:EM: Found matching exchange: 24055i, Delegate: 0x7fb9e000f680 [1694587839.179718][19556:19558] CHIP:EM: Rxd Ack; Removing MessageCounter:42081506 from Retrans Table on exchange 24055i [1694587839.179763][19556:19558] CHIP:DMG: StatusResponseMessage = [1694587839.179783][19556:19558] CHIP:DMG: { [1694587839.179799][19556:19558] CHIP:DMG: Status = 0x80 (INVALID_ACTION), [1694587839.179816][19556:19558] CHIP:DMG: InteractionModelRevision = 1 [1694587839.179830][19556:19558] CHIP:DMG: } [1694587839.179849][19556:19558] CHIP:IM: Received status response, status is 0x80 (INVALID_ACTION) [1694587839.179929][19556:19558] CHIP:EM: <<< [E:24055i S:37832 M:42081507 (Ack:247239270)] (S) Msg TX to 1:0000000000000002 [4F3E] --- Type 0001:01 (IM:StatusResponse) [1694587839.179959][19556:19558] CHIP:IN: (S) Sending msg 42081507 on secure session with LSID: 37832 [1694587839.180078][19556:19558] CHIP:DMG: MoveToState ReadClient[0x7fb9e000f670]: Moving to [ Idle] [1694587839.180110][19556:19558] CHIP:TOO: Error: IM Error 0x00000580: General error: 0x80 (INVALID_ACTION) [1694587839.180140][19556:19558] CHIP:TOO: Run command failure: IM Error 0x00000580: General error: 0x80 (INVALID_ACTION) [1694587839.180400][19556:19558] CHIP:EM: >>> [E:24055i S:37832 M:247239271 (Ack:42081507)] (S) Msg RX from 1:0000000000000002 [4F3E] --- Type 0000:10 (SecureChannel:StandaloneAck) [1694587839.180428][19556:19558] CHIP:EM: Found matching exchange: 24055i, Delegate: (nil) [1694587839.180452][19556:19558] CHIP:EM: Rxd Ack; Removing MessageCounter:42081507 from Retrans Table on exchange 24055i >>> accesscontrol write acl '[{"fabricIndex": 1, "privilege": 5, "authMode":2, "subjects":[112233], "targets":null}]' 2 0 [1694587847.777543][19556:19556] CHIP:TOO: Command: accesscontrol write acl [{"fabricIndex": 1, "privilege": 5, "authMode":2, "subjects":[112233], "targets":null}] 2 0 [1694587847.778207][19556:19558] CHIP:TOO: Sending command to node 0x2 [1694587847.778517][19556:19558] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000002] [1694587847.778542][19556:19558] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1694587847.778567][19556:19558] CHIP:DIS: Found an existing secure session to [1:0000000000000002]! [1694587847.778583][19556:19558] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: State change 1 --> 5 [1694587847.778632][19556:19558] CHIP:TOO: cluster 0x0000_001F, attribute: 0x0000_0000, endpoint 0 [1694587847.778682][19556:19558] CHIP:DMG: WriteClient moving to [AddAttribu] [1694587847.778707][19556:19558] CHIP:DMG: WriteClient moving to [AddAttribu] [1694587847.778822][19556:19558] CHIP:EM: <<< [E:24056i S:37832 M:42081508] (S) Msg TX to 1:0000000000000002 [4F3E] --- Type 0001:06 (IM:WriteRequest) [1694587847.778858][19556:19558] CHIP:IN: (S) Sending msg 42081508 on secure session with LSID: 37832 [1694587847.779002][19556:19558] CHIP:DMG: WriteClient moving to [AwaitingRe] [1694587847.782721][19556:19558] CHIP:EM: >>> [E:24056i S:37832 M:247239272 (Ack:42081508)] (S) Msg RX from 1:0000000000000002 [4F3E] --- Type 0001:07 (IM:WriteResponse) [1694587847.782762][19556:19558] CHIP:EM: Found matching exchange: 24056i, Delegate: 0x7fb9e000a990 [1694587847.782791][19556:19558] CHIP:EM: Rxd Ack; Removing MessageCounter:42081508 from Retrans Table on exchange 24056i [1694587847.782820][19556:19558] CHIP:DMG: WriteClient moving to [ResponseRe] [1694587847.782871][19556:19558] CHIP:DMG: WriteResponseMessage = [1694587847.782889][19556:19558] CHIP:DMG: { [1694587847.782903][19556:19558] CHIP:DMG: AttributeStatusIBs = [1694587847.782927][19556:19558] CHIP:DMG: [ [1694587847.782942][19556:19558] CHIP:DMG: AttributeStatusIB = [1694587847.782960][19556:19558] CHIP:DMG: { [1694587847.782975][19556:19558] CHIP:DMG: AttributePathIB = [1694587847.782994][19556:19558] CHIP:DMG: { [1694587847.783012][19556:19558] CHIP:DMG: Endpoint = 0x0, [1694587847.783037][19556:19558] CHIP:DMG: Cluster = 0x1f, [1694587847.783056][19556:19558] CHIP:DMG: Attribute = 0x0000_0000, [1694587847.783073][19556:19558] CHIP:DMG: } [1694587847.783097][19556:19558] CHIP:DMG: [1694587847.783113][19556:19558] CHIP:DMG: StatusIB = [1694587847.783131][19556:19558] CHIP:DMG: { [1694587847.783149][19556:19558] CHIP:DMG: status = 0x00 (SUCCESS), [1694587847.783166][19556:19558] CHIP:DMG: }, [1694587847.783184][19556:19558] CHIP:DMG: [1694587847.783199][19556:19558] CHIP:DMG: }, [1694587847.783229][19556:19558] CHIP:DMG: [1694587847.783244][19556:19558] CHIP:DMG: AttributeStatusIB = [1694587847.783260][19556:19558] CHIP:DMG: { [1694587847.783275][19556:19558] CHIP:DMG: AttributePathIB = [1694587847.783293][19556:19558] CHIP:DMG: { [1694587847.783311][19556:19558] CHIP:DMG: Endpoint = 0x0, [1694587847.783346][19556:19558] CHIP:DMG: Cluster = 0x1f, [1694587847.783366][19556:19558] CHIP:DMG: Attribute = 0x0000_0000, [1694587847.783384][19556:19558] CHIP:DMG: ListIndex = Null, [1694587847.783399][19556:19558] CHIP:DMG: } [1694587847.783422][19556:19558] CHIP:DMG: [1694587847.783440][19556:19558] CHIP:DMG: StatusIB = [1694587847.783457][19556:19558] CHIP:DMG: { [1694587847.783474][19556:19558] CHIP:DMG: status = 0x00 (SUCCESS), [1694587847.783489][19556:19558] CHIP:DMG: }, [1694587847.783506][19556:19558] CHIP:DMG: [1694587847.783523][19556:19558] CHIP:DMG: }, [1694587847.783546][19556:19558] CHIP:DMG: [1694587847.783560][19556:19558] CHIP:DMG: ], [1694587847.783589][19556:19558] CHIP:DMG: [1694587847.783604][19556:19558] CHIP:DMG: InteractionModelRevision = 1 [1694587847.783618][19556:19558] CHIP:DMG: } [1694587847.783729][19556:19558] CHIP:DMG: WriteClient moving to [AwaitingDe] [1694587847.783807][19556:19558] CHIP:EM: <<< [E:24056i S:37832 M:42081509 (Ack:247239272)] (S) Msg TX to 1:0000000000000002 [4F3E] --- Type 0000:10 (SecureChannel:StandaloneAck) [1694587847.783839][19556:19558] CHIP:IN: (S) Sending msg 42081509 on secure session with LSID: 37832 [1694587847.783964][19556:19558] CHIP:EM: Flushed pending ack for MessageCounter:247239272 on exchange 24056i >>> accesscontrol write acl '[{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects": [1234], "targets": null}]' 2 0 [1694587857.793502][19556:19556] CHIP:TOO: Command: accesscontrol write acl [{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects": [1234], "targets": null}] 2 0 [1694587857.794164][19556:19558] CHIP:TOO: Sending command to node 0x2 [1694587857.794459][19556:19558] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000002] [1694587857.794483][19556:19558] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1694587857.794509][19556:19558] CHIP:DIS: Found an existing secure session to [1:0000000000000002]! [1694587857.794525][19556:19558] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: State change 1 --> 5 [1694587857.794579][19556:19558] CHIP:TOO: cluster 0x0000_001F, attribute: 0x0000_0000, endpoint 0 [1694587857.794628][19556:19558] CHIP:DMG: WriteClient moving to [AddAttribu] [1694587857.794658][19556:19558] CHIP:DMG: WriteClient moving to [AddAttribu] [1694587857.794767][19556:19558] CHIP:EM: <<< [E:24057i S:37832 M:42081510] (S) Msg TX to 1:0000000000000002 [4F3E] --- Type 0001:06 (IM:WriteRequest) [1694587857.794803][19556:19558] CHIP:IN: (S) Sending msg 42081510 on secure session with LSID: 37832 [1694587857.794948][19556:19558] CHIP:DMG: WriteClient moving to [AwaitingRe] [1694587857.798657][19556:19558] CHIP:EM: >>> [E:24057i S:37832 M:247239273 (Ack:42081510)] (S) Msg RX from 1:0000000000000002 [4F3E] --- Type 0001:07 (IM:WriteResponse) [1694587857.798700][19556:19558] CHIP:EM: Found matching exchange: 24057i, Delegate: 0x7fb9e000a990 [1694587857.798725][19556:19558] CHIP:EM: Rxd Ack; Removing MessageCounter:42081510 from Retrans Table on exchange 24057i [1694587857.798754][19556:19558] CHIP:DMG: WriteClient moving to [ResponseRe] [1694587857.798804][19556:19558] CHIP:DMG: WriteResponseMessage = [1694587857.798820][19556:19558] CHIP:DMG: { [1694587857.798832][19556:19558] CHIP:DMG: AttributeStatusIBs = [1694587857.798854][19556:19558] CHIP:DMG: [ [1694587857.798869][19556:19558] CHIP:DMG: AttributeStatusIB = [1694587857.798887][19556:19558] CHIP:DMG: { [1694587857.798904][19556:19558] CHIP:DMG: AttributePathIB = [1694587857.798922][19556:19558] CHIP:DMG: { [1694587857.798949][19556:19558] CHIP:DMG: Endpoint = 0x0, [1694587857.798966][19556:19558] CHIP:DMG: Cluster = 0x1f, [1694587857.798982][19556:19558] CHIP:DMG: Attribute = 0x0000_0000, [1694587857.798998][19556:19558] CHIP:DMG: } [1694587857.799024][19556:19558] CHIP:DMG: [1694587857.799041][19556:19558] CHIP:DMG: StatusIB = [1694587857.799058][19556:19558] CHIP:DMG: { [1694587857.799075][19556:19558] CHIP:DMG: status = 0x00 (SUCCESS), [1694587857.799091][19556:19558] CHIP:DMG: }, [1694587857.799109][19556:19558] CHIP:DMG: [1694587857.799127][19556:19558] CHIP:DMG: }, [1694587857.799156][19556:19558] CHIP:DMG: [1694587857.799171][19556:19558] CHIP:DMG: AttributeStatusIB = [1694587857.799187][19556:19558] CHIP:DMG: { [1694587857.799202][19556:19558] CHIP:DMG: AttributePathIB = [1694587857.799219][19556:19558] CHIP:DMG: { [1694587857.799236][19556:19558] CHIP:DMG: Endpoint = 0x0, [1694587857.799254][19556:19558] CHIP:DMG: Cluster = 0x1f, [1694587857.799272][19556:19558] CHIP:DMG: Attribute = 0x0000_0000, [1694587857.799288][19556:19558] CHIP:DMG: ListIndex = Null, [1694587857.799304][19556:19558] CHIP:DMG: } [1694587857.799346][19556:19558] CHIP:DMG: [1694587857.799362][19556:19558] CHIP:DMG: StatusIB = [1694587857.799380][19556:19558] CHIP:DMG: { [1694587857.799397][19556:19558] CHIP:DMG: status = 0x00 (SUCCESS), [1694587857.799413][19556:19558] CHIP:DMG: }, [1694587857.799431][19556:19558] CHIP:DMG: [1694587857.799446][19556:19558] CHIP:DMG: }, [1694587857.799469][19556:19558] CHIP:DMG: [1694587857.799483][19556:19558] CHIP:DMG: ], [1694587857.799512][19556:19558] CHIP:DMG: [1694587857.799527][19556:19558] CHIP:DMG: InteractionModelRevision = 1 [1694587857.799541][19556:19558] CHIP:DMG: } [1694587857.799650][19556:19558] CHIP:DMG: WriteClient moving to [AwaitingDe] [1694587857.799731][19556:19558] CHIP:EM: <<< [E:24057i S:37832 M:42081511 (Ack:247239273)] (S) Msg TX to 1:0000000000000002 [4F3E] --- Type 0000:10 (SecureChannel:StandaloneAck) [1694587857.799766][19556:19558] CHIP:IN: (S) Sending msg 42081511 on secure session with LSID: 37832 [1694587857.799852][19556:19558] CHIP:EM: Flushed pending ack for MessageCounter:247239273 on exchange 24057i >>> any subscribe-event-by-id 0xFFFFFFFF 0xFFFFFFFF 100 1000 2 0xFFFF [1694587865.929658][19556:19556] CHIP:TOO: Command: any subscribe-event-by-id 0xFFFFFFFF 0xFFFFFFFF 100 1000 2 0xFFFF [1694587865.930048][19556:19558] CHIP:TOO: Sending command to node 0x2 [1694587865.930348][19556:19558] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000002] [1694587865.930372][19556:19558] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1694587865.930399][19556:19558] CHIP:DIS: Found an existing secure session to [1:0000000000000002]! [1694587865.930415][19556:19558] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: State change 1 --> 5 [1694587865.930452][19556:19558] CHIP:TOO: Sending SubscribeEvent to: [1694587865.930472][19556:19558] CHIP:TOO: cluster 0xFFFF_FFFF, event: 0xFFFF_FFFF, endpoint 65535 [1694587865.930611][19556:19558] CHIP:EM: <<< [E:24058i S:37832 M:42081512] (S) Msg TX to 1:0000000000000002 [4F3E] --- Type 0001:03 (IM:SubscribeRequest) [1694587865.930648][19556:19558] CHIP:IN: (S) Sending msg 42081512 on secure session with LSID: 37832 [1694587865.930795][19556:19558] CHIP:DMG: MoveToState ReadClient[0x7fb9e0018cd0]: Moving to [AwaitingIn] [1694587865.932880][19556:19558] CHIP:EM: >>> [E:24058i S:37832 M:247239274 (Ack:42081512)] (S) Msg RX from 1:0000000000000002 [4F3E] --- Type 0001:01 (IM:StatusResponse) [1694587865.932911][19556:19558] CHIP:EM: Found matching exchange: 24058i, Delegate: 0x7fb9e0018ce0 [1694587865.932938][19556:19558] CHIP:EM: Rxd Ack; Removing MessageCounter:42081512 from Retrans Table on exchange 24058i [1694587865.932983][19556:19558] CHIP:DMG: StatusResponseMessage = [1694587865.932999][19556:19558] CHIP:DMG: { [1694587865.933017][19556:19558] CHIP:DMG: Status = 0x80 (INVALID_ACTION), [1694587865.933036][19556:19558] CHIP:DMG: InteractionModelRevision = 1 [1694587865.933047][19556:19558] CHIP:DMG: } [1694587865.933065][19556:19558] CHIP:IM: Received status response, status is 0x80 (INVALID_ACTION) [1694587865.933140][19556:19558] CHIP:EM: <<< [E:24058i S:37832 M:42081513 (Ack:247239274)] (S) Msg TX to 1:0000000000000002 [4F3E] --- Type 0001:01 (IM:StatusResponse) [1694587865.933169][19556:19558] CHIP:IN: (S) Sending msg 42081513 on secure session with LSID: 37832 [1694587865.933267][19556:19558] CHIP:DMG: MoveToState ReadClient[0x7fb9e0018cd0]: Moving to [ Idle] [1694587865.933299][19556:19558] CHIP:TOO: Error: IM Error 0x00000580: General error: 0x80 (INVALID_ACTION) [1694587865.933328][19556:19558] CHIP:TOO: Run command failure: IM Error 0x00000580: General error: 0x80 (INVALID_ACTION) [1694587865.933705][19556:19558] CHIP:EM: >>> [E:24058i S:37832 M:247239275 (Ack:42081513)] (S) Msg RX from 1:0000000000000002 [4F3E] --- Type 0000:10 (SecureChannel:StandaloneAck) [1694587865.933731][19556:19558] CHIP:EM: Found matching exchange: 24058i, Delegate: (nil) [1694587865.933756][19556:19558] CHIP:EM: Rxd Ack; Removing MessageCounter:42081513 from Retrans Table on exchange 24058i