Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[TC-IDM-5.2] Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:454: CHIP Error 0x00000032: Timeout #23081

Closed
liuck8 opened this issue Oct 8, 2022 · 5 comments
Closed

[TC-IDM-5.2] Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:454: CHIP Error 0x00000032: Timeout #23081

liuck8 opened this issue Oct 8, 2022 · 5 comments

Comments

@liuck8
Copy link

liuck8 commented Oct 8, 2022

Reproduction steps

1. Use chip-tool of TH2.5 to test IDM TC-5.2-step3
2. The command is:  ./chip-tool onoff on 1 1 --repeat-delay-ms 5000  --timedInteractionTimeoutMs 200
3. Problem occurred as follows:
[1664296721.188029][2573:2578] CHIP:SC: Sent Sigma3 msg
[1664296721.303544][2573:2578] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:253963654 on exchange 17608i
[1664296721.303636][2573:2578] CHIP:EM: Found matching exchange: 17608i, Delegate: 0xffff9400b138
[1664296721.303721][2573:2578] CHIP:EM: Rxd Ack; Removing MessageCounter:26024419 from Retrans Table on exchange 17608i
[1664296721.303784][2573:2578] CHIP:EM: Removed CHIP MessageCounter:26024419 from RetransTable on exchange 17608i
[1664296725.319786][2573:2578] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:253963655 on exchange 17608i
[1664296725.319975][2573:2578] CHIP:EM: Found matching exchange: 17608i, Delegate: 0xffff9400b138
[1664296725.320046][2573:2578] CHIP:EM: CHIP MessageCounter:26024419 not in RetransTable on exchange 17608i
[1664296725.320144][2573:2578] CHIP:SC: Success status report received. Session was established
[1664296725.326589][2573:2578] CHIP:SC: SecureSession[0xffff9400a0a0]: Moving from state 'kEstablishing' --> 'kActive'
[1664296725.326695][2573:2578] CHIP:IN: SecureSession[0xffff9400a0a0]: Activated - Type:2 LSID:28135
[1664296725.326750][2573:2578] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:28135 PSID:15700!
[1664296725.326819][2573:2578] CHIP:CTL: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1664296725.326936][2573:2578] CHIP:TOO: Sending cluster (0x00000006) command (0x00000001) on endpoint 1
[1664296725.327054][2573:2578] CHIP:DMG: ICR moving to [AddingComm]
[1664296725.327290][2573:2578] CHIP:DMG: ICR moving to [AddedComma]
[1664296725.327551][2573:2578] CHIP:IN: Prepared secure message 0xffff9400d208 to 0x0000000000000001 (1)  of type 0xa and protocolId (0, 1) on exchange 17609i with MessageCounter:247302642.
[1664296725.327681][2573:2578] CHIP:IN: Sending encrypted msg 0xffff9400d208 with MessageCounter:247302642 to 0x0000000000000001 (1) at monotonic time: 00000000004980CE msec
[1664296725.328039][2573:2578] CHIP:DMG: ICR moving to [AwaitingTi]
[1664296730.328363][2573:2578] CHIP:EM: Sending Standalone Ack for MessageCounter:253963655 on exchange 17608i
[1664296730.328491][2573:2578] CHIP:IN: Prepared unauthenticated message 0xffffaa03d968 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 17608i with MessageCounter:26024420.
[1664296730.328566][2573:2578] CHIP:IN: Sending unauthenticated msg 0xffffaa03d968 with MessageCounter:26024420 to 0x0000000000000000 at monotonic time: 0000000000499456 msec
[1664296730.328874][2573:2578] CHIP:EM: Flushed pending ack for MessageCounter:253963655 on exchange 17608i
[1664296730.329188][2573:2573] CHIP:CTL: Shutting down the commissioner
[1664296730.329243][2573:2573] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1664296730.329283][2573:2573] CHIP:CTL: Shutting down the controller
[1664296730.329321][2573:2573] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1664296730.329357][2573:2573] CHIP:IN: SecureSession[0xffff9400a0a0]: MarkForEviction Type:2 LSID:28135
[1664296730.329396][2573:2573] CHIP:SC: SecureSession[0xffff9400a0a0]: Moving from state 'kActive' --> 'kPendingEviction'
[1664296730.329458][2573:2573] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 17609i
[1664296730.329511][2573:2573] CHIP:TOO: Error: ../../src/app/CommandSender.cpp:248: CHIP Error 0x00000032: Timeout
[1664296730.329547][2573:2573] CHIP:DMG: ICR moving to [AwaitingDe]
[1664296730.329678][2573:2573] CHIP:IN: SecureSession[0xffff9400a0a0]: Released - Type:2 LSID:28135
[1664296730.329741][2573:2573] CHIP:FP: Forgetting fabric 0x1
[1664296730.329813][2573:2573] CHIP:TS: Pending Last Known Good Time: 2022-09-26T18:46:11
[1664296730.330138][2573:2573] CHIP:TS: Previous Last Known Good Time: 2022-09-26T18:46:11
[1664296730.330209][2573:2573] CHIP:TS: Reverted Last Known Good Time to previous value
[1664296730.330313][2573:2573] CHIP:CTL: Shutting down the commissioner
[1664296730.330379][2573:2573] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1664296730.330437][2573:2573] CHIP:CTL: Shutting down the controller
[1664296730.330491][2573:2573] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1664296730.332499][2573:2573] CHIP:DMG: IM WH moving to [Uninitialized]
[1664296730.332580][2573:2573] CHIP:DMG: IM WH moving to [Uninitialized]
[1664296730.332634][2573:2573] CHIP:DMG: IM WH moving to [Uninitialized]
[1664296730.332684][2573:2573] CHIP:DMG: IM WH moving to [Uninitialized]
[1664296730.332741][2573:2573] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1664296730.332908][2573:2573] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1664296730.334196][2573:2573] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Nc9I6x)
[1664296730.337544][2573:2573] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1664296730.337738][2573:2573] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1664296730.337807][2573:2573] CHIP:DL: Inet Layer shutdown
[1664296730.337861][2573:2573] CHIP:DL: BLE shutdown
[1664296730.337916][2573:2573] CHIP:DL: System Layer shutdown
[1664296730.338480][2573:2573] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:454: CHIP Error 0x00000032: Timeout

