Control the group of light bulbs

susepc 22 days ago

Dear Nordic:

I used V2.8.0 SDK to build light bulb, and I have commissioned bulb A(node id: 11) and bulb B(node id: 11) successfully!

Then I used below command to add two bulbs to group successfully:

./chip-tool groups add-group 0x4141 Bulb 11 1
./chip-tool groups add-group 0x4141 Bulb 12 1

Finally, I want to control this group, so I use this command:

./chip-tool onoff on 0xffffffffffff4141 1

But the tool popup error msg, as blow:

user@NB24010009-UB2401:~/Public/PC/CHIP_tool$ ./chip-tool onoff on 0xffffffffffff4141 1
[1747107598.917] [20847:20847] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1747107598.918] [20847:20847] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1747107598.918] [20847:20847] [DL] ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1747107598.919] [20847:20847] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1747107598.919] [20847:20847] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1747107598.919] [20847:20847] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1747107598.919] [20847:20847] [DL] wrote settings to /tmp/chip_counters.ini
[1747107598.919] [20847:20847] [DL] NVS set: chip-counters/reboot-count = 214 (0xD6)
[1747107598.919] [20847:20847] [DL] Got Ethernet interface: enp0s31f6
[1747107598.919] [20847:20847] [DL] Found the primary Ethernet interface:enp0s31f6
[1747107598.919] [20847:20847] [DL] Got WiFi interface: wlp0s20f3
[1747107598.920] [20847:20847] [DL] Found the primary WiFi interface:wlp0s20f3
[1747107598.920] [20847:20847] [IN] UDP::Init bind&listen port=0
[1747107598.920] [20847:20847] [IN] UDP::Init bound to port=36849
[1747107598.920] [20847:20847] [IN] UDP::Init bind&listen port=0
[1747107598.920] [20847:20847] [IN] UDP::Init bound to port=48168
[1747107598.920] [20847:20847] [IN] BLEBase::Init - setting/overriding transport
[1747107598.920] [20847:20847] [IN] TransportMgr initialized
[1747107598.920] [20847:20847] [FP] Initializing FabricTable from persistent storage
[1747107598.920] [20847:20847] [TS] Last Known Good Time: 2023-10-14T01:16:48
[1747107598.920] [20847:20847] [FP] Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xDCA3061115C193DE, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1747107598.926] [20847:20847] [ZCL] Using ZAP configuration...
[1747107598.926] [20847:20847] [DIS] GlobalMinimalMdnsServer::StartServer port(5353)
[1747107598.926] [20847:20847] [DIS] listenUdp Bind: addressType(1), port(5353), interfaceId(3)
[1747107598.926] [20847:20847] [DIS] listenUdp Listen
[1747107598.927] [20847:20847] [DIS] listenUdp Bind: addressType(2), port(5353), interfaceId(3)
[1747107598.927] [20847:20847] [DIS] listenUdp Listen
[1747107598.927] [20847:20847] [CTL] System State Initialized...
[1747107598.927] [20847:20847] [CTL] Setting attestation nonce to random value
[1747107598.927] [20847:20847] [CTL] Setting CSR nonce to random value
[1747107598.927] [20847:20847] [IN] UDP::Init bind&listen port=5550
[1747107598.927] [20847:20847] [IN] UDP::Init bound to port=5550
[1747107598.927] [20847:20847] [IN] UDP::Init bind&listen port=5550
[1747107598.927] [20847:20847] [IN] UDP::Init bound to port=5550
[1747107598.927] [20847:20847] [IN] TransportMgr initialized
[1747107598.927] [20847:20849] [DL] CHIP task running
[1747107598.927] [20847:20849] [DL] HandlePlatformSpecificBLEEvent 32786
[1747107598.927] [20847:20849] [CTL] Setting attestation nonce to random value
[1747107598.927] [20847:20849] [CTL] Setting CSR nonce to random value
[1747107598.927] [20847:20849] [CTL] Generating NOC
[1747107598.927] [20847:20849] [FP] Validating NOC chain
[1747107598.928] [20847:20849] [FP] NOC chain validation successful
[1747107598.928] [20847:20849] [FP] Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1747107598.928] [20847:20849] [TS] Last Known Good Time: 2023-10-14T01:16:48
[1747107598.928] [20847:20849] [TS] New proposed Last Known Good Time: 2021-01-01T00:00:00
[1747107598.928] [20847:20849] [TS] Retaining current Last Known Good Time
[1747107598.928] [20847:20849] [FP] Metadata for Fabric 0x1 persisted to storage.
[1747107598.928] [20847:20849] [TS] Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1747107598.929] [20847:20849] [CTL] Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: DCA3061115C193DE)
[1747107598.929] [20847:20849] [IN] UDP::Init bind&listen port=5550
[1747107598.929] [20847:20849] [IN] UDP::Init bound to port=5550
[1747107598.929] [20847:20849] [IN] UDP::Init bind&listen port=5550
[1747107598.929] [20847:20849] [IN] UDP::Init bound to port=5550
[1747107598.929] [20847:20849] [IN] TransportMgr initialized
[1747107598.931] [20847:20849] [TOO] Sending command to group 0x4141
[1747107598.931] [20847:20849] [TOO] Sending cluster (0x00000006) command (0x00000001) on Group 16705
[1747107598.931] [20847:20849] [DMG] ICR moving to [AddingComm]
[1747107598.931] [20847:20849] [DMG] ICR moving to [AddedComma]
[1747107598.931] [20847:20847] [CTL] Shutting down the commissioner
[1747107598.931] [20847:20847] [CTL] Shutting down the controller
[1747107598.931] [20847:20847] [IN] Expiring all sessions for fabric 0x1!!
[1747107598.931] [20847:20847] [FP] Forgetting fabric 0x1
[1747107598.931] [20847:20847] [TS] Pending Last Known Good Time: 2023-10-14T01:16:48
[1747107598.931] [20847:20847] [TS] Previous Last Known Good Time: 2023-10-14T01:16:48
[1747107598.931] [20847:20847] [TS] Reverted Last Known Good Time to previous value
[1747107598.931] [20847:20847] [CTL] Shutting down the commissioner
[1747107598.931] [20847:20847] [CTL] Shutting down the controller
[1747107598.931] [20847:20847] [CTL] Shutting down the System State, this will teardown the CHIP Stack
[1747107598.931] [20847:20847] [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[1747107598.931] [20847:20847] [FP] Shutting down FabricTable
[1747107598.931] [20847:20847] [TS] Pending Last Known Good Time: 2023-10-14T01:16:48
[1747107598.931] [20847:20847] [TS] Previous Last Known Good Time: 2023-10-14T01:16:48
[1747107598.931] [20847:20847] [TS] Reverted Last Known Good Time to previous value
[1747107598.932] [20847:20847] [DL] wrote settings to /tmp/chip_counters.ini
[1747107598.932] [20847:20847] [DL] NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1747107598.932] [20847:20847] [DL] Inet Layer shutdown
[1747107598.932] [20847:20847] [DL] BLE Layer shutdown
[1747107598.932] [20847:20847] [DL] System Layer shutdown
[1747107598.932] [20847:20847] [TOO] Run command failure: src/transport/SessionManager.cpp:257: CHIP Error 0x000000AC: Internal error

