>>> switch subscribe-event switch-latched 1 100 1 1 [1659776911.274105][3195:3200] CHIP:TOO: Sending command to node 0x1 [1659776911.274212][3195:3200] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1659776911.274312][3195:3200] CHIP:TOO: Sending SubscribeEvent to: [1659776911.274374][3195:3200] CHIP:TOO: cluster 0x0000_003B, event: 0x0000_0000, endpoint 1 [1659776911.274768][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x3 and protocolId (0, 1) on exchange 59683i with MessageCounter:240089695. [1659776911.274904][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089695 to 0x0000000000000001 (1) at monotonic time: 0000000000443AB6 msec [1659776911.275280][3195:3200] CHIP:DMG: MoveToState ReadClient[0xffff6800afc0]: Moving to [AwaitingIn] [1659776911.279428][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610508 on exchange 59683i [1659776911.279481][3195:3200] CHIP:EM: Found matching exchange: 59683i, Delegate: 0xffff6800afd0 [1659776911.279534][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089695 from Retrans Table on exchange 59683i [1659776911.279572][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089695 from RetransTable on exchange 59683i [1659776911.279657][3195:3200] CHIP:DMG: ReportDataMessage = [1659776911.279700][3195:3200] CHIP:DMG: { [1659776911.279758][3195:3200] CHIP:DMG: SubscriptionId = 0x41d1dc6f, [1659776911.279796][3195:3200] CHIP:DMG: EventReportIBs = [1659776911.279860][3195:3200] CHIP:DMG: [ [1659776911.279900][3195:3200] CHIP:DMG: EventReportIB = [1659776911.279959][3195:3200] CHIP:DMG: { [1659776911.280015][3195:3200] CHIP:DMG: EventDataIB = [1659776911.280069][3195:3200] CHIP:DMG: { [1659776911.280129][3195:3200] CHIP:DMG: EventPath = [1659776911.280183][3195:3200] CHIP:DMG: { [1659776911.280256][3195:3200] CHIP:DMG: Endpoint = 0x1, [1659776911.280313][3195:3200] CHIP:DMG: Cluster = 0x3b, [1659776911.280384][3195:3200] CHIP:DMG: Event = 0x0, [1659776911.280441][3195:3200] CHIP:DMG: }, [1659776911.280511][3195:3200] CHIP:DMG: [1659776911.280563][3195:3200] CHIP:DMG: EventNumber = 0x3, [1659776911.280629][3195:3200] CHIP:DMG: PriorityLevel = 0x1, [1659776911.280683][3195:3200] CHIP:DMG: SystemTimestamp = 0x3c135f, [1659776911.280748][3195:3200] CHIP:DMG: EventData = [1659776911.280803][3195:3200] CHIP:DMG: { [1659776911.280874][3195:3200] CHIP:DMG: 0x0 = 1, [1659776911.280971][3195:3200] CHIP:DMG: }, [1659776911.281041][3195:3200] CHIP:DMG: }, [1659776911.281112][3195:3200] CHIP:DMG: [1659776911.281158][3195:3200] CHIP:DMG: }, [1659776911.281211][3195:3200] CHIP:DMG: [1659776911.281249][3195:3200] CHIP:DMG: ], [1659776911.281297][3195:3200] CHIP:DMG: [1659776911.281337][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659776911.281373][3195:3200] CHIP:DMG: } [1659776911.281546][3195:3200] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_003B Event 0x0000_0000 [1659776911.281585][3195:3200] CHIP:TOO: Event number: 3 [1659776911.281620][3195:3200] CHIP:TOO: Priority: Info [1659776911.281654][3195:3200] CHIP:TOO: Timestamp: 3937119 [1659776911.281705][3195:3200] CHIP:TOO: SwitchLatched: { [1659776911.281746][3195:3200] CHIP:TOO: NewPosition: 1 [1659776911.281782][3195:3200] CHIP:TOO: } [1659776911.281852][3195:3200] CHIP:DMG: MoveToState ReadClient[0xffff6800afc0]: Moving to [AwaitingSu] [1659776911.281928][3195:3200] CHIP:EM: Piggybacking Ack for MessageCounter:14610508 on exchange: 59683i [1659776911.282025][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x1 and protocolId (0, 1) on exchange 59683i with MessageCounter:240089696. [1659776911.282082][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089696 to 0x0000000000000001 (1) at monotonic time: 0000000000443ABD msec [1659776911.283938][3195:3200] CHIP:EM: Received message of type 0x4 with protocolId (0, 1) and MessageCounter:14610509 on exchange 59683i [1659776911.283988][3195:3200] CHIP:EM: Found matching exchange: 59683i, Delegate: 0xffff6800afd0 [1659776911.284036][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089696 from Retrans Table on exchange 59683i [1659776911.284073][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089696 from RetransTable on exchange 59683i [1659776911.284139][3195:3200] CHIP:DMG: SubscribeResponseMessage = [1659776911.284182][3195:3200] CHIP:DMG: { [1659776911.284220][3195:3200] CHIP:DMG: SubscriptionId = 0x41d1dc6f, [1659776911.284261][3195:3200] CHIP:DMG: MaxInterval = 0x64, [1659776911.284301][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659776911.284357][3195:3200] CHIP:DMG: } [1659776911.284400][3195:3200] CHIP:DMG: Subscription established with SubscriptionID = 0x41d1dc6f MinInterval = 1s MaxInterval = 100s Peer = 01:0000000000000001 [1659776911.284442][3195:3200] CHIP:DMG: MoveToState ReadClient[0xffff6800afc0]: Moving to [Subscripti] [1659776911.284525][3195:3200] CHIP:DMG: Refresh LivenessCheckTime for 125000 milliseconds with SubscriptionId = 0x41d1dc6f Peer = 01:0000000000000001 [1659776911.284595][3195:3200] CHIP:EM: Sending Standalone Ack for MessageCounter:14610509 on exchange 59683i [1659776911.284688][3195:3200] CHIP:IN: Prepared secure message 0xffff7d45d978 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 59683i with MessageCounter:240089697. [1659776911.284760][3195:3200] CHIP:IN: Sending encrypted msg 0xffff7d45d978 with MessageCounter:240089697 to 0x0000000000000001 (1) at monotonic time: 0000000000443ABF msec [1659776911.284925][3195:3200] CHIP:EM: Flushed pending ack for MessageCounter:14610509 on exchange 59683i >>> switch read current-position 1 1 [1659776954.018085][3195:3200] CHIP:TOO: Sending command to node 0x1 [1659776954.018193][3195:3200] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1659776954.018303][3195:3200] CHIP:TOO: cluster 0x0000_003B, attribute: 0x0000_0001, endpoint 1 [1659776954.018380][3195:3200] CHIP:TOO: Sending ReadAttribute to: [1659776954.018459][3195:3200] CHIP:DMG: SendReadRequest ReadClient[0xffff68003150]: Sending Read Request [1659776954.018834][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x2 and protocolId (0, 1) on exchange 59684i with MessageCounter:240089698. [1659776954.018964][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089698 to 0x0000000000000001 (1) at monotonic time: 000000000044E1AE msec [1659776954.019338][3195:3200] CHIP:DMG: MoveToState ReadClient[0xffff68003150]: Moving to [AwaitingIn] [1659776954.021389][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610510 on exchange 59684i [1659776954.021475][3195:3200] CHIP:EM: Found matching exchange: 59684i, Delegate: 0xffff68003160 [1659776954.021562][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089698 from Retrans Table on exchange 59684i [1659776954.021627][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089698 from RetransTable on exchange 59684i [1659776954.021753][3195:3200] CHIP:DMG: ReportDataMessage = [1659776954.021827][3195:3200] CHIP:DMG: { [1659776954.021914][3195:3200] CHIP:DMG: AttributeReportIBs = [1659776954.021995][3195:3200] CHIP:DMG: [ [1659776954.022090][3195:3200] CHIP:DMG: AttributeReportIB = [1659776954.022191][3195:3200] CHIP:DMG: { [1659776954.022290][3195:3200] CHIP:DMG: AttributeDataIB = [1659776954.022384][3195:3200] CHIP:DMG: { [1659776954.022504][3195:3200] CHIP:DMG: DataVersion = 0x34b335d0, [1659776954.022591][3195:3200] CHIP:DMG: AttributePathIB = [1659776954.022705][3195:3200] CHIP:DMG: { [1659776954.022796][3195:3200] CHIP:DMG: Endpoint = 0x1, [1659776954.022915][3195:3200] CHIP:DMG: Cluster = 0x3b, [1659776954.023017][3195:3200] CHIP:DMG: Attribute = 0x0000_0001, [1659776954.023104][3195:3200] CHIP:DMG: } [1659776954.023195][3195:3200] CHIP:DMG: [1659776954.023289][3195:3200] CHIP:DMG: Data = 1, [1659776954.023370][3195:3200] CHIP:DMG: }, [1659776954.023458][3195:3200] CHIP:DMG: [1659776954.023530][3195:3200] CHIP:DMG: }, [1659776954.023613][3195:3200] CHIP:DMG: [1659776954.023675][3195:3200] CHIP:DMG: ], [1659776954.023752][3195:3200] CHIP:DMG: [1659776954.023816][3195:3200] CHIP:DMG: SuppressResponse = true, [1659776954.023882][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659776954.023943][3195:3200] CHIP:DMG: } [1659776954.024168][3195:3200] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_003B Attribute 0x0000_0001 DataVersion: 884159952 [1659776954.024283][3195:3200] CHIP:TOO: current position: 1 [1659776954.024443][3195:3200] CHIP:EM: Sending Standalone Ack for MessageCounter:14610510 on exchange 59684i [1659776954.024621][3195:3200] CHIP:IN: Prepared secure message 0xffff7d45d978 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 59684i with MessageCounter:240089699. [1659776954.024721][3195:3200] CHIP:IN: Sending encrypted msg 0xffff7d45d978 with MessageCounter:240089699 to 0x0000000000000001 (1) at monotonic time: 000000000044E1B3 msec [1659776954.025017][3195:3200] CHIP:EM: Flushed pending ack for MessageCounter:14610510 on exchange 59684i [1659776995.584886][3195:3200] CHIP:DMG: Subscription Liveness timeout with SubscriptionID = 0xfd9cd82f, Peer = 01:0000000000000001 [1659776995.585056][3195:3200] CHIP:DMG: mResubscribePolicy is null [1659776995.585134][3195:3200] CHIP:TOO: Error: ../../src/app/ReadClient.cpp:762: CHIP Error 0x00000032: Timeout [1659776995.585190][3195:3200] CHIP:DMG: MoveToState ReadClient[0xffff6800aec0]: Moving to [ Idle] [1659777011.292385][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610511 on exchange 44014r [1659777011.292518][3195:3200] CHIP:EM: Handling via exchange: 44014r, Delegate: 0xaaaac56a35a8 [1659777011.292802][3195:3200] CHIP:DMG: ReportDataMessage = [1659777011.292875][3195:3200] CHIP:DMG: { [1659777011.293002][3195:3200] CHIP:DMG: SubscriptionId = 0x41d1dc6f, [1659777011.293111][3195:3200] CHIP:DMG: EventReportIBs = [1659777011.293201][3195:3200] CHIP:DMG: [ [1659777011.293267][3195:3200] CHIP:DMG: EventReportIB = [1659777011.293395][3195:3200] CHIP:DMG: { [1659777011.293473][3195:3200] CHIP:DMG: EventDataIB = [1659777011.293589][3195:3200] CHIP:DMG: { [1659777011.293673][3195:3200] CHIP:DMG: EventPath = [1659777011.293785][3195:3200] CHIP:DMG: { [1659777011.293879][3195:3200] CHIP:DMG: Endpoint = 0x1, [1659777011.294000][3195:3200] CHIP:DMG: Cluster = 0x3b, [1659777011.294091][3195:3200] CHIP:DMG: Event = 0x0, [1659777011.294201][3195:3200] CHIP:DMG: }, [1659777011.294296][3195:3200] CHIP:DMG: [1659777011.294405][3195:3200] CHIP:DMG: EventNumber = 0x5, [1659777011.294496][3195:3200] CHIP:DMG: PriorityLevel = 0x1, [1659777011.294608][3195:3200] CHIP:DMG: SystemTimestamp = 0x44ac30, [1659777011.294693][3195:3200] CHIP:DMG: EventData = [1659777011.294801][3195:3200] CHIP:DMG: { [1659777011.294894][3195:3200] CHIP:DMG: 0x0 = 1, [1659777011.295010][3195:3200] CHIP:DMG: }, [1659777011.295092][3195:3200] CHIP:DMG: }, [1659777011.295190][3195:3200] CHIP:DMG: [1659777011.295262][3195:3200] CHIP:DMG: }, [1659777011.295364][3195:3200] CHIP:DMG: [1659777011.295427][3195:3200] CHIP:DMG: EventReportIB = [1659777011.295518][3195:3200] CHIP:DMG: { [1659777011.295591][3195:3200] CHIP:DMG: EventDataIB = [1659777011.295679][3195:3200] CHIP:DMG: { [1659777011.295757][3195:3200] CHIP:DMG: EventPath = [1659777011.295842][3195:3200] CHIP:DMG: { [1659777011.295930][3195:3200] CHIP:DMG: Endpoint = 0x1, [1659777011.296019][3195:3200] CHIP:DMG: Cluster = 0x3b, [1659777011.296116][3195:3200] CHIP:DMG: Event = 0x0, [1659777011.296201][3195:3200] CHIP:DMG: }, [1659777011.296291][3195:3200] CHIP:DMG: [1659777011.296374][3195:3200] CHIP:DMG: EventNumber = 0x6, [1659777011.296462][3195:3200] CHIP:DMG: PriorityLevel = 0x1, [1659777011.296547][3195:3200] CHIP:DMG: DeltaSystemTimestamp = 0x24be, [1659777011.296631][3195:3200] CHIP:DMG: EventData = [1659777011.296716][3195:3200] CHIP:DMG: { [1659777011.296836][3195:3200] CHIP:DMG: 0x0 = 1, [1659777011.296958][3195:3200] CHIP:DMG: }, [1659777011.297042][3195:3200] CHIP:DMG: }, [1659777011.297157][3195:3200] CHIP:DMG: [1659777011.297230][3195:3200] CHIP:DMG: }, [1659777011.297333][3195:3200] CHIP:DMG: [1659777011.297425][3195:3200] CHIP:DMG: EventReportIB = [1659777011.297519][3195:3200] CHIP:DMG: { [1659777011.297613][3195:3200] CHIP:DMG: EventDataIB = [1659777011.297699][3195:3200] CHIP:DMG: { [1659777011.297800][3195:3200] CHIP:DMG: EventPath = [1659777011.297889][3195:3200] CHIP:DMG: { [1659777011.297978][3195:3200] CHIP:DMG: Endpoint = 0x1, [1659777011.298096][3195:3200] CHIP:DMG: Cluster = 0x3b, [1659777011.298188][3195:3200] CHIP:DMG: Event = 0x0, [1659777011.298298][3195:3200] CHIP:DMG: }, [1659777011.298398][3195:3200] CHIP:DMG: [1659777011.298503][3195:3200] CHIP:DMG: EventNumber = 0x7, [1659777011.298595][3195:3200] CHIP:DMG: PriorityLevel = 0x1, [1659777011.298681][3195:3200] CHIP:DMG: DeltaSystemTimestamp = 0xa07, [1659777011.298793][3195:3200] CHIP:DMG: EventData = [1659777011.298881][3195:3200] CHIP:DMG: { [1659777011.298991][3195:3200] CHIP:DMG: 0x0 = 1, [1659777011.299085][3195:3200] CHIP:DMG: }, [1659777011.299192][3195:3200] CHIP:DMG: }, [1659777011.299285][3195:3200] CHIP:DMG: [1659777011.299378][3195:3200] CHIP:DMG: }, [1659777011.299465][3195:3200] CHIP:DMG: [1659777011.299547][3195:3200] CHIP:DMG: ], [1659777011.299655][3195:3200] CHIP:DMG: [1659777011.299746][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659777011.299810][3195:3200] CHIP:DMG: } [1659777011.300166][3195:3200] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_003B Event 0x0000_0000 [1659777011.300231][3195:3200] CHIP:TOO: Event number: 5 [1659777011.300290][3195:3200] CHIP:TOO: Priority: Info [1659777011.300347][3195:3200] CHIP:TOO: Timestamp: 4500528 [1659777011.300432][3195:3200] CHIP:TOO: SwitchLatched: { [1659777011.300499][3195:3200] CHIP:TOO: NewPosition: 1 [1659777011.300556][3195:3200] CHIP:TOO: } [1659777011.300802][3195:3200] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_003B Event 0x0000_0000 [1659777011.300865][3195:3200] CHIP:TOO: Event number: 6 [1659777011.300950][3195:3200] CHIP:TOO: Priority: Info [1659777011.301033][3195:3200] CHIP:TOO: Timestamp: 4509934 [1659777011.301108][3195:3200] CHIP:TOO: SwitchLatched: { [1659777011.301170][3195:3200] CHIP:TOO: NewPosition: 1 [1659777011.301228][3195:3200] CHIP:TOO: } [1659777011.301471][3195:3200] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_003B Event 0x0000_0000 [1659777011.301532][3195:3200] CHIP:TOO: Event number: 7 [1659777011.301590][3195:3200] CHIP:TOO: Priority: Info [1659777011.301646][3195:3200] CHIP:TOO: Timestamp: 4512501 [1659777011.301741][3195:3200] CHIP:TOO: SwitchLatched: { [1659777011.301804][3195:3200] CHIP:TOO: NewPosition: 1 [1659777011.301862][3195:3200] CHIP:TOO: } [1659777011.302063][3195:3200] CHIP:DMG: Refresh LivenessCheckTime for 125000 milliseconds with SubscriptionId = 0x41d1dc6f Peer = 01:0000000000000001 [1659777011.302206][3195:3200] CHIP:EM: Piggybacking Ack for MessageCounter:14610511 on exchange: 44014r [1659777011.302574][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x1 and protocolId (0, 1) on exchange 44014r with MessageCounter:240089700. [1659777011.302672][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089700 to 0x0000000000000001 (1) at monotonic time: 000000000045C171 msec [1659777011.304581][3195:3200] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:14610512 on exchange 44014r [1659777011.304664][3195:3200] CHIP:EM: Found matching exchange: 44014r, Delegate: (nil) [1659777011.304744][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089700 from Retrans Table on exchange 44014r [1659777011.304798][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089700 from RetransTable on exchange 44014r [1659777111.293440][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610513 on exchange 44015r [1659777111.293537][3195:3200] CHIP:EM: Handling via exchange: 44015r, Delegate: 0xaaaac56a35a8 [1659777111.293647][3195:3200] CHIP:DMG: ReportDataMessage = [1659777111.293691][3195:3200] CHIP:DMG: { [1659777111.293729][3195:3200] CHIP:DMG: SubscriptionId = 0x41d1dc6f, [1659777111.293770][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659777111.293807][3195:3200] CHIP:DMG: } [1659777111.293903][3195:3200] CHIP:DMG: Refresh LivenessCheckTime for 125000 milliseconds with SubscriptionId = 0x41d1dc6f Peer = 01:0000000000000001 [1659777111.293978][3195:3200] CHIP:EM: Piggybacking Ack for MessageCounter:14610513 on exchange: 44015r [1659777111.294093][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x1 and protocolId (0, 1) on exchange 44015r with MessageCounter:240089701. [1659777111.294169][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089701 to 0x0000000000000001 (1) at monotonic time: 0000000000474809 msec [1659777111.295677][3195:3200] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:14610514 on exchange 44015r [1659777111.295759][3195:3200] CHIP:EM: Found matching exchange: 44015r, Delegate: (nil) [1659777111.295840][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089701 from Retrans Table on exchange 44015r [1659777111.295902][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089701 from RetransTable on exchange 44015r >>> switch subscribe-event multi-press-complete 1 100 1 1 [1659777122.646137][3195:3200] CHIP:TOO: Sending command to node 0x1 [1659777122.646235][3195:3200] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1659777122.646321][3195:3200] CHIP:TOO: Sending SubscribeEvent to: [1659777122.646375][3195:3200] CHIP:TOO: cluster 0x0000_003B, event: 0x0000_0006, endpoint 1 [1659777122.646726][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x3 and protocolId (0, 1) on exchange 59685i with MessageCounter:240089702. [1659777122.646842][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089702 to 0x0000000000000001 (1) at monotonic time: 0000000000477461 msec [1659777122.647175][3195:3200] CHIP:DMG: MoveToState ReadClient[0xffff6800aec0]: Moving to [AwaitingIn] [1659777122.651570][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610515 on exchange 59685i [1659777122.651646][3195:3200] CHIP:EM: Found matching exchange: 59685i, Delegate: 0xffff6800aed0 [1659777122.651722][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089702 from Retrans Table on exchange 59685i [1659777122.651777][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089702 from RetransTable on exchange 59685i [1659777122.651879][3195:3200] CHIP:DMG: ReportDataMessage = [1659777122.651950][3195:3200] CHIP:DMG: { [1659777122.652031][3195:3200] CHIP:DMG: SubscriptionId = 0xaf6f42e8, [1659777122.652090][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659777122.652169][3195:3200] CHIP:DMG: } [1659777122.652252][3195:3200] CHIP:DMG: MoveToState ReadClient[0xffff6800aec0]: Moving to [AwaitingSu] [1659777122.652382][3195:3200] CHIP:EM: Piggybacking Ack for MessageCounter:14610515 on exchange: 59685i [1659777122.652545][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x1 and protocolId (0, 1) on exchange 59685i with MessageCounter:240089703. [1659777122.652625][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089703 to 0x0000000000000001 (1) at monotonic time: 0000000000477467 msec [1659777122.654842][3195:3200] CHIP:EM: Received message of type 0x4 with protocolId (0, 1) and MessageCounter:14610516 on exchange 59685i [1659777122.654922][3195:3200] CHIP:EM: Found matching exchange: 59685i, Delegate: 0xffff6800aed0 [1659777122.654997][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089703 from Retrans Table on exchange 59685i [1659777122.655051][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089703 from RetransTable on exchange 59685i [1659777122.655152][3195:3200] CHIP:DMG: SubscribeResponseMessage = [1659777122.655214][3195:3200] CHIP:DMG: { [1659777122.655268][3195:3200] CHIP:DMG: SubscriptionId = 0xaf6f42e8, [1659777122.655358][3195:3200] CHIP:DMG: MaxInterval = 0x64, [1659777122.655415][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659777122.655467][3195:3200] CHIP:DMG: } [1659777122.655545][3195:3200] CHIP:DMG: Subscription established with SubscriptionID = 0xaf6f42e8 MinInterval = 1s MaxInterval = 100s Peer = 01:0000000000000001 [1659777122.655606][3195:3200] CHIP:DMG: MoveToState ReadClient[0xffff6800aec0]: Moving to [Subscripti] [1659777122.655717][3195:3200] CHIP:DMG: Refresh LivenessCheckTime for 125000 milliseconds with SubscriptionId = 0xaf6f42e8 Peer = 01:0000000000000001 [1659777122.655890][3195:3200] CHIP:EM: Sending Standalone Ack for MessageCounter:14610516 on exchange 59685i [1659777122.656114][3195:3200] CHIP:IN: Prepared secure message 0xffff7d45d978 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 59685i with MessageCounter:240089704. [1659777122.656191][3195:3200] CHIP:IN: Sending encrypted msg 0xffff7d45d978 with MessageCounter:240089704 to 0x0000000000000001 (1) at monotonic time: 000000000047746B msec [1659777122.656370][3195:3200] CHIP:EM: Flushed pending ack for MessageCounter:14610516 on exchange 59685i [1659777222.665001][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610517 on exchange 44016r [1659777222.665130][3195:3200] CHIP:EM: Handling via exchange: 44016r, Delegate: 0xaaaac56a35a8 [1659777222.665291][3195:3200] CHIP:DMG: ReportDataMessage = [1659777222.665366][3195:3200] CHIP:DMG: { [1659777222.665429][3195:3200] CHIP:DMG: SubscriptionId = 0xaf6f42e8, [1659777222.665500][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659777222.665562][3195:3200] CHIP:DMG: } [1659777222.665704][3195:3200] CHIP:DMG: Refresh LivenessCheckTime for 125000 milliseconds with SubscriptionId = 0xaf6f42e8 Peer = 01:0000000000000001 [1659777222.665823][3195:3200] CHIP:EM: Piggybacking Ack for MessageCounter:14610517 on exchange: 44016r [1659777222.666001][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x1 and protocolId (0, 1) on exchange 44016r with MessageCounter:240089705. [1659777222.666117][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089705 to 0x0000000000000001 (1) at monotonic time: 000000000048FB15 msec [1659777222.667417][3195:3200] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:14610518 on exchange 44016r [1659777222.667497][3195:3200] CHIP:EM: Found matching exchange: 44016r, Delegate: (nil) [1659777222.667577][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089705 from Retrans Table on exchange 44016r [1659777222.667639][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089705 from RetransTable on exchange 44016r [1659777236.308523][3195:3200] CHIP:DMG: Subscription Liveness timeout with SubscriptionID = 0x41d1dc6f, Peer = 01:0000000000000001 [1659777236.308630][3195:3200] CHIP:DMG: mResubscribePolicy is null [1659777236.308708][3195:3200] CHIP:TOO: Error: ../../src/app/ReadClient.cpp:762: CHIP Error 0x00000032: Timeout [1659777236.308766][3195:3200] CHIP:DMG: MoveToState ReadClient[0xffff6800afc0]: Moving to [ Idle] [1659777322.669116][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610519 on exchange 44017r [1659777322.669250][3195:3200] CHIP:EM: Handling via exchange: 44017r, Delegate: 0xaaaac56a35a8 [1659777322.669413][3195:3200] CHIP:DMG: ReportDataMessage = [1659777322.669487][3195:3200] CHIP:DMG: { [1659777322.669550][3195:3200] CHIP:DMG: SubscriptionId = 0xaf6f42e8, [1659777322.669617][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659777322.669679][3195:3200] CHIP:DMG: } [1659777322.669823][3195:3200] CHIP:DMG: Refresh LivenessCheckTime for 125000 milliseconds with SubscriptionId = 0xaf6f42e8 Peer = 01:0000000000000001 [1659777322.669966][3195:3200] CHIP:EM: Piggybacking Ack for MessageCounter:14610519 on exchange: 44017r [1659777322.670115][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x1 and protocolId (0, 1) on exchange 44017r with MessageCounter:240089706. [1659777322.670232][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089706 to 0x0000000000000001 (1) at monotonic time: 00000000004A81B9 msec [1659777322.672404][3195:3200] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:14610520 on exchange 44017r [1659777322.672488][3195:3200] CHIP:EM: Found matching exchange: 44017r, Delegate: (nil) [1659777322.672569][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089706 from Retrans Table on exchange 44017r [1659777322.672632][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089706 from RetransTable on exchange 44017r [1659777422.679056][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610521 on exchange 44018r [1659777422.679130][3195:3200] CHIP:EM: Handling via exchange: 44018r, Delegate: 0xaaaac56a35a8 [1659777422.679208][3195:3200] CHIP:DMG: ReportDataMessage = [1659777422.679234][3195:3200] CHIP:DMG: { [1659777422.679257][3195:3200] CHIP:DMG: SubscriptionId = 0xaf6f42e8, [1659777422.679280][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659777422.679301][3195:3200] CHIP:DMG: } [1659777422.679343][3195:3200] CHIP:DMG: Refresh LivenessCheckTime for 125000 milliseconds with SubscriptionId = 0xaf6f42e8 Peer = 01:0000000000000001 [1659777422.679416][3195:3200] CHIP:EM: Piggybacking Ack for MessageCounter:14610521 on exchange: 44018r [1659777422.679497][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x1 and protocolId (0, 1) on exchange 44018r with MessageCounter:240089707. [1659777422.679542][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089707 to 0x0000000000000001 (1) at monotonic time: 00000000004C0862 msec [1659777422.681475][3195:3200] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:14610522 on exchange 44018r [1659777422.681520][3195:3200] CHIP:EM: Found matching exchange: 44018r, Delegate: (nil) [1659777422.681560][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089707 from Retrans Table on exchange 44018r [1659777422.681592][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089707 from RetransTable on exchange 44018r [1659777522.684661][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610523 on exchange 44019r [1659777522.684793][3195:3200] CHIP:EM: Handling via exchange: 44019r, Delegate: 0xaaaac56a35a8 [1659777522.685012][3195:3200] CHIP:DMG: ReportDataMessage = [1659777522.685087][3195:3200] CHIP:DMG: { [1659777522.685151][3195:3200] CHIP:DMG: SubscriptionId = 0xaf6f42e8, [1659777522.685219][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659777522.685282][3195:3200] CHIP:DMG: } [1659777522.685426][3195:3200] CHIP:DMG: Refresh LivenessCheckTime for 125000 milliseconds with SubscriptionId = 0xaf6f42e8 Peer = 01:0000000000000001 [1659777522.685566][3195:3200] CHIP:EM: Piggybacking Ack for MessageCounter:14610523 on exchange: 44019r [1659777522.685719][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x1 and protocolId (0, 1) on exchange 44019r with MessageCounter:240089708. [1659777522.685838][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089708 to 0x0000000000000001 (1) at monotonic time: 00000000004D8F08 msec [1659777522.687696][3195:3200] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:14610524 on exchange 44019r [1659777522.687778][3195:3200] CHIP:EM: Found matching exchange: 44019r, Delegate: (nil) [1659777522.687858][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089708 from Retrans Table on exchange 44019r [1659777522.687920][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089708 from RetransTable on exchange 44019r [1659777622.699643][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610525 on exchange 44020r [1659777622.699780][3195:3200] CHIP:EM: Handling via exchange: 44020r, Delegate: 0xaaaac56a35a8 [1659777622.699941][3195:3200] CHIP:DMG: ReportDataMessage = [1659777622.700013][3195:3200] CHIP:DMG: { [1659777622.700079][3195:3200] CHIP:DMG: SubscriptionId = 0xaf6f42e8, [1659777622.700148][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659777622.700210][3195:3200] CHIP:DMG: } [1659777622.700350][3195:3200] CHIP:DMG: Refresh LivenessCheckTime for 125000 milliseconds with SubscriptionId = 0xaf6f42e8 Peer = 01:0000000000000001 [1659777622.700463][3195:3200] CHIP:EM: Piggybacking Ack for MessageCounter:14610525 on exchange: 44020r [1659777622.700639][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x1 and protocolId (0, 1) on exchange 44020r with MessageCounter:240089709. [1659777622.700800][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089709 to 0x0000000000000001 (1) at monotonic time: 00000000004F15B7 msec [1659777622.703029][3195:3200] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:14610526 on exchange 44020r [1659777622.703106][3195:3200] CHIP:EM: Found matching exchange: 44020r, Delegate: (nil) [1659777622.703169][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089709 from Retrans Table on exchange 44020r [1659777622.703217][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089709 from RetransTable on exchange 44020r [1659777722.713855][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610527 on exchange 44021r [1659777722.713927][3195:3200] CHIP:EM: Handling via exchange: 44021r, Delegate: 0xaaaac56a35a8 [1659777722.714004][3195:3200] CHIP:DMG: ReportDataMessage = [1659777722.714029][3195:3200] CHIP:DMG: { [1659777722.714052][3195:3200] CHIP:DMG: SubscriptionId = 0xaf6f42e8, [1659777722.714074][3195:3200] CHIP:DMG: InteractionModelRevision = 1 [1659777722.714095][3195:3200] CHIP:DMG: } [1659777722.714137][3195:3200] CHIP:DMG: Refresh LivenessCheckTime for 125000 milliseconds with SubscriptionId = 0xaf6f42e8 Peer = 01:0000000000000001 [1659777722.714208][3195:3200] CHIP:EM: Piggybacking Ack for MessageCounter:14610527 on exchange: 44021r [1659777722.714285][3195:3200] CHIP:IN: Prepared secure message 0xffff68006278 to 0x0000000000000001 (1) of type 0x1 and protocolId (0, 1) on exchange 44021r with MessageCounter:240089710. [1659777722.714329][3195:3200] CHIP:IN: Sending encrypted msg 0xffff68006278 with MessageCounter:240089710 to 0x0000000000000001 (1) at monotonic time: 0000000000509C65 msec [1659777722.716329][3195:3200] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:14610528 on exchange 44021r [1659777722.716359][3195:3200] CHIP:EM: Found matching exchange: 44021r, Delegate: (nil) [1659777722.716387][3195:3200] CHIP:EM: Rxd Ack; Removing MessageCounter:240089710 from Retrans Table on exchange 44021r [1659777722.716408][3195:3200] CHIP:EM: Removed CHIP MessageCounter:240089710 from RetransTable on exchange 44021r [1659777822.723634][3195:3200] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:14610529 on exchange 44022r [1659777822.723774][3195:3200] CHIP:EM: Handling via exchange: 44022r, Delegate: 0xaaaac56a35a8