Hi,
I'm testing the Matter cluster Scenes in order to develop a device that implements it correctly.
I have this setup:
- One nrf52840dk flashed with the light_bulb using the configuration file prj.conf, whith "CONFIG_CHIP_LIB_SHELL=y" added;
- One Raspberry Pi 4 as Openthread Border Router built from openthread/ot-br-posix github project;
- One nrf52840dk flashed with the openthread/rcp sample, connected to the Border Router;
- CHIP Tool running on Ubuntu LTS 22.04.
I succesfully commissioned the light_bulb device to a Matter fabric using "chip-tool pairing ble-thread" command.
Then i tried to add a scene with "chip-tool scenes add-scene" command, which requires a groupId, so i tried to add the device to a group with "chip-tool groups add-group" command.
luca@luca-desktop:~/connectedhomeip/BUILD_PATH$ ./chip-tool groups add-group 1 prova 76 1
[1666953709.332305][4921:4921] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1666953709.337962][4921:4921] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1666953709.338239][4921:4921] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1666953709.338667][4921:4921] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1666953709.339240][4921:4921] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ilHd1p)
[1666953709.340117][4921:4921] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1666953709.340216][4921:4921] CHIP:DL: NVS set: chip-counters/reboot-count = 33 (0x21)
[1666953709.340832][4921:4921] CHIP:DL: Got Ethernet interface: eth0
[1666953709.341236][4921:4921] CHIP:DL: Found the primary Ethernet interface:eth0
[1666953709.341791][4921:4921] CHIP:DL: Got WiFi interface: wlan0
[1666953709.347775][4921:4921] CHIP:DL: Found the primary WiFi interface:wlan0
[1666953709.347909][4921:4921] CHIP:IN: UDP::Init bind&listen port=0
[1666953709.348026][4921:4921] CHIP:IN: UDP::Init bound to port=36312
[1666953709.348051][4921:4921] CHIP:IN: UDP::Init bind&listen port=0
[1666953709.348183][4921:4921] CHIP:IN: UDP::Init bound to port=57480
[1666953709.348205][4921:4921] CHIP:IN: BLEBase::Init - setting/overriding transport
[1666953709.348225][4921:4921] CHIP:IN: TransportMgr initialized
[1666953709.348257][4921:4921] CHIP:FP: Initializing FabricTable from persistent storage
[1666953709.348408][4921:4921] CHIP:TS: Last Known Good Time: 2022-10-18T09:28:28
[1666953709.350025][4921:4921] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x1BC21A27C76E5D8F, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1666953709.356008][4921:4921] CHIP:ZCL: Using ZAP configuration...
[1666953709.357598][4921:4921] CHIP:DL: MDNS failed to join multicast group on eth0 for address type IPv4: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:761: Inet Error 0x00000110: Address not found
[1666953709.359708][4921:4921] CHIP:CTL: System State Initialized...
[1666953709.360014][4921:4921] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953709.360132][4921:4921] CHIP:CTL: Setting attestation nonce to random value
[1666953709.360249][4921:4921] CHIP:CTL: Setting CSR nonce to random value
[1666953709.360373][4921:4921] CHIP:IN: UDP::Init bind&listen port=5550
[1666953709.360536][4921:4921] CHIP:IN: UDP::Init bound to port=5550
[1666953709.360571][4921:4921] CHIP:IN: UDP::Init bind&listen port=5550
[1666953709.360678][4921:4921] CHIP:IN: UDP::Init bound to port=5550
[1666953709.360711][4921:4921] CHIP:IN: TransportMgr initialized
[1666953709.361532][4921:4926] CHIP:DL: CHIP task running
[1666953709.362412][4921:4926] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953709.362509][4921:4926] CHIP:CTL: Setting attestation nonce to random value
[1666953709.362736][4921:4926] CHIP:CTL: Setting CSR nonce to random value
[1666953709.364108][4921:4926] CHIP:CTL: Generating NOC
[1666953709.365508][4921:4926] CHIP:FP: Validating NOC chain
[1666953709.367916][4921:4926] CHIP:FP: NOC chain validation successful
[1666953709.368161][4921:4926] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1666953709.368203][4921:4926] CHIP:TS: Last Known Good Time: 2022-10-18T09:28:28
[1666953709.368230][4921:4926] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1666953709.368254][4921:4926] CHIP:TS: Retaining current Last Known Good Time
[1666953709.379537][4921:4926] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1666953709.385308][4921:4926] CHIP:TS: Committing Last Known Good Time to storage: 2022-10-18T09:28:28
[1666953709.387453][4921:4926] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1666953709.387519][4921:4926] CHIP:IN: UDP::Init bind&listen port=5550
[1666953709.387641][4921:4926] CHIP:IN: UDP::Init bound to port=5550
[1666953709.387667][4921:4926] CHIP:IN: UDP::Init bind&listen port=5550
[1666953709.387758][4921:4926] CHIP:IN: UDP::Init bound to port=5550
[1666953709.387781][4921:4926] CHIP:IN: TransportMgr initialized
[1666953709.402961][4921:4926] CHIP:TOO: Sending command to node 0x4c
[1666953709.403425][4921:4926] CHIP:CSM: FindOrEstablishSession: PeerId = [1:000000000000004C]
[1666953709.403465][4921:4926] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1666953709.403507][4921:4926] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 1 --> 2
[1666953709.403873][4921:4926] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:409: OS Error 0x02000065: Network is unreachable
[1666953709.404160][4921:4926] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 1 failures.
[1666953709.534884][4921:4926] CHIP:DIS: Lookup clearing interface for non LL address
[1666953709.534982][4921:4926] CHIP:DIS: UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba%wlan0]:5540: new best score: 4
[1666953709.535044][4921:4926] CHIP:DIS: Checking node lookup status after 132 ms
[1666953709.535100][4921:4926] CHIP:DIS: Keeping DNSSD lookup active
[1666953709.603429][4921:4926] CHIP:DIS: Checking node lookup status after 200 ms
[1666953709.603527][4921:4926] CHIP:DIS: OperationalSessionSetup[1:000000000000004C]: Updating device address to UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba]:5540 while in state 2
[1666953709.603573][4921:4926] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 2 --> 3
[1666953709.603739][4921:4926] CHIP:IN: SecureSession[0xffff8800b030]: Allocated Type:2 LSID:48228
[1666953709.603803][4921:4926] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x000000000000004C
[1666953709.605125][4921:4926] CHIP:SC: Including MRP parameters
[1666953709.605344][4921:4926] CHIP:EM: <<< [E:43995i M:148448985] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1666953709.605433][4921:4926] CHIP:IN: (U) Sending msg 148448985 to IP address 'UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba]:5540'
[1666953709.605842][4921:4926] CHIP:SC: Sent Sigma1 msg
[1666953709.605913][4921:4926] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 3 --> 4
[1666953709.630006][4921:4926] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:409: OS Error 0x02000065: Network is unreachable
[1666953709.630525][4921:4926] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 1 failures.
[1666953709.630825][4921:4926] CHIP:DIS: SRV record already actively processed.
[1666953709.630984][4921:4926] CHIP:DIS: SRV record already actively processed.
[1666953709.631323][4921:4926] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:409: OS Error 0x02000065: Network is unreachable
[1666953709.631536][4921:4926] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 1 failures.
[1666953709.842483][4921:4926] CHIP:EM: >>> [E:43995i M:239373057 (Ack:148448985)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953709.842631][4921:4926] CHIP:EM: Found matching exchange: 43995i, Delegate: 0xffff8800ec18
[1666953709.842734][4921:4926] CHIP:EM: Rxd Ack; Removing MessageCounter:148448985 from Retrans Table on exchange 43995i
[1666953710.181842][4921:4926] CHIP:EM: >>> [E:43995i M:239373058 (Ack:148448985)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1666953710.181968][4921:4926] CHIP:EM: Found matching exchange: 43995i, Delegate: 0xffff8800ec18
[1666953710.182038][4921:4926] CHIP:EM: CHIP MessageCounter:148448985 not in RetransTable on exchange 43995i
[1666953710.182145][4921:4926] CHIP:SC: Received Sigma2 msg
[1666953710.182234][4921:4926] CHIP:SC: Peer assigned session session ID 47726
[1666953710.192324][4921:4926] CHIP:SC: Found MRP parameters in the message
[1666953710.192661][4921:4926] CHIP:SC: Sending Sigma3
[1666953710.194159][4921:4926] CHIP:EM: <<< [E:43995i M:148448986 (Ack:239373058)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1666953710.194588][4921:4926] CHIP:IN: (U) Sending msg 148448986 to IP address 'UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba%wlan0]:5540'
[1666953710.195074][4921:4926] CHIP:SC: Sent Sigma3 msg
[1666953710.353013][4921:4926] CHIP:EM: >>> [E:43995i M:239373059 (Ack:148448986)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953710.353088][4921:4926] CHIP:EM: Found matching exchange: 43995i, Delegate: 0xffff8800ec18
[1666953710.353132][4921:4926] CHIP:EM: Rxd Ack; Removing MessageCounter:148448986 from Retrans Table on exchange 43995i
[1666953710.735544][4921:4926] CHIP:EM: >>> [E:43995i M:239373060 (Ack:148448986)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1666953710.735658][4921:4926] CHIP:EM: Found matching exchange: 43995i, Delegate: 0xffff8800ec18
[1666953710.735728][4921:4926] CHIP:EM: CHIP MessageCounter:148448986 not in RetransTable on exchange 43995i
[1666953710.735826][4921:4926] CHIP:SC: Success status report received. Session was established
[1666953710.746481][4921:4926] CHIP:SC: SecureSession[0xffff8800b030]: Moving from state 'kEstablishing' --> 'kActive'
[1666953710.746617][4921:4926] CHIP:IN: SecureSession[0xffff8800b030]: Activated - Type:2 LSID:48228
[1666953710.746943][4921:4926] CHIP:IN: New secure session activated for device <000000000000004C, 1>, LSID:48228 PSID:47726!
[1666953710.747031][4921:4926] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 4 --> 5
[1666953710.747172][4921:4926] CHIP:TOO: Sending cluster (0x00000004) command (0x00000000) on endpoint 1
[1666953710.747318][4921:4926] CHIP:DMG: ICR moving to [AddingComm]
[1666953710.747405][4921:4926] CHIP:DMG: ICR moving to [AddedComma]
[1666953710.747765][4921:4926] CHIP:EM: <<< [E:43996i M:26925266] (S) Msg TX to 1:000000000000004C [5D8F] --- Type 0001:08 (IM:InvokeCommandRequest)
[1666953710.747882][4921:4926] CHIP:IN: (S) Sending msg 26925266 on secure session with LSID: 48228
[1666953710.748401][4921:4926] CHIP:DMG: ICR moving to [CommandSen]
[1666953710.748562][4921:4926] CHIP:EM: <<< [E:43995i M:148448987 (Ack:239373060)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953710.748831][4921:4926] CHIP:IN: (U) Sending msg 148448987 to IP address 'UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba%wlan0]:5540'
[1666953710.748994][4921:4926] CHIP:EM: Flushed pending ack for MessageCounter:239373060 on exchange 43995i
[1666953710.864887][4921:4926] CHIP:EM: >>> [E:43996i M:221331001 (Ack:26925266)] (S) Msg RX from 1:000000000000004C [5D8F] --- Type 0001:09 (IM:InvokeCommandResponse)
[1666953710.865063][4921:4926] CHIP:EM: Found matching exchange: 43996i, Delegate: 0xffff8800a7a8
[1666953710.865160][4921:4926] CHIP:EM: Rxd Ack; Removing MessageCounter:26925266 from Retrans Table on exchange 43996i
[1666953710.865252][4921:4926] CHIP:DMG: ICR moving to [ResponseRe]
[1666953710.865364][4921:4926] CHIP:DMG: InvokeResponseMessage =
[1666953710.865430][4921:4926] CHIP:DMG: {
[1666953710.865491][4921:4926] CHIP:DMG: suppressResponse = false,
[1666953710.865554][4921:4926] CHIP:DMG: InvokeResponseIBs =
[1666953710.865636][4921:4926] CHIP:DMG: [
[1666953710.865766][4921:4926] CHIP:DMG: InvokeResponseIB =
[1666953710.865866][4921:4926] CHIP:DMG: {
[1666953710.865934][4921:4926] CHIP:DMG: CommandDataIB =
[1666953710.866015][4921:4926] CHIP:DMG: {
[1666953710.866100][4921:4926] CHIP:DMG: CommandPathIB =
[1666953710.866186][4921:4926] CHIP:DMG: {
[1666953710.866277][4921:4926] CHIP:DMG: EndpointId = 0x1,
[1666953710.866371][4921:4926] CHIP:DMG: ClusterId = 0x4,
[1666953710.866459][4921:4926] CHIP:DMG: CommandId = 0x0,
[1666953710.866541][4921:4926] CHIP:DMG: },
[1666953710.866628][4921:4926] CHIP:DMG:
[1666953710.866707][4921:4926] CHIP:DMG: CommandFields =
[1666953710.866791][4921:4926] CHIP:DMG: {
[1666953710.866937][4921:4926] CHIP:DMG: 0x0 = 126,
[1666953710.867035][4921:4926] CHIP:DMG: 0x1 = 1,
[1666953710.867125][4921:4926] CHIP:DMG: },
[1666953710.867206][4921:4926] CHIP:DMG: },
[1666953710.867295][4921:4926] CHIP:DMG:
[1666953710.867366][4921:4926] CHIP:DMG: },
[1666953710.867447][4921:4926] CHIP:DMG:
[1666953710.867509][4921:4926] CHIP:DMG: ],
[1666953710.867586][4921:4926] CHIP:DMG:
[1666953710.867647][4921:4926] CHIP:DMG: InteractionModelRevision = 1
[1666953710.867710][4921:4926] CHIP:DMG: },
[1666953710.867854][4921:4926] CHIP:DMG: Received Command Response Data, Endpoint=1 Cluster=0x0000_0004 Command=0x0000_0000
[1666953710.867973][4921:4926] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0004 Command 0x0000_0000
[1666953710.868095][4921:4926] CHIP:TOO: AddGroupResponse: {
[1666953710.868179][4921:4926] CHIP:TOO: status: 126
[1666953710.868239][4921:4926] CHIP:TOO: groupId: 1
[1666953710.868296][4921:4926] CHIP:TOO: }
[1666953710.868386][4921:4926] CHIP:DMG: ICR moving to [AwaitingDe]
[1666953710.868627][4921:4926] CHIP:EM: <<< [E:43996i M:26925267 (Ack:221331001)] (S) Msg TX to 1:000000000000004C [5D8F] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953710.868723][4921:4926] CHIP:IN: (S) Sending msg 26925267 on secure session with LSID: 48228
[1666953710.868995][4921:4926] CHIP:EM: Flushed pending ack for MessageCounter:221331001 on exchange 43996i
[1666953710.869463][4921:4921] CHIP:CTL: Shutting down the commissioner
[1666953710.869543][4921:4921] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953710.869892][4921:4921] CHIP:CTL: Shutting down the controller
[1666953710.869982][4921:4921] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1666953710.870041][4921:4921] CHIP:IN: SecureSession[0xffff8800b030]: MarkForEviction Type:2 LSID:48228
[1666953710.870099][4921:4921] CHIP:SC: SecureSession[0xffff8800b030]: Moving from state 'kActive' --> 'kPendingEviction'
[1666953710.870158][4921:4921] CHIP:IN: SecureSession[0xffff8800b030]: Released - Type:2 LSID:48228
[1666953710.870220][4921:4921] CHIP:FP: Forgetting fabric 0x1
[1666953710.870299][4921:4921] CHIP:TS: Pending Last Known Good Time: 2022-10-18T09:28:28
[1666953710.870582][4921:4921] CHIP:TS: Previous Last Known Good Time: 2022-10-18T09:28:28
[1666953710.870647][4921:4921] CHIP:TS: Reverted Last Known Good Time to previous value
[1666953710.870748][4921:4921] CHIP:CTL: Shutting down the commissioner
[1666953710.870811][4921:4921] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953710.871052][4921:4921] CHIP:CTL: Shutting down the controller
[1666953710.871113][4921:4921] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1666953710.871804][4921:4921] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953710.871865][4921:4921] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953710.871917][4921:4921] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953710.871970][4921:4921] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953710.872027][4921:4921] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1666953710.872264][4921:4921] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1666953710.872367][4921:4921] CHIP:FP: Shutting down FabricTable
[1666953710.872432][4921:4921] CHIP:TS: Pending Last Known Good Time: 2022-10-18T09:28:28
[1666953710.872633][4921:4921] CHIP:TS: Previous Last Known Good Time: 2022-10-18T09:28:28
[1666953710.872695][4921:4921] CHIP:TS: Reverted Last Known Good Time to previous value
[1666953710.873266][4921:4921] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-U7NQcZ)
[1666953710.875163][4921:4921] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1666953710.875336][4921:4921] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1666953710.875403][4921:4921] CHIP:DL: Inet Layer shutdown
[1666953710.875460][4921:4921] CHIP:DL: BLE shutdown
[1666953710.875518][4921:4921] CHIP:DL: System Layer shutdown
As reported above the AddGroupResponse has status 126, which i found as UNSUPPORTED_ACCESS, so i tried to add the grpups cluster of endpoint 1 to the acl attribute of Access Control Cluster of endpoint 0 as follow:
luca@luca-desktop:~/connectedhomeip/BUILD_PATH$ ./chip-tool accesscontrol write acl '[{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects": [112233], "targets": [{"cluster": 4, "endpoint": 1, "deviceType": null}]}]' 76 0
[1666953746.317590][4929:4929] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1666953746.323417][4929:4929] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1666953746.323702][4929:4929] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1666953746.323822][4929:4929] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1666953746.324305][4929:4929] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-BRQtZy)
[1666953746.325025][4929:4929] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1666953746.325093][4929:4929] CHIP:DL: NVS set: chip-counters/reboot-count = 34 (0x22)
[1666953746.325701][4929:4929] CHIP:DL: Got Ethernet interface: eth0
[1666953746.326042][4929:4929] CHIP:DL: Found the primary Ethernet interface:eth0
[1666953746.326403][4929:4929] CHIP:DL: Got WiFi interface: wlan0
[1666953746.332353][4929:4929] CHIP:DL: Found the primary WiFi interface:wlan0
[1666953746.332550][4929:4929] CHIP:IN: UDP::Init bind&listen port=0
[1666953746.332682][4929:4929] CHIP:IN: UDP::Init bound to port=34598
[1666953746.332709][4929:4929] CHIP:IN: UDP::Init bind&listen port=0
[1666953746.332807][4929:4929] CHIP:IN: UDP::Init bound to port=53299
[1666953746.332832][4929:4929] CHIP:IN: BLEBase::Init - setting/overriding transport
[1666953746.332852][4929:4929] CHIP:IN: TransportMgr initialized
[1666953746.332885][4929:4929] CHIP:FP: Initializing FabricTable from persistent storage
[1666953746.333046][4929:4929] CHIP:TS: Last Known Good Time: 2022-10-18T09:28:28
[1666953746.334940][4929:4929] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x1BC21A27C76E5D8F, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1666953746.341514][4929:4929] CHIP:ZCL: Using ZAP configuration...
[1666953746.343379][4929:4929] CHIP:DL: MDNS failed to join multicast group on eth0 for address type IPv4: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:761: Inet Error 0x00000110: Address not found
[1666953746.344949][4929:4929] CHIP:CTL: System State Initialized...
[1666953746.345115][4929:4929] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953746.345240][4929:4929] CHIP:CTL: Setting attestation nonce to random value
[1666953746.345360][4929:4929] CHIP:CTL: Setting CSR nonce to random value
[1666953746.345494][4929:4929] CHIP:IN: UDP::Init bind&listen port=5550
[1666953746.345727][4929:4929] CHIP:IN: UDP::Init bound to port=5550
[1666953746.345771][4929:4929] CHIP:IN: UDP::Init bind&listen port=5550
[1666953746.345898][4929:4929] CHIP:IN: UDP::Init bound to port=5550
[1666953746.345926][4929:4929] CHIP:IN: TransportMgr initialized
[1666953746.346539][4929:4934] CHIP:DL: CHIP task running
[1666953746.347096][4929:4934] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953746.347155][4929:4934] CHIP:CTL: Setting attestation nonce to random value
[1666953746.347355][4929:4934] CHIP:CTL: Setting CSR nonce to random value
[1666953746.348402][4929:4934] CHIP:CTL: Generating NOC
[1666953746.349580][4929:4934] CHIP:FP: Validating NOC chain
[1666953746.351666][4929:4934] CHIP:FP: NOC chain validation successful
[1666953746.351868][4929:4934] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1666953746.351909][4929:4934] CHIP:TS: Last Known Good Time: 2022-10-18T09:28:28
[1666953746.351935][4929:4934] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1666953746.351961][4929:4934] CHIP:TS: Retaining current Last Known Good Time
[1666953746.365120][4929:4934] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1666953746.367614][4929:4934] CHIP:TS: Committing Last Known Good Time to storage: 2022-10-18T09:28:28
[1666953746.369911][4929:4934] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1666953746.369992][4929:4934] CHIP:IN: UDP::Init bind&listen port=5550
[1666953746.370165][4929:4934] CHIP:IN: UDP::Init bound to port=5550
[1666953746.370209][4929:4934] CHIP:IN: UDP::Init bind&listen port=5550
[1666953746.370366][4929:4934] CHIP:IN: UDP::Init bound to port=5550
[1666953746.370405][4929:4934] CHIP:IN: TransportMgr initialized
[1666953746.388927][4929:4934] CHIP:TOO: Sending command to node 0x4c
[1666953746.389422][4929:4934] CHIP:CSM: FindOrEstablishSession: PeerId = [1:000000000000004C]
[1666953746.389455][4929:4934] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1666953746.389495][4929:4934] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 1 --> 2
[1666953746.389888][4929:4934] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:409: OS Error 0x02000065: Network is unreachable
[1666953746.390164][4929:4934] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 1 failures.
[1666953746.474261][4929:4934] CHIP:DIS: Lookup clearing interface for non LL address
[1666953746.474359][4929:4934] CHIP:DIS: UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba%wlan0]:5540: new best score: 4
[1666953746.474425][4929:4934] CHIP:DIS: Checking node lookup status after 85 ms
[1666953746.474481][4929:4934] CHIP:DIS: Keeping DNSSD lookup active
[1666953746.572170][4929:4934] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:409: OS Error 0x02000065: Network is unreachable
[1666953746.572660][4929:4934] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 1 failures.
[1666953746.574640][4929:4934] CHIP:DIS: SRV record already actively processed.
[1666953746.574837][4929:4934] CHIP:DIS: SRV record already actively processed.
[1666953746.575342][4929:4934] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:409: OS Error 0x02000065: Network is unreachable
[1666953746.575712][4929:4934] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 1 failures.
[1666953746.589455][4929:4934] CHIP:DIS: Checking node lookup status after 200 ms
[1666953746.589611][4929:4934] CHIP:DIS: OperationalSessionSetup[1:000000000000004C]: Updating device address to UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba]:5540 while in state 2
[1666953746.589786][4929:4934] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 2 --> 3
[1666953746.590003][4929:4934] CHIP:IN: SecureSession[0xffff9000b030]: Allocated Type:2 LSID:8000
[1666953746.590085][4929:4934] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x000000000000004C
[1666953746.591748][4929:4934] CHIP:SC: Including MRP parameters
[1666953746.592059][4929:4934] CHIP:EM: <<< [E:26020i M:113239298] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1666953746.592168][4929:4934] CHIP:IN: (U) Sending msg 113239298 to IP address 'UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba]:5540'
[1666953746.592515][4929:4934] CHIP:SC: Sent Sigma1 msg
[1666953746.592588][4929:4934] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 3 --> 4
[1666953746.770073][4929:4934] CHIP:EM: >>> [E:26020i M:239373061 (Ack:113239298)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953746.770191][4929:4934] CHIP:EM: Found matching exchange: 26020i, Delegate: 0xffff9000d918
[1666953746.770288][4929:4934] CHIP:EM: Rxd Ack; Removing MessageCounter:113239298 from Retrans Table on exchange 26020i
[1666953747.100407][4929:4934] CHIP:EM: >>> [E:26020i M:239373062 (Ack:113239298)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1666953747.100513][4929:4934] CHIP:EM: Found matching exchange: 26020i, Delegate: 0xffff9000d918
[1666953747.100573][4929:4934] CHIP:EM: CHIP MessageCounter:113239298 not in RetransTable on exchange 26020i
[1666953747.100663][4929:4934] CHIP:SC: Received Sigma2 msg
[1666953747.100737][4929:4934] CHIP:SC: Peer assigned session session ID 47727
[1666953747.110986][4929:4934] CHIP:SC: Found MRP parameters in the message
[1666953747.111117][4929:4934] CHIP:SC: Sending Sigma3
[1666953747.112512][4929:4934] CHIP:EM: <<< [E:26020i M:113239299 (Ack:239373062)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1666953747.112971][4929:4934] CHIP:IN: (U) Sending msg 113239299 to IP address 'UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba%wlan0]:5540'
[1666953747.113429][4929:4934] CHIP:SC: Sent Sigma3 msg
[1666953747.280411][4929:4934] CHIP:EM: >>> [E:26020i M:239373063 (Ack:113239299)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953747.280528][4929:4934] CHIP:EM: Found matching exchange: 26020i, Delegate: 0xffff9000d918
[1666953747.280626][4929:4934] CHIP:EM: Rxd Ack; Removing MessageCounter:113239299 from Retrans Table on exchange 26020i
[1666953747.630008][4929:4934] CHIP:EM: >>> [E:26020i M:239373064 (Ack:113239299)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1666953747.630122][4929:4934] CHIP:EM: Found matching exchange: 26020i, Delegate: 0xffff9000d918
[1666953747.630183][4929:4934] CHIP:EM: CHIP MessageCounter:113239299 not in RetransTable on exchange 26020i
[1666953747.630274][4929:4934] CHIP:SC: Success status report received. Session was established
[1666953747.639928][4929:4934] CHIP:SC: SecureSession[0xffff9000b030]: Moving from state 'kEstablishing' --> 'kActive'
[1666953747.640043][4929:4934] CHIP:IN: SecureSession[0xffff9000b030]: Activated - Type:2 LSID:8000
[1666953747.640095][4929:4934] CHIP:IN: New secure session activated for device <000000000000004C, 1>, LSID:8000 PSID:47727!
[1666953747.640156][4929:4934] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 4 --> 5
[1666953747.640311][4929:4934] CHIP:TOO: cluster 0x0000_001F, attribute: 0x0000_0000, endpoint 0
[1666953747.640458][4929:4934] CHIP:DMG: WriteClient moving to [AddAttribu]
[1666953747.640551][4929:4934] CHIP:DMG: WriteClient moving to [AddAttribu]
[1666953747.640803][4929:4934] CHIP:EM: <<< [E:26021i M:256754090] (S) Msg TX to 1:000000000000004C [5D8F] --- Type 0001:06 (IM:WriteRequest)
[1666953747.640895][4929:4934] CHIP:IN: (S) Sending msg 256754090 on secure session with LSID: 8000
[1666953747.641285][4929:4934] CHIP:DMG: WriteClient moving to [AwaitingRe]
[1666953747.641449][4929:4934] CHIP:EM: <<< [E:26020i M:113239300 (Ack:239373064)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953747.641806][4929:4934] CHIP:IN: (U) Sending msg 113239300 to IP address 'UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba%wlan0]:5540'
[1666953747.642027][4929:4934] CHIP:EM: Flushed pending ack for MessageCounter:239373064 on exchange 26020i
[1666953747.871410][4929:4934] CHIP:EM: >>> [E:26021i M:181252837 (Ack:256754090)] (S) Msg RX from 1:000000000000004C [5D8F] --- Type 0001:07 (IM:WriteResponse)
[1666953747.871530][4929:4934] CHIP:EM: Found matching exchange: 26021i, Delegate: 0xffff9000a7b0
[1666953747.871609][4929:4934] CHIP:EM: Rxd Ack; Removing MessageCounter:256754090 from Retrans Table on exchange 26021i
[1666953747.871683][4929:4934] CHIP:DMG: WriteClient moving to [ResponseRe]
[1666953747.871787][4929:4934] CHIP:DMG: WriteResponseMessage =
[1666953747.871843][4929:4934] CHIP:DMG: {
[1666953747.871890][4929:4934] CHIP:DMG: AttributeStatusIBs =
[1666953747.871957][4929:4934] CHIP:DMG: [
[1666953747.872012][4929:4934] CHIP:DMG: AttributeStatusIB =
[1666953747.872078][4929:4934] CHIP:DMG: {
[1666953747.872136][4929:4934] CHIP:DMG: AttributePathIB =
[1666953747.872205][4929:4934] CHIP:DMG: {
[1666953747.872281][4929:4934] CHIP:DMG: Endpoint = 0x0,
[1666953747.872358][4929:4934] CHIP:DMG: Cluster = 0x1f,
[1666953747.872432][4929:4934] CHIP:DMG: Attribute = 0x0000_0000,
[1666953747.872501][4929:4934] CHIP:DMG: }
[1666953747.872576][4929:4934] CHIP:DMG:
[1666953747.872641][4929:4934] CHIP:DMG: StatusIB =
[1666953747.872712][4929:4934] CHIP:DMG: {
[1666953747.872780][4929:4934] CHIP:DMG: status = 0x00 (SUCCESS),
[1666953747.872847][4929:4934] CHIP:DMG: },
[1666953747.872915][4929:4934] CHIP:DMG:
[1666953747.872975][4929:4934] CHIP:DMG: },
[1666953747.873057][4929:4934] CHIP:DMG:
[1666953747.873110][4929:4934] CHIP:DMG: AttributeStatusIB =
[1666953747.873169][4929:4934] CHIP:DMG: {
[1666953747.873224][4929:4934] CHIP:DMG: AttributePathIB =
[1666953747.873289][4929:4934] CHIP:DMG: {
[1666953747.873359][4929:4934] CHIP:DMG: Endpoint = 0x0,
[1666953747.873438][4929:4934] CHIP:DMG: Cluster = 0x1f,
[1666953747.873510][4929:4934] CHIP:DMG: Attribute = 0x0000_0000,
[1666953747.873579][4929:4934] CHIP:DMG: ListIndex = Null,
[1666953747.873684][4929:4934] CHIP:DMG: }
[1666953747.873772][4929:4934] CHIP:DMG:
[1666953747.873845][4929:4934] CHIP:DMG: StatusIB =
[1666953747.873912][4929:4934] CHIP:DMG: {
[1666953747.873988][4929:4934] CHIP:DMG: status = 0x00 (SUCCESS),
[1666953747.874063][4929:4934] CHIP:DMG: },
[1666953747.874130][4929:4934] CHIP:DMG:
[1666953747.874185][4929:4934] CHIP:DMG: },
[1666953747.874250][4929:4934] CHIP:DMG:
[1666953747.874303][4929:4934] CHIP:DMG: ],
[1666953747.874373][4929:4934] CHIP:DMG:
[1666953747.874426][4929:4934] CHIP:DMG: InteractionModelRevision = 1
[1666953747.874477][4929:4934] CHIP:DMG: }
[1666953747.874682][4929:4934] CHIP:DMG: WriteClient moving to [AwaitingDe]
[1666953747.874908][4929:4934] CHIP:EM: <<< [E:26021i M:256754091 (Ack:181252837)] (S) Msg TX to 1:000000000000004C [5D8F] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953747.874992][4929:4934] CHIP:IN: (S) Sending msg 256754091 on secure session with LSID: 8000
[1666953747.875247][4929:4934] CHIP:EM: Flushed pending ack for MessageCounter:181252837 on exchange 26021i
[1666953747.875617][4929:4929] CHIP:CTL: Shutting down the commissioner
[1666953747.875684][4929:4929] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953747.875933][4929:4929] CHIP:CTL: Shutting down the controller
[1666953747.875991][4929:4929] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1666953747.876041][4929:4929] CHIP:IN: SecureSession[0xffff9000b030]: MarkForEviction Type:2 LSID:8000
[1666953747.876091][4929:4929] CHIP:SC: SecureSession[0xffff9000b030]: Moving from state 'kActive' --> 'kPendingEviction'
[1666953747.876141][4929:4929] CHIP:IN: SecureSession[0xffff9000b030]: Released - Type:2 LSID:8000
[1666953747.876195][4929:4929] CHIP:FP: Forgetting fabric 0x1
[1666953747.876261][4929:4929] CHIP:TS: Pending Last Known Good Time: 2022-10-18T09:28:28
[1666953747.876555][4929:4929] CHIP:TS: Previous Last Known Good Time: 2022-10-18T09:28:28
[1666953747.876614][4929:4929] CHIP:TS: Reverted Last Known Good Time to previous value
[1666953747.876696][4929:4929] CHIP:CTL: Shutting down the commissioner
[1666953747.876746][4929:4929] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953747.876948][4929:4929] CHIP:CTL: Shutting down the controller
[1666953747.876998][4929:4929] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1666953747.877594][4929:4929] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953747.877697][4929:4929] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953747.877745][4929:4929] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953747.877789][4929:4929] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953747.877838][4929:4929] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1666953747.878037][4929:4929] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1666953747.878144][4929:4929] CHIP:FP: Shutting down FabricTable
[1666953747.878203][4929:4929] CHIP:TS: Pending Last Known Good Time: 2022-10-18T09:28:28
[1666953747.878379][4929:4929] CHIP:TS: Previous Last Known Good Time: 2022-10-18T09:28:28
[1666953747.878434][4929:4929] CHIP:TS: Reverted Last Known Good Time to previous value
[1666953747.878938][4929:4929] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-dMG3Eu)
[1666953747.880315][4929:4929] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1666953747.880465][4929:4929] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1666953747.880672][4929:4929] CHIP:DL: Inet Layer shutdown
[1666953747.880724][4929:4929] CHIP:DL: BLE shutdown
[1666953747.880772][4929:4929] CHIP:DL: System Layer shutdown
The response status is 0, so SUCCESS. I expected that this time the "chip-tool groups add-group" command works, but the response status is still 126.
luca@luca-desktop:~/connectedhomeip/BUILD_PATH$ ./chip-tool groups add-group 1 prova 76 1
[1666953753.178154][4935:4935] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1666953753.184055][4935:4935] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1666953753.184456][4935:4935] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1666953753.184603][4935:4935] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1666953753.185063][4935:4935] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-FWzKuc)
[1666953753.185891][4935:4935] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1666953753.185973][4935:4935] CHIP:DL: NVS set: chip-counters/reboot-count = 35 (0x23)
[1666953753.186653][4935:4935] CHIP:DL: Got Ethernet interface: eth0
[1666953753.187060][4935:4935] CHIP:DL: Found the primary Ethernet interface:eth0
[1666953753.187511][4935:4935] CHIP:DL: Got WiFi interface: wlan0
[1666953753.189840][4935:4935] CHIP:DL: Found the primary WiFi interface:wlan0
[1666953753.190003][4935:4935] CHIP:IN: UDP::Init bind&listen port=0
[1666953753.190160][4935:4935] CHIP:IN: UDP::Init bound to port=46629
[1666953753.190195][4935:4935] CHIP:IN: UDP::Init bind&listen port=0
[1666953753.190310][4935:4935] CHIP:IN: UDP::Init bound to port=57414
[1666953753.190339][4935:4935] CHIP:IN: BLEBase::Init - setting/overriding transport
[1666953753.190365][4935:4935] CHIP:IN: TransportMgr initialized
[1666953753.190406][4935:4935] CHIP:FP: Initializing FabricTable from persistent storage
[1666953753.190596][4935:4935] CHIP:TS: Last Known Good Time: 2022-10-18T09:28:28
[1666953753.192523][4935:4935] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x1BC21A27C76E5D8F, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1666953753.195925][4935:4935] CHIP:ZCL: Using ZAP configuration...
[1666953753.197234][4935:4935] CHIP:DL: MDNS failed to join multicast group on eth0 for address type IPv4: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:761: Inet Error 0x00000110: Address not found
[1666953753.198464][4935:4935] CHIP:CTL: System State Initialized...
[1666953753.198542][4935:4935] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953753.198617][4935:4935] CHIP:CTL: Setting attestation nonce to random value
[1666953753.198683][4935:4935] CHIP:CTL: Setting CSR nonce to random value
[1666953753.198761][4935:4935] CHIP:IN: UDP::Init bind&listen port=5550
[1666953753.198868][4935:4935] CHIP:IN: UDP::Init bound to port=5550
[1666953753.198900][4935:4935] CHIP:IN: UDP::Init bind&listen port=5550
[1666953753.198996][4935:4935] CHIP:IN: UDP::Init bound to port=5550
[1666953753.199025][4935:4935] CHIP:IN: TransportMgr initialized
[1666953753.199376][4935:4940] CHIP:DL: CHIP task running
[1666953753.199892][4935:4940] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953753.199945][4935:4940] CHIP:CTL: Setting attestation nonce to random value
[1666953753.200143][4935:4940] CHIP:CTL: Setting CSR nonce to random value
[1666953753.201191][4935:4940] CHIP:CTL: Generating NOC
[1666953753.202376][4935:4940] CHIP:FP: Validating NOC chain
[1666953753.204514][4935:4940] CHIP:FP: NOC chain validation successful
[1666953753.204775][4935:4940] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1666953753.204818][4935:4940] CHIP:TS: Last Known Good Time: 2022-10-18T09:28:28
[1666953753.204846][4935:4940] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1666953753.204872][4935:4940] CHIP:TS: Retaining current Last Known Good Time
[1666953753.217186][4935:4940] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1666953753.219826][4935:4940] CHIP:TS: Committing Last Known Good Time to storage: 2022-10-18T09:28:28
[1666953753.222023][4935:4940] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1666953753.222095][4935:4940] CHIP:IN: UDP::Init bind&listen port=5550
[1666953753.222226][4935:4940] CHIP:IN: UDP::Init bound to port=5550
[1666953753.222251][4935:4940] CHIP:IN: UDP::Init bind&listen port=5550
[1666953753.222333][4935:4940] CHIP:IN: UDP::Init bound to port=5550
[1666953753.222356][4935:4940] CHIP:IN: TransportMgr initialized
[1666953753.238842][4935:4940] CHIP:TOO: Sending command to node 0x4c
[1666953753.239357][4935:4940] CHIP:CSM: FindOrEstablishSession: PeerId = [1:000000000000004C]
[1666953753.239423][4935:4940] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1666953753.239469][4935:4940] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 1 --> 2
[1666953753.240396][4935:4940] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on eth0: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:409: OS Error 0x02000065: Network is unreachable
[1666953753.241334][4935:4940] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 1 failures.
[1666953753.333959][4935:4940] CHIP:DIS: Lookup clearing interface for non LL address
[1666953753.334047][4935:4940] CHIP:DIS: UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba%wlan0]:5540: new best score: 4
[1666953753.334100][4935:4940] CHIP:DIS: Checking node lookup status after 94 ms
[1666953753.334167][4935:4940] CHIP:DIS: Keeping DNSSD lookup active
[1666953753.440614][4935:4940] CHIP:DIS: Checking node lookup status after 200 ms
[1666953753.440762][4935:4940] CHIP:DIS: OperationalSessionSetup[1:000000000000004C]: Updating device address to UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba]:5540 while in state 2
[1666953753.440826][4935:4940] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 2 --> 3
[1666953753.441078][4935:4940] CHIP:IN: SecureSession[0xffff7800b030]: Allocated Type:2 LSID:26909
[1666953753.441179][4935:4940] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x000000000000004C
[1666953753.443174][4935:4940] CHIP:SC: Including MRP parameters
[1666953753.443501][4935:4940] CHIP:EM: <<< [E:45045i M:176804508] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1666953753.443631][4935:4940] CHIP:IN: (U) Sending msg 176804508 to IP address 'UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba]:5540'
[1666953753.444095][4935:4940] CHIP:SC: Sent Sigma1 msg
[1666953753.444243][4935:4940] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 3 --> 4
[1666953753.607129][4935:4940] CHIP:EM: >>> [E:45045i M:239373065 (Ack:176804508)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953753.607252][4935:4940] CHIP:EM: Found matching exchange: 45045i, Delegate: 0xffff7800ec18
[1666953753.607350][4935:4940] CHIP:EM: Rxd Ack; Removing MessageCounter:176804508 from Retrans Table on exchange 45045i
[1666953753.942990][4935:4940] CHIP:EM: >>> [E:45045i M:239373066 (Ack:176804508)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1666953753.943096][4935:4940] CHIP:EM: Found matching exchange: 45045i, Delegate: 0xffff7800ec18
[1666953753.943158][4935:4940] CHIP:EM: CHIP MessageCounter:176804508 not in RetransTable on exchange 45045i
[1666953753.943248][4935:4940] CHIP:SC: Received Sigma2 msg
[1666953753.943324][4935:4940] CHIP:SC: Peer assigned session session ID 47728
[1666953753.953494][4935:4940] CHIP:SC: Found MRP parameters in the message
[1666953753.953841][4935:4940] CHIP:SC: Sending Sigma3
[1666953753.955296][4935:4940] CHIP:EM: <<< [E:45045i M:176804509 (Ack:239373066)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1666953753.955813][4935:4940] CHIP:IN: (U) Sending msg 176804509 to IP address 'UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba%wlan0]:5540'
[1666953753.956384][4935:4940] CHIP:SC: Sent Sigma3 msg
[1666953754.113596][4935:4940] CHIP:EM: >>> [E:45045i M:239373067 (Ack:176804509)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953754.113754][4935:4940] CHIP:EM: Found matching exchange: 45045i, Delegate: 0xffff7800ec18
[1666953754.113852][4935:4940] CHIP:EM: Rxd Ack; Removing MessageCounter:176804509 from Retrans Table on exchange 45045i
[1666953754.457550][4935:4940] CHIP:EM: >>> [E:45045i M:239373068 (Ack:176804509)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1666953754.457735][4935:4940] CHIP:EM: Found matching exchange: 45045i, Delegate: 0xffff7800ec18
[1666953754.457810][4935:4940] CHIP:EM: CHIP MessageCounter:176804509 not in RetransTable on exchange 45045i
[1666953754.457921][4935:4940] CHIP:SC: Success status report received. Session was established
[1666953754.468465][4935:4940] CHIP:SC: SecureSession[0xffff7800b030]: Moving from state 'kEstablishing' --> 'kActive'
[1666953754.468579][4935:4940] CHIP:IN: SecureSession[0xffff7800b030]: Activated - Type:2 LSID:26909
[1666953754.468639][4935:4940] CHIP:IN: New secure session activated for device <000000000000004C, 1>, LSID:26909 PSID:47728!
[1666953754.468934][4935:4940] CHIP:CTL: OperationalSessionSetup[1:000000000000004C]: State change 4 --> 5
[1666953754.469080][4935:4940] CHIP:TOO: Sending cluster (0x00000004) command (0x00000000) on endpoint 1
[1666953754.469214][4935:4940] CHIP:DMG: ICR moving to [AddingComm]
[1666953754.469305][4935:4940] CHIP:DMG: ICR moving to [AddedComma]
[1666953754.469728][4935:4940] CHIP:EM: <<< [E:45046i M:184478176] (S) Msg TX to 1:000000000000004C [5D8F] --- Type 0001:08 (IM:InvokeCommandRequest)
[1666953754.469850][4935:4940] CHIP:IN: (S) Sending msg 184478176 on secure session with LSID: 26909
[1666953754.470373][4935:4940] CHIP:DMG: ICR moving to [CommandSen]
[1666953754.470549][4935:4940] CHIP:EM: <<< [E:45045i M:176804510 (Ack:239373068)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953754.470908][4935:4940] CHIP:IN: (U) Sending msg 176804510 to IP address 'UDP:[fd6c:1211:8162:1:d16b:619d:a9c8:1bba%wlan0]:5540'
[1666953754.471192][4935:4940] CHIP:EM: Flushed pending ack for MessageCounter:239373068 on exchange 45045i
[1666953754.591891][4935:4940] CHIP:EM: >>> [E:45046i M:216369990 (Ack:184478176)] (S) Msg RX from 1:000000000000004C [5D8F] --- Type 0001:09 (IM:InvokeCommandResponse)
[1666953754.592013][4935:4940] CHIP:EM: Found matching exchange: 45046i, Delegate: 0xffff7800a7a8
[1666953754.592112][4935:4940] CHIP:EM: Rxd Ack; Removing MessageCounter:184478176 from Retrans Table on exchange 45046i
[1666953754.592202][4935:4940] CHIP:DMG: ICR moving to [ResponseRe]
[1666953754.592322][4935:4940] CHIP:DMG: InvokeResponseMessage =
[1666953754.592393][4935:4940] CHIP:DMG: {
[1666953754.592456][4935:4940] CHIP:DMG: suppressResponse = false,
[1666953754.592518][4935:4940] CHIP:DMG: InvokeResponseIBs =
[1666953754.592600][4935:4940] CHIP:DMG: [
[1666953754.592663][4935:4940] CHIP:DMG: InvokeResponseIB =
[1666953754.592763][4935:4940] CHIP:DMG: {
[1666953754.592831][4935:4940] CHIP:DMG: CommandDataIB =
[1666953754.592913][4935:4940] CHIP:DMG: {
[1666953754.592999][4935:4940] CHIP:DMG: CommandPathIB =
[1666953754.593089][4935:4940] CHIP:DMG: {
[1666953754.593177][4935:4940] CHIP:DMG: EndpointId = 0x1,
[1666953754.593277][4935:4940] CHIP:DMG: ClusterId = 0x4,
[1666953754.593374][4935:4940] CHIP:DMG: CommandId = 0x0,
[1666953754.593459][4935:4940] CHIP:DMG: },
[1666953754.593548][4935:4940] CHIP:DMG:
[1666953754.593628][4935:4940] CHIP:DMG: CommandFields =
[1666953754.593769][4935:4940] CHIP:DMG: {
[1666953754.593920][4935:4940] CHIP:DMG: 0x0 = 126,
[1666953754.594012][4935:4940] CHIP:DMG: 0x1 = 1,
[1666953754.594111][4935:4940] CHIP:DMG: },
[1666953754.594195][4935:4940] CHIP:DMG: },
[1666953754.594284][4935:4940] CHIP:DMG:
[1666953754.594356][4935:4940] CHIP:DMG: },
[1666953754.594439][4935:4940] CHIP:DMG:
[1666953754.594501][4935:4940] CHIP:DMG: ],
[1666953754.594577][4935:4940] CHIP:DMG:
[1666953754.594640][4935:4940] CHIP:DMG: InteractionModelRevision = 1
[1666953754.594702][4935:4940] CHIP:DMG: },
[1666953754.594846][4935:4940] CHIP:DMG: Received Command Response Data, Endpoint=1 Cluster=0x0000_0004 Command=0x0000_0000
[1666953754.594963][4935:4940] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0004 Command 0x0000_0000
[1666953754.595084][4935:4940] CHIP:TOO: AddGroupResponse: {
[1666953754.595169][4935:4940] CHIP:TOO: status: 126
[1666953754.595230][4935:4940] CHIP:TOO: groupId: 1
[1666953754.595288][4935:4940] CHIP:TOO: }
[1666953754.595378][4935:4940] CHIP:DMG: ICR moving to [AwaitingDe]
[1666953754.595632][4935:4940] CHIP:EM: <<< [E:45046i M:184478177 (Ack:216369990)] (S) Msg TX to 1:000000000000004C [5D8F] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1666953754.595730][4935:4940] CHIP:IN: (S) Sending msg 184478177 on secure session with LSID: 26909
[1666953754.596029][4935:4940] CHIP:EM: Flushed pending ack for MessageCounter:216369990 on exchange 45046i
[1666953754.596526][4935:4935] CHIP:CTL: Shutting down the commissioner
[1666953754.596631][4935:4935] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953754.596920][4935:4935] CHIP:CTL: Shutting down the controller
[1666953754.596990][4935:4935] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1666953754.597048][4935:4935] CHIP:IN: SecureSession[0xffff7800b030]: MarkForEviction Type:2 LSID:26909
[1666953754.597106][4935:4935] CHIP:SC: SecureSession[0xffff7800b030]: Moving from state 'kActive' --> 'kPendingEviction'
[1666953754.597164][4935:4935] CHIP:IN: SecureSession[0xffff7800b030]: Released - Type:2 LSID:26909
[1666953754.597228][4935:4935] CHIP:FP: Forgetting fabric 0x1
[1666953754.597302][4935:4935] CHIP:TS: Pending Last Known Good Time: 2022-10-18T09:28:28
[1666953754.597583][4935:4935] CHIP:TS: Previous Last Known Good Time: 2022-10-18T09:28:28
[1666953754.597709][4935:4935] CHIP:TS: Reverted Last Known Good Time to previous value
[1666953754.597814][4935:4935] CHIP:CTL: Shutting down the commissioner
[1666953754.597874][4935:4935] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1666953754.598121][4935:4935] CHIP:CTL: Shutting down the controller
[1666953754.598180][4935:4935] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1666953754.598874][4935:4935] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953754.598940][4935:4935] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953754.598992][4935:4935] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953754.599043][4935:4935] CHIP:DMG: IM WH moving to [Uninitialized]
[1666953754.599100][4935:4935] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1666953754.599332][4935:4935] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1666953754.599437][4935:4935] CHIP:FP: Shutting down FabricTable
[1666953754.599507][4935:4935] CHIP:TS: Pending Last Known Good Time: 2022-10-18T09:28:28
[1666953754.599712][4935:4935] CHIP:TS: Previous Last Known Good Time: 2022-10-18T09:28:28
[1666953754.599774][4935:4935] CHIP:TS: Reverted Last Known Good Time to previous value
[1666953754.600347][4935:4935] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-O32jOk)
[1666953754.602149][4935:4935] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1666953754.602320][4935:4935] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1666953754.602388][4935:4935] CHIP:DL: Inet Layer shutdown
[1666953754.602443][4935:4935] CHIP:DL: BLE shutdown
[1666953754.602499][4935:4935] CHIP:DL: System Layer shutdown