Is there anything wrong, and how can I fix this issue?

Chuan

Parents

0 Marte Myrvold 22 days ago

Hi Chuan,

Can you share the log from chip-tool when you add the devices to the group with add-group?

Best regards,
Marte
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

0 susepc 20 days ago in reply to Marte Myrvold

Marte Myrvold

./chip-tool groups add-group 0x4141 bulb_group 10 1

log as below:

[1747303637.586517][29062:29062] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1747303637.586651][29062:29062] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-cxbIke)
[1747303637.586729][29062:29062] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1747303637.586732][29062:29062] CHIP:DL: NVS set: chip-counters/reboot-count = 250 (0xFA)
[1747303637.586929][29062:29062] CHIP:DL: Got Ethernet interface: enp0s31f6
[1747303637.587102][29062:29062] CHIP:DL: Found the primary Ethernet interface:enp0s31f6
[1747303637.587244][29062:29062] CHIP:DL: Got WiFi interface: wlp0s20f3
[1747303637.587249][29062:29062] CHIP:DL: Failed to reset WiFi statistic counts
[1747303637.587298][29062:29062] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1747303637.587374][29062:29062] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xDCA3061115C193DE, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1747303637.594796][29062:29062] CHIP:ZCL: Using ZAP configuration...
[1747303637.597236][29062:29062] CHIP:DL: Avahi client registered
[1747303637.597315][29062:29062] CHIP:CTL: Setting attestation nonce to random value
[1747303637.597320][29062:29062] CHIP:CTL: Setting CSR nonce to random value
[1747303637.597551][29062:29065] CHIP:CTL: Setting attestation nonce to random value
[1747303637.597559][29062:29065] CHIP:CTL: Setting CSR nonce to random value
[1747303637.599827][29062:29065] CHIP:CTL: Generating NOC
[1747303637.602132][29062:29065] CHIP:FP: Validating NOC chain
[1747303637.608541][29062:29065] CHIP:FP: NOC chain validation successful
[1747303637.608546][29062:29065] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1747303637.608565][29062:29065] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1747303637.608566][29062:29065] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1747303637.608567][29062:29065] CHIP:TS: Retaining current Last Known Good Time
[1747303637.609008][29062:29065] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1747303637.609119][29062:29065] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1747303637.609223][29062:29065] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: DCA3061115C193DE)
[1747303637.610317][29062:29065] CHIP:TOO: Sending command to node 0xb
[1747303637.610428][29062:29065] CHIP:DIS: Resolving DCA3061115C193DE:000000000000000B ...
[1747303637.713260][29062:29065] CHIP:DL: Avahi resolve found
[1747303637.713279][29062:29065] CHIP:DIS: Node ID resolved for DCA3061115C193DE:000000000000000B
[1747303637.713524][29062:29065] CHIP:DIS: UDP:[fd07:7a59:52ac:1:bb3d:28a7:89d8:ea46%enp0s31f6]:5540: new best score: 3
[1747303637.713529][29062:29065] CHIP:DIS: Checking node lookup status after 103 ms
[1747303637.713531][29062:29065] CHIP:DIS: Keeping DNSSD lookup active
[1747303637.811185][29062:29065] CHIP:DIS: Checking node lookup status after 201 ms
[1747303637.811259][29062:29065] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x000000000000000B
[1747303637.813534][29062:29065] CHIP:EM: <<< [E:44109i S:0 M:17910984] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd07:7a59:52ac:1:bb3d:28a7:89d8:ea46]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1747303637.813580][29062:29065] CHIP:SC: Sent Sigma1 msg
[1747303637.860498][29062:29065] CHIP:EM: >>> [E:44109i S:0 M:170964442 (Ack:17910984)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303638.580759][29062:29065] CHIP:EM: >>> [E:44109i S:0 M:170964443 (Ack:17910984)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1747303638.580775][29062:29065] CHIP:SC: Received Sigma2 msg
[1747303638.594393][29062:29065] CHIP:EM: <<< [E:44109i S:0 M:17910985 (Ack:170964443)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd07:7a59:52ac:1:bb3d:28a7:89d8:ea46]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1747303638.594431][29062:29065] CHIP:SC: Sent Sigma3 msg
[1747303638.683614][29062:29065] CHIP:EM: >>> [E:44109i S:0 M:170964444 (Ack:17910985)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303640.167955][29062:29065] CHIP:EM: >>> [E:44109i S:0 M:170964445 (Ack:17910985)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1747303640.167972][29062:29065] CHIP:SC: Success status report received. Session was established
[1747303640.175621][29062:29065] CHIP:SC: SecureSession[0x73f2b000b3d0, LSID:36714]: State change 'kEstablishing' --> 'kActive'
[1747303640.175641][29062:29065] CHIP:TOO: Sending cluster (0x00000004) command (0x00000000) on endpoint 1
[1747303640.175686][29062:29065] CHIP:EM: <<< [E:44110i S:36714 M:103667073] (S) Msg TX to 1:000000000000000B [93DE] [UDP:[fd07:7a59:52ac:1:bb3d:28a7:89d8:ea46]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[1747303640.175722][29062:29065] CHIP:EM: <<< [E:44109i S:0 M:17910986 (Ack:170964445)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd07:7a59:52ac:1:bb3d:28a7:89d8:ea46]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303640.232418][29062:29065] CHIP:EM: >>> [E:44110i S:36714 M:17165740 (Ack:103667073)] (S) Msg RX from 1:000000000000000B [93DE] --- Type 0001:09 (IM:InvokeCommandResponse)
[1747303640.232457][29062:29065] CHIP:DMG: Received Command Response Data, Endpoint=1 Cluster=0x0000_0004 Command=0x0000_0000
[1747303640.232469][29062:29065] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0004 Command 0x0000_0000
[1747303640.232488][29062:29065] CHIP:TOO:   AddGroupResponse: {
[1747303640.232490][29062:29065] CHIP:TOO:     status: 126
[1747303640.232491][29062:29065] CHIP:TOO:     groupID: 16705
[1747303640.232492][29062:29065] CHIP:TOO:    }
[1747303640.232514][29062:29065] CHIP:EM: <<< [E:44110i S:36714 M:103667074 (Ack:17165740)] (S) Msg TX to 1:000000000000000B [93DE] [UDP:[fd07:7a59:52ac:1:bb3d:28a7:89d8:ea46]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303640.232746][29062:29062] CHIP:SC: SecureSession[0x73f2b000b3d0, LSID:36714]: State change 'kActive' --> 'kPendingEviction'
[1747303640.232754][29062:29062] CHIP:FP: Forgetting fabric 0x1
[1747303640.232759][29062:29062] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1747303640.232815][29062:29062] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1747303640.232818][29062:29062] CHIP:TS: Reverted Last Known Good Time to previous value
[1747303640.232893][29062:29062] CHIP:FP: Shutting down FabricTable
[1747303640.232896][29062:29062] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1747303640.232913][29062:29062] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1747303640.232915][29062:29062] CHIP:TS: Reverted Last Known Good Time to previous value
[1747303640.232982][29062:29062] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-fKEUQV)
[1747303640.233142][29062:29062] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1747303640.233162][29062:29062] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1747303640.233165][29062:29062] CHIP:DL: Inet Layer shutdown
[1747303640.233167][29062:29062] CHIP:DL: BLE shutdown
[1747303640.233366][29062:29062] CHIP:DL: System Layer shutdown