Bug prevalence

always

GitHub hash of the SDK that was being used

3897c9b

Platform

ameba

Platform Version(s)

Realtek 8720CMF

Type

Test Improvement

Anything else?

No response
@liuck8 liuck8 changed the title [1.0] [TC-IDM-5.2] Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:454: CHIP Error 0x00000032: Timeout Oct 8, 2022
@bzbarsky-apple
Copy link
Contributor

@liuck8 What does the full log look like, starting with when the command was issued? At first glance this is just a case of the server being slow and the chip-tool default command timeout getting hit. That said, that default timeout is 20 seconds on the SHA listed above, so I'm a little surprised you're hitting it. Are you sure your chip-tool was built from that SHA and not an earlier version that had a 10s timeout? Because the log sure looks like a 10s timeout is getting hit (~5s to establish CASE, 5s sitting around due to the --repeat-delay-ms 5000).

@mideayanghui
Copy link
Contributor

mideayanghui commented Oct 11, 2022 •
edited by bzbarsky-apple
Loading

@bzbarsky-apple @liuck8 Here is the full log. The chip-tool is from TH2.5, I am not sure chip-tool's SHA.

$ ./chip-tool onoff on 2 1 --repeat-delay-ms 5000 --timedInteractionTimeoutMs 200 --trace_decode 1 
[1665398336.546196][2559:2559] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1665398336.551982][2559:2559] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1665398336.552306][2559:2559] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1665398336.552435][2559:2559] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1665398336.552767][2559:2559] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-hvQKjX)
[1665398336.553373][2559:2559] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1665398336.553420][2559:2559] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1665398336.554387][2559:2559] CHIP:DL: Got Ethernet interface: eth0
[1665398336.554938][2559:2559] CHIP:DL: Found the primary Ethernet interface:eth0
[1665398336.555498][2559:2559] CHIP:DL: Got WiFi interface: wlan0
[1665398336.555565][2559:2559] CHIP:DL: Failed to reset WiFi statistic counts
[1665398336.555613][2559:2559] CHIP:IN: UDP::Init bind&listen port=0
[1665398336.555721][2559:2559] CHIP:IN: UDP::Init bound to port=36216
[1665398336.555744][2559:2559] CHIP:IN: BLEBase::Init - setting/overriding transport
[1665398336.555763][2559:2559] CHIP:IN: TransportMgr initialized
[1665398336.555796][2559:2559] CHIP:FP: Initializing FabricTable from persistent storage
[1665398336.555926][2559:2559] CHIP:TS: Last Known Good Time: 2022-09-26T18:46:11
[1665398336.557478][2559:2559] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x934B2588B60D7AD2, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1665398336.559622][2559:2559] CHIP:ZCL: Using ZAP configuration...
[1665398336.563277][2559:2559] CHIP:DL: Avahi client registered
[1665398336.564327][2559:2559] CHIP:CTL: System State Initialized...
[1665398336.564450][2559:2559] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1665398336.564487][2559:2559] CHIP:CTL: Setting attestation nonce to random value
[1665398336.564518][2559:2559] CHIP:CTL: Setting CSR nonce to random value
[1665398336.564776][2559:2564] CHIP:DL: CHIP task running
[1665398336.564935][2559:2564] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1665398336.564992][2559:2564] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1665398336.565019][2559:2564] CHIP:CTL: Setting attestation nonce to random value
[1665398336.565167][2559:2564] CHIP:CTL: Setting CSR nonce to random value
[1665398336.566079][2559:2564] CHIP:CTL: Generating NOC
[1665398336.566980][2559:2564] CHIP:FP: Validating NOC chain
[1665398336.568649][2559:2564] CHIP:FP: NOC chain validation successful
[1665398336.568806][2559:2564] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1665398336.568832][2559:2564] CHIP:TS: Last Known Good Time: 2022-09-26T18:46:11
[1665398336.568851][2559:2564] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1665398336.568868][2559:2564] CHIP:TS: Retaining current Last Known Good Time
[1665398336.574207][2559:2564] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1665398336.576227][2559:2564] CHIP:TS: Committing Last Known Good Time to storage: 2022-09-26T18:46:11
[1665398336.578209][2559:2564] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1665398336.587454][2559:2564] CHIP:TOO: Sending command to node 0x2
[1665398336.587503][2559:2564] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000002]
[1665398336.587525][2559:2564] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1665398336.587557][2559:2564] CHIP:CTL: OperationalSessionSetup[1:0000000000000002]: State change 1 --> 2
[1665398336.587585][2559:2564] CHIP:DIS: Resolving 934B2588B60D7AD2:0000000000000002 ...
[1665398336.589222][2559:2564] CHIP:DL: Avahi resolve found
[1665398336.589304][2559:2564] CHIP:DIS: Node ID resolved for 934B2588B60D7AD2:0000000000000002
[1665398336.589325][2559:2564] CHIP:DIS: 	Hostname: 701D0807693C
[1665398336.589345][2559:2564] CHIP:DIS: 	IP Address #1: fe80::721d:8ff:fe07:693c
[1665398336.589402][2559:2564] CHIP:DIS: 	Port: 5540
[1665398336.589419][2559:2564] CHIP:DIS: 	Mrp Interval idle: 5000 ms
[1665398336.589435][2559:2564] CHIP:DIS: 	Mrp Interval active: 300 ms
[1665398336.589451][2559:2564] CHIP:DIS: 	TCP Supported: 1
[1665398336.589556][2559:2564] CHIP:DIS: UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540: new best score: 3
[1665398336.589577][2559:2564] CHIP:DIS: Checking node lookup status after 2 ms
[1665398336.589594][2559:2564] CHIP:DIS: Keeping DNSSD lookup active
[1665398336.787715][2559:2564] CHIP:DIS: Checking node lookup status after 200 ms
[1665398336.788026][2559:2564] CHIP:DIS: OperationalSessionSetup[1:0000000000000002]: Updating device address to UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540 while in state 2
[1665398336.788088][2559:2564] CHIP:CTL: OperationalSessionSetup[1:0000000000000002]: State change 2 --> 3
[1665398336.788373][2559:2564] CHIP:IN: SecureSession[0xffff7800a0a0]: Allocated Type:2 LSID:34639
[1665398336.788462][2559:2564] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000002
[1665398336.790025][2559:2564] CHIP:SC: Including MRP parameters
[1665398336.790709][2559:2564] CHIP:IN: Prepared unauthenticated message 0xffff78007028 to 0x0000000000000000 (0)  of type 0x30 and protocolId (0, 0) on exchange 12976i with MessageCounter:108486450.
[1665398336.790807][2559:2564] CHIP:IN: Sending unauthenticated msg 0xffff78007028 with MessageCounter:108486450 to 0x0000000000000000 at monotonic time: 00000000002F5156 msec
[1665398336.791535][2559:2564] CHIP:DMG: >> to UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540 | 108486450 | [Secure Channel  (0) / Certificate Authenticated Session Establishment Sigma '1' (0x30) / Session = 0 / Exchange = 12976]
[1665398336.791650][2559:2564] CHIP:DMG: Header Flags =
[1665398336.791706][2559:2564] CHIP:DMG: {
[1665398336.791777][2559:2564] CHIP:DMG:     Message (0x04) =
[1665398336.791832][2559:2564] CHIP:DMG:     {
[1665398336.791890][2559:2564] CHIP:DMG:         SourceNodeId = BD7C77925A45D8FB
[1665398336.791943][2559:2564] CHIP:DMG:     }
[1665398336.792015][2559:2564] CHIP:DMG:     Exchange (0x05) =
[1665398336.792069][2559:2564] CHIP:DMG:     {
[1665398336.792117][2559:2564] CHIP:DMG:         Initiator = true
[1665398336.792169][2559:2564] CHIP:DMG:         NeedsAck = true
[1665398336.792220][2559:2564] CHIP:DMG:     }
[1665398336.792367][2559:2564] CHIP:DMG: }
[1665398336.792421][2559:2564] CHIP:DMG:  
[1665398336.792487][2559:2564] CHIP:DMG: Encrypted Payload (177 bytes) =
[1665398336.792541][2559:2564] CHIP:DMG: {
[1665398336.792593][2559:2564] CHIP:DMG:     data = 04000000325f7706fbd8455a92777cbd0530b03200001530012036b3da31e78d144f19eff71dfb8b0bc14537106497e32dd7c82a3d66af08088225024f87300320362a3910af25de69020e484aa8c8ae593c61262bcfa66e3fe65f563447c3b06930044104237e82c1f5a1196d982ffeacb4cd69b6c72f3503e7703899277f65506580a06118f0dc9f9c96700efa654b714b144f9c3cf8caa5c96940f8782edb7c9cb7637035052501881325022c011818
[1665398336.792646][2559:2564] CHIP:DMG:     buffer_ptr = 281472695057824
[1665398336.792696][2559:2564] CHIP:DMG: }
[1665398336.792745][2559:2564] CHIP:DMG:  
[1665398336.792880][2559:2564] CHIP:DMG: Parameters =
[1665398336.792937][2559:2564] CHIP:DMG: {
[1665398336.793019][2559:2564] CHIP:DMG:     InitiatorRandom (32) = 36B3DA31E78D144F19EFF71DFB8B0BC14537106497E32DD7C82A3D66AF080882
[1665398336.793074][2559:2564] CHIP:DMG:     InitiatorSessionId = 34639
[1665398336.793132][2559:2564] CHIP:DMG:     DestinationId (32) = 362A3910AF25DE69020E484AA8C8AE593C61262BCFA66E3FE65F563447C3B069
[1665398336.793194][2559:2564] CHIP:DMG:     InitiatorEphPubKey (65) = 04237E82C1F5A1196D982FFEACB4CD69B6C72F3503E7703899277F65506580A06118F0DC9F9C96700EFA654B714B144F9C3CF8CAA5C96940F8782EDB7C9CB76370
[1665398336.793250][2559:2564] CHIP:DMG:     SED =
[1665398336.793301][2559:2564] CHIP:DMG:     {
[1665398336.793358][2559:2564] CHIP:DMG:         Idle Retransmit Timeout = 5000
[1665398336.793415][2559:2564] CHIP:DMG:         Active Retransmit Timeout = 300
[1665398336.793470][2559:2564] CHIP:DMG:     }
[1665398336.793525][2559:2564] CHIP:DMG: }
[1665398336.793649][2559:2564] CHIP:DMG:  
[1665398336.793703][2559:2564] CHIP:DMG:  
[1665398336.794204][2559:2564] CHIP:SC: Sent Sigma1 msg
[1665398336.794276][2559:2564] CHIP:CTL: OperationalSessionSetup[1:0000000000000002]: State change 3 --> 4
[1665398336.879147][2559:2564] CHIP:DMG: << from UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540 | 171213677 | [Secure Channel  (0) / Standalone Ack (0x10) / Session = 0 / Exchange = 12976]
[1665398336.879281][2559:2564] CHIP:DMG: Header Flags =
[1665398336.879336][2559:2564] CHIP:DMG: {
[1665398336.879406][2559:2564] CHIP:DMG:     Message (0x01) =
[1665398336.879461][2559:2564] CHIP:DMG:     {
[1665398336.879518][2559:2564] CHIP:DMG:         DestinationNodeId = BD7C77925A45D8FB
[1665398336.879570][2559:2564] CHIP:DMG:     }
[1665398336.879641][2559:2564] CHIP:DMG:     Exchange (0x02) =
[1665398336.879695][2559:2564] CHIP:DMG:     {
[1665398336.879751][2559:2564] CHIP:DMG:         AckMsg = 108486450
[1665398336.879803][2559:2564] CHIP:DMG:     }
[1665398336.879873][2559:2564] CHIP:DMG: }
[1665398336.879925][2559:2564] CHIP:DMG:  
[1665398336.879990][2559:2564] CHIP:DMG: Encrypted Payload (26 bytes) =
[1665398336.880043][2559:2564] CHIP:DMG: {
[1665398336.880094][2559:2564] CHIP:DMG:     data = 010000006d83340afbd8455a92777cbd0210b0320000325f7706
[1665398336.880145][2559:2564] CHIP:DMG:     buffer_ptr = 281472695021664
[1665398336.880195][2559:2564] CHIP:DMG: }
[1665398336.880311][2559:2564] CHIP:DMG:  
[1665398336.880415][2559:2564] CHIP:DMG: Additional Fields =
[1665398336.880470][2559:2564] CHIP:DMG: {
[1665398336.880526][2559:2564] CHIP:DMG:     peer_address = UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540
[1665398336.880581][2559:2564] CHIP:DMG: }
[1665398336.880630][2559:2564] CHIP:DMG:  
[1665398336.880692][2559:2564] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:171213677 on exchange 12976i
[1665398336.880751][2559:2564] CHIP:EM: Found matching exchange: 12976i, Delegate: 0xffff7800b138
[1665398336.880831][2559:2564] CHIP:EM: Rxd Ack; Removing MessageCounter:108486450 from Retrans Table on exchange 12976i
[1665398336.880889][2559:2564] CHIP:EM: Removed CHIP MessageCounter:108486450 from RetransTable on exchange 12976i
[1665398338.711156][2559:2564] CHIP:DMG: << from UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540 | 171213678 | [Secure Channel  (0) / Certificate Authenticated Session Establishment Sigma '2' (0x31) / Session = 0 / Exchange = 12976]
[1665398338.711329][2559:2564] CHIP:DMG: Header Flags =
[1665398338.711386][2559:2564] CHIP:DMG: {
[1665398338.711457][2559:2564] CHIP:DMG:     Message (0x01) =
[1665398338.711512][2559:2564] CHIP:DMG:     {
[1665398338.711570][2559:2564] CHIP:DMG:         DestinationNodeId = BD7C77925A45D8FB
[1665398338.711622][2559:2564] CHIP:DMG:     }
[1665398338.711695][2559:2564] CHIP:DMG:     Exchange (0x06) =
[1665398338.711748][2559:2564] CHIP:DMG:     {
[1665398338.711805][2559:2564] CHIP:DMG:         AckMsg = 108486450
[1665398338.711857][2559:2564] CHIP:DMG:         NeedsAck = true
[1665398338.711907][2559:2564] CHIP:DMG:     }
[1665398338.711976][2559:2564] CHIP:DMG: }
[1665398338.712029][2559:2564] CHIP:DMG:  
[1665398338.712098][2559:2564] CHIP:DMG: Encrypted Payload (732 bytes) =
[1665398338.712151][2559:2564] CHIP:DMG: {
[1665398338.712204][2559:2564] CHIP:DMG:     data = 010000006e83340afbd8455a92777cbd0631b0320000325f770615300120467cee8aea4fdeeac1918e6acc8d9b48bddc5fd359fb691387a5ccf79a2c43f525025acc30034104be3567795dd75525e23bc79de9ee259436eaec1dee952b76ab1745154a08604ed1dc1690d05177d97684c6410b73c7d2b9d4e7e187b1661bd804037b1f2bf42131044602114a1d2e8f2610f53c94ec995c8304c34b2e6232641fc5344173b02da9f4bf14f0c0c518e2b0403f38142fb2f6aba98ec115da6ace6d41cb20940082458e64db8b3c720e0d710be3093ab2dbc43d279aeed303971f22921a74eac02126a0c09f3c0b8f5f0a0b8c072c07248e8adb4b26f87b14cc9a60f1e81d6886f9fbc923aff5373f326e0c029eb559243f59194b707fe1d806f05a615b4b81cef243bed8cfc7a4a310d558277e20538a14fcc7f98abcd496aceef1ec933ddfcd9ca77a9331c23f705322f33d140f70595265b65632bd5814bdaa9dbb46b603fe225ce22880c30ec6e6c09a3e8a4f1de78f68d0c5b8c0d2487a5fb4fc0f98e79a413aa4b7dc7222e9759ea85974b3542dd33816ec403dfa3321a9c1ab2ea202f264a7d26369d59fe638d7972f3b017b9c25a37aab89fc71510798789089bf95ff6dd6cb55728505de66c54295c8262ccba5951cb200baee76476be356332acf25ea7dcbcefd8f601f59044141cd0c889f6d05b16878b1722a6b52f0b8578c30b40923410304be8ceed40327c391bf751788ac8f4e9951a4ba7d094018ef087d9747c7c28193312798bfa9db97ea947ead1fa8662cc8c4e615d5662460506a145ca89b3cd94937a4924ae3fe567cca5f750e5bacd9df5a178c2fc1abe9218a28312f8431f3de15435b68aa435172835a253eba357af8fdcca110e62933b6b868afc4c54425fe68f191719b88c18a976dab9ecd1e57d8419d464bfeba1b5db0d1a4f65471495b562156e017597033e54835aa098632e745f06e308dda9a8a5bdfdad2eb223b3f3591b636348c35052501881325022c011818
[1665398338.712409][2559:2564] CHIP:DMG:     buffer_ptr = 281472695071808
[1665398338.712473][2559:2564] CHIP:DMG: }
[1665398338.712523][2559:2564] CHIP:DMG:  
[1665398338.712802][2559:2564] CHIP:DMG: Parameters =
[1665398338.712860][2559:2564] CHIP:DMG: {
[1665398338.712920][2559:2564] CHIP:DMG:     ResponderRandom (32) = 467CEE8AEA4FDEEAC1918E6ACC8D9B48BDDC5FD359FB691387A5CCF79A2C43F5
[1665398338.712972][2559:2564] CHIP:DMG:     ResponderSessionId = 52314
[1665398338.713032][2559:2564] CHIP:DMG:     ResponderEphPubKey (65) = 04BE3567795DD75525E23BC79DE9EE259436EAEC1DEE952B76AB1745154A08604ED1DC1690D05177D97684C6410B73C7D2B9D4E7E187B1661BD804037B1F2BF421
[1665398338.713149][2559:2564] CHIP:DMG:     Encrypted2 (582) = 114A1D2E8F2610F53C94EC995C8304C34B2E6232641FC5344173B02DA9F4BF14F0C0C518E2B0403F38142FB2F6ABA98EC115DA6ACE6D41CB20940082458E64DB8B3C720E0D710BE3093AB2DBC43D279AEED303971F22921A74EAC02126A0C09F3C0B8F5F0A0B8C072C07248E8ADB4B26F87B14CC9A60F1E81D6886F9FBC923AFF5373F326E0C029EB559243F59194B707FE1D806F05A615B4B81CEF243BED8CFC7A4A310D558277E20538A14FCC7F98ABCD496ACEEF1EC933DDFCD9CA77A9331C23F705322F33D140F70595265B65632BD5814BDAA9DBB46B603FE225CE22880C30EC6E6C09A3E8A4F1DE78F68D0C5B8C0D2487A5FB4FC0F98E79A413AA4B7DC7222E9759EA85974B3542DD33816EC403DFA3321A9C1AB2EA202F264A7D26369D59FE638D7972F3B017B9C25A37AAB89FC71510798789089BF95FF6DD6CB55728505DE66C54295C8262CCBA5951CB200BAEE76476BE356332ACF25EA7DCBCEFD8F601F59044141CD0C889F6D05B16878B1722A6B52F0B8578C30B40923410304BE8CEED40327C391BF751788AC8F4E9951A4BA7D094018EF087D9747C7C28193312798BFA9DB97EA947EAD1FA8662CC8C4E615D5662460506A145CA89B3CD94937A4924AE3FE567CCA5F750E5BACD9DF5A178C2FC1ABE9218A28312F8431F3DE15435B68AA435172835A253EBA357AF8FDCCA110E62933B6B868AFC4C54425FE68F191719B88C18A976DAB9ECD1E57D8419D464BFEBA1B5DB0D1A4F65471495B562156E017597033E54835AA098632E745F06E308DDA9A8A5BDFDAD2EB223B3F3591B636348C
[1665398338.713205][2559:2564] CHIP:DMG:     SED =
[1665398338.713257][2559:2564] CHIP:DMG:     {
[1665398338.713314][2559:2564] CHIP:DMG:         Idle Retransmit Timeout = 5000
[1665398338.713372][2559:2564] CHIP:DMG:         Active Retransmit Timeout = 300
[1665398338.713427][2559:2564] CHIP:DMG:     }
[1665398338.713482][2559:2564] CHIP:DMG: }
[1665398338.713533][2559:2564] CHIP:DMG:  
[1665398338.713584][2559:2564] CHIP:DMG:  
[1665398338.713661][2559:2564] CHIP:DMG: Additional Fields =
[1665398338.713716][2559:2564] CHIP:DMG: {
[1665398338.713773][2559:2564] CHIP:DMG:     peer_address = UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540
[1665398338.713827][2559:2564] CHIP:DMG: }
[1665398338.713877][2559:2564] CHIP:DMG:  
[1665398338.713944][2559:2564] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:171213678 on exchange 12976i
[1665398338.714004][2559:2564] CHIP:EM: Found matching exchange: 12976i, Delegate: 0xffff7800b138
[1665398338.714063][2559:2564] CHIP:EM: CHIP MessageCounter:108486450 not in RetransTable on exchange 12976i
[1665398338.714152][2559:2564] CHIP:SC: Received Sigma2 msg
[1665398338.714220][2559:2564] CHIP:SC: Peer assigned session session ID 52314
[1665398338.723366][2559:2564] CHIP:SC: Found MRP parameters in the message
[1665398338.723449][2559:2564] CHIP:SC: Sending Sigma3
[1665398338.723887][2559:2564] CHIP:EM: Piggybacking Ack for MessageCounter:171213678 on exchange: 12976i
[1665398338.724148][2559:2564] CHIP:IN: Prepared unauthenticated message 0xffff78009e48 to 0x0000000000000000 (0)  of type 0x32 and protocolId (0, 0) on exchange 12976i with MessageCounter:108486451.
[1665398338.724286][2559:2564] CHIP:IN: Sending unauthenticated msg 0xffff78009e48 with MessageCounter:108486451 to 0x0000000000000000 at monotonic time: 00000000002F58E4 msec
[1665398338.724614][2559:2564] CHIP:DMG: >> to UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540 | 108486451 | [Secure Channel  (0) / Certificate Authenticated Session Establishment Sigma '3' (0x32) / Session = 0 / Exchange = 12976]
[1665398338.724647][2559:2564] CHIP:DMG: Header Flags =
[1665398338.724665][2559:2564] CHIP:DMG: {
[1665398338.724690][2559:2564] CHIP:DMG:     Message (0x04) =
[1665398338.724708][2559:2564] CHIP:DMG:     {
[1665398338.724727][2559:2564] CHIP:DMG:         SourceNodeId = BD7C77925A45D8FB
[1665398338.724745][2559:2564] CHIP:DMG:     }
[1665398338.724769][2559:2564] CHIP:DMG:     Exchange (0x07) =
[1665398338.724787][2559:2564] CHIP:DMG:     {
[1665398338.724803][2559:2564] CHIP:DMG:         Initiator = true
[1665398338.724822][2559:2564] CHIP:DMG:         AckMsg = 171213678
[1665398338.724839][2559:2564] CHIP:DMG:         NeedsAck = true
[1665398338.724856][2559:2564] CHIP:DMG:     }
[1665398338.724879][2559:2564] CHIP:DMG: }
[1665398338.724897][2559:2564] CHIP:DMG:  
[1665398338.724922][2559:2564] CHIP:DMG: Encrypted Payload (598 bytes) =
[1665398338.724939][2559:2564] CHIP:DMG: {
[1665398338.724956][2559:2564] CHIP:DMG:     data = 04000000335f7706fbd8455a92777cbd0732b03200006e83340a1531013602f2e396b28ef60a17fce0464f619a16d2d1be4ef93c0e9a3c95ef83b21b018c669a3fe1fbe464b58443fe176dcb6d54f4c9af49e7e03e2d6ab989b511a78957d0582cf9039f594077d71fd4a1bea2e954fe87e9ca0297192b7b2ac8ec3037465b5f65e12da66cd48a063f0a6ec6051ff5fcf6a93401230f219d88b6a6e1d5fbb043008f374d0ab603c0e002503d5992404d745e723e9c1a791880092f334a44a74c9adb9fd6d74cb6a213914ab98e1e238869bb992c0904f173a8a09c585de61501707ba1d8b7a4baeb905c4940783e4a1bfdacb3c7461bfa62d0b396ba0402e151d7dd1fb80d641b3b2929d6b7d0f007683ce61a85ab823fd71c7f9c576a443c59a3788ea832c019cb835dd8c0cadb210b7025b18c3e6cbe022af35b14e9b21786f9c2738dde574329663d22560436d6183cee36ad7598eab39c0bd896f12740c8cf2fc7b27f3b0f7b83cfe339a110c18239068762b626c30bbbfe47c1aac78ab80419db6bea4f2c0749d0a9104e2a2593ad860b2e616e43d48052f497c9909f76e767d6bb48aa66a9120090d25a0c974852e07f089287a69cfecc3c7dde6155e5403796c95504ddb234f4d291622e9a47547bc3c620b6d014b1586cc013699e035cae1b4b8a93d32b3353e11db1be824a9ce8127463a9766ce0cefec75b48f3c5c840800dcd526846845cd40f70b2e75b8c0fd7f613d55ef5ad1da81de0c3ebae8d234913cfb3466cdd42a6f86101020bb70efdd53bf29cd896bf7d0e0fbadaeb41e1e023e639d3b12c74a8dd2233fc7426dd2dfc7f18
[1665398338.724974][2559:2564] CHIP:DMG:     buffer_ptr = 281472695073024
[1665398338.724991][2559:2564] CHIP:DMG: }
[1665398338.725007][2559:2564] CHIP:DMG:  
[1665398338.725088][2559:2564] CHIP:DMG: Parameters =
[1665398338.725109][2559:2564] CHIP:DMG: {
[1665398338.725148][2559:2564] CHIP:DMG:     Encrypted3 (566) = F2E396B28EF60A17FCE0464F619A16D2D1BE4EF93C0E9A3C95EF83B21B018C669A3FE1FBE464B58443FE176DCB6D54F4C9AF49E7E03E2D6AB989B511A78957D0582CF9039F594077D71FD4A1BEA2E954FE87E9CA0297192B7B2AC8EC3037465B5F65E12DA66CD48A063F0A6EC6051FF5FCF6A93401230F219D88B6A6E1D5FBB043008F374D0AB603C0E002503D5992404D745E723E9C1A791880092F334A44A74C9ADB9FD6D74CB6A213914AB98E1E238869BB992C0904F173A8A09C585DE61501707BA1D8B7A4BAEB905C4940783E4A1BFDACB3C7461BFA62D0B396BA0402E151D7DD1FB80D641B3B2929D6B7D0F007683CE61A85AB823FD71C7F9C576A443C59A3788EA832C019CB835DD8C0CADB210B7025B18C3E6CBE022AF35B14E9B21786F9C2738DDE574329663D22560436D6183CEE36AD7598EAB39C0BD896F12740C8CF2FC7B27F3B0F7B83CFE339A110C18239068762B626C30BBBFE47C1AAC78AB80419DB6BEA4F2C0749D0A9104E2A2593AD860B2E616E43D48052F497C9909F76E767D6BB48AA66A9120090D25A0C974852E07F089287A69CFECC3C7DDE6155E5403796C95504DDB234F4D291622E9A47547BC3C620B6D014B1586CC013699E035CAE1B4B8A93D32B3353E11DB1BE824A9CE8127463A9766CE0CEFEC75B48F3C5C840800DCD526846845CD40F70B2E75B8C0FD7F613D55EF5AD1DA81DE0C3EBAE8D234913CFB3466CDD42A6F86101020BB70EFDD53BF29CD896BF7D0E0FBADAEB41E1E023E639D3B12C74A8DD2233FC7426DD2DFC7F
[1665398338.725188][2559:2564] CHIP:DMG: }
[1665398338.725205][2559:2564] CHIP:DMG:  
[1665398338.725223][2559:2564] CHIP:DMG:  
[1665398338.725474][2559:2564] CHIP:SC: Sent Sigma3 msg
[1665398338.806627][2559:2564] CHIP:DMG: << from UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540 | 171213679 | [Secure Channel  (0) / Standalone Ack (0x10) / Session = 0 / Exchange = 12976]
[1665398338.806704][2559:2564] CHIP:DMG: Header Flags =
[1665398338.806737][2559:2564] CHIP:DMG: {
[1665398338.806780][2559:2564] CHIP:DMG:     Message (0x01) =
[1665398338.806813][2559:2564] CHIP:DMG:     {
[1665398338.806847][2559:2564] CHIP:DMG:         DestinationNodeId = BD7C77925A45D8FB
[1665398338.806879][2559:2564] CHIP:DMG:     }
[1665398338.806921][2559:2564] CHIP:DMG:     Exchange (0x02) =
[1665398338.806953][2559:2564] CHIP:DMG:     {
[1665398338.806987][2559:2564] CHIP:DMG:         AckMsg = 108486451
[1665398338.807018][2559:2564] CHIP:DMG:     }
[1665398338.807060][2559:2564] CHIP:DMG: }
[1665398338.807091][2559:2564] CHIP:DMG:  
[1665398338.807130][2559:2564] CHIP:DMG: Encrypted Payload (26 bytes) =
[1665398338.807162][2559:2564] CHIP:DMG: {
[1665398338.807192][2559:2564] CHIP:DMG:     data = 010000006f83340afbd8455a92777cbd0210b0320000335f7706
[1665398338.807223][2559:2564] CHIP:DMG:     buffer_ptr = 281472695029136
[1665398338.807253][2559:2564] CHIP:DMG: }
[1665398338.807282][2559:2564] CHIP:DMG:  
[1665398338.807334][2559:2564] CHIP:DMG: Additional Fields =
[1665398338.807367][2559:2564] CHIP:DMG: {
[1665398338.807401][2559:2564] CHIP:DMG:     peer_address = UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540
[1665398338.807434][2559:2564] CHIP:DMG: }
[1665398338.807464][2559:2564] CHIP:DMG:  
[1665398338.807501][2559:2564] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:171213679 on exchange 12976i
[1665398338.807536][2559:2564] CHIP:EM: Found matching exchange: 12976i, Delegate: 0xffff7800b138
[1665398338.807585][2559:2564] CHIP:EM: Rxd Ack; Removing MessageCounter:108486451 from Retrans Table on exchange 12976i
[1665398338.807620][2559:2564] CHIP:EM: Removed CHIP MessageCounter:108486451 from RetransTable on exchange 12976i
[1665398342.773248][2559:2564] CHIP:DMG: << from UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540 | 171213680 | [Secure Channel  (0) / Status Report (0x40) / Session = 0 / Exchange = 12976]
[1665398342.773402][2559:2564] CHIP:DMG: Header Flags =
[1665398342.773458][2559:2564] CHIP:DMG: {
[1665398342.773529][2559:2564] CHIP:DMG:     Message (0x01) =
[1665398342.773583][2559:2564] CHIP:DMG:     {
[1665398342.773641][2559:2564] CHIP:DMG:         DestinationNodeId = BD7C77925A45D8FB
[1665398342.773693][2559:2564] CHIP:DMG:     }
[1665398342.773765][2559:2564] CHIP:DMG:     Exchange (0x06) =
[1665398342.773819][2559:2564] CHIP:DMG:     {
[1665398342.773875][2559:2564] CHIP:DMG:         AckMsg = 108486451
[1665398342.773928][2559:2564] CHIP:DMG:         NeedsAck = true
[1665398342.773978][2559:2564] CHIP:DMG:     }
[1665398342.774047][2559:2564] CHIP:DMG: }
[1665398342.774100][2559:2564] CHIP:DMG:  
[1665398342.774166][2559:2564] CHIP:DMG: Encrypted Payload (34 bytes) =
[1665398342.774218][2559:2564] CHIP:DMG: {
[1665398342.774270][2559:2564] CHIP:DMG:     data = 010000007083340afbd8455a92777cbd0640b0320000335f77060000000000000000
[1665398342.774322][2559:2564] CHIP:DMG:     buffer_ptr = 281472695048368
[1665398342.774372][2559:2564] CHIP:DMG: }
[1665398342.774421][2559:2564] CHIP:DMG:  
[1665398342.774505][2559:2564] CHIP:DMG: Parameters =
[1665398342.774560][2559:2564] CHIP:DMG: {
[1665398342.774612][2559:2564] CHIP:DMG:     GeneralStatusCode = 0
[1665398342.774663][2559:2564] CHIP:DMG:     ProtocolId = 0
[1665398342.774713][2559:2564] CHIP:DMG:     ProtocolCode = 0
[1665398342.774762][2559:2564] CHIP:DMG: }
[1665398342.774812][2559:2564] CHIP:DMG:  
[1665398342.774863][2559:2564] CHIP:DMG:  
[1665398342.774938][2559:2564] CHIP:DMG: Additional Fields =
[1665398342.774992][2559:2564] CHIP:DMG: {
[1665398342.775049][2559:2564] CHIP:DMG:     peer_address = UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540
[1665398342.775183][2559:2564] CHIP:DMG: }
[1665398342.775235][2559:2564] CHIP:DMG:  
[1665398342.775299][2559:2564] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:171213680 on exchange 12976i
[1665398342.775359][2559:2564] CHIP:EM: Found matching exchange: 12976i, Delegate: 0xffff7800b138
[1665398342.775419][2559:2564] CHIP:EM: CHIP MessageCounter:108486451 not in RetransTable on exchange 12976i
[1665398342.775511][2559:2564] CHIP:SC: Success status report received. Session was established
[1665398342.781821][2559:2564] CHIP:SC: SecureSession[0xffff7800a0a0]: Moving from state 'kEstablishing' --> 'kActive'
[1665398342.781925][2559:2564] CHIP:IN: SecureSession[0xffff7800a0a0]: Activated - Type:2 LSID:34639
[1665398342.781978][2559:2564] CHIP:IN: New secure session activated for device <0000000000000002, 1>, LSID:34639 PSID:52314!
[1665398342.782041][2559:2564] CHIP:CTL: OperationalSessionSetup[1:0000000000000002]: State change 4 --> 5
[1665398342.782155][2559:2564] CHIP:TOO: Sending cluster (0x00000006) command (0x00000001) on endpoint 1
[1665398342.782269][2559:2564] CHIP:DMG: ICR moving to [AddingComm]
[1665398342.782385][2559:2564] CHIP:DMG: ICR moving to [AddedComma]
[1665398342.782937][2559:2564] CHIP:IN: Prepared secure message 0xffff7800b7f8 to 0x0000000000000002 (1)  of type 0xa and protocolId (0, 1) on exchange 12977i with MessageCounter:225669865.
[1665398342.783034][2559:2564] CHIP:IN: Sending encrypted msg 0xffff7800b7f8 with MessageCounter:225669865 to 0x0000000000000002 (1) at monotonic time: 00000000002F68BE msec
[1665398342.783689][2559:2564] CHIP:DMG: >> to UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540 | 225669865 | [Interaction Model  (1) / Timed Request (0x0a) / Session = 52314 / Exchange = 12977]
[1665398342.783780][2559:2564] CHIP:DMG: Header Flags =
[1665398342.783834][2559:2564] CHIP:DMG: {
[1665398342.783918][2559:2564] CHIP:DMG:     Exchange (0x05) =
[1665398342.783973][2559:2564] CHIP:DMG:     {
[1665398342.784020][2559:2564] CHIP:DMG:         Initiator = true
[1665398342.784071][2559:2564] CHIP:DMG:         NeedsAck = true
[1665398342.784122][2559:2564] CHIP:DMG:     }
[1665398342.784190][2559:2564] CHIP:DMG: }
[1665398342.784293][2559:2564] CHIP:DMG:  
[1665398342.784375][2559:2564] CHIP:DMG: Encrypted Payload (38 bytes) =
[1665398342.784428][2559:2564] CHIP:DMG: {
[1665398342.784480][2559:2564] CHIP:DMG:     data = 005acc00e972730dab90a5e0ab1ef297d8c1889a12cc3cafd7e6113d08e27036f65b767ec2bd
[1665398342.784532][2559:2564] CHIP:DMG:     buffer_ptr = 281472695030480
[1665398342.784581][2559:2564] CHIP:DMG: }
[1665398342.784630][2559:2564] CHIP:DMG:  
[1665398342.784737][2559:2564] CHIP:DMG: TimedRequestMessage =
[1665398342.784770][2559:2564] CHIP:DMG: {
[1665398342.784790][2559:2564] CHIP:DMG: 	TimeoutMs = 0xc8,
[1665398342.784808][2559:2564] CHIP:DMG: 	InteractionModelRevision = 1
[1665398342.784825][2559:2564] CHIP:DMG: }
[1665398342.784843][2559:2564] CHIP:DMG:  
[1665398342.785089][2559:2564] CHIP:DMG: ICR moving to [AwaitingTi]
[1665398347.785306][2559:2564] CHIP:EM: Sending Standalone Ack for MessageCounter:171213680 on exchange 12976i
[1665398347.785867][2559:2564] CHIP:IN: Prepared unauthenticated message 0xffff827cd968 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 12976i with MessageCounter:108486452.
[1665398347.785967][2559:2564] CHIP:IN: Sending unauthenticated msg 0xffff827cd968 with MessageCounter:108486452 to 0x0000000000000000 at monotonic time: 00000000002F7C49 msec
[1665398347.786652][2559:2564] CHIP:DMG: >> to UDP:[fe80::721d:8ff:fe07:693c%eth0]:5540 | 108486452 | [Secure Channel  (0) / Standalone Ack (0x10) / Session = 0 / Exchange = 12976]
[1665398347.786743][2559:2564] CHIP:DMG: Header Flags =
[1665398347.786800][2559:2564] CHIP:DMG: {
[1665398347.786870][2559:2564] CHIP:DMG:     Message (0x04) =
[1665398347.786924][2559:2564] CHIP:DMG:     {
[1665398347.786981][2559:2564] CHIP:DMG:         SourceNodeId = BD7C77925A45D8FB
[1665398347.787033][2559:2564] CHIP:DMG:     }
[1665398347.787184][2559:2564] CHIP:DMG:     Exchange (0x03) =
[1665398347.787240][2559:2564] CHIP:DMG:     {
[1665398347.787287][2559:2564] CHIP:DMG:         Initiator = true
[1665398347.787344][2559:2564] CHIP:DMG:         AckMsg = 171213680
[1665398347.787396][2559:2564] CHIP:DMG:     }
[1665398347.787466][2559:2564] CHIP:DMG: }
[1665398347.787519][2559:2564] CHIP:DMG:  
[1665398347.787585][2559:2564] CHIP:DMG: Encrypted Payload (26 bytes) =
[1665398347.787637][2559:2564] CHIP:DMG: {
[1665398347.787689][2559:2564] CHIP:DMG:     data = 04000000345f7706fbd8455a92777cbd0310b03200007083340a
[1665398347.787741][2559:2564] CHIP:DMG:     buffer_ptr = 281472695056416
[1665398347.787791][2559:2564] CHIP:DMG: }
[1665398347.787840][2559:2564] CHIP:DMG:  
[1665398347.788304][2559:2564] CHIP:EM: Flushed pending ack for MessageCounter:171213680 on exchange 12976i
[1665398347.788719][2559:2559] CHIP:CTL: Shutting down the commissioner
[1665398347.788800][2559:2559] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1665398347.788855][2559:2559] CHIP:CTL: Shutting down the controller
[1665398347.788907][2559:2559] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1665398347.788959][2559:2559] CHIP:IN: SecureSession[0xffff7800a0a0]: MarkForEviction Type:2 LSID:34639
[1665398347.789010][2559:2559] CHIP:SC: SecureSession[0xffff7800a0a0]: Moving from state 'kActive' --> 'kPendingEviction'
[1665398347.789094][2559:2559] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 12977i
[1665398347.789163][2559:2559] CHIP:TOO: Error: ../../src/app/CommandSender.cpp:248: CHIP Error 0x00000032: Timeout
[1665398347.789214][2559:2559] CHIP:DMG: ICR moving to [AwaitingDe]
[1665398347.789348][2559:2559] CHIP:IN: SecureSession[0xffff7800a0a0]: Released - Type:2 LSID:34639
[1665398347.789414][2559:2559] CHIP:FP: Forgetting fabric 0x1
[1665398347.789482][2559:2559] CHIP:TS: Pending Last Known Good Time: 2022-09-26T18:46:11
[1665398347.789764][2559:2559] CHIP:TS: Previous Last Known Good Time: 2022-09-26T18:46:11
[1665398347.789822][2559:2559] CHIP:TS: Reverted Last Known Good Time to previous value
[1665398347.789906][2559:2559] CHIP:CTL: Shutting down the commissioner
[1665398347.789963][2559:2559] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1665398347.790016][2559:2559] CHIP:CTL: Shutting down the controller
[1665398347.790064][2559:2559] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1665398347.792055][2559:2559] CHIP:DMG: IM WH moving to [Uninitialized]
[1665398347.792143][2559:2559] CHIP:DMG: IM WH moving to [Uninitialized]
[1665398347.792188][2559:2559] CHIP:DMG: IM WH moving to [Uninitialized]
[1665398347.792217][2559:2559] CHIP:DMG: IM WH moving to [Uninitialized]
[1665398347.792291][2559:2559] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1665398347.792406][2559:2559] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1665398347.792749][2559:2559] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-mn5FGy)
[1665398347.793708][2559:2559] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1665398347.793794][2559:2559] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1665398347.793830][2559:2559] CHIP:DL: Inet Layer shutdown
[1665398347.793861][2559:2559] CHIP:DL: BLE shutdown
[1665398347.793892][2559:2559] CHIP:DL: System Layer shutdown
[1665398347.794063][2559:2559] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:454: CHIP Error 0x00000032: Timeout

@bzbarsky-apple
Copy link
Contributor

Yes, that's timing out after 10 seconds, so it's an old-ish chip-tool.

You can pass --timeout 20 (or whatever value you want) to increase the timeout value.

@s07641069
Copy link
Contributor

@bzbarsky-apple Could you point m in which exactly SHA timeout was changed from 10s into 20s ?
Because with chip-tool under TH2.6 image this issue still exist for us with TC-CADMIN-1.19 test.
But if we use same recommendation --timeout 20 we are able to pass this test.
Also with chip tool from master there no such problem.
I just wondering if chip-tool from TH2.6 is still with 10s timeout or this is another issue.

@bzbarsky-apple
Copy link
Contributor

@bzbarsky-apple Could you point m in which exactly SHA timeout was changed from 10s into 20s ?

70253a8

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@s07641069 @bzbarsky-apple @liuck8 @mideayanghui