Hi,
I'm developing a custom window cover device for Matter and I have a weird issue where Matter packets sometimes seem to take a very long time to go though. Window Cover devices are Matter Sleepy End Devices and also ICD in Thread. So I guess some delay in the packets is normal. But I get something like 10..20 s delay in all commands from Google Home for example. Smart Things seems to be near instant. And the delay can sometimes be smaller in Google Home but it seems to be consistently problematic in some hubs while others seem to be consistently better. I can see the delay also happening in chip-tool for example. I have tried different timing configurations for these conf values:
CONFIG_CHIP_ICD_IDLE_MODE_DURATION=120
CONFIG_CHIP_ICD_ACTIVE_MODE_DURATION=300
CONFIG_CHIP_ICD_SLOW_POLL_INTERVAL=1000
CONFIG_CHIP_ICD_FAST_POLLING_INTERVAL=200
Changing these in normal ways has very little effect. I have not tried setting idle mode to 30000 for example but I'm guessing that would just make things worse or fail completely. Here is a log from chip-tool with these conf values set as shown. I can see commands failing and retransmitted which I guess is causing the delay. But I'm not sure why this would happen as syncing the transmissions to active windows should happen normally as I understand.
>>> windowcovering up-or-open 1 1
[1761039817.667] [8987:8987] [TOO] Command: windowcovering up-or-open 1 1
[1761039817.668] [8987:8989] [CTL] Setting attestation nonce to random value
[1761039817.668] [8987:8989] [CTL] Setting CSR nonce to random value
[1761039817.669] [8987:8989] [CTL] Generating NOC
[1761039817.669] [8987:8989] [FP] Validating NOC chain
[1761039817.671] [8987:8989] [FP] NOC chain validation successful
[1761039817.671] [8987:8989] [FP] Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1761039817.671] [8987:8989] [TS] Last Known Good Time: 2023-10-14T01:16:48
[1761039817.671] [8987:8989] [TS] New proposed Last Known Good Time: 2021-01-01T00:00:00
[1761039817.671] [8987:8989] [TS] Retaining current Last Known Good Time
[1761039817.679] [8987:8989] [FP] Metadata for Fabric 0x1 persisted to storage.
[1761039817.681] [8987:8989] [TS] Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1761039817.683] [8987:8989] [CTL] Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 807DCA3AF139A415)
[1761039817.683] [8987:8989] [IN] UDP::Init bind&listen port=5550
[1761039817.683] [8987:8989] [IN] UDP::Init bound to port=5550
[1761039817.683] [8987:8989] [IN] TransportMgr initialized
[1761039817.683] [8987:8989] [DIS] Updating services using commissioning mode 0
[1761039817.684] [8987:8989] [DL] Using WiFi MAC for hostname
[1761039817.684] [8987:8989] [DIS] Advertise operational node 807DCA3AF139A415-000000000001B669
[1761039817.684] [8987:8989] [DL] PublishService 807DCA3AF139A415-000000000001B669._matter._tcp60752.-1
[1761039817.684] [8987:8989] [DL] Using addresses from interface id=0 name=
[1761039817.689] [8987:8989] [DIS] mDNS service published: _matter._tcp; instance name: 807DCA3AF139A415-000000000001B669
[1761039817.689] [8987:8989] [DL] Using WiFi MAC for hostname
[1761039817.689] [8987:8989] [DIS] Advertise commission parameter vendorID=65521 productID=32769 discriminator=0000/00 cm=0 cp=0
[1761039817.690] [8987:8989] [DL] PublishService 71D691AB3BD1F347._matterd._udp5550.-1
[1761039817.690] [8987:8989] [DL] Using addresses from interface id=0 name=
[1761039817.695] [8987:8989] [DIS] mDNS service published: _matterd._udp; instance name: 71D691AB3BD1F347
[1761039817.705] [8987:8989] [TOO] Sending command to node 0x1
[1761039817.706] [8987:8989] [CSM] FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761039817.706] [8987:8989] [CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761039817.706] [8987:8989] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1761039817.706] [8987:8989] [DIS] Resolving 807DCA3AF139A415:0000000000000001 ...
[1761039817.706] [8987:8989] [DIS] Lookup started for 807DCA3AF139A415-0000000000000001
[1761039817.706] [8987:8989] [DL] Avahi resolve found
[1761039817.706] [8987:8989] [DIS] Node ID resolved for 807DCA3AF139A415-0000000000000001
[1761039817.706] [8987:8989] [DIS] Hostname: D2C947797D7B43B0
[1761039817.706] [8987:8989] [DIS] IP Address #1: fd11:35::2773:5b0f:fcc1:19b5
[1761039817.706] [8987:8989] [DIS] Port: 5540
[1761039817.706] [8987:8989] [DIS] Mrp Interval idle: 3000 ms
[1761039817.706] [8987:8989] [DIS] Mrp Interval active: 2200 ms
[1761039817.706] [8987:8989] [DIS] Mrp Active Threshold: 300 ms
[1761039817.706] [8987:8989] [DIS] TCP Client Supported: 0
[1761039817.706] [8987:8989] [DIS] TCP Server Supported: 0
[1761039817.706] [8987:8989] [DIS] ICD: not present
[1761039817.707] [8987:8989] [DIS] Lookup clearing interface for non LL address
[1761039817.707] [8987:8989] [DIS] UDP:[fd11:35::2773:5b0f:fcc1:19b5%veth3d8e88e]:5540: new best score: 5 (for 807DCA3AF139A415-0000000000000001)
[1761039817.707] [8987:8989] [DIS] Checking node lookup status for 807DCA3AF139A415-0000000000000001 after 1 ms
[1761039817.707] [8987:8989] [DIS] Keeping DNSSD lookup active
[1761039817.906] [8987:8989] [DIS] Checking node lookup status for 807DCA3AF139A415-0000000000000001 after 200 ms
[1761039817.906] [8987:8989] [DIS] OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::2773:5b0f:fcc1:19b5]:5540 while in state 2
[1761039817.906] [8987:8989] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1761039817.906] [8987:8989] [IN] SecureSession[0xffff88008a80]: Allocated Type:2 LSID:54870
[1761039817.906] [8987:8989] [SC] Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1761039817.907] [8987:8989] [EM] <<< [E:55957i S:0 M:37464837] (U) Msg TX from DD40F93712B4BD61 to 0:0000000000000000 [0000] [UDP:[fd11:35::2773:5b0f:fcc1:19b5]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196)
[1761039817.907] [8987:8989] [EM] ??1 [E:55957i S:0 M:37464837] (U) Msg Retransmission to 0:0000000000000000 in 3439ms [State:Idle II:3000 AI:2200 AT:300]
[1761039817.907] [8987:8989] [SC] Sent Sigma1 msg to <0000000000000001, 1> [II:500ms AI:300ms AT:4000ms]
[1761039817.907] [8987:8989] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1761039818.641] [8987:8989] [DL] Avahi group established
[1761039818.648] [8987:8989] [DL] Avahi group established
[1761039821.348] [8987:8989] [EM] <<1 [E:55957i S:0 M:37464837] (U) Msg Retransmission to 0:0000000000000000
[1761039821.348] [8987:8989] [EM] ??2 [E:55957i S:0 M:37464837] (U) Msg Retransmission to 0:0000000000000000 in 4071ms [State:Idle II:3000 AI:2200 AT:300]
[1761039825.423] [8987:8989] [EM] <<2 [E:55957i S:0 M:37464837] (U) Msg Retransmission to 0:0000000000000000
[1761039825.424] [8987:8989] [EM] ??3 [E:55957i S:0 M:37464837] (U) Msg Retransmission to 0:0000000000000000 in 6302ms [State:Idle II:3000 AI:2200 AT:300]
[1761039831.732] [8987:8989] [EM] <<3 [E:55957i S:0 M:37464837] (U) Msg Retransmission to 0:0000000000000000
[1761039831.732] [8987:8989] [EM] ??4 [E:55957i S:0 M:37464837] (U) Msg Retransmission to 0:0000000000000000 in 9712ms [State:Idle II:3000 AI:2200 AT:300]
[1761039834.937] [8987:8989] [EM] >>> [E:55957i S:0 M:22981905 (Ack:37464837)] (U) Msg RX from 0:0000000000000000 [0000] to DD40F93712B4BD61 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1761039834.937] [8987:8989] [EM] Found matching exchange: 55957i, Delegate: 0xffff8800c038
[1761039834.937] [8987:8989] [EM] Rxd Ack; Removing MessageCounter:37464837 from Retrans Table on exchange 55957i
[1761039835.369] [8987:8989] [EM] >>> [E:55957i S:0 M:22981906 (Ack:37464837)] (U) Msg RX from 0:0000000000000000 [0000] to DD40F93712B4BD61 --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:751)
[1761039835.369] [8987:8989] [EM] Found matching exchange: 55957i, Delegate: 0xffff8800c038
[1761039835.369] [8987:8989] [EM] CHIP MessageCounter:37464837 not in RetransTable on exchange 55957i
[1761039835.369] [8987:8989] [SC] Received Sigma2 msg
[1761039835.369] [8987:8989] [SC] Peer assigned session session ID 23696
[1761039835.372] [8987:8989] [SC] Found MRP parameters in the message
[1761039835.372] [8987:8989] [SC] Sending Sigma3
[1761039835.372] [8987:8989] [EM] <<< [E:55957i S:0 M:37464838 (Ack:22981906)] (U) Msg TX from DD40F93712B4BD61 to 0:0000000000000000 [0000] [UDP:[fd11:35::2773:5b0f:fcc1:19b5]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:598)
[1761039835.373] [8987:8989] [EM] ??1 [E:55957i S:0 M:37464838] (U) Msg Retransmission to 0:0000000000000000 in 2735ms [State:Active II:3000 AI:2200 AT:300]
[1761039835.373] [8987:8989] [SC] Sent Sigma3 msg
[1761039835.389] [8987:8989] [EM] >>> [E:55957i S:0 M:22981907 (Ack:37464837)] (U) Msg RX from 0:0000000000000000 [0000] to DD40F93712B4BD61 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1761039835.389] [8987:8989] [EM] Found matching exchange: 55957i, Delegate: 0xffff8800c038
[1761039835.389] [8987:8989] [EM] CHIP MessageCounter:37464837 not in RetransTable on exchange 55957i
[1761039835.413] [8987:8989] [EM] >>> [E:55957i S:0 M:22981908 (Ack:37464837)] (U) Msg RX from 0:0000000000000000 [0000] to DD40F93712B4BD61 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1761039835.413] [8987:8989] [EM] Found matching exchange: 55957i, Delegate: 0xffff8800c038
[1761039835.413] [8987:8989] [EM] CHIP MessageCounter:37464837 not in RetransTable on exchange 55957i
[1761039835.441] [8987:8989] [EM] >>> [E:55957i S:0 M:22981909 (Ack:37464837)] (U) Msg RX from 0:0000000000000000 [0000] to DD40F93712B4BD61 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1761039835.441] [8987:8989] [EM] Found matching exchange: 55957i, Delegate: 0xffff8800c038
[1761039835.441] [8987:8989] [EM] CHIP MessageCounter:37464837 not in RetransTable on exchange 55957i
[1761039835.541] [8987:8989] [EM] >>> [E:55957i S:0 M:22981910 (Ack:37464838)] (U) Msg RX from 0:0000000000000000 [0000] to DD40F93712B4BD61 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1761039835.541] [8987:8989] [EM] Found matching exchange: 55957i, Delegate: 0xffff8800c038
[1761039835.541] [8987:8989] [EM] Rxd Ack; Removing MessageCounter:37464838 from Retrans Table on exchange 55957i
[1761039835.753] [8987:8989] [EM] >>> [E:55957i S:0 M:22981911 (Ack:37464838)] (U) Msg RX from 0:0000000000000000 [0000] to DD40F93712B4BD61 --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
[1761039835.753] [8987:8989] [EM] Found matching exchange: 55957i, Delegate: 0xffff8800c038
[1761039835.753] [8987:8989] [EM] CHIP MessageCounter:37464838 not in RetransTable on exchange 55957i
[1761039835.753] [8987:8989] [SC] Success status report received. Session was established
[1761039835.760] [8987:8989] [SC] SecureSession[0xffff88008a80, LSID:54870]: State change 'kEstablishing' --> 'kActive'
[1761039835.760] [8987:8989] [IN] SecureSession[0xffff88008a80]: Activated - Type:2 LSID:54870
[1761039835.760] [8987:8989] [IN] New secure session activated for device <0000000000000001, 1>, LSID:54870 PSID:23696!
[1761039835.760] [8987:8989] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1761039835.760] [8987:8989] [TOO] Sending cluster (0x00000102) command (0x00000000) on endpoint 1
[1761039835.760] [8987:8989] [DMG] ICR moving to [AddingComm]
[1761039835.760] [8987:8989] [DMG] ICR moving to [AddedComma]
[1761039835.761] [8987:8989] [EM] <<< [E:55958i S:54870 M:132777164] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [A415] [UDP:[fd11:35::2773:5b0f:fcc1:19b5]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) (B:60)
[1761039835.761] [8987:8989] [EM] ??1 [E:55958i S:54870 M:132777164] (S) Msg Retransmission to 1:0000000000000001 in 2721ms [State:Active II:3000 AI:2200 AT:300]
[1761039835.761] [8987:8989] [DMG] ICR moving to [AwaitingRe]
[1761039835.761] [8987:8989] [EM] <<< [E:55957i S:0 M:37464839 (Ack:22981911)] (U) Msg TX from DD40F93712B4BD61 to 0:0000000000000000 [0000] [UDP:[fd11:35::2773:5b0f:fcc1:19b5]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1761039835.761] [8987:8989] [EM] Flushed pending ack for MessageCounter:22981911 on exchange 55957i
[1761039835.761] [8987:8989] [DL] HandlePlatformSpecificBLEEvent 32792
[1761039835.958] [8987:8989] [EM] >>> [E:55958i S:54870 M:165782688 (Ack:132777164)] (S) Msg RX from 1:0000000000000001 [A415] to 000000000001B669 --- Type 0001:09 (IM:InvokeCommandResponse) (B:68)
[1761039835.958] [8987:8989] [EM] Found matching exchange: 55958i, Delegate: 0xffff880081c8
[1761039835.958] [8987:8989] [EM] Rxd Ack; Removing MessageCounter:132777164 from Retrans Table on exchange 55958i
[1761039835.958] [8987:8989] [DMG] ICR moving to [ResponseRe]
[1761039835.958] [8987:8989] [DMG] InvokeResponseMessage =
[1761039835.958] [8987:8989] [DMG] {
[1761039835.958] [8987:8989] [DMG] suppressResponse = false,
[1761039835.958] [8987:8989] [DMG] InvokeResponseIBs =
[1761039835.958] [8987:8989] [DMG] [
[1761039835.958] [8987:8989] [DMG] InvokeResponseIB =
[1761039835.958] [8987:8989] [DMG] {
[1761039835.958] [8987:8989] [DMG] CommandStatusIB =
[1761039835.958] [8987:8989] [DMG] {
[1761039835.958] [8987:8989] [DMG] CommandPathIB =
[1761039835.958] [8987:8989] [DMG] {
[1761039835.958] [8987:8989] [DMG] EndpointId = 0x1,
[1761039835.958] [8987:8989] [DMG] ClusterId = 0x102,
[1761039835.958] [8987:8989] [DMG] CommandId = 0x0,
[1761039835.958] [8987:8989] [DMG] },
[1761039835.958] [8987:8989] [DMG]
[1761039835.958] [8987:8989] [DMG] StatusIB =
[1761039835.958] [8987:8989] [DMG] {
[1761039835.958] [8987:8989] [DMG] status = 0x00 (SUCCESS),
[1761039835.958] [8987:8989] [DMG] },
[1761039835.958] [8987:8989] [DMG]
[1761039835.958] [8987:8989] [DMG] },
[1761039835.958] [8987:8989] [DMG]
[1761039835.958] [8987:8989] [DMG] },
[1761039835.958] [8987:8989] [DMG]
[1761039835.958] [8987:8989] [DMG] ],
[1761039835.958] [8987:8989] [DMG]
[1761039835.958] [8987:8989] [DMG] InteractionModelRevision = 12
[1761039835.958] [8987:8989] [DMG] },
[1761039835.958] [8987:8989] [DMG] Received Command Response Status for Endpoint=1 Cluster=0x0000_0102 Command=0x0000_0000 Status=0x0
[1761039835.958] [8987:8989] [DMG] ICR moving to [AwaitingDe]
[1761039835.958] [8987:8989] [EM] <<< [E:55958i S:54870 M:132777165 (Ack:165782688)] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [A415] [UDP:[fd11:35::2773:5b0f:fcc1:19b5]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1761039835.958] [8987:8989] [EM] Flushed pending ack for MessageCounter:165782688 on exchange 55958i
>>> windowcovering down-or-close 1 1
[1761039846.620] [8987:8987] [TOO] Command: windowcovering down-or-close 1 1
[1761039846.620] [8987:8989] [TOO] Sending command to node 0x1
[1761039846.620] [8987:8989] [CSM] FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761039846.620] [8987:8989] [CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761039846.620] [8987:8989] [DIS] Found an existing secure session to [1:0000000000000001]!
[1761039846.620] [8987:8989] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5
[1761039846.620] [8987:8989] [TOO] Sending cluster (0x00000102) command (0x00000001) on endpoint 1
[1761039846.620] [8987:8989] [DMG] ICR moving to [AddingComm]
[1761039846.620] [8987:8989] [DMG] ICR moving to [AddedComma]
[1761039846.620] [8987:8989] [EM] <<< [E:55959i S:54870 M:132777166] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [A415] [UDP:[fd11:35::2773:5b0f:fcc1:19b5]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) (B:60)
[1761039846.621] [8987:8989] [EM] ??1 [E:55959i S:54870 M:132777166] (S) Msg Retransmission to 1:0000000000000001 in 3433ms [State:Idle II:3000 AI:2200 AT:300]
[1761039846.621] [8987:8989] [DMG] ICR moving to [AwaitingRe]
[1761039850.057] [8987:8989] [EM] <<1 [E:55959i S:54870 M:132777166] (S) Msg Retransmission to 1:0000000000000001
[1761039850.057] [8987:8989] [EM] ??2 [E:55959i S:54870 M:132777166] (S) Msg Retransmission to 1:0000000000000001 in 3417ms [State:Idle II:3000 AI:2200 AT:300]
[1761039853.478] [8987:8989] [EM] <<2 [E:55959i S:54870 M:132777166] (S) Msg Retransmission to 1:0000000000000001
[1761039853.478] [8987:8989] [EM] ??3 [E:55959i S:54870 M:132777166] (S) Msg Retransmission to 1:0000000000000001 in 6420ms [State:Idle II:3000 AI:2200 AT:300]
[1761039855.522] [8987:8989] [EM] >>> [E:55959i S:54870 M:165782689 (Ack:132777166)] (S) Msg RX from 1:0000000000000001 [A415] to 000000000001B669 --- Type 0001:09 (IM:InvokeCommandResponse) (B:68)
[1761039855.522] [8987:8989] [EM] Found matching exchange: 55959i, Delegate: 0xffff880081c8
[1761039855.522] [8987:8989] [EM] Rxd Ack; Removing MessageCounter:132777166 from Retrans Table on exchange 55959i
[1761039855.522] [8987:8989] [DMG] ICR moving to [ResponseRe]
[1761039855.522] [8987:8989] [DMG] InvokeResponseMessage =
[1761039855.522] [8987:8989] [DMG] {
[1761039855.522] [8987:8989] [DMG] suppressResponse = false,
[1761039855.522] [8987:8989] [DMG] InvokeResponseIBs =
[1761039855.522] [8987:8989] [DMG] [
[1761039855.522] [8987:8989] [DMG] InvokeResponseIB =
[1761039855.522] [8987:8989] [DMG] {
[1761039855.522] [8987:8989] [DMG] CommandStatusIB =
[1761039855.522] [8987:8989] [DMG] {
[1761039855.522] [8987:8989] [DMG] CommandPathIB =
[1761039855.522] [8987:8989] [DMG] {
[1761039855.522] [8987:8989] [DMG] EndpointId = 0x1,
[1761039855.522] [8987:8989] [DMG] ClusterId = 0x102,
[1761039855.522] [8987:8989] [DMG] CommandId = 0x1,
[1761039855.522] [8987:8989] [DMG] },
[1761039855.522] [8987:8989] [DMG]
[1761039855.522] [8987:8989] [DMG] StatusIB =
[1761039855.522] [8987:8989] [DMG] {
[1761039855.522] [8987:8989] [DMG] status = 0x00 (SUCCESS),
[1761039855.522] [8987:8989] [DMG] },
[1761039855.522] [8987:8989] [DMG]
[1761039855.522] [8987:8989] [DMG] },
[1761039855.522] [8987:8989] [DMG]
[1761039855.522] [8987:8989] [DMG] },
[1761039855.522] [8987:8989] [DMG]
[1761039855.522] [8987:8989] [DMG] ],
[1761039855.522] [8987:8989] [DMG]
[1761039855.522] [8987:8989] [DMG] InteractionModelRevision = 12
[1761039855.522] [8987:8989] [DMG] },
[1761039855.522] [8987:8989] [DMG] Received Command Response Status for Endpoint=1 Cluster=0x0000_0102 Command=0x0000_0001 Status=0x0
[1761039855.522] [8987:8989] [DMG] ICR moving to [AwaitingDe]
[1761039855.522] [8987:8989] [EM] <<< [E:55959i S:54870 M:132777167 (Ack:165782689)] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [A415] [UDP:[fd11:35::2773:5b0f:fcc1:19b5]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1761039855.522] [8987:8989] [EM] Flushed pending ack for MessageCounter:165782689 on exchange 55959i
[1761039855.564] [8987:8989] [EM] >>> [E:55959i S:54870 M:165782690 (Ack:132777166)] (S) Msg RX from 1:0000000000000001 [A415] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1761039855.590] [8987:8989] [EM] >>> [E:55959i S:54870 M:165782691 (Ack:132777166)] (S) Msg RX from 1:0000000000000001 [A415] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
>>> windowcovering down-or-close 1 1
[1761040000.733] [8987:8987] [TOO] Command: windowcovering down-or-close 1 1
[1761040000.734] [8987:8989] [TOO] Sending command to node 0x1
[1761040000.734] [8987:8989] [CSM] FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761040000.734] [8987:8989] [CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761040000.734] [8987:8989] [DIS] Found an existing secure session to [1:0000000000000001]!
[1761040000.734] [8987:8989] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5
[1761040000.734] [8987:8989] [TOO] Sending cluster (0x00000102) command (0x00000001) on endpoint 1
[1761040000.734] [8987:8989] [DMG] ICR moving to [AddingComm]
[1761040000.734] [8987:8989] [DMG] ICR moving to [AddedComma]
[1761040000.734] [8987:8989] [EM] <<< [E:55960i S:54870 M:132777168] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [A415] [UDP:[fd11:35::2773:5b0f:fcc1:19b5]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) (B:60)
[1761040000.735] [8987:8989] [EM] ??1 [E:55960i S:54870 M:132777168] (S) Msg Retransmission to 1:0000000000000001 in 3739ms [State:Idle II:3000 AI:2200 AT:300]
[1761040000.735] [8987:8989] [DMG] ICR moving to [AwaitingRe]
[1761040004.477] [8987:8989] [EM] <<1 [E:55960i S:54870 M:132777168] (S) Msg Retransmission to 1:0000000000000001
[1761040004.477] [8987:8989] [EM] ??2 [E:55960i S:54870 M:132777168] (S) Msg Retransmission to 1:0000000000000001 in 3755ms [State:Idle II:3000 AI:2200 AT:300]
[1761040008.236] [8987:8989] [EM] <<2 [E:55960i S:54870 M:132777168] (S) Msg Retransmission to 1:0000000000000001
[1761040008.236] [8987:8989] [EM] ??3 [E:55960i S:54870 M:132777168] (S) Msg Retransmission to 1:0000000000000001 in 6477ms [State:Idle II:3000 AI:2200 AT:300]
[1761040014.322] [8987:8989] [EM] >>> [E:55960i S:54870 M:165782692 (Ack:132777168)] (S) Msg RX from 1:0000000000000001 [A415] to 000000000001B669 --- Type 0001:09 (IM:InvokeCommandResponse) (B:68)
[1761040014.322] [8987:8989] [EM] Found matching exchange: 55960i, Delegate: 0xffff880081c8
[1761040014.322] [8987:8989] [EM] Rxd Ack; Removing MessageCounter:132777168 from Retrans Table on exchange 55960i
[1761040014.322] [8987:8989] [DMG] ICR moving to [ResponseRe]
[1761040014.322] [8987:8989] [DMG] InvokeResponseMessage =
[1761040014.322] [8987:8989] [DMG] {
[1761040014.322] [8987:8989] [DMG] suppressResponse = false,
[1761040014.322] [8987:8989] [DMG] InvokeResponseIBs =
[1761040014.322] [8987:8989] [DMG] [
[1761040014.322] [8987:8989] [DMG] InvokeResponseIB =
[1761040014.322] [8987:8989] [DMG] {
[1761040014.322] [8987:8989] [DMG] CommandStatusIB =
[1761040014.322] [8987:8989] [DMG] {
[1761040014.322] [8987:8989] [DMG] CommandPathIB =
[1761040014.322] [8987:8989] [DMG] {
[1761040014.322] [8987:8989] [DMG] EndpointId = 0x1,
[1761040014.322] [8987:8989] [DMG] ClusterId = 0x102,
[1761040014.322] [8987:8989] [DMG] CommandId = 0x1,
[1761040014.322] [8987:8989] [DMG] },
[1761040014.322] [8987:8989] [DMG]
[1761040014.322] [8987:8989] [DMG] StatusIB =
[1761040014.322] [8987:8989] [DMG] {
[1761040014.322] [8987:8989] [DMG] status = 0x00 (SUCCESS),
[1761040014.323] [8987:8989] [DMG] },
[1761040014.323] [8987:8989] [DMG]
[1761040014.323] [8987:8989] [DMG] },
[1761040014.323] [8987:8989] [DMG]
[1761040014.323] [8987:8989] [DMG] },
[1761040014.323] [8987:8989] [DMG]
[1761040014.323] [8987:8989] [DMG] ],
[1761040014.323] [8987:8989] [DMG]
[1761040014.323] [8987:8989] [DMG] InteractionModelRevision = 12
[1761040014.323] [8987:8989] [DMG] },
[1761040014.323] [8987:8989] [DMG] Received Command Response Status for Endpoint=1 Cluster=0x0000_0102 Command=0x0000_0001 Status=0x0
[1761040014.323] [8987:8989] [DMG] ICR moving to [AwaitingDe]
[1761040014.323] [8987:8989] [EM] <<< [E:55960i S:54870 M:132777169 (Ack:165782692)] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [A415] [UDP:[fd11:35::2773:5b0f:fcc1:19b5]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1761040014.323] [8987:8989] [EM] Flushed pending ack for MessageCounter:165782692 on exchange 55960i
[1761040014.359] [8987:8989] [EM] >>> [E:55960i S:54870 M:165782693 (Ack:132777168)] (S) Msg RX from 1:0000000000000001 [A415] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1761040014.380] [8987:8989] [EM] >>> [E:55960i S:54870 M:165782694 (Ack:132777168)] (S) Msg RX from 1:0000000000000001 [A415] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
chip-tool reports this:
[1761039817.706] [8987:8989] [DIS] Hostname: D2C947797D7B43B0
[1761039817.706] [8987:8989] [DIS] IP Address #1: fd11:35::2773:5b0f:fcc1:19b5
[1761039817.706] [8987:8989] [DIS] Port: 5540
[1761039817.706] [8987:8989] [DIS] Mrp Interval idle: 3000 ms
[1761039817.706] [8987:8989] [DIS] Mrp Interval active: 2200 ms
[1761039817.706] [8987:8989] [DIS] Mrp Active Threshold: 300 ms
[1761039817.706] [8987:8989] [DIS] TCP Client Supported: 0
[1761039817.706] [8987:8989] [DIS] TCP Server Supported: 0
[1761039817.706] [8987:8989] [DIS] ICD: not present
Why does it say ICD not present and the intervals seem very random as well. Is there something I'm doing wrong on my device causing chip-tool to not understand that it is a sleepy end device?
Tiit