0 susepc 20 days ago in reply to susepc

Marte Myrvold

./chip-tool groups add-group 0x4141 bulb_group 11 1

log as below:

[1747303624.331274][29057:29057] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1747303624.331453][29057:29057] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-GWlFQ9)
[1747303624.331544][29057:29057] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1747303624.331547][29057:29057] CHIP:DL: NVS set: chip-counters/reboot-count = 249 (0xF9)
[1747303624.331784][29057:29057] CHIP:DL: Got Ethernet interface: enp0s31f6
[1747303624.331927][29057:29057] CHIP:DL: Found the primary Ethernet interface:enp0s31f6
[1747303624.332096][29057:29057] CHIP:DL: Got WiFi interface: wlp0s20f3
[1747303624.332101][29057:29057] CHIP:DL: Failed to reset WiFi statistic counts
[1747303624.332165][29057:29057] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1747303624.332241][29057:29057] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xDCA3061115C193DE, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1747303624.339143][29057:29057] CHIP:ZCL: Using ZAP configuration...
[1747303624.340848][29057:29057] CHIP:DL: Avahi client registered
[1747303624.340916][29057:29057] CHIP:CTL: Setting attestation nonce to random value
[1747303624.340920][29057:29057] CHIP:CTL: Setting CSR nonce to random value
[1747303624.341137][29057:29060] CHIP:CTL: Setting attestation nonce to random value
[1747303624.341145][29057:29060] CHIP:CTL: Setting CSR nonce to random value
[1747303624.343447][29057:29060] CHIP:CTL: Generating NOC
[1747303624.345897][29057:29060] CHIP:FP: Validating NOC chain
[1747303624.355256][29057:29060] CHIP:FP: NOC chain validation successful
[1747303624.355271][29057:29060] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1747303624.355274][29057:29060] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1747303624.355275][29057:29060] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1747303624.355276][29057:29060] CHIP:TS: Retaining current Last Known Good Time
[1747303624.355702][29057:29060] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1747303624.355822][29057:29060] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1747303624.355929][29057:29060] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: DCA3061115C193DE)
[1747303624.356963][29057:29060] CHIP:TOO: Sending command to node 0xa
[1747303624.357054][29057:29060] CHIP:DIS: Resolving DCA3061115C193DE:000000000000000A ...
[1747303624.459567][29057:29060] CHIP:DL: Avahi resolve found
[1747303624.459589][29057:29060] CHIP:DIS: Node ID resolved for DCA3061115C193DE:000000000000000A
[1747303624.459817][29057:29060] CHIP:DIS: UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4%enp0s31f6]:5540: new best score: 3
[1747303624.459820][29057:29060] CHIP:DIS: Checking node lookup status after 102 ms
[1747303624.459822][29057:29060] CHIP:DIS: Keeping DNSSD lookup active
[1747303624.558306][29057:29060] CHIP:DIS: Checking node lookup status after 201 ms
[1747303624.558360][29057:29060] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x000000000000000A
[1747303624.560649][29057:29060] CHIP:EM: <<< [E:57506i S:0 M:143375449] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1747303624.560701][29057:29060] CHIP:SC: Sent Sigma1 msg
[1747303624.610229][29057:29060] CHIP:EM: >>> [E:57506i S:0 M:9079717 (Ack:143375449)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303625.337281][29057:29060] CHIP:EM: >>> [E:57506i S:0 M:9079718 (Ack:143375449)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1747303625.337303][29057:29060] CHIP:SC: Received Sigma2 msg
[1747303625.351003][29057:29060] CHIP:EM: <<< [E:57506i S:0 M:143375450 (Ack:9079718)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1747303625.351048][29057:29060] CHIP:SC: Sent Sigma3 msg
[1747303625.442285][29057:29060] CHIP:EM: >>> [E:57506i S:0 M:9079719 (Ack:143375450)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303626.934252][29057:29060] CHIP:EM: >>> [E:57506i S:0 M:9079720 (Ack:143375450)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1747303626.934273][29057:29060] CHIP:SC: Success status report received. Session was established
[1747303626.942276][29057:29060] CHIP:SC: SecureSession[0x71b03c00b410, LSID:30593]: State change 'kEstablishing' --> 'kActive'
[1747303626.942298][29057:29060] CHIP:TOO: Sending cluster (0x00000004) command (0x00000000) on endpoint 1
[1747303626.942346][29057:29060] CHIP:EM: <<< [E:57507i S:30593 M:154574839] (S) Msg TX to 1:000000000000000A [93DE] [UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[1747303626.942393][29057:29060] CHIP:EM: <<< [E:57506i S:0 M:143375451 (Ack:9079720)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303627.002042][29057:29060] CHIP:EM: >>> [E:57507i S:30593 M:156903157 (Ack:154574839)] (S) Msg RX from 1:000000000000000A [93DE] --- Type 0001:09 (IM:InvokeCommandResponse)
[1747303627.002092][29057:29060] CHIP:DMG: Received Command Response Data, Endpoint=1 Cluster=0x0000_0004 Command=0x0000_0000
[1747303627.002108][29057:29060] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0004 Command 0x0000_0000
[1747303627.002132][29057:29060] CHIP:TOO:   AddGroupResponse: {
[1747303627.002136][29057:29060] CHIP:TOO:     status: 126
[1747303627.002138][29057:29060] CHIP:TOO:     groupID: 16705
[1747303627.002140][29057:29060] CHIP:TOO:    }
[1747303627.002176][29057:29060] CHIP:EM: <<< [E:57507i S:30593 M:154574840 (Ack:156903157)] (S) Msg TX to 1:000000000000000A [93DE] [UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303627.002385][29057:29057] CHIP:SC: SecureSession[0x71b03c00b410, LSID:30593]: State change 'kActive' --> 'kPendingEviction'
[1747303627.002392][29057:29057] CHIP:FP: Forgetting fabric 0x1
[1747303627.002397][29057:29057] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1747303627.002436][29057:29057] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1747303627.002437][29057:29057] CHIP:TS: Reverted Last Known Good Time to previous value
[1747303627.002495][29057:29057] CHIP:FP: Shutting down FabricTable
[1747303627.002498][29057:29057] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1747303627.002515][29057:29057] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1747303627.002516][29057:29057] CHIP:TS: Reverted Last Known Good Time to previous value
[1747303627.002580][29057:29057] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-BZxQic)
[1747303627.002715][29057:29057] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1747303627.002737][29057:29057] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1747303627.002740][29057:29057] CHIP:DL: Inet Layer shutdown
[1747303627.002742][29057:29057] CHIP:DL: BLE shutdown
[1747303627.002767][29057:29057] CHIP:DL: System Layer shutdown

Reply

0 susepc 20 days ago in reply to susepc

Marte Myrvold

./chip-tool groups add-group 0x4141 bulb_group 11 1

log as below:

[1747303624.331274][29057:29057] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1747303624.331453][29057:29057] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-GWlFQ9)
[1747303624.331544][29057:29057] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1747303624.331547][29057:29057] CHIP:DL: NVS set: chip-counters/reboot-count = 249 (0xF9)
[1747303624.331784][29057:29057] CHIP:DL: Got Ethernet interface: enp0s31f6
[1747303624.331927][29057:29057] CHIP:DL: Found the primary Ethernet interface:enp0s31f6
[1747303624.332096][29057:29057] CHIP:DL: Got WiFi interface: wlp0s20f3
[1747303624.332101][29057:29057] CHIP:DL: Failed to reset WiFi statistic counts
[1747303624.332165][29057:29057] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1747303624.332241][29057:29057] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xDCA3061115C193DE, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1747303624.339143][29057:29057] CHIP:ZCL: Using ZAP configuration...
[1747303624.340848][29057:29057] CHIP:DL: Avahi client registered
[1747303624.340916][29057:29057] CHIP:CTL: Setting attestation nonce to random value
[1747303624.340920][29057:29057] CHIP:CTL: Setting CSR nonce to random value
[1747303624.341137][29057:29060] CHIP:CTL: Setting attestation nonce to random value
[1747303624.341145][29057:29060] CHIP:CTL: Setting CSR nonce to random value
[1747303624.343447][29057:29060] CHIP:CTL: Generating NOC
[1747303624.345897][29057:29060] CHIP:FP: Validating NOC chain
[1747303624.355256][29057:29060] CHIP:FP: NOC chain validation successful
[1747303624.355271][29057:29060] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1747303624.355274][29057:29060] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1747303624.355275][29057:29060] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1747303624.355276][29057:29060] CHIP:TS: Retaining current Last Known Good Time
[1747303624.355702][29057:29060] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1747303624.355822][29057:29060] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1747303624.355929][29057:29060] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: DCA3061115C193DE)
[1747303624.356963][29057:29060] CHIP:TOO: Sending command to node 0xa
[1747303624.357054][29057:29060] CHIP:DIS: Resolving DCA3061115C193DE:000000000000000A ...
[1747303624.459567][29057:29060] CHIP:DL: Avahi resolve found
[1747303624.459589][29057:29060] CHIP:DIS: Node ID resolved for DCA3061115C193DE:000000000000000A
[1747303624.459817][29057:29060] CHIP:DIS: UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4%enp0s31f6]:5540: new best score: 3
[1747303624.459820][29057:29060] CHIP:DIS: Checking node lookup status after 102 ms
[1747303624.459822][29057:29060] CHIP:DIS: Keeping DNSSD lookup active
[1747303624.558306][29057:29060] CHIP:DIS: Checking node lookup status after 201 ms
[1747303624.558360][29057:29060] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x000000000000000A
[1747303624.560649][29057:29060] CHIP:EM: <<< [E:57506i S:0 M:143375449] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1747303624.560701][29057:29060] CHIP:SC: Sent Sigma1 msg
[1747303624.610229][29057:29060] CHIP:EM: >>> [E:57506i S:0 M:9079717 (Ack:143375449)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303625.337281][29057:29060] CHIP:EM: >>> [E:57506i S:0 M:9079718 (Ack:143375449)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1747303625.337303][29057:29060] CHIP:SC: Received Sigma2 msg
[1747303625.351003][29057:29060] CHIP:EM: <<< [E:57506i S:0 M:143375450 (Ack:9079718)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1747303625.351048][29057:29060] CHIP:SC: Sent Sigma3 msg
[1747303625.442285][29057:29060] CHIP:EM: >>> [E:57506i S:0 M:9079719 (Ack:143375450)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303626.934252][29057:29060] CHIP:EM: >>> [E:57506i S:0 M:9079720 (Ack:143375450)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1747303626.934273][29057:29060] CHIP:SC: Success status report received. Session was established
[1747303626.942276][29057:29060] CHIP:SC: SecureSession[0x71b03c00b410, LSID:30593]: State change 'kEstablishing' --> 'kActive'
[1747303626.942298][29057:29060] CHIP:TOO: Sending cluster (0x00000004) command (0x00000000) on endpoint 1
[1747303626.942346][29057:29060] CHIP:EM: <<< [E:57507i S:30593 M:154574839] (S) Msg TX to 1:000000000000000A [93DE] [UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[1747303626.942393][29057:29060] CHIP:EM: <<< [E:57506i S:0 M:143375451 (Ack:9079720)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303627.002042][29057:29060] CHIP:EM: >>> [E:57507i S:30593 M:156903157 (Ack:154574839)] (S) Msg RX from 1:000000000000000A [93DE] --- Type 0001:09 (IM:InvokeCommandResponse)
[1747303627.002092][29057:29060] CHIP:DMG: Received Command Response Data, Endpoint=1 Cluster=0x0000_0004 Command=0x0000_0000
[1747303627.002108][29057:29060] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0004 Command 0x0000_0000
[1747303627.002132][29057:29060] CHIP:TOO:   AddGroupResponse: {
[1747303627.002136][29057:29060] CHIP:TOO:     status: 126
[1747303627.002138][29057:29060] CHIP:TOO:     groupID: 16705
[1747303627.002140][29057:29060] CHIP:TOO:    }
[1747303627.002176][29057:29060] CHIP:EM: <<< [E:57507i S:30593 M:154574840 (Ack:156903157)] (S) Msg TX to 1:000000000000000A [93DE] [UDP:[fd07:7a59:52ac:1:93eb:33fa:ed0:9d4]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1747303627.002385][29057:29057] CHIP:SC: SecureSession[0x71b03c00b410, LSID:30593]: State change 'kActive' --> 'kPendingEviction'
[1747303627.002392][29057:29057] CHIP:FP: Forgetting fabric 0x1
[1747303627.002397][29057:29057] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1747303627.002436][29057:29057] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1747303627.002437][29057:29057] CHIP:TS: Reverted Last Known Good Time to previous value
[1747303627.002495][29057:29057] CHIP:FP: Shutting down FabricTable
[1747303627.002498][29057:29057] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1747303627.002515][29057:29057] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1747303627.002516][29057:29057] CHIP:TS: Reverted Last Known Good Time to previous value
[1747303627.002580][29057:29057] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-BZxQic)
[1747303627.002715][29057:29057] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1747303627.002737][29057:29057] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1747303627.002740][29057:29057] CHIP:DL: Inet Layer shutdown
[1747303627.002742][29057:29057] CHIP:DL: BLE shutdown
[1747303627.002767][29057:29057] CHIP:DL: System Layer shutdown

Children

No Data