[1691473680.859559][175121:175121] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1691473680.860944][175121:175121] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1691473680.860997][175121:175121] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1691473680.861011][175121:175121] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1691473680.861069][175121:175121] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-4XZ05W) [1691473680.861175][175121:175121] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1691473680.861204][175121:175121] CHIP:DL: NVS set: chip-counters/reboot-count = 13 (0xD) [1691473680.861297][175121:175121] CHIP:DL: Got Ethernet interface: eth0 [1691473680.861362][175121:175121] CHIP:DL: Found the primary Ethernet interface:eth0 [1691473680.861403][175121:175121] CHIP:DL: Failed to get WiFi interface [1691473680.861419][175121:175121] CHIP:DL: Failed to reset WiFi statistic counts [1691473680.861433][175121:175121] CHIP:IN: UDP::Init bind&listen port=0 [1691473680.861446][175121:175121] CHIP:IN: UDP::Init bound to port=52026 [1691473680.861449][175121:175121] CHIP:IN: UDP::Init bind&listen port=0 [1691473680.861455][175121:175121] CHIP:IN: UDP::Init bound to port=60388 [1691473680.861458][175121:175121] CHIP:IN: BLEBase::Init - setting/overriding transport [1691473680.861459][175121:175121] CHIP:IN: TransportMgr initialized [1691473680.861466][175121:175121] CHIP:FP: Initializing FabricTable from persistent storage [1691473680.861522][175121:175121] CHIP:TS: Last Known Good Time: 2023-08-07T11:26:55 [1691473680.861868][175121:175121] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x5B53930E0EAEF3A1, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1691473680.862760][175121:175121] CHIP:ZCL: Using ZAP configuration... [1691473680.863122][175121:175121] CHIP:CTL: System State Initialized... [1691473680.863184][175121:175121] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1691473680.863200][175121:175121] CHIP:CTL: Setting attestation nonce to random value [1691473680.863210][175121:175121] CHIP:CTL: Setting CSR nonce to random value [1691473680.863223][175121:175121] CHIP:IN: UDP::Init bind&listen port=5550 [1691473680.863231][175121:175121] CHIP:IN: UDP::Init bound to port=5550 [1691473680.863234][175121:175121] CHIP:IN: UDP::Init bind&listen port=5550 [1691473680.863239][175121:175121] CHIP:IN: UDP::Init bound to port=5550 [1691473680.863241][175121:175121] CHIP:IN: TransportMgr initialized [1691473680.863344][175121:175123] CHIP:DL: CHIP task running [1691473680.863399][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1691473680.863477][175121:175123] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1691473680.863501][175121:175123] CHIP:CTL: Setting attestation nonce to random value [1691473680.863546][175121:175123] CHIP:CTL: Setting CSR nonce to random value [1691473680.863803][175121:175123] CHIP:CTL: Generating NOC [1691473680.864037][175121:175123] CHIP:FP: Validating NOC chain [1691473680.864376][175121:175123] CHIP:FP: NOC chain validation successful [1691473680.864432][175121:175123] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1691473680.864440][175121:175123] CHIP:TS: Last Known Good Time: 2023-08-07T11:26:55 [1691473680.864442][175121:175123] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1691473680.864444][175121:175123] CHIP:TS: Retaining current Last Known Good Time [1691473680.867173][175121:175123] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1691473680.868287][175121:175123] CHIP:TS: Committing Last Known Good Time to storage: 2023-08-07T11:26:55 [1691473680.868875][175121:175123] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 5B53930E0EAEF3A1) [1691473680.868909][175121:175123] CHIP:IN: UDP::Init bind&listen port=5550 [1691473680.868924][175121:175123] CHIP:IN: UDP::Init bound to port=5550 [1691473680.868931][175121:175123] CHIP:IN: UDP::Init bind&listen port=5550 [1691473680.868938][175121:175123] CHIP:IN: UDP::Init bound to port=5550 [1691473680.868943][175121:175123] CHIP:IN: TransportMgr initialized [1691473680.872615][175121:175123] CHIP:TOO: ***** Test Start : Test_TC_SMOKECO_2_6 [1691473680.872647][175121:175123] CHIP:TOO: ***** Test Step 0 : Commission DUT to TH [1691473680.872709][175121:175123] CHIP:IN: Expiring all sessions for node <0000000000000001, 1>!! [1691473680.872758][175121:175123] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1691473680.872776][175121:175123] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1691473680.872786][175121:175123] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1691473680.873280][175121:175123] CHIP:DIS: UDP:[fe80::215:5dff:fe83:df65%eth0]:5540: new best score: 7 [1691473680.873317][175121:175123] CHIP:DIS: UDP:172.20.0.6%eth0:5540: score has not improved: 2 [1691473680.873322][175121:175123] CHIP:DIS: Checking node lookup status after 0 ms [1691473680.873324][175121:175123] CHIP:DIS: Keeping DNSSD lookup active [1691473680.873474][175121:175123] CHIP:DIS: UDP:[fe80::215:5dff:fe83:df65%eth0]:5540: score has not improved: 7 [1691473680.873508][175121:175123] CHIP:DIS: UDP:172.20.0.6%eth0:5540: score has not improved: 2 [1691473680.873513][175121:175123] CHIP:DIS: Checking node lookup status after 1 ms [1691473680.873516][175121:175123] CHIP:DIS: Keeping DNSSD lookup active [1691473680.873646][175121:175123] CHIP:DIS: UDP:172.17.0.1%docker0:5540: score has not improved: 2 [1691473680.873675][175121:175123] CHIP:DIS: Checking node lookup status after 1 ms [1691473680.873680][175121:175123] CHIP:DIS: Keeping DNSSD lookup active [1691473681.072967][175121:175123] CHIP:DIS: Checking node lookup status after 200 ms [1691473681.073031][175121:175123] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::215:5dff:fe83:df65%eth0]:5540 while in state 2 [1691473681.073037][175121:175123] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1691473681.073091][175121:175123] CHIP:IN: SecureSession[0x7f6e1000b0e0]: Allocated Type:2 LSID:53893 [1691473681.073101][175121:175123] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1691473681.073323][175121:175123] CHIP:EM: <<< [E:31912i S:0 M:223697644] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1691473681.073364][175121:175123] CHIP:IN: (U) Sending msg 223697644 to IP address 'UDP:[fe80::215:5dff:fe83:df65%eth0]:5540' [1691473681.073412][175121:175123] CHIP:SC: Sent Sigma1 msg [1691473681.073432][175121:175123] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1691473681.073441][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.075606][175121:175123] CHIP:EM: >>> [E:31912i S:0 M:142776306 (Ack:223697644)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1691473681.075654][175121:175123] CHIP:EM: Found matching exchange: 31912i, Delegate: 0x7f6e1000e238 [1691473681.075665][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:223697644 from Retrans Table on exchange 31912i [1691473681.075674][175121:175123] CHIP:SC: Received Sigma2 msg [1691473681.075688][175121:175123] CHIP:SC: Peer assigned session session ID 33002 [1691473681.076376][175121:175123] CHIP:SC: Sending Sigma3 [1691473681.076515][175121:175123] CHIP:EM: <<< [E:31912i S:0 M:223697645 (Ack:142776306)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1691473681.076554][175121:175123] CHIP:IN: (U) Sending msg 223697645 to IP address 'UDP:[fe80::215:5dff:fe83:df65%eth0]:5540' [1691473681.076588][175121:175123] CHIP:SC: Sent Sigma3 msg [1691473681.076611][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.076617][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.087302][175121:175123] CHIP:EM: >>> [E:31912i S:0 M:142776307 (Ack:223697645)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1691473681.087354][175121:175123] CHIP:EM: Found matching exchange: 31912i, Delegate: 0x7f6e1000e238 [1691473681.087369][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:223697645 from Retrans Table on exchange 31912i [1691473681.087380][175121:175123] CHIP:SC: Success status report received. Session was established [1691473681.099872][175121:175123] CHIP:SC: SecureSession[0x7f6e1000b0e0, LSID:53893]: State change 'kEstablishing' --> 'kActive' [1691473681.099901][175121:175123] CHIP:IN: SecureSession[0x7f6e1000b0e0]: Activated - Type:2 LSID:53893 [1691473681.099907][175121:175123] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:53893 PSID:33002! [1691473681.099913][175121:175123] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1691473681.099929][175121:175123] CHIP:TOO: **** Test Setup: Device Connected [1691473681.099955][175121:175123] CHIP:EM: <<< [E:31912i S:0 M:223697646 (Ack:142776307)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473681.099976][175121:175123] CHIP:IN: (U) Sending msg 223697646 to IP address 'UDP:[fe80::215:5dff:fe83:df65%eth0]:5540' [1691473681.100016][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:142776307 on exchange 31912i [1691473681.100041][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.100058][175121:175123] CHIP:TOO: ***** Test Step 1 : TH reads ExpressedState attribute from DUT [1691473681.100068][175121:175123] CHIP:TOO: Sending ReadAttribute to: [1691473681.100081][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0000, endpoint 1 [1691473681.100102][175121:175123] CHIP:DMG: SendReadRequest ReadClient[0x7f6e1000fc20]: Sending Read Request [1691473681.100136][175121:175123] CHIP:EM: <<< [E:31913i S:53893 M:111219928] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473681.100156][175121:175123] CHIP:IN: (S) Sending msg 111219928 on secure session with LSID: 53893 [1691473681.100180][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e1000fc20]: Moving to [AwaitingIn] [1691473681.100202][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.100952][175121:175123] CHIP:EM: >>> [E:31913i S:53893 M:156510088 (Ack:111219928)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473681.100989][175121:175123] CHIP:EM: Found matching exchange: 31913i, Delegate: 0x7f6e1000fc30 [1691473681.100999][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219928 from Retrans Table on exchange 31913i [1691473681.101013][175121:175123] CHIP:DMG: ReportDataMessage = [1691473681.101017][175121:175123] CHIP:DMG: { [1691473681.101019][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473681.101022][175121:175123] CHIP:DMG: [ [1691473681.101024][175121:175123] CHIP:DMG: AttributeReportIB = [1691473681.101028][175121:175123] CHIP:DMG: { [1691473681.101030][175121:175123] CHIP:DMG: AttributeDataIB = [1691473681.101032][175121:175123] CHIP:DMG: { [1691473681.101035][175121:175123] CHIP:DMG: DataVersion = 0x220ec228, [1691473681.101037][175121:175123] CHIP:DMG: AttributePathIB = [1691473681.101039][175121:175123] CHIP:DMG: { [1691473681.101041][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473681.101043][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473681.101045][175121:175123] CHIP:DMG: Attribute = 0x0000_0000, [1691473681.101047][175121:175123] CHIP:DMG: } [1691473681.101050][175121:175123] CHIP:DMG: [1691473681.101053][175121:175123] CHIP:DMG: Data = 0, [1691473681.101055][175121:175123] CHIP:DMG: }, [1691473681.101057][175121:175123] CHIP:DMG: [1691473681.101059][175121:175123] CHIP:DMG: }, [1691473681.101062][175121:175123] CHIP:DMG: [1691473681.101064][175121:175123] CHIP:DMG: ], [1691473681.101067][175121:175123] CHIP:DMG: [1691473681.101074][175121:175123] CHIP:DMG: SuppressResponse = true, [1691473681.101076][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.101078][175121:175123] CHIP:DMG: } [1691473681.101143][175121:175123] CHIP:EM: <<< [E:31913i S:53893 M:111219929 (Ack:156510088)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473681.101178][175121:175123] CHIP:IN: (S) Sending msg 111219929 on secure session with LSID: 53893 [1691473681.101205][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510088 on exchange 31913i [1691473681.101214][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.101221][175121:175123] CHIP:TOO: ***** Test Step 2 : TH subscribes to BatteryAlert attribute from DUT [1691473681.101228][175121:175123] CHIP:TOO: Sending SubscribeAttribute to: [1691473681.101232][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0003, endpoint 1 [1691473681.101253][175121:175123] CHIP:EM: <<< [E:31914i S:53893 M:111219930] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:03 (IM:SubscribeRequest) [1691473681.101272][175121:175123] CHIP:IN: (S) Sending msg 111219930 on secure session with LSID: 53893 [1691473681.101291][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e1000fc20]: Moving to [AwaitingIn] [1691473681.101299][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.105776][175121:175123] CHIP:EM: >>> [E:31914i S:53893 M:156510089 (Ack:111219930)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473681.105816][175121:175123] CHIP:EM: Found matching exchange: 31914i, Delegate: 0x7f6e1000fc30 [1691473681.105828][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219930 from Retrans Table on exchange 31914i [1691473681.105849][175121:175123] CHIP:DMG: ReportDataMessage = [1691473681.105854][175121:175123] CHIP:DMG: { [1691473681.105858][175121:175123] CHIP:DMG: SubscriptionId = 0x21deb51b, [1691473681.105860][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473681.105865][175121:175123] CHIP:DMG: [ [1691473681.105867][175121:175123] CHIP:DMG: AttributeReportIB = [1691473681.105870][175121:175123] CHIP:DMG: { [1691473681.105872][175121:175123] CHIP:DMG: AttributeDataIB = [1691473681.105874][175121:175123] CHIP:DMG: { [1691473681.105877][175121:175123] CHIP:DMG: DataVersion = 0x220ec228, [1691473681.105879][175121:175123] CHIP:DMG: AttributePathIB = [1691473681.105882][175121:175123] CHIP:DMG: { [1691473681.105884][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473681.105886][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473681.105889][175121:175123] CHIP:DMG: Attribute = 0x0000_0003, [1691473681.105890][175121:175123] CHIP:DMG: } [1691473681.105893][175121:175123] CHIP:DMG: [1691473681.105896][175121:175123] CHIP:DMG: Data = 0, [1691473681.105897][175121:175123] CHIP:DMG: }, [1691473681.105900][175121:175123] CHIP:DMG: [1691473681.105902][175121:175123] CHIP:DMG: }, [1691473681.105905][175121:175123] CHIP:DMG: [1691473681.105907][175121:175123] CHIP:DMG: ], [1691473681.105910][175121:175123] CHIP:DMG: [1691473681.105913][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.105914][175121:175123] CHIP:DMG: } [1691473681.105942][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e1000fc20]: Moving to [AwaitingSu] [1691473681.105965][175121:175123] CHIP:EM: <<< [E:31914i S:53893 M:111219931 (Ack:156510089)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473681.105971][175121:175123] CHIP:IN: (S) Sending msg 111219931 on secure session with LSID: 53893 [1691473681.106009][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.106016][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.106617][175121:175123] CHIP:EM: >>> [E:31914i S:53893 M:156510090 (Ack:111219931)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:04 (IM:SubscribeResponse) [1691473681.106664][175121:175123] CHIP:EM: Found matching exchange: 31914i, Delegate: 0x7f6e1000fc30 [1691473681.106688][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219931 from Retrans Table on exchange 31914i [1691473681.106696][175121:175123] CHIP:DMG: SubscribeResponse is received [1691473681.106705][175121:175123] CHIP:DMG: SubscribeResponseMessage = [1691473681.106710][175121:175123] CHIP:DMG: { [1691473681.106713][175121:175123] CHIP:DMG: SubscriptionId = 0x21deb51b, [1691473681.106717][175121:175123] CHIP:DMG: MaxInterval = 0x1e, [1691473681.106719][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.106722][175121:175123] CHIP:DMG: } [1691473681.106726][175121:175123] CHIP:DMG: Subscription established with SubscriptionID = 0x21deb51b MinInterval = 3s MaxInterval = 30s Peer = 01:0000000000000001 [1691473681.106731][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e1000fc20]: Moving to [Subscripti] [1691473681.106742][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x21deb51b Peer = 01:0000000000000001 [1691473681.106762][175121:175123] CHIP:EM: <<< [E:31914i S:53893 M:111219932 (Ack:156510090)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473681.106784][175121:175123] CHIP:IN: (S) Sending msg 111219932 on secure session with LSID: 53893 [1691473681.106819][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510090 on exchange 31914i [1691473681.106831][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.106842][175121:175123] CHIP:TOO: ***** Test Step 3 : TH subscribes to InterconnectSmokeAlarm attribute from DUT [1691473681.106860][175121:175123] CHIP:TOO: Sending SubscribeAttribute to: [1691473681.106868][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0008, endpoint 1 [1691473681.106904][175121:175123] CHIP:EM: <<< [E:31915i S:53893 M:111219933] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:03 (IM:SubscribeRequest) [1691473681.106928][175121:175123] CHIP:IN: (S) Sending msg 111219933 on secure session with LSID: 53893 [1691473681.106952][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e100122e0]: Moving to [AwaitingIn] [1691473681.106965][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.111818][175121:175123] CHIP:EM: >>> [E:31915i S:53893 M:156510091 (Ack:111219933)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473681.111870][175121:175123] CHIP:EM: Found matching exchange: 31915i, Delegate: 0x7f6e100122f0 [1691473681.111883][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219933 from Retrans Table on exchange 31915i [1691473681.111898][175121:175123] CHIP:DMG: ReportDataMessage = [1691473681.111902][175121:175123] CHIP:DMG: { [1691473681.111905][175121:175123] CHIP:DMG: SubscriptionId = 0xd198a9a4, [1691473681.111906][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473681.111910][175121:175123] CHIP:DMG: [ [1691473681.111912][175121:175123] CHIP:DMG: AttributeReportIB = [1691473681.111916][175121:175123] CHIP:DMG: { [1691473681.111918][175121:175123] CHIP:DMG: AttributeDataIB = [1691473681.111920][175121:175123] CHIP:DMG: { [1691473681.111922][175121:175123] CHIP:DMG: DataVersion = 0x220ec228, [1691473681.111924][175121:175123] CHIP:DMG: AttributePathIB = [1691473681.111927][175121:175123] CHIP:DMG: { [1691473681.111929][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473681.111931][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473681.111933][175121:175123] CHIP:DMG: Attribute = 0x0000_0008, [1691473681.111935][175121:175123] CHIP:DMG: } [1691473681.111937][175121:175123] CHIP:DMG: [1691473681.111940][175121:175123] CHIP:DMG: Data = 0, [1691473681.111942][175121:175123] CHIP:DMG: }, [1691473681.111945][175121:175123] CHIP:DMG: [1691473681.111947][175121:175123] CHIP:DMG: }, [1691473681.111949][175121:175123] CHIP:DMG: [1691473681.111951][175121:175123] CHIP:DMG: ], [1691473681.111955][175121:175123] CHIP:DMG: [1691473681.111962][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.111964][175121:175123] CHIP:DMG: } [1691473681.111991][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e100122e0]: Moving to [AwaitingSu] [1691473681.112028][175121:175123] CHIP:EM: <<< [E:31915i S:53893 M:111219934 (Ack:156510091)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473681.112036][175121:175123] CHIP:IN: (S) Sending msg 111219934 on secure session with LSID: 53893 [1691473681.112076][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.112097][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.112443][175121:175123] CHIP:EM: >>> [E:31915i S:53893 M:156510092 (Ack:111219934)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:04 (IM:SubscribeResponse) [1691473681.112475][175121:175123] CHIP:EM: Found matching exchange: 31915i, Delegate: 0x7f6e100122f0 [1691473681.112485][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219934 from Retrans Table on exchange 31915i [1691473681.112490][175121:175123] CHIP:DMG: SubscribeResponse is received [1691473681.112495][175121:175123] CHIP:DMG: SubscribeResponseMessage = [1691473681.112498][175121:175123] CHIP:DMG: { [1691473681.112500][175121:175123] CHIP:DMG: SubscriptionId = 0xd198a9a4, [1691473681.112502][175121:175123] CHIP:DMG: MaxInterval = 0x1e, [1691473681.112504][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.112505][175121:175123] CHIP:DMG: } [1691473681.112509][175121:175123] CHIP:DMG: Subscription established with SubscriptionID = 0xd198a9a4 MinInterval = 3s MaxInterval = 30s Peer = 01:0000000000000001 [1691473681.112512][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e100122e0]: Moving to [Subscripti] [1691473681.112519][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0xd198a9a4 Peer = 01:0000000000000001 [1691473681.112531][175121:175123] CHIP:EM: <<< [E:31915i S:53893 M:111219935 (Ack:156510092)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473681.112537][175121:175123] CHIP:IN: (S) Sending msg 111219935 on secure session with LSID: 53893 [1691473681.112563][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510092 on exchange 31915i [1691473681.112578][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.112586][175121:175123] CHIP:TOO: ***** Test Step 4 : TH subscribes to InterconnectCOAlarm attribute from DUT [1691473681.112600][175121:175123] CHIP:TOO: Sending SubscribeAttribute to: [1691473681.112606][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0009, endpoint 1 [1691473681.112631][175121:175123] CHIP:EM: <<< [E:31916i S:53893 M:111219936] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:03 (IM:SubscribeRequest) [1691473681.112637][175121:175123] CHIP:IN: (S) Sending msg 111219936 on secure session with LSID: 53893 [1691473681.112652][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e100111f0]: Moving to [AwaitingIn] [1691473681.112661][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.117608][175121:175123] CHIP:EM: >>> [E:31916i S:53893 M:156510093 (Ack:111219936)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473681.117649][175121:175123] CHIP:EM: Found matching exchange: 31916i, Delegate: 0x7f6e10011200 [1691473681.117661][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219936 from Retrans Table on exchange 31916i [1691473681.117676][175121:175123] CHIP:DMG: ReportDataMessage = [1691473681.117679][175121:175123] CHIP:DMG: { [1691473681.117682][175121:175123] CHIP:DMG: SubscriptionId = 0x3a748d18, [1691473681.117684][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473681.117687][175121:175123] CHIP:DMG: [ [1691473681.117690][175121:175123] CHIP:DMG: AttributeReportIB = [1691473681.117693][175121:175123] CHIP:DMG: { [1691473681.117695][175121:175123] CHIP:DMG: AttributeDataIB = [1691473681.117697][175121:175123] CHIP:DMG: { [1691473681.117704][175121:175123] CHIP:DMG: DataVersion = 0x220ec228, [1691473681.117706][175121:175123] CHIP:DMG: AttributePathIB = [1691473681.117708][175121:175123] CHIP:DMG: { [1691473681.117710][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473681.117712][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473681.117715][175121:175123] CHIP:DMG: Attribute = 0x0000_0009, [1691473681.117716][175121:175123] CHIP:DMG: } [1691473681.117719][175121:175123] CHIP:DMG: [1691473681.117722][175121:175123] CHIP:DMG: Data = 0, [1691473681.117724][175121:175123] CHIP:DMG: }, [1691473681.117727][175121:175123] CHIP:DMG: [1691473681.117728][175121:175123] CHIP:DMG: }, [1691473681.117731][175121:175123] CHIP:DMG: [1691473681.117733][175121:175123] CHIP:DMG: ], [1691473681.117737][175121:175123] CHIP:DMG: [1691473681.117739][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.117740][175121:175123] CHIP:DMG: } [1691473681.117768][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e100111f0]: Moving to [AwaitingSu] [1691473681.117787][175121:175123] CHIP:EM: <<< [E:31916i S:53893 M:111219937 (Ack:156510093)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473681.117793][175121:175123] CHIP:IN: (S) Sending msg 111219937 on secure session with LSID: 53893 [1691473681.117833][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.117840][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.118169][175121:175123] CHIP:EM: >>> [E:31916i S:53893 M:156510094 (Ack:111219937)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:04 (IM:SubscribeResponse) [1691473681.118203][175121:175123] CHIP:EM: Found matching exchange: 31916i, Delegate: 0x7f6e10011200 [1691473681.118214][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219937 from Retrans Table on exchange 31916i [1691473681.118222][175121:175123] CHIP:DMG: SubscribeResponse is received [1691473681.118229][175121:175123] CHIP:DMG: SubscribeResponseMessage = [1691473681.118232][175121:175123] CHIP:DMG: { [1691473681.118236][175121:175123] CHIP:DMG: SubscriptionId = 0x3a748d18, [1691473681.118239][175121:175123] CHIP:DMG: MaxInterval = 0x1e, [1691473681.118242][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.118245][175121:175123] CHIP:DMG: } [1691473681.118249][175121:175123] CHIP:DMG: Subscription established with SubscriptionID = 0x3a748d18 MinInterval = 3s MaxInterval = 30s Peer = 01:0000000000000001 [1691473681.118254][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e100111f0]: Moving to [Subscripti] [1691473681.118263][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x3a748d18 Peer = 01:0000000000000001 [1691473681.118281][175121:175123] CHIP:EM: <<< [E:31916i S:53893 M:111219938 (Ack:156510094)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473681.118303][175121:175123] CHIP:IN: (S) Sending msg 111219938 on secure session with LSID: 53893 [1691473681.118332][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510094 on exchange 31916i [1691473681.118342][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.118350][175121:175123] CHIP:TOO: ***** Test Step 5 : TH subscribes to COState attribute from DUT [1691473681.118364][175121:175123] CHIP:TOO: Sending SubscribeAttribute to: [1691473681.118384][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0002, endpoint 1 [1691473681.118412][175121:175123] CHIP:EM: <<< [E:31917i S:53893 M:111219939] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:03 (IM:SubscribeRequest) [1691473681.118434][175121:175123] CHIP:IN: (S) Sending msg 111219939 on secure session with LSID: 53893 [1691473681.118476][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e10012bc0]: Moving to [AwaitingIn] [1691473681.118506][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.124054][175121:175123] CHIP:EM: >>> [E:31917i S:53893 M:156510095 (Ack:111219939)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473681.124098][175121:175123] CHIP:EM: Found matching exchange: 31917i, Delegate: 0x7f6e10012bd0 [1691473681.124113][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219939 from Retrans Table on exchange 31917i [1691473681.124131][175121:175123] CHIP:DMG: ReportDataMessage = [1691473681.124135][175121:175123] CHIP:DMG: { [1691473681.124137][175121:175123] CHIP:DMG: SubscriptionId = 0x3dad49f0, [1691473681.124139][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473681.124143][175121:175123] CHIP:DMG: [ [1691473681.124145][175121:175123] CHIP:DMG: AttributeReportIB = [1691473681.124149][175121:175123] CHIP:DMG: { [1691473681.124151][175121:175123] CHIP:DMG: AttributeDataIB = [1691473681.124153][175121:175123] CHIP:DMG: { [1691473681.124155][175121:175123] CHIP:DMG: DataVersion = 0x220ec228, [1691473681.124157][175121:175123] CHIP:DMG: AttributePathIB = [1691473681.124160][175121:175123] CHIP:DMG: { [1691473681.124162][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473681.124164][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473681.124166][175121:175123] CHIP:DMG: Attribute = 0x0000_0002, [1691473681.124168][175121:175123] CHIP:DMG: } [1691473681.124170][175121:175123] CHIP:DMG: [1691473681.124173][175121:175123] CHIP:DMG: Data = 0, [1691473681.124175][175121:175123] CHIP:DMG: }, [1691473681.124178][175121:175123] CHIP:DMG: [1691473681.124180][175121:175123] CHIP:DMG: }, [1691473681.124183][175121:175123] CHIP:DMG: [1691473681.124185][175121:175123] CHIP:DMG: ], [1691473681.124189][175121:175123] CHIP:DMG: [1691473681.124191][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.124193][175121:175123] CHIP:DMG: } [1691473681.124221][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e10012bc0]: Moving to [AwaitingSu] [1691473681.124261][175121:175123] CHIP:EM: <<< [E:31917i S:53893 M:111219940 (Ack:156510095)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473681.124282][175121:175123] CHIP:IN: (S) Sending msg 111219940 on secure session with LSID: 53893 [1691473681.124327][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.124347][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.124703][175121:175123] CHIP:EM: >>> [E:31917i S:53893 M:156510096 (Ack:111219940)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:04 (IM:SubscribeResponse) [1691473681.124744][175121:175123] CHIP:EM: Found matching exchange: 31917i, Delegate: 0x7f6e10012bd0 [1691473681.124755][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219940 from Retrans Table on exchange 31917i [1691473681.124761][175121:175123] CHIP:DMG: SubscribeResponse is received [1691473681.124767][175121:175123] CHIP:DMG: SubscribeResponseMessage = [1691473681.124769][175121:175123] CHIP:DMG: { [1691473681.124772][175121:175123] CHIP:DMG: SubscriptionId = 0x3dad49f0, [1691473681.124774][175121:175123] CHIP:DMG: MaxInterval = 0x1e, [1691473681.124776][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.124778][175121:175123] CHIP:DMG: } [1691473681.124781][175121:175123] CHIP:DMG: Subscription established with SubscriptionID = 0x3dad49f0 MinInterval = 3s MaxInterval = 30s Peer = 01:0000000000000001 [1691473681.124784][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e10012bc0]: Moving to [Subscripti] [1691473681.124792][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x3dad49f0 Peer = 01:0000000000000001 [1691473681.124805][175121:175123] CHIP:EM: <<< [E:31917i S:53893 M:111219941 (Ack:156510096)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473681.124833][175121:175123] CHIP:IN: (S) Sending msg 111219941 on secure session with LSID: 53893 [1691473681.124862][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510096 on exchange 31917i [1691473681.124892][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.124903][175121:175123] CHIP:TOO: ***** Test Step 6 : TH subscribes to SmokeState attribute from DUT [1691473681.124918][175121:175123] CHIP:TOO: Sending SubscribeAttribute to: [1691473681.124925][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0001, endpoint 1 [1691473681.124951][175121:175123] CHIP:EM: <<< [E:31918i S:53893 M:111219942] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:03 (IM:SubscribeRequest) [1691473681.124972][175121:175123] CHIP:IN: (S) Sending msg 111219942 on secure session with LSID: 53893 [1691473681.125007][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e10012d50]: Moving to [AwaitingIn] [1691473681.125020][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.130470][175121:175123] CHIP:EM: >>> [E:31918i S:53893 M:156510097 (Ack:111219942)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473681.130502][175121:175123] CHIP:EM: Found matching exchange: 31918i, Delegate: 0x7f6e10012d60 [1691473681.130514][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219942 from Retrans Table on exchange 31918i [1691473681.130532][175121:175123] CHIP:DMG: ReportDataMessage = [1691473681.130536][175121:175123] CHIP:DMG: { [1691473681.130539][175121:175123] CHIP:DMG: SubscriptionId = 0x420bc651, [1691473681.130541][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473681.130544][175121:175123] CHIP:DMG: [ [1691473681.130546][175121:175123] CHIP:DMG: AttributeReportIB = [1691473681.130549][175121:175123] CHIP:DMG: { [1691473681.130551][175121:175123] CHIP:DMG: AttributeDataIB = [1691473681.130553][175121:175123] CHIP:DMG: { [1691473681.130556][175121:175123] CHIP:DMG: DataVersion = 0x220ec228, [1691473681.130558][175121:175123] CHIP:DMG: AttributePathIB = [1691473681.130560][175121:175123] CHIP:DMG: { [1691473681.130562][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473681.130564][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473681.130567][175121:175123] CHIP:DMG: Attribute = 0x0000_0001, [1691473681.130568][175121:175123] CHIP:DMG: } [1691473681.130571][175121:175123] CHIP:DMG: [1691473681.130574][175121:175123] CHIP:DMG: Data = 0, [1691473681.130575][175121:175123] CHIP:DMG: }, [1691473681.130578][175121:175123] CHIP:DMG: [1691473681.130580][175121:175123] CHIP:DMG: }, [1691473681.130583][175121:175123] CHIP:DMG: [1691473681.130585][175121:175123] CHIP:DMG: ], [1691473681.130588][175121:175123] CHIP:DMG: [1691473681.130590][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.130592][175121:175123] CHIP:DMG: } [1691473681.130619][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e10012d50]: Moving to [AwaitingSu] [1691473681.130639][175121:175123] CHIP:EM: <<< [E:31918i S:53893 M:111219943 (Ack:156510097)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473681.130644][175121:175123] CHIP:IN: (S) Sending msg 111219943 on secure session with LSID: 53893 [1691473681.130684][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.130705][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.131127][175121:175123] CHIP:EM: >>> [E:31918i S:53893 M:156510098 (Ack:111219943)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:04 (IM:SubscribeResponse) [1691473681.131160][175121:175123] CHIP:EM: Found matching exchange: 31918i, Delegate: 0x7f6e10012d60 [1691473681.131170][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219943 from Retrans Table on exchange 31918i [1691473681.131176][175121:175123] CHIP:DMG: SubscribeResponse is received [1691473681.131181][175121:175123] CHIP:DMG: SubscribeResponseMessage = [1691473681.131183][175121:175123] CHIP:DMG: { [1691473681.131185][175121:175123] CHIP:DMG: SubscriptionId = 0x420bc651, [1691473681.131187][175121:175123] CHIP:DMG: MaxInterval = 0x1e, [1691473681.131189][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.131195][175121:175123] CHIP:DMG: } [1691473681.131199][175121:175123] CHIP:DMG: Subscription established with SubscriptionID = 0x420bc651 MinInterval = 3s MaxInterval = 30s Peer = 01:0000000000000001 [1691473681.131201][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e10012d50]: Moving to [Subscripti] [1691473681.131208][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x420bc651 Peer = 01:0000000000000001 [1691473681.131220][175121:175123] CHIP:EM: <<< [E:31918i S:53893 M:111219944 (Ack:156510098)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473681.131225][175121:175123] CHIP:IN: (S) Sending msg 111219944 on secure session with LSID: 53893 [1691473681.131250][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510098 on exchange 31918i [1691473681.131271][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.131282][175121:175123] CHIP:TOO: ***** Test Step 7 : TH reads TestEventTriggersEnabled attribute from General Diagnostics Cluster [1691473681.131296][175121:175123] CHIP:TOO: Sending ReadAttribute to: [1691473681.131302][175121:175123] CHIP:TOO: cluster 0x0000_0033, attribute: 0x0000_0008, endpoint 0 [1691473681.131309][175121:175123] CHIP:DMG: SendReadRequest ReadClient[0x7f6e1000eb40]: Sending Read Request [1691473681.131328][175121:175123] CHIP:EM: <<< [E:31919i S:53893 M:111219945] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473681.131348][175121:175123] CHIP:IN: (S) Sending msg 111219945 on secure session with LSID: 53893 [1691473681.131367][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e1000eb40]: Moving to [AwaitingIn] [1691473681.131376][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.131991][175121:175123] CHIP:EM: >>> [E:31919i S:53893 M:156510099 (Ack:111219945)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473681.132025][175121:175123] CHIP:EM: Found matching exchange: 31919i, Delegate: 0x7f6e1000eb50 [1691473681.132034][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219945 from Retrans Table on exchange 31919i [1691473681.132044][175121:175123] CHIP:DMG: ReportDataMessage = [1691473681.132047][175121:175123] CHIP:DMG: { [1691473681.132049][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473681.132052][175121:175123] CHIP:DMG: [ [1691473681.132054][175121:175123] CHIP:DMG: AttributeReportIB = [1691473681.132057][175121:175123] CHIP:DMG: { [1691473681.132059][175121:175123] CHIP:DMG: AttributeDataIB = [1691473681.132061][175121:175123] CHIP:DMG: { [1691473681.132063][175121:175123] CHIP:DMG: DataVersion = 0x835b76d0, [1691473681.132065][175121:175123] CHIP:DMG: AttributePathIB = [1691473681.132067][175121:175123] CHIP:DMG: { [1691473681.132069][175121:175123] CHIP:DMG: Endpoint = 0x0, [1691473681.132072][175121:175123] CHIP:DMG: Cluster = 0x33, [1691473681.132074][175121:175123] CHIP:DMG: Attribute = 0x0000_0008, [1691473681.132075][175121:175123] CHIP:DMG: } [1691473681.132078][175121:175123] CHIP:DMG: [1691473681.132080][175121:175123] CHIP:DMG: Data = true, [1691473681.132082][175121:175123] CHIP:DMG: }, [1691473681.132085][175121:175123] CHIP:DMG: [1691473681.132087][175121:175123] CHIP:DMG: }, [1691473681.132090][175121:175123] CHIP:DMG: [1691473681.132092][175121:175123] CHIP:DMG: ], [1691473681.132095][175121:175123] CHIP:DMG: [1691473681.132097][175121:175123] CHIP:DMG: SuppressResponse = true, [1691473681.132099][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.132101][175121:175123] CHIP:DMG: } [1691473681.132139][175121:175123] CHIP:EM: <<< [E:31919i S:53893 M:111219946 (Ack:156510099)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473681.132158][175121:175123] CHIP:IN: (S) Sending msg 111219946 on secure session with LSID: 53893 [1691473681.132185][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510099 on exchange 31919i [1691473681.132210][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.132221][175121:175123] CHIP:TOO: ***** Test Step 8 : TH sends TestEventTrigger command to General Diagnostics Cluster on Endpoint 0 with EnableKey field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER_KEY and EventTrigger field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER for Warning Battery Alert Test Event [1691473681.132232][175121:175123] CHIP:DMG: ICR moving to [AddingComm] [1691473681.132243][175121:175123] CHIP:DMG: ICR moving to [AddedComma] [1691473681.132258][175121:175123] CHIP:EM: <<< [E:31920i S:53893 M:111219947] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473681.132278][175121:175123] CHIP:IN: (S) Sending msg 111219947 on secure session with LSID: 53893 [1691473681.132297][175121:175123] CHIP:DMG: ICR moving to [CommandSen] [1691473681.132305][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.133971][175121:175123] CHIP:EM: >>> [E:31920i S:53893 M:156510100 (Ack:111219947)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473681.134005][175121:175123] CHIP:EM: Found matching exchange: 31920i, Delegate: 0x7f6e1000a368 [1691473681.134015][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219947 from Retrans Table on exchange 31920i [1691473681.134021][175121:175123] CHIP:DMG: ICR moving to [ResponseRe] [1691473681.134029][175121:175123] CHIP:DMG: InvokeResponseMessage = [1691473681.134031][175121:175123] CHIP:DMG: { [1691473681.134034][175121:175123] CHIP:DMG: suppressResponse = false, [1691473681.134035][175121:175123] CHIP:DMG: InvokeResponseIBs = [1691473681.134039][175121:175123] CHIP:DMG: [ [1691473681.134041][175121:175123] CHIP:DMG: InvokeResponseIB = [1691473681.134044][175121:175123] CHIP:DMG: { [1691473681.134046][175121:175123] CHIP:DMG: CommandStatusIB = [1691473681.134048][175121:175123] CHIP:DMG: { [1691473681.134050][175121:175123] CHIP:DMG: CommandPathIB = [1691473681.134052][175121:175123] CHIP:DMG: { [1691473681.134054][175121:175123] CHIP:DMG: EndpointId = 0x0, [1691473681.134056][175121:175123] CHIP:DMG: ClusterId = 0x33, [1691473681.134058][175121:175123] CHIP:DMG: CommandId = 0x0, [1691473681.134060][175121:175123] CHIP:DMG: }, [1691473681.134063][175121:175123] CHIP:DMG: [1691473681.134065][175121:175123] CHIP:DMG: StatusIB = [1691473681.134067][175121:175123] CHIP:DMG: { [1691473681.134070][175121:175123] CHIP:DMG: status = 0x00 (SUCCESS), [1691473681.134071][175121:175123] CHIP:DMG: }, [1691473681.134073][175121:175123] CHIP:DMG: [1691473681.134075][175121:175123] CHIP:DMG: }, [1691473681.134078][175121:175123] CHIP:DMG: [1691473681.134080][175121:175123] CHIP:DMG: }, [1691473681.134083][175121:175123] CHIP:DMG: [1691473681.134085][175121:175123] CHIP:DMG: ], [1691473681.134088][175121:175123] CHIP:DMG: [1691473681.134090][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473681.134091][175121:175123] CHIP:DMG: }, [1691473681.134102][175121:175123] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473681.134109][175121:175123] CHIP:DMG: ICR moving to [AwaitingDe] [1691473681.134124][175121:175123] CHIP:EM: <<< [E:31920i S:53893 M:111219948 (Ack:156510100)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473681.134129][175121:175123] CHIP:IN: (S) Sending msg 111219948 on secure session with LSID: 53893 [1691473681.134155][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510100 on exchange 31920i [1691473681.134164][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473681.134172][175121:175123] CHIP:TOO: ***** Test Step 9 : TH waits for a report of BatteryAlert attribute from DUT with a timeout of 300 seconds [1691473684.109962][175121:175123] CHIP:EM: >>> [E:47139r S:53893 M:156510101] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473684.110026][175121:175123] CHIP:EM: Handling via exchange: 47139r, Delegate: 0x5648d9317508 [1691473684.110045][175121:175123] CHIP:DMG: ReportDataMessage = [1691473684.110049][175121:175123] CHIP:DMG: { [1691473684.110052][175121:175123] CHIP:DMG: SubscriptionId = 0x21deb51b, [1691473684.110054][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473684.110057][175121:175123] CHIP:DMG: [ [1691473684.110059][175121:175123] CHIP:DMG: AttributeReportIB = [1691473684.110063][175121:175123] CHIP:DMG: { [1691473684.110065][175121:175123] CHIP:DMG: AttributeDataIB = [1691473684.110067][175121:175123] CHIP:DMG: { [1691473684.110069][175121:175123] CHIP:DMG: DataVersion = 0x220ec22a, [1691473684.110071][175121:175123] CHIP:DMG: AttributePathIB = [1691473684.110074][175121:175123] CHIP:DMG: { [1691473684.110076][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473684.110078][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473684.110080][175121:175123] CHIP:DMG: Attribute = 0x0000_0003, [1691473684.110081][175121:175123] CHIP:DMG: } [1691473684.110084][175121:175123] CHIP:DMG: [1691473684.110086][175121:175123] CHIP:DMG: Data = 1, [1691473684.110088][175121:175123] CHIP:DMG: }, [1691473684.110091][175121:175123] CHIP:DMG: [1691473684.110093][175121:175123] CHIP:DMG: }, [1691473684.110096][175121:175123] CHIP:DMG: [1691473684.110097][175121:175123] CHIP:DMG: ], [1691473684.110101][175121:175123] CHIP:DMG: [1691473684.110103][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473684.110104][175121:175123] CHIP:DMG: } [1691473684.110146][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x21deb51b Peer = 01:0000000000000001 [1691473684.110169][175121:175123] CHIP:EM: <<< [E:47139r S:53893 M:111219949 (Ack:156510101)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473684.110188][175121:175123] CHIP:IN: (S) Sending msg 111219949 on secure session with LSID: 53893 [1691473684.110229][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.110243][175121:175123] CHIP:TOO: ***** Test Step 10 : TH sends TestEventTrigger command to General Diagnostics Cluster on Endpoint 0 with EnableKey field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER_KEY and EventTrigger field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER for Interconnect Smoke Alarm Test Event [1691473684.110258][175121:175123] CHIP:DMG: ICR moving to [AddingComm] [1691473684.110263][175121:175123] CHIP:DMG: ICR moving to [AddedComma] [1691473684.110277][175121:175123] CHIP:EM: <<< [E:31921i S:53893 M:111219950] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473684.110297][175121:175123] CHIP:IN: (S) Sending msg 111219950 on secure session with LSID: 53893 [1691473684.110315][175121:175123] CHIP:DMG: ICR moving to [CommandSen] [1691473684.110331][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.110587][175121:175123] CHIP:EM: >>> [E:47139r S:53893 M:156510102 (Ack:111219949)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473684.110635][175121:175123] CHIP:EM: Found matching exchange: 47139r, Delegate: (nil) [1691473684.110651][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219949 from Retrans Table on exchange 47139r [1691473684.110659][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.111573][175121:175123] CHIP:EM: >>> [E:31921i S:53893 M:156510103 (Ack:111219950)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473684.111613][175121:175123] CHIP:EM: Found matching exchange: 31921i, Delegate: 0x7f6e1000a368 [1691473684.111623][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219950 from Retrans Table on exchange 31921i [1691473684.111628][175121:175123] CHIP:DMG: ICR moving to [ResponseRe] [1691473684.111636][175121:175123] CHIP:DMG: InvokeResponseMessage = [1691473684.111642][175121:175123] CHIP:DMG: { [1691473684.111645][175121:175123] CHIP:DMG: suppressResponse = false, [1691473684.111647][175121:175123] CHIP:DMG: InvokeResponseIBs = [1691473684.111650][175121:175123] CHIP:DMG: [ [1691473684.111652][175121:175123] CHIP:DMG: InvokeResponseIB = [1691473684.111655][175121:175123] CHIP:DMG: { [1691473684.111657][175121:175123] CHIP:DMG: CommandStatusIB = [1691473684.111660][175121:175123] CHIP:DMG: { [1691473684.111661][175121:175123] CHIP:DMG: CommandPathIB = [1691473684.111664][175121:175123] CHIP:DMG: { [1691473684.111666][175121:175123] CHIP:DMG: EndpointId = 0x0, [1691473684.111668][175121:175123] CHIP:DMG: ClusterId = 0x33, [1691473684.111670][175121:175123] CHIP:DMG: CommandId = 0x0, [1691473684.111672][175121:175123] CHIP:DMG: }, [1691473684.111675][175121:175123] CHIP:DMG: [1691473684.111677][175121:175123] CHIP:DMG: StatusIB = [1691473684.111679][175121:175123] CHIP:DMG: { [1691473684.111681][175121:175123] CHIP:DMG: status = 0x00 (SUCCESS), [1691473684.111683][175121:175123] CHIP:DMG: }, [1691473684.111685][175121:175123] CHIP:DMG: [1691473684.111687][175121:175123] CHIP:DMG: }, [1691473684.111690][175121:175123] CHIP:DMG: [1691473684.111691][175121:175123] CHIP:DMG: }, [1691473684.111695][175121:175123] CHIP:DMG: [1691473684.111696][175121:175123] CHIP:DMG: ], [1691473684.111700][175121:175123] CHIP:DMG: [1691473684.111702][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473684.111703][175121:175123] CHIP:DMG: }, [1691473684.111714][175121:175123] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473684.111736][175121:175123] CHIP:DMG: ICR moving to [AwaitingDe] [1691473684.111755][175121:175123] CHIP:EM: <<< [E:31921i S:53893 M:111219951 (Ack:156510103)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473684.111761][175121:175123] CHIP:IN: (S) Sending msg 111219951 on secure session with LSID: 53893 [1691473684.111789][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510103 on exchange 31921i [1691473684.111798][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.111805][175121:175123] CHIP:TOO: ***** Test Step 11 : TH waits for a report of InterconnectSmokeAlarm attribute from DUT with a timeout of 300 seconds [1691473684.111821][175121:175123] CHIP:EM: >>> [E:47140r S:53893 M:156510104] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473684.111826][175121:175123] CHIP:EM: Handling via exchange: 47140r, Delegate: 0x5648d9317508 [1691473684.111835][175121:175123] CHIP:DMG: ReportDataMessage = [1691473684.111837][175121:175123] CHIP:DMG: { [1691473684.111839][175121:175123] CHIP:DMG: SubscriptionId = 0xd198a9a4, [1691473684.111841][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473684.111845][175121:175123] CHIP:DMG: [ [1691473684.111847][175121:175123] CHIP:DMG: AttributeReportIB = [1691473684.111850][175121:175123] CHIP:DMG: { [1691473684.111852][175121:175123] CHIP:DMG: AttributeDataIB = [1691473684.111854][175121:175123] CHIP:DMG: { [1691473684.111856][175121:175123] CHIP:DMG: DataVersion = 0x220ec22c, [1691473684.111858][175121:175123] CHIP:DMG: AttributePathIB = [1691473684.111860][175121:175123] CHIP:DMG: { [1691473684.111862][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473684.111864][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473684.111867][175121:175123] CHIP:DMG: Attribute = 0x0000_0008, [1691473684.111868][175121:175123] CHIP:DMG: } [1691473684.111871][175121:175123] CHIP:DMG: [1691473684.111873][175121:175123] CHIP:DMG: Data = 1, [1691473684.111875][175121:175123] CHIP:DMG: }, [1691473684.111878][175121:175123] CHIP:DMG: [1691473684.111880][175121:175123] CHIP:DMG: }, [1691473684.111883][175121:175123] CHIP:DMG: [1691473684.111885][175121:175123] CHIP:DMG: ], [1691473684.111888][175121:175123] CHIP:DMG: [1691473684.111894][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473684.111896][175121:175123] CHIP:DMG: } [1691473684.111929][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0xd198a9a4 Peer = 01:0000000000000001 [1691473684.111960][175121:175123] CHIP:EM: <<< [E:47140r S:53893 M:111219952 (Ack:156510104)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473684.111968][175121:175123] CHIP:IN: (S) Sending msg 111219952 on secure session with LSID: 53893 [1691473684.112025][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.112061][175121:175123] CHIP:TOO: ***** Test Step 12 : TH sends TestEventTrigger command to General Diagnostics Cluster on Endpoint 0 with EnableKey field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER_KEY and EventTrigger field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER for Interconnect CO Alarm Test Event [1691473684.112073][175121:175123] CHIP:DMG: ICR moving to [AddingComm] [1691473684.112077][175121:175123] CHIP:DMG: ICR moving to [AddedComma] [1691473684.112093][175121:175123] CHIP:EM: <<< [E:31922i S:53893 M:111219953] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473684.112099][175121:175123] CHIP:IN: (S) Sending msg 111219953 on secure session with LSID: 53893 [1691473684.112113][175121:175123] CHIP:DMG: ICR moving to [CommandSen] [1691473684.112118][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.112378][175121:175123] CHIP:EM: >>> [E:47140r S:53893 M:156510105 (Ack:111219952)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473684.112421][175121:175123] CHIP:EM: Found matching exchange: 47140r, Delegate: (nil) [1691473684.112435][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219952 from Retrans Table on exchange 47140r [1691473684.112444][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.113390][175121:175123] CHIP:EM: >>> [E:31922i S:53893 M:156510106 (Ack:111219953)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473684.113423][175121:175123] CHIP:EM: Found matching exchange: 31922i, Delegate: 0x7f6e1000a368 [1691473684.113434][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219953 from Retrans Table on exchange 31922i [1691473684.113440][175121:175123] CHIP:DMG: ICR moving to [ResponseRe] [1691473684.113447][175121:175123] CHIP:DMG: InvokeResponseMessage = [1691473684.113449][175121:175123] CHIP:DMG: { [1691473684.113452][175121:175123] CHIP:DMG: suppressResponse = false, [1691473684.113453][175121:175123] CHIP:DMG: InvokeResponseIBs = [1691473684.113457][175121:175123] CHIP:DMG: [ [1691473684.113459][175121:175123] CHIP:DMG: InvokeResponseIB = [1691473684.113462][175121:175123] CHIP:DMG: { [1691473684.113464][175121:175123] CHIP:DMG: CommandStatusIB = [1691473684.113466][175121:175123] CHIP:DMG: { [1691473684.113468][175121:175123] CHIP:DMG: CommandPathIB = [1691473684.113470][175121:175123] CHIP:DMG: { [1691473684.113472][175121:175123] CHIP:DMG: EndpointId = 0x0, [1691473684.113474][175121:175123] CHIP:DMG: ClusterId = 0x33, [1691473684.113476][175121:175123] CHIP:DMG: CommandId = 0x0, [1691473684.113478][175121:175123] CHIP:DMG: }, [1691473684.113481][175121:175123] CHIP:DMG: [1691473684.113483][175121:175123] CHIP:DMG: StatusIB = [1691473684.113485][175121:175123] CHIP:DMG: { [1691473684.113487][175121:175123] CHIP:DMG: status = 0x00 (SUCCESS), [1691473684.113489][175121:175123] CHIP:DMG: }, [1691473684.113491][175121:175123] CHIP:DMG: [1691473684.113493][175121:175123] CHIP:DMG: }, [1691473684.113496][175121:175123] CHIP:DMG: [1691473684.113497][175121:175123] CHIP:DMG: }, [1691473684.113500][175121:175123] CHIP:DMG: [1691473684.113502][175121:175123] CHIP:DMG: ], [1691473684.113505][175121:175123] CHIP:DMG: [1691473684.113507][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473684.113509][175121:175123] CHIP:DMG: }, [1691473684.113523][175121:175123] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473684.113544][175121:175123] CHIP:DMG: ICR moving to [AwaitingDe] [1691473684.113564][175121:175123] CHIP:EM: <<< [E:31922i S:53893 M:111219954 (Ack:156510106)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473684.113571][175121:175123] CHIP:IN: (S) Sending msg 111219954 on secure session with LSID: 53893 [1691473684.113595][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510106 on exchange 31922i [1691473684.113616][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.113626][175121:175123] CHIP:TOO: ***** Test Step 13 : TH waits for a report of InterconnectCOAlarm attribute from DUT with a timeout of 300 seconds [1691473684.118240][175121:175123] CHIP:EM: >>> [E:47141r S:53893 M:156510107] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473684.118305][175121:175123] CHIP:EM: Handling via exchange: 47141r, Delegate: 0x5648d9317508 [1691473684.118335][175121:175123] CHIP:DMG: ReportDataMessage = [1691473684.118341][175121:175123] CHIP:DMG: { [1691473684.118344][175121:175123] CHIP:DMG: SubscriptionId = 0x3a748d18, [1691473684.118346][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473684.118350][175121:175123] CHIP:DMG: [ [1691473684.118352][175121:175123] CHIP:DMG: AttributeReportIB = [1691473684.118356][175121:175123] CHIP:DMG: { [1691473684.118358][175121:175123] CHIP:DMG: AttributeDataIB = [1691473684.118360][175121:175123] CHIP:DMG: { [1691473684.118363][175121:175123] CHIP:DMG: DataVersion = 0x220ec22d, [1691473684.118364][175121:175123] CHIP:DMG: AttributePathIB = [1691473684.118367][175121:175123] CHIP:DMG: { [1691473684.118369][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473684.118371][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473684.118373][175121:175123] CHIP:DMG: Attribute = 0x0000_0009, [1691473684.118375][175121:175123] CHIP:DMG: } [1691473684.118378][175121:175123] CHIP:DMG: [1691473684.118381][175121:175123] CHIP:DMG: Data = 1, [1691473684.118382][175121:175123] CHIP:DMG: }, [1691473684.118385][175121:175123] CHIP:DMG: [1691473684.118387][175121:175123] CHIP:DMG: }, [1691473684.118390][175121:175123] CHIP:DMG: [1691473684.118392][175121:175123] CHIP:DMG: ], [1691473684.118396][175121:175123] CHIP:DMG: [1691473684.118398][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473684.118399][175121:175123] CHIP:DMG: } [1691473684.118440][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x3a748d18 Peer = 01:0000000000000001 [1691473684.118479][175121:175123] CHIP:EM: <<< [E:47141r S:53893 M:111219955 (Ack:156510107)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473684.118487][175121:175123] CHIP:IN: (S) Sending msg 111219955 on secure session with LSID: 53893 [1691473684.118533][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.118560][175121:175123] CHIP:TOO: ***** Test Step 14 : TH sends TestEventTrigger command to General Diagnostics Cluster on Endpoint 0 with EnableKey field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER_KEY and EventTrigger field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER for Warning CO Alarm Test Event [1691473684.118579][175121:175123] CHIP:DMG: ICR moving to [AddingComm] [1691473684.118585][175121:175123] CHIP:DMG: ICR moving to [AddedComma] [1691473684.118601][175121:175123] CHIP:EM: <<< [E:31923i S:53893 M:111219956] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473684.118620][175121:175123] CHIP:IN: (S) Sending msg 111219956 on secure session with LSID: 53893 [1691473684.118639][175121:175123] CHIP:DMG: ICR moving to [CommandSen] [1691473684.118646][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.118986][175121:175123] CHIP:EM: >>> [E:47141r S:53893 M:156510108 (Ack:111219955)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473684.119034][175121:175123] CHIP:EM: Found matching exchange: 47141r, Delegate: (nil) [1691473684.119047][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219955 from Retrans Table on exchange 47141r [1691473684.119053][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.120239][175121:175123] CHIP:EM: >>> [E:31923i S:53893 M:156510109 (Ack:111219956)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473684.120279][175121:175123] CHIP:EM: Found matching exchange: 31923i, Delegate: 0x7f6e1000a368 [1691473684.120290][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219956 from Retrans Table on exchange 31923i [1691473684.120296][175121:175123] CHIP:DMG: ICR moving to [ResponseRe] [1691473684.120305][175121:175123] CHIP:DMG: InvokeResponseMessage = [1691473684.120307][175121:175123] CHIP:DMG: { [1691473684.120309][175121:175123] CHIP:DMG: suppressResponse = false, [1691473684.120311][175121:175123] CHIP:DMG: InvokeResponseIBs = [1691473684.120315][175121:175123] CHIP:DMG: [ [1691473684.120326][175121:175123] CHIP:DMG: InvokeResponseIB = [1691473684.120332][175121:175123] CHIP:DMG: { [1691473684.120334][175121:175123] CHIP:DMG: CommandStatusIB = [1691473684.120337][175121:175123] CHIP:DMG: { [1691473684.120340][175121:175123] CHIP:DMG: CommandPathIB = [1691473684.120342][175121:175123] CHIP:DMG: { [1691473684.120345][175121:175123] CHIP:DMG: EndpointId = 0x0, [1691473684.120347][175121:175123] CHIP:DMG: ClusterId = 0x33, [1691473684.120349][175121:175123] CHIP:DMG: CommandId = 0x0, [1691473684.120351][175121:175123] CHIP:DMG: }, [1691473684.120354][175121:175123] CHIP:DMG: [1691473684.120356][175121:175123] CHIP:DMG: StatusIB = [1691473684.120358][175121:175123] CHIP:DMG: { [1691473684.120361][175121:175123] CHIP:DMG: status = 0x00 (SUCCESS), [1691473684.120363][175121:175123] CHIP:DMG: }, [1691473684.120365][175121:175123] CHIP:DMG: [1691473684.120367][175121:175123] CHIP:DMG: }, [1691473684.120369][175121:175123] CHIP:DMG: [1691473684.120371][175121:175123] CHIP:DMG: }, [1691473684.120374][175121:175123] CHIP:DMG: [1691473684.120376][175121:175123] CHIP:DMG: ], [1691473684.120380][175121:175123] CHIP:DMG: [1691473684.120389][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473684.120409][175121:175123] CHIP:DMG: }, [1691473684.120424][175121:175123] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473684.120433][175121:175123] CHIP:DMG: ICR moving to [AwaitingDe] [1691473684.120469][175121:175123] CHIP:EM: <<< [E:31923i S:53893 M:111219957 (Ack:156510109)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473684.120495][175121:175123] CHIP:IN: (S) Sending msg 111219957 on secure session with LSID: 53893 [1691473684.120526][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510109 on exchange 31923i [1691473684.120549][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.120561][175121:175123] CHIP:TOO: ***** Test Step 15 : TH waits for a report of COState attribute from DUT with a timeout of 300 seconds [1691473684.126624][175121:175123] CHIP:EM: >>> [E:47142r S:53893 M:156510110] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473684.126812][175121:175123] CHIP:EM: Handling via exchange: 47142r, Delegate: 0x5648d9317508 [1691473684.126923][175121:175123] CHIP:DMG: ReportDataMessage = [1691473684.126933][175121:175123] CHIP:DMG: { [1691473684.126939][175121:175123] CHIP:DMG: SubscriptionId = 0x3dad49f0, [1691473684.126943][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473684.126949][175121:175123] CHIP:DMG: [ [1691473684.126953][175121:175123] CHIP:DMG: AttributeReportIB = [1691473684.126959][175121:175123] CHIP:DMG: { [1691473684.126962][175121:175123] CHIP:DMG: AttributeDataIB = [1691473684.126998][175121:175123] CHIP:DMG: { [1691473684.127001][175121:175123] CHIP:DMG: DataVersion = 0x220ec22e, [1691473684.127003][175121:175123] CHIP:DMG: AttributePathIB = [1691473684.127007][175121:175123] CHIP:DMG: { [1691473684.127009][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473684.127011][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473684.127015][175121:175123] CHIP:DMG: Attribute = 0x0000_0002, [1691473684.127017][175121:175123] CHIP:DMG: } [1691473684.127020][175121:175123] CHIP:DMG: [1691473684.127025][175121:175123] CHIP:DMG: Data = 1, [1691473684.127027][175121:175123] CHIP:DMG: }, [1691473684.127031][175121:175123] CHIP:DMG: [1691473684.127032][175121:175123] CHIP:DMG: }, [1691473684.127035][175121:175123] CHIP:DMG: [1691473684.127037][175121:175123] CHIP:DMG: ], [1691473684.127042][175121:175123] CHIP:DMG: [1691473684.127045][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473684.127047][175121:175123] CHIP:DMG: } [1691473684.127122][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x3dad49f0 Peer = 01:0000000000000001 [1691473684.127173][175121:175123] CHIP:EM: <<< [E:47142r S:53893 M:111219958 (Ack:156510110)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473684.127200][175121:175123] CHIP:IN: (S) Sending msg 111219958 on secure session with LSID: 53893 [1691473684.127258][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.127290][175121:175123] CHIP:TOO: ***** Test Step 16 : TH sends TestEventTrigger command to General Diagnostics Cluster on Endpoint 0 with EnableKey field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER_KEY and EventTrigger field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER for Warning Smoke Alarm Test Event [1691473684.127313][175121:175123] CHIP:DMG: ICR moving to [AddingComm] [1691473684.127319][175121:175123] CHIP:DMG: ICR moving to [AddedComma] [1691473684.127390][175121:175123] CHIP:EM: <<< [E:31924i S:53893 M:111219959] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473684.127418][175121:175123] CHIP:IN: (S) Sending msg 111219959 on secure session with LSID: 53893 [1691473684.127446][175121:175123] CHIP:DMG: ICR moving to [CommandSen] [1691473684.127469][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.127858][175121:175123] CHIP:EM: >>> [E:47142r S:53893 M:156510111 (Ack:111219958)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473684.127895][175121:175123] CHIP:EM: Found matching exchange: 47142r, Delegate: (nil) [1691473684.127910][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219958 from Retrans Table on exchange 47142r [1691473684.127917][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.129801][175121:175123] CHIP:EM: >>> [E:31924i S:53893 M:156510112 (Ack:111219959)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473684.129841][175121:175123] CHIP:EM: Found matching exchange: 31924i, Delegate: 0x7f6e1000a368 [1691473684.129853][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219959 from Retrans Table on exchange 31924i [1691473684.129860][175121:175123] CHIP:DMG: ICR moving to [ResponseRe] [1691473684.129870][175121:175123] CHIP:DMG: InvokeResponseMessage = [1691473684.129873][175121:175123] CHIP:DMG: { [1691473684.129875][175121:175123] CHIP:DMG: suppressResponse = false, [1691473684.129877][175121:175123] CHIP:DMG: InvokeResponseIBs = [1691473684.129881][175121:175123] CHIP:DMG: [ [1691473684.129883][175121:175123] CHIP:DMG: InvokeResponseIB = [1691473684.129886][175121:175123] CHIP:DMG: { [1691473684.129888][175121:175123] CHIP:DMG: CommandStatusIB = [1691473684.129890][175121:175123] CHIP:DMG: { [1691473684.129892][175121:175123] CHIP:DMG: CommandPathIB = [1691473684.129895][175121:175123] CHIP:DMG: { [1691473684.129897][175121:175123] CHIP:DMG: EndpointId = 0x0, [1691473684.129904][175121:175123] CHIP:DMG: ClusterId = 0x33, [1691473684.129907][175121:175123] CHIP:DMG: CommandId = 0x0, [1691473684.129908][175121:175123] CHIP:DMG: }, [1691473684.129911][175121:175123] CHIP:DMG: [1691473684.129913][175121:175123] CHIP:DMG: StatusIB = [1691473684.129916][175121:175123] CHIP:DMG: { [1691473684.129918][175121:175123] CHIP:DMG: status = 0x00 (SUCCESS), [1691473684.129920][175121:175123] CHIP:DMG: }, [1691473684.129922][175121:175123] CHIP:DMG: [1691473684.129924][175121:175123] CHIP:DMG: }, [1691473684.129927][175121:175123] CHIP:DMG: [1691473684.129929][175121:175123] CHIP:DMG: }, [1691473684.129932][175121:175123] CHIP:DMG: [1691473684.129933][175121:175123] CHIP:DMG: ], [1691473684.129937][175121:175123] CHIP:DMG: [1691473684.129939][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473684.129940][175121:175123] CHIP:DMG: }, [1691473684.129950][175121:175123] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473684.129959][175121:175123] CHIP:DMG: ICR moving to [AwaitingDe] [1691473684.129978][175121:175123] CHIP:EM: <<< [E:31924i S:53893 M:111219960 (Ack:156510112)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473684.129999][175121:175123] CHIP:IN: (S) Sending msg 111219960 on secure session with LSID: 53893 [1691473684.130030][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510112 on exchange 31924i [1691473684.130053][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.130064][175121:175123] CHIP:TOO: ***** Test Step 17 : TH waits for a report of SmokeState attribute from DUT with a timeout of 300 seconds [1691473684.131500][175121:175123] CHIP:EM: >>> [E:47143r S:53893 M:156510113] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473684.131523][175121:175123] CHIP:EM: Handling via exchange: 47143r, Delegate: 0x5648d9317508 [1691473684.131537][175121:175123] CHIP:DMG: ReportDataMessage = [1691473684.131540][175121:175123] CHIP:DMG: { [1691473684.131542][175121:175123] CHIP:DMG: SubscriptionId = 0x420bc651, [1691473684.131544][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473684.131548][175121:175123] CHIP:DMG: [ [1691473684.131550][175121:175123] CHIP:DMG: AttributeReportIB = [1691473684.131553][175121:175123] CHIP:DMG: { [1691473684.131555][175121:175123] CHIP:DMG: AttributeDataIB = [1691473684.131557][175121:175123] CHIP:DMG: { [1691473684.131559][175121:175123] CHIP:DMG: DataVersion = 0x220ec230, [1691473684.131561][175121:175123] CHIP:DMG: AttributePathIB = [1691473684.131563][175121:175123] CHIP:DMG: { [1691473684.131565][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473684.131567][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473684.131570][175121:175123] CHIP:DMG: Attribute = 0x0000_0001, [1691473684.131572][175121:175123] CHIP:DMG: } [1691473684.131574][175121:175123] CHIP:DMG: [1691473684.131577][175121:175123] CHIP:DMG: Data = 1, [1691473684.131579][175121:175123] CHIP:DMG: }, [1691473684.131582][175121:175123] CHIP:DMG: [1691473684.131583][175121:175123] CHIP:DMG: }, [1691473684.131586][175121:175123] CHIP:DMG: [1691473684.131588][175121:175123] CHIP:DMG: ], [1691473684.131592][175121:175123] CHIP:DMG: [1691473684.131594][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473684.131595][175121:175123] CHIP:DMG: } [1691473684.131633][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x420bc651 Peer = 01:0000000000000001 [1691473684.131666][175121:175123] CHIP:EM: <<< [E:47143r S:53893 M:111219961 (Ack:156510113)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473684.131674][175121:175123] CHIP:IN: (S) Sending msg 111219961 on secure session with LSID: 53893 [1691473684.131710][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.131737][175121:175123] CHIP:TOO: ***** Test Step 18 : TH reads ExpressedState attribute from DUT [1691473684.131752][175121:175123] CHIP:TOO: Sending ReadAttribute to: [1691473684.131759][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0000, endpoint 1 [1691473684.131766][175121:175123] CHIP:DMG: SendReadRequest ReadClient[0x7f6e1000eb40]: Sending Read Request [1691473684.131784][175121:175123] CHIP:EM: <<< [E:31925i S:53893 M:111219962] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473684.131804][175121:175123] CHIP:IN: (S) Sending msg 111219962 on secure session with LSID: 53893 [1691473684.131824][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e1000eb40]: Moving to [AwaitingIn] [1691473684.131833][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.132097][175121:175123] CHIP:EM: >>> [E:47143r S:53893 M:156510114 (Ack:111219961)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473684.132130][175121:175123] CHIP:EM: Found matching exchange: 47143r, Delegate: (nil) [1691473684.132142][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219961 from Retrans Table on exchange 47143r [1691473684.132148][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.132768][175121:175123] CHIP:EM: >>> [E:31925i S:53893 M:156510115 (Ack:111219962)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473684.132800][175121:175123] CHIP:EM: Found matching exchange: 31925i, Delegate: 0x7f6e1000eb50 [1691473684.132810][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219962 from Retrans Table on exchange 31925i [1691473684.132821][175121:175123] CHIP:DMG: ReportDataMessage = [1691473684.132824][175121:175123] CHIP:DMG: { [1691473684.132826][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473684.132829][175121:175123] CHIP:DMG: [ [1691473684.132831][175121:175123] CHIP:DMG: AttributeReportIB = [1691473684.132835][175121:175123] CHIP:DMG: { [1691473684.132837][175121:175123] CHIP:DMG: AttributeDataIB = [1691473684.132839][175121:175123] CHIP:DMG: { [1691473684.132841][175121:175123] CHIP:DMG: DataVersion = 0x220ec230, [1691473684.132843][175121:175123] CHIP:DMG: AttributePathIB = [1691473684.132845][175121:175123] CHIP:DMG: { [1691473684.132847][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473684.132850][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473684.132852][175121:175123] CHIP:DMG: Attribute = 0x0000_0000, [1691473684.132854][175121:175123] CHIP:DMG: } [1691473684.132856][175121:175123] CHIP:DMG: [1691473684.132859][175121:175123] CHIP:DMG: Data = 1, [1691473684.132861][175121:175123] CHIP:DMG: }, [1691473684.132863][175121:175123] CHIP:DMG: [1691473684.132865][175121:175123] CHIP:DMG: }, [1691473684.132868][175121:175123] CHIP:DMG: [1691473684.132870][175121:175123] CHIP:DMG: ], [1691473684.132873][175121:175123] CHIP:DMG: [1691473684.132876][175121:175123] CHIP:DMG: SuppressResponse = true, [1691473684.132878][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473684.132879][175121:175123] CHIP:DMG: } [1691473684.132919][175121:175123] CHIP:EM: <<< [E:31925i S:53893 M:111219963 (Ack:156510115)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473684.132925][175121:175123] CHIP:IN: (S) Sending msg 111219963 on secure session with LSID: 53893 [1691473684.132950][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510115 on exchange 31925i [1691473684.132959][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.132966][175121:175123] CHIP:TOO: ***** Test Step 19 : TH sends TestEventTrigger command to General Diagnostics Cluster on Endpoint 0 with EnableKey field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER_KEY and EventTrigger field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER for Smoke Alarm Test Event Clear [1691473684.132977][175121:175123] CHIP:DMG: ICR moving to [AddingComm] [1691473684.132986][175121:175123] CHIP:DMG: ICR moving to [AddedComma] [1691473684.133002][175121:175123] CHIP:EM: <<< [E:31926i S:53893 M:111219964] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473684.133007][175121:175123] CHIP:IN: (S) Sending msg 111219964 on secure session with LSID: 53893 [1691473684.133023][175121:175123] CHIP:DMG: ICR moving to [CommandSen] [1691473684.133028][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.134600][175121:175123] CHIP:EM: >>> [E:31926i S:53893 M:156510116 (Ack:111219964)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473684.134638][175121:175123] CHIP:EM: Found matching exchange: 31926i, Delegate: 0x7f6e1000a368 [1691473684.134650][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219964 from Retrans Table on exchange 31926i [1691473684.134656][175121:175123] CHIP:DMG: ICR moving to [ResponseRe] [1691473684.134663][175121:175123] CHIP:DMG: InvokeResponseMessage = [1691473684.134666][175121:175123] CHIP:DMG: { [1691473684.134668][175121:175123] CHIP:DMG: suppressResponse = false, [1691473684.134670][175121:175123] CHIP:DMG: InvokeResponseIBs = [1691473684.134674][175121:175123] CHIP:DMG: [ [1691473684.134676][175121:175123] CHIP:DMG: InvokeResponseIB = [1691473684.134679][175121:175123] CHIP:DMG: { [1691473684.134681][175121:175123] CHIP:DMG: CommandStatusIB = [1691473684.134683][175121:175123] CHIP:DMG: { [1691473684.134685][175121:175123] CHIP:DMG: CommandPathIB = [1691473684.134687][175121:175123] CHIP:DMG: { [1691473684.134689][175121:175123] CHIP:DMG: EndpointId = 0x0, [1691473684.134691][175121:175123] CHIP:DMG: ClusterId = 0x33, [1691473684.134693][175121:175123] CHIP:DMG: CommandId = 0x0, [1691473684.134695][175121:175123] CHIP:DMG: }, [1691473684.134698][175121:175123] CHIP:DMG: [1691473684.134700][175121:175123] CHIP:DMG: StatusIB = [1691473684.134703][175121:175123] CHIP:DMG: { [1691473684.134705][175121:175123] CHIP:DMG: status = 0x00 (SUCCESS), [1691473684.134707][175121:175123] CHIP:DMG: }, [1691473684.134709][175121:175123] CHIP:DMG: [1691473684.134711][175121:175123] CHIP:DMG: }, [1691473684.134714][175121:175123] CHIP:DMG: [1691473684.134716][175121:175123] CHIP:DMG: }, [1691473684.134719][175121:175123] CHIP:DMG: [1691473684.134721][175121:175123] CHIP:DMG: ], [1691473684.134724][175121:175123] CHIP:DMG: [1691473684.134726][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473684.134728][175121:175123] CHIP:DMG: }, [1691473684.134738][175121:175123] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473684.134746][175121:175123] CHIP:DMG: ICR moving to [AwaitingDe] [1691473684.134762][175121:175123] CHIP:EM: <<< [E:31926i S:53893 M:111219965 (Ack:156510116)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473684.134782][175121:175123] CHIP:IN: (S) Sending msg 111219965 on secure session with LSID: 53893 [1691473684.134812][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510116 on exchange 31926i [1691473684.134834][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473684.165697][175121:175123] CHIP:TOO: ***** Test Step 20 : TH waits for a report of SmokeState attribute from DUT with a timeout of 300 seconds [1691473687.131504][175121:175123] CHIP:EM: >>> [E:47144r S:53893 M:156510117] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473687.131562][175121:175123] CHIP:EM: Handling via exchange: 47144r, Delegate: 0x5648d9317508 [1691473687.131583][175121:175123] CHIP:DMG: ReportDataMessage = [1691473687.131587][175121:175123] CHIP:DMG: { [1691473687.131590][175121:175123] CHIP:DMG: SubscriptionId = 0x420bc651, [1691473687.131592][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473687.131596][175121:175123] CHIP:DMG: [ [1691473687.131598][175121:175123] CHIP:DMG: AttributeReportIB = [1691473687.131609][175121:175123] CHIP:DMG: { [1691473687.131611][175121:175123] CHIP:DMG: AttributeDataIB = [1691473687.131613][175121:175123] CHIP:DMG: { [1691473687.131616][175121:175123] CHIP:DMG: DataVersion = 0x220ec232, [1691473687.131618][175121:175123] CHIP:DMG: AttributePathIB = [1691473687.131620][175121:175123] CHIP:DMG: { [1691473687.131622][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473687.131624][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473687.131626][175121:175123] CHIP:DMG: Attribute = 0x0000_0001, [1691473687.131628][175121:175123] CHIP:DMG: } [1691473687.131630][175121:175123] CHIP:DMG: [1691473687.131633][175121:175123] CHIP:DMG: Data = 0, [1691473687.131635][175121:175123] CHIP:DMG: }, [1691473687.131638][175121:175123] CHIP:DMG: [1691473687.131640][175121:175123] CHIP:DMG: }, [1691473687.131643][175121:175123] CHIP:DMG: [1691473687.131644][175121:175123] CHIP:DMG: ], [1691473687.131648][175121:175123] CHIP:DMG: [1691473687.131650][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.131651][175121:175123] CHIP:DMG: } [1691473687.131693][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x420bc651 Peer = 01:0000000000000001 [1691473687.131716][175121:175123] CHIP:EM: <<< [E:47144r S:53893 M:111219966 (Ack:156510117)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473687.131735][175121:175123] CHIP:IN: (S) Sending msg 111219966 on secure session with LSID: 53893 [1691473687.131782][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.131797][175121:175123] CHIP:TOO: ***** Test Step 21 : TH reads ExpressedState attribute from DUT [1691473687.131813][175121:175123] CHIP:TOO: Sending ReadAttribute to: [1691473687.131833][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0000, endpoint 1 [1691473687.131843][175121:175123] CHIP:DMG: SendReadRequest ReadClient[0x7f6e1000eb40]: Sending Read Request [1691473687.131863][175121:175123] CHIP:EM: <<< [E:31927i S:53893 M:111219967] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473687.131883][175121:175123] CHIP:IN: (S) Sending msg 111219967 on secure session with LSID: 53893 [1691473687.131901][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e1000eb40]: Moving to [AwaitingIn] [1691473687.131911][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.132220][175121:175123] CHIP:EM: >>> [E:47144r S:53893 M:156510118 (Ack:111219966)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.132258][175121:175123] CHIP:EM: Found matching exchange: 47144r, Delegate: (nil) [1691473687.132271][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219966 from Retrans Table on exchange 47144r [1691473687.132277][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.132898][175121:175123] CHIP:EM: >>> [E:31927i S:53893 M:156510119 (Ack:111219967)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473687.132933][175121:175123] CHIP:EM: Found matching exchange: 31927i, Delegate: 0x7f6e1000eb50 [1691473687.132944][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219967 from Retrans Table on exchange 31927i [1691473687.132955][175121:175123] CHIP:DMG: ReportDataMessage = [1691473687.132958][175121:175123] CHIP:DMG: { [1691473687.132960][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473687.132964][175121:175123] CHIP:DMG: [ [1691473687.132966][175121:175123] CHIP:DMG: AttributeReportIB = [1691473687.132969][175121:175123] CHIP:DMG: { [1691473687.132971][175121:175123] CHIP:DMG: AttributeDataIB = [1691473687.132973][175121:175123] CHIP:DMG: { [1691473687.132976][175121:175123] CHIP:DMG: DataVersion = 0x220ec232, [1691473687.132978][175121:175123] CHIP:DMG: AttributePathIB = [1691473687.132980][175121:175123] CHIP:DMG: { [1691473687.132982][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473687.132991][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473687.132993][175121:175123] CHIP:DMG: Attribute = 0x0000_0000, [1691473687.132995][175121:175123] CHIP:DMG: } [1691473687.132998][175121:175123] CHIP:DMG: [1691473687.133001][175121:175123] CHIP:DMG: Data = 7, [1691473687.133003][175121:175123] CHIP:DMG: }, [1691473687.133006][175121:175123] CHIP:DMG: [1691473687.133008][175121:175123] CHIP:DMG: }, [1691473687.133011][175121:175123] CHIP:DMG: [1691473687.133013][175121:175123] CHIP:DMG: ], [1691473687.133016][175121:175123] CHIP:DMG: [1691473687.133018][175121:175123] CHIP:DMG: SuppressResponse = true, [1691473687.133020][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.133022][175121:175123] CHIP:DMG: } [1691473687.133061][175121:175123] CHIP:EM: <<< [E:31927i S:53893 M:111219968 (Ack:156510119)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.133081][175121:175123] CHIP:IN: (S) Sending msg 111219968 on secure session with LSID: 53893 [1691473687.133110][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510119 on exchange 31927i [1691473687.133120][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.133127][175121:175123] CHIP:TOO: ***** Test Step 22 : TH sends TestEventTrigger command to General Diagnostics Cluster on Endpoint 0 with EnableKey field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER_KEY and EventTrigger field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER for CO Alarm Test Event clear [1691473687.133139][175121:175123] CHIP:DMG: ICR moving to [AddingComm] [1691473687.133157][175121:175123] CHIP:DMG: ICR moving to [AddedComma] [1691473687.133178][175121:175123] CHIP:EM: <<< [E:31928i S:53893 M:111219969] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473687.133185][175121:175123] CHIP:IN: (S) Sending msg 111219969 on secure session with LSID: 53893 [1691473687.133201][175121:175123] CHIP:DMG: ICR moving to [CommandSen] [1691473687.133220][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.134227][175121:175123] CHIP:EM: >>> [E:31928i S:53893 M:156510120 (Ack:111219969)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473687.134263][175121:175123] CHIP:EM: Found matching exchange: 31928i, Delegate: 0x7f6e1000a368 [1691473687.134272][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219969 from Retrans Table on exchange 31928i [1691473687.134278][175121:175123] CHIP:DMG: ICR moving to [ResponseRe] [1691473687.134286][175121:175123] CHIP:DMG: InvokeResponseMessage = [1691473687.134288][175121:175123] CHIP:DMG: { [1691473687.134290][175121:175123] CHIP:DMG: suppressResponse = false, [1691473687.134292][175121:175123] CHIP:DMG: InvokeResponseIBs = [1691473687.134295][175121:175123] CHIP:DMG: [ [1691473687.134298][175121:175123] CHIP:DMG: InvokeResponseIB = [1691473687.134301][175121:175123] CHIP:DMG: { [1691473687.134303][175121:175123] CHIP:DMG: CommandStatusIB = [1691473687.134305][175121:175123] CHIP:DMG: { [1691473687.134307][175121:175123] CHIP:DMG: CommandPathIB = [1691473687.134309][175121:175123] CHIP:DMG: { [1691473687.134312][175121:175123] CHIP:DMG: EndpointId = 0x0, [1691473687.134314][175121:175123] CHIP:DMG: ClusterId = 0x33, [1691473687.134316][175121:175123] CHIP:DMG: CommandId = 0x0, [1691473687.134317][175121:175123] CHIP:DMG: }, [1691473687.134321][175121:175123] CHIP:DMG: [1691473687.134323][175121:175123] CHIP:DMG: StatusIB = [1691473687.134325][175121:175123] CHIP:DMG: { [1691473687.134328][175121:175123] CHIP:DMG: status = 0x00 (SUCCESS), [1691473687.134329][175121:175123] CHIP:DMG: }, [1691473687.134331][175121:175123] CHIP:DMG: [1691473687.134333][175121:175123] CHIP:DMG: }, [1691473687.134337][175121:175123] CHIP:DMG: [1691473687.134339][175121:175123] CHIP:DMG: }, [1691473687.134342][175121:175123] CHIP:DMG: [1691473687.134348][175121:175123] CHIP:DMG: ], [1691473687.134352][175121:175123] CHIP:DMG: [1691473687.134354][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.134356][175121:175123] CHIP:DMG: }, [1691473687.134366][175121:175123] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473687.134395][175121:175123] CHIP:DMG: ICR moving to [AwaitingDe] [1691473687.134415][175121:175123] CHIP:EM: <<< [E:31928i S:53893 M:111219970 (Ack:156510120)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.134421][175121:175123] CHIP:IN: (S) Sending msg 111219970 on secure session with LSID: 53893 [1691473687.134434][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510120 on exchange 31928i [1691473687.134443][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.134450][175121:175123] CHIP:TOO: ***** Test Step 23 : TH waits for a report of COState attribute from DUT with a timeout of 300 seconds [1691473687.134466][175121:175123] CHIP:EM: >>> [E:47145r S:53893 M:156510121] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473687.134473][175121:175123] CHIP:EM: Handling via exchange: 47145r, Delegate: 0x5648d9317508 [1691473687.134481][175121:175123] CHIP:DMG: ReportDataMessage = [1691473687.134486][175121:175123] CHIP:DMG: { [1691473687.134488][175121:175123] CHIP:DMG: SubscriptionId = 0x3dad49f0, [1691473687.134490][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473687.134493][175121:175123] CHIP:DMG: [ [1691473687.134495][175121:175123] CHIP:DMG: AttributeReportIB = [1691473687.134498][175121:175123] CHIP:DMG: { [1691473687.134500][175121:175123] CHIP:DMG: AttributeDataIB = [1691473687.134502][175121:175123] CHIP:DMG: { [1691473687.134504][175121:175123] CHIP:DMG: DataVersion = 0x220ec233, [1691473687.134506][175121:175123] CHIP:DMG: AttributePathIB = [1691473687.134508][175121:175123] CHIP:DMG: { [1691473687.134510][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473687.134512][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473687.134514][175121:175123] CHIP:DMG: Attribute = 0x0000_0002, [1691473687.134516][175121:175123] CHIP:DMG: } [1691473687.134519][175121:175123] CHIP:DMG: [1691473687.134521][175121:175123] CHIP:DMG: Data = 0, [1691473687.134523][175121:175123] CHIP:DMG: }, [1691473687.134526][175121:175123] CHIP:DMG: [1691473687.134528][175121:175123] CHIP:DMG: }, [1691473687.134531][175121:175123] CHIP:DMG: [1691473687.134533][175121:175123] CHIP:DMG: ], [1691473687.134536][175121:175123] CHIP:DMG: [1691473687.134538][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.134540][175121:175123] CHIP:DMG: } [1691473687.134571][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x3dad49f0 Peer = 01:0000000000000001 [1691473687.134603][175121:175123] CHIP:EM: <<< [E:47145r S:53893 M:111219971 (Ack:156510121)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473687.134611][175121:175123] CHIP:IN: (S) Sending msg 111219971 on secure session with LSID: 53893 [1691473687.134630][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.134652][175121:175123] CHIP:TOO: ***** Test Step 24 : TH reads ExpressedState attribute from DUT [1691473687.134664][175121:175123] CHIP:TOO: Sending ReadAttribute to: [1691473687.134669][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0000, endpoint 1 [1691473687.134674][175121:175123] CHIP:DMG: SendReadRequest ReadClient[0x7f6e1000eb40]: Sending Read Request [1691473687.134692][175121:175123] CHIP:EM: <<< [E:31929i S:53893 M:111219972] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473687.134712][175121:175123] CHIP:IN: (S) Sending msg 111219972 on secure session with LSID: 53893 [1691473687.134731][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e1000eb40]: Moving to [AwaitingIn] [1691473687.134743][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.134946][175121:175123] CHIP:EM: >>> [E:47145r S:53893 M:156510122 (Ack:111219971)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.134979][175121:175123] CHIP:EM: Found matching exchange: 47145r, Delegate: (nil) [1691473687.134990][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219971 from Retrans Table on exchange 47145r [1691473687.134996][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.135610][175121:175123] CHIP:EM: >>> [E:31929i S:53893 M:156510123 (Ack:111219972)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473687.135647][175121:175123] CHIP:EM: Found matching exchange: 31929i, Delegate: 0x7f6e1000eb50 [1691473687.135657][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219972 from Retrans Table on exchange 31929i [1691473687.135670][175121:175123] CHIP:DMG: ReportDataMessage = [1691473687.135674][175121:175123] CHIP:DMG: { [1691473687.135677][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473687.135704][175121:175123] CHIP:DMG: [ [1691473687.135711][175121:175123] CHIP:DMG: AttributeReportIB = [1691473687.135717][175121:175123] CHIP:DMG: { [1691473687.135720][175121:175123] CHIP:DMG: AttributeDataIB = [1691473687.135723][175121:175123] CHIP:DMG: { [1691473687.135726][175121:175123] CHIP:DMG: DataVersion = 0x220ec233, [1691473687.135729][175121:175123] CHIP:DMG: AttributePathIB = [1691473687.135732][175121:175123] CHIP:DMG: { [1691473687.135736][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473687.135739][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473687.135742][175121:175123] CHIP:DMG: Attribute = 0x0000_0000, [1691473687.135745][175121:175123] CHIP:DMG: } [1691473687.135748][175121:175123] CHIP:DMG: [1691473687.135752][175121:175123] CHIP:DMG: Data = 7, [1691473687.135755][175121:175123] CHIP:DMG: }, [1691473687.135759][175121:175123] CHIP:DMG: [1691473687.135762][175121:175123] CHIP:DMG: }, [1691473687.135766][175121:175123] CHIP:DMG: [1691473687.135769][175121:175123] CHIP:DMG: ], [1691473687.135774][175121:175123] CHIP:DMG: [1691473687.135777][175121:175123] CHIP:DMG: SuppressResponse = true, [1691473687.135780][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.135783][175121:175123] CHIP:DMG: } [1691473687.135833][175121:175123] CHIP:EM: <<< [E:31929i S:53893 M:111219973 (Ack:156510123)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.135845][175121:175123] CHIP:IN: (S) Sending msg 111219973 on secure session with LSID: 53893 [1691473687.135879][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510123 on exchange 31929i [1691473687.135891][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.135902][175121:175123] CHIP:TOO: ***** Test Step 25 : TH sends TestEventTrigger command to General Diagnostics Cluster on Endpoint 0 with EnableKey field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER_KEY and EventTrigger field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER for Interconnect CO Alarm Test Event Clear [1691473687.135914][175121:175123] CHIP:DMG: ICR moving to [AddingComm] [1691473687.135919][175121:175123] CHIP:DMG: ICR moving to [AddedComma] [1691473687.135935][175121:175123] CHIP:EM: <<< [E:31930i S:53893 M:111219974] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473687.135941][175121:175123] CHIP:IN: (S) Sending msg 111219974 on secure session with LSID: 53893 [1691473687.135957][175121:175123] CHIP:DMG: ICR moving to [CommandSen] [1691473687.135962][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.137133][175121:175123] CHIP:EM: >>> [E:31930i S:53893 M:156510124 (Ack:111219974)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473687.137180][175121:175123] CHIP:EM: Found matching exchange: 31930i, Delegate: 0x7f6e1000a368 [1691473687.137204][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219974 from Retrans Table on exchange 31930i [1691473687.137214][175121:175123] CHIP:DMG: ICR moving to [ResponseRe] [1691473687.137227][175121:175123] CHIP:DMG: InvokeResponseMessage = [1691473687.137230][175121:175123] CHIP:DMG: { [1691473687.137233][175121:175123] CHIP:DMG: suppressResponse = false, [1691473687.137235][175121:175123] CHIP:DMG: InvokeResponseIBs = [1691473687.137238][175121:175123] CHIP:DMG: [ [1691473687.137241][175121:175123] CHIP:DMG: InvokeResponseIB = [1691473687.137244][175121:175123] CHIP:DMG: { [1691473687.137247][175121:175123] CHIP:DMG: CommandStatusIB = [1691473687.137249][175121:175123] CHIP:DMG: { [1691473687.137251][175121:175123] CHIP:DMG: CommandPathIB = [1691473687.137253][175121:175123] CHIP:DMG: { [1691473687.137256][175121:175123] CHIP:DMG: EndpointId = 0x0, [1691473687.137257][175121:175123] CHIP:DMG: ClusterId = 0x33, [1691473687.137259][175121:175123] CHIP:DMG: CommandId = 0x0, [1691473687.137261][175121:175123] CHIP:DMG: }, [1691473687.137264][175121:175123] CHIP:DMG: [1691473687.137266][175121:175123] CHIP:DMG: StatusIB = [1691473687.137269][175121:175123] CHIP:DMG: { [1691473687.137271][175121:175123] CHIP:DMG: status = 0x00 (SUCCESS), [1691473687.137273][175121:175123] CHIP:DMG: }, [1691473687.137276][175121:175123] CHIP:DMG: [1691473687.137277][175121:175123] CHIP:DMG: }, [1691473687.137280][175121:175123] CHIP:DMG: [1691473687.137282][175121:175123] CHIP:DMG: }, [1691473687.137286][175121:175123] CHIP:DMG: [1691473687.137289][175121:175123] CHIP:DMG: ], [1691473687.137294][175121:175123] CHIP:DMG: [1691473687.137297][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.137300][175121:175123] CHIP:DMG: }, [1691473687.137312][175121:175123] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473687.137324][175121:175123] CHIP:DMG: ICR moving to [AwaitingDe] [1691473687.137352][175121:175123] CHIP:EM: <<< [E:31930i S:53893 M:111219975 (Ack:156510124)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.137380][175121:175123] CHIP:IN: (S) Sending msg 111219975 on secure session with LSID: 53893 [1691473687.137399][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510124 on exchange 31930i [1691473687.137409][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.137421][175121:175123] CHIP:TOO: ***** Test Step 26 : TH waits for a report of InterconnectCOAlarm attribute from DUT with a timeout of 300 seconds [1691473687.137463][175121:175123] CHIP:EM: >>> [E:47146r S:53893 M:156510125] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473687.137472][175121:175123] CHIP:EM: Handling via exchange: 47146r, Delegate: 0x5648d9317508 [1691473687.137485][175121:175123] CHIP:DMG: ReportDataMessage = [1691473687.137490][175121:175123] CHIP:DMG: { [1691473687.137494][175121:175123] CHIP:DMG: SubscriptionId = 0x3a748d18, [1691473687.137497][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473687.137502][175121:175123] CHIP:DMG: [ [1691473687.137505][175121:175123] CHIP:DMG: AttributeReportIB = [1691473687.137510][175121:175123] CHIP:DMG: { [1691473687.137512][175121:175123] CHIP:DMG: AttributeDataIB = [1691473687.137514][175121:175123] CHIP:DMG: { [1691473687.137516][175121:175123] CHIP:DMG: DataVersion = 0x220ec234, [1691473687.137518][175121:175123] CHIP:DMG: AttributePathIB = [1691473687.137520][175121:175123] CHIP:DMG: { [1691473687.137522][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473687.137525][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473687.137527][175121:175123] CHIP:DMG: Attribute = 0x0000_0009, [1691473687.137528][175121:175123] CHIP:DMG: } [1691473687.137532][175121:175123] CHIP:DMG: [1691473687.137536][175121:175123] CHIP:DMG: Data = 0, [1691473687.137539][175121:175123] CHIP:DMG: }, [1691473687.137549][175121:175123] CHIP:DMG: [1691473687.137552][175121:175123] CHIP:DMG: }, [1691473687.137557][175121:175123] CHIP:DMG: [1691473687.137559][175121:175123] CHIP:DMG: ], [1691473687.137564][175121:175123] CHIP:DMG: [1691473687.137568][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.137570][175121:175123] CHIP:DMG: } [1691473687.137619][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x3a748d18 Peer = 01:0000000000000001 [1691473687.137666][175121:175123] CHIP:EM: <<< [E:47146r S:53893 M:111219976 (Ack:156510125)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473687.137676][175121:175123] CHIP:IN: (S) Sending msg 111219976 on secure session with LSID: 53893 [1691473687.137728][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.137743][175121:175123] CHIP:TOO: ***** Test Step 27 : TH reads ExpressedState attribute from DUT [1691473687.137761][175121:175123] CHIP:TOO: Sending ReadAttribute to: [1691473687.137768][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0000, endpoint 1 [1691473687.137778][175121:175123] CHIP:DMG: SendReadRequest ReadClient[0x7f6e1000eb40]: Sending Read Request [1691473687.137802][175121:175123] CHIP:EM: <<< [E:31931i S:53893 M:111219977] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473687.137811][175121:175123] CHIP:IN: (S) Sending msg 111219977 on secure session with LSID: 53893 [1691473687.137830][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e1000eb40]: Moving to [AwaitingIn] [1691473687.137840][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.138106][175121:175123] CHIP:EM: >>> [E:47146r S:53893 M:156510126 (Ack:111219976)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.138153][175121:175123] CHIP:EM: Found matching exchange: 47146r, Delegate: (nil) [1691473687.138168][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219976 from Retrans Table on exchange 47146r [1691473687.138176][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.139063][175121:175123] CHIP:EM: >>> [E:31931i S:53893 M:156510127 (Ack:111219977)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473687.139138][175121:175123] CHIP:EM: Found matching exchange: 31931i, Delegate: 0x7f6e1000eb50 [1691473687.139156][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219977 from Retrans Table on exchange 31931i [1691473687.139185][175121:175123] CHIP:DMG: ReportDataMessage = [1691473687.139189][175121:175123] CHIP:DMG: { [1691473687.139192][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473687.139197][175121:175123] CHIP:DMG: [ [1691473687.139200][175121:175123] CHIP:DMG: AttributeReportIB = [1691473687.139204][175121:175123] CHIP:DMG: { [1691473687.139206][175121:175123] CHIP:DMG: AttributeDataIB = [1691473687.139210][175121:175123] CHIP:DMG: { [1691473687.139214][175121:175123] CHIP:DMG: DataVersion = 0x220ec234, [1691473687.139216][175121:175123] CHIP:DMG: AttributePathIB = [1691473687.139218][175121:175123] CHIP:DMG: { [1691473687.139220][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473687.139222][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473687.139224][175121:175123] CHIP:DMG: Attribute = 0x0000_0000, [1691473687.139226][175121:175123] CHIP:DMG: } [1691473687.139228][175121:175123] CHIP:DMG: [1691473687.139233][175121:175123] CHIP:DMG: Data = 7, [1691473687.139235][175121:175123] CHIP:DMG: }, [1691473687.139238][175121:175123] CHIP:DMG: [1691473687.139240][175121:175123] CHIP:DMG: }, [1691473687.139243][175121:175123] CHIP:DMG: [1691473687.139245][175121:175123] CHIP:DMG: ], [1691473687.139248][175121:175123] CHIP:DMG: [1691473687.139251][175121:175123] CHIP:DMG: SuppressResponse = true, [1691473687.139253][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.139271][175121:175123] CHIP:DMG: } [1691473687.139383][175121:175123] CHIP:EM: <<< [E:31931i S:53893 M:111219978 (Ack:156510127)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.139412][175121:175123] CHIP:IN: (S) Sending msg 111219978 on secure session with LSID: 53893 [1691473687.139463][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510127 on exchange 31931i [1691473687.139492][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.139512][175121:175123] CHIP:TOO: ***** Test Step 28 : TH sends TestEventTrigger command to General Diagnostics Cluster on Endpoint 0 with EnableKey field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER_KEY and EventTrigger field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER for Interconnect Smoke Alarm Test Event Clear [1691473687.139554][175121:175123] CHIP:DMG: ICR moving to [AddingComm] [1691473687.139578][175121:175123] CHIP:DMG: ICR moving to [AddedComma] [1691473687.139615][175121:175123] CHIP:EM: <<< [E:31932i S:53893 M:111219979] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473687.139623][175121:175123] CHIP:IN: (S) Sending msg 111219979 on secure session with LSID: 53893 [1691473687.139643][175121:175123] CHIP:DMG: ICR moving to [CommandSen] [1691473687.139664][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.143017][175121:175123] CHIP:EM: >>> [E:31932i S:53893 M:156510128 (Ack:111219979)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473687.143060][175121:175123] CHIP:EM: Found matching exchange: 31932i, Delegate: 0x7f6e1000a368 [1691473687.143076][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219979 from Retrans Table on exchange 31932i [1691473687.143084][175121:175123] CHIP:DMG: ICR moving to [ResponseRe] [1691473687.143095][175121:175123] CHIP:DMG: InvokeResponseMessage = [1691473687.143098][175121:175123] CHIP:DMG: { [1691473687.143101][175121:175123] CHIP:DMG: suppressResponse = false, [1691473687.143104][175121:175123] CHIP:DMG: InvokeResponseIBs = [1691473687.143109][175121:175123] CHIP:DMG: [ [1691473687.143113][175121:175123] CHIP:DMG: InvokeResponseIB = [1691473687.143117][175121:175123] CHIP:DMG: { [1691473687.143120][175121:175123] CHIP:DMG: CommandStatusIB = [1691473687.143123][175121:175123] CHIP:DMG: { [1691473687.143125][175121:175123] CHIP:DMG: CommandPathIB = [1691473687.143129][175121:175123] CHIP:DMG: { [1691473687.143133][175121:175123] CHIP:DMG: EndpointId = 0x0, [1691473687.143136][175121:175123] CHIP:DMG: ClusterId = 0x33, [1691473687.143139][175121:175123] CHIP:DMG: CommandId = 0x0, [1691473687.143142][175121:175123] CHIP:DMG: }, [1691473687.143145][175121:175123] CHIP:DMG: [1691473687.143148][175121:175123] CHIP:DMG: StatusIB = [1691473687.143150][175121:175123] CHIP:DMG: { [1691473687.143152][175121:175123] CHIP:DMG: status = 0x00 (SUCCESS), [1691473687.143154][175121:175123] CHIP:DMG: }, [1691473687.143156][175121:175123] CHIP:DMG: [1691473687.143158][175121:175123] CHIP:DMG: }, [1691473687.143161][175121:175123] CHIP:DMG: [1691473687.143163][175121:175123] CHIP:DMG: }, [1691473687.143166][175121:175123] CHIP:DMG: [1691473687.143168][175121:175123] CHIP:DMG: ], [1691473687.143171][175121:175123] CHIP:DMG: [1691473687.143173][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.143175][175121:175123] CHIP:DMG: }, [1691473687.143186][175121:175123] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473687.143195][175121:175123] CHIP:DMG: ICR moving to [AwaitingDe] [1691473687.143216][175121:175123] CHIP:EM: <<< [E:31932i S:53893 M:111219980 (Ack:156510128)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.143222][175121:175123] CHIP:IN: (S) Sending msg 111219980 on secure session with LSID: 53893 [1691473687.143240][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510128 on exchange 31932i [1691473687.143252][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.143262][175121:175123] CHIP:TOO: ***** Test Step 29 : TH waits for a report of InterconnectSmokeAlarm attribute from DUT with a timeout of 300 seconds [1691473687.143400][175121:175123] CHIP:EM: >>> [E:47147r S:53893 M:156510129] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473687.143428][175121:175123] CHIP:EM: Handling via exchange: 47147r, Delegate: 0x5648d9317508 [1691473687.143445][175121:175123] CHIP:DMG: ReportDataMessage = [1691473687.143452][175121:175123] CHIP:DMG: { [1691473687.143457][175121:175123] CHIP:DMG: SubscriptionId = 0xd198a9a4, [1691473687.143460][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473687.143465][175121:175123] CHIP:DMG: [ [1691473687.143468][175121:175123] CHIP:DMG: AttributeReportIB = [1691473687.143474][175121:175123] CHIP:DMG: { [1691473687.143477][175121:175123] CHIP:DMG: AttributeDataIB = [1691473687.143481][175121:175123] CHIP:DMG: { [1691473687.143484][175121:175123] CHIP:DMG: DataVersion = 0x220ec236, [1691473687.143486][175121:175123] CHIP:DMG: AttributePathIB = [1691473687.143489][175121:175123] CHIP:DMG: { [1691473687.143491][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473687.143493][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473687.143495][175121:175123] CHIP:DMG: Attribute = 0x0000_0008, [1691473687.143497][175121:175123] CHIP:DMG: } [1691473687.143499][175121:175123] CHIP:DMG: [1691473687.143502][175121:175123] CHIP:DMG: Data = 0, [1691473687.143504][175121:175123] CHIP:DMG: }, [1691473687.143507][175121:175123] CHIP:DMG: [1691473687.143508][175121:175123] CHIP:DMG: }, [1691473687.143511][175121:175123] CHIP:DMG: [1691473687.143513][175121:175123] CHIP:DMG: ], [1691473687.143517][175121:175123] CHIP:DMG: [1691473687.143519][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.143521][175121:175123] CHIP:DMG: } [1691473687.143560][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0xd198a9a4 Peer = 01:0000000000000001 [1691473687.143596][175121:175123] CHIP:EM: <<< [E:47147r S:53893 M:111219981 (Ack:156510129)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473687.143603][175121:175123] CHIP:IN: (S) Sending msg 111219981 on secure session with LSID: 53893 [1691473687.143641][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.143666][175121:175123] CHIP:TOO: ***** Test Step 30 : TH reads ExpressedState attribute from DUT [1691473687.143685][175121:175123] CHIP:TOO: Sending ReadAttribute to: [1691473687.143692][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0000, endpoint 1 [1691473687.143699][175121:175123] CHIP:DMG: SendReadRequest ReadClient[0x7f6e1000eb40]: Sending Read Request [1691473687.143718][175121:175123] CHIP:EM: <<< [E:31933i S:53893 M:111219982] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473687.143737][175121:175123] CHIP:IN: (S) Sending msg 111219982 on secure session with LSID: 53893 [1691473687.143756][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e1000eb40]: Moving to [AwaitingIn] [1691473687.143766][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.144094][175121:175123] CHIP:EM: >>> [E:47147r S:53893 M:156510130 (Ack:111219981)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.144138][175121:175123] CHIP:EM: Found matching exchange: 47147r, Delegate: (nil) [1691473687.144153][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219981 from Retrans Table on exchange 47147r [1691473687.144162][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.144811][175121:175123] CHIP:EM: >>> [E:31933i S:53893 M:156510131 (Ack:111219982)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473687.144858][175121:175123] CHIP:EM: Found matching exchange: 31933i, Delegate: 0x7f6e1000eb50 [1691473687.144869][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219982 from Retrans Table on exchange 31933i [1691473687.144883][175121:175123] CHIP:DMG: ReportDataMessage = [1691473687.144886][175121:175123] CHIP:DMG: { [1691473687.144888][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473687.144891][175121:175123] CHIP:DMG: [ [1691473687.144893][175121:175123] CHIP:DMG: AttributeReportIB = [1691473687.144896][175121:175123] CHIP:DMG: { [1691473687.144898][175121:175123] CHIP:DMG: AttributeDataIB = [1691473687.144901][175121:175123] CHIP:DMG: { [1691473687.144903][175121:175123] CHIP:DMG: DataVersion = 0x220ec236, [1691473687.144905][175121:175123] CHIP:DMG: AttributePathIB = [1691473687.144907][175121:175123] CHIP:DMG: { [1691473687.144909][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473687.144911][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473687.144913][175121:175123] CHIP:DMG: Attribute = 0x0000_0000, [1691473687.144915][175121:175123] CHIP:DMG: } [1691473687.144918][175121:175123] CHIP:DMG: [1691473687.144920][175121:175123] CHIP:DMG: Data = 3, [1691473687.144922][175121:175123] CHIP:DMG: }, [1691473687.144925][175121:175123] CHIP:DMG: [1691473687.144927][175121:175123] CHIP:DMG: }, [1691473687.144930][175121:175123] CHIP:DMG: [1691473687.144931][175121:175123] CHIP:DMG: ], [1691473687.144934][175121:175123] CHIP:DMG: [1691473687.144937][175121:175123] CHIP:DMG: SuppressResponse = true, [1691473687.144939][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.144941][175121:175123] CHIP:DMG: } [1691473687.144985][175121:175123] CHIP:EM: <<< [E:31933i S:53893 M:111219983 (Ack:156510131)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.144992][175121:175123] CHIP:IN: (S) Sending msg 111219983 on secure session with LSID: 53893 [1691473687.145021][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510131 on exchange 31933i [1691473687.145031][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.145039][175121:175123] CHIP:TOO: ***** Test Step 31 : TH sends TestEventTrigger command to General Diagnostics Cluster on Endpoint 0 with EnableKey field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER_KEY and EventTrigger field set to PIXIT.SMOKECO.TEST_EVENT_TRIGGER for Battery Alert Test Event Clear [1691473687.145052][175121:175123] CHIP:DMG: ICR moving to [AddingComm] [1691473687.145057][175121:175123] CHIP:DMG: ICR moving to [AddedComma] [1691473687.145073][175121:175123] CHIP:EM: <<< [E:31934i S:53893 M:111219984] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473687.145079][175121:175123] CHIP:IN: (S) Sending msg 111219984 on secure session with LSID: 53893 [1691473687.145096][175121:175123] CHIP:DMG: ICR moving to [CommandSen] [1691473687.145102][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.146977][175121:175123] CHIP:EM: >>> [E:31934i S:53893 M:156510132 (Ack:111219984)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473687.147017][175121:175123] CHIP:EM: Found matching exchange: 31934i, Delegate: 0x7f6e1000a368 [1691473687.147029][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219984 from Retrans Table on exchange 31934i [1691473687.147036][175121:175123] CHIP:DMG: ICR moving to [ResponseRe] [1691473687.147046][175121:175123] CHIP:DMG: InvokeResponseMessage = [1691473687.147048][175121:175123] CHIP:DMG: { [1691473687.147051][175121:175123] CHIP:DMG: suppressResponse = false, [1691473687.147054][175121:175123] CHIP:DMG: InvokeResponseIBs = [1691473687.147057][175121:175123] CHIP:DMG: [ [1691473687.147059][175121:175123] CHIP:DMG: InvokeResponseIB = [1691473687.147063][175121:175123] CHIP:DMG: { [1691473687.147065][175121:175123] CHIP:DMG: CommandStatusIB = [1691473687.147067][175121:175123] CHIP:DMG: { [1691473687.147074][175121:175123] CHIP:DMG: CommandPathIB = [1691473687.147077][175121:175123] CHIP:DMG: { [1691473687.147080][175121:175123] CHIP:DMG: EndpointId = 0x0, [1691473687.147082][175121:175123] CHIP:DMG: ClusterId = 0x33, [1691473687.147084][175121:175123] CHIP:DMG: CommandId = 0x0, [1691473687.147085][175121:175123] CHIP:DMG: }, [1691473687.147088][175121:175123] CHIP:DMG: [1691473687.147090][175121:175123] CHIP:DMG: StatusIB = [1691473687.147093][175121:175123] CHIP:DMG: { [1691473687.147095][175121:175123] CHIP:DMG: status = 0x00 (SUCCESS), [1691473687.147097][175121:175123] CHIP:DMG: }, [1691473687.147099][175121:175123] CHIP:DMG: [1691473687.147101][175121:175123] CHIP:DMG: }, [1691473687.147103][175121:175123] CHIP:DMG: [1691473687.147105][175121:175123] CHIP:DMG: }, [1691473687.147108][175121:175123] CHIP:DMG: [1691473687.147110][175121:175123] CHIP:DMG: ], [1691473687.147113][175121:175123] CHIP:DMG: [1691473687.147116][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.147117][175121:175123] CHIP:DMG: }, [1691473687.147127][175121:175123] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473687.147134][175121:175123] CHIP:DMG: ICR moving to [AwaitingDe] [1691473687.147152][175121:175123] CHIP:EM: <<< [E:31934i S:53893 M:111219985 (Ack:156510132)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.147172][175121:175123] CHIP:IN: (S) Sending msg 111219985 on secure session with LSID: 53893 [1691473687.147191][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510132 on exchange 31934i [1691473687.147200][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.147209][175121:175123] CHIP:TOO: ***** Test Step 32 : TH waits for a report of BatteryAlert attribute from DUT with a timeout of 300 seconds [1691473687.147225][175121:175123] CHIP:EM: >>> [E:47148r S:53893 M:156510133] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473687.147232][175121:175123] CHIP:EM: Handling via exchange: 47148r, Delegate: 0x5648d9317508 [1691473687.147241][175121:175123] CHIP:DMG: ReportDataMessage = [1691473687.147244][175121:175123] CHIP:DMG: { [1691473687.147246][175121:175123] CHIP:DMG: SubscriptionId = 0x21deb51b, [1691473687.147248][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473687.147251][175121:175123] CHIP:DMG: [ [1691473687.147253][175121:175123] CHIP:DMG: AttributeReportIB = [1691473687.147257][175121:175123] CHIP:DMG: { [1691473687.147259][175121:175123] CHIP:DMG: AttributeDataIB = [1691473687.147261][175121:175123] CHIP:DMG: { [1691473687.147263][175121:175123] CHIP:DMG: DataVersion = 0x220ec238, [1691473687.147265][175121:175123] CHIP:DMG: AttributePathIB = [1691473687.147267][175121:175123] CHIP:DMG: { [1691473687.147269][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473687.147271][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473687.147274][175121:175123] CHIP:DMG: Attribute = 0x0000_0003, [1691473687.147275][175121:175123] CHIP:DMG: } [1691473687.147278][175121:175123] CHIP:DMG: [1691473687.147280][175121:175123] CHIP:DMG: Data = 0, [1691473687.147282][175121:175123] CHIP:DMG: }, [1691473687.147285][175121:175123] CHIP:DMG: [1691473687.147287][175121:175123] CHIP:DMG: }, [1691473687.147290][175121:175123] CHIP:DMG: [1691473687.147292][175121:175123] CHIP:DMG: ], [1691473687.147295][175121:175123] CHIP:DMG: [1691473687.147297][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.147299][175121:175123] CHIP:DMG: } [1691473687.147332][175121:175123] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x21deb51b Peer = 01:0000000000000001 [1691473687.147366][175121:175123] CHIP:EM: <<< [E:47148r S:53893 M:111219986 (Ack:156510133)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473687.147387][175121:175123] CHIP:IN: (S) Sending msg 111219986 on secure session with LSID: 53893 [1691473687.147415][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.147442][175121:175123] CHIP:TOO: ***** Test Step 33 : TH reads ExpressedState attribute from DUT [1691473687.147459][175121:175123] CHIP:TOO: Sending ReadAttribute to: [1691473687.147466][175121:175123] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0000, endpoint 1 [1691473687.147473][175121:175123] CHIP:DMG: SendReadRequest ReadClient[0x7f6e1000eb40]: Sending Read Request [1691473687.147493][175121:175123] CHIP:EM: <<< [E:31935i S:53893 M:111219987] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473687.147513][175121:175123] CHIP:IN: (S) Sending msg 111219987 on secure session with LSID: 53893 [1691473687.147539][175121:175123] CHIP:DMG: MoveToState ReadClient[0x7f6e1000eb40]: Moving to [AwaitingIn] [1691473687.147552][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.147851][175121:175123] CHIP:EM: >>> [E:47148r S:53893 M:156510134 (Ack:111219986)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.147890][175121:175123] CHIP:EM: Found matching exchange: 47148r, Delegate: (nil) [1691473687.147905][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219986 from Retrans Table on exchange 47148r [1691473687.147913][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.148851][175121:175123] CHIP:EM: >>> [E:31935i S:53893 M:156510135 (Ack:111219987)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473687.148896][175121:175123] CHIP:EM: Found matching exchange: 31935i, Delegate: 0x7f6e1000eb50 [1691473687.148909][175121:175123] CHIP:EM: Rxd Ack; Removing MessageCounter:111219987 from Retrans Table on exchange 31935i [1691473687.148927][175121:175123] CHIP:DMG: ReportDataMessage = [1691473687.148933][175121:175123] CHIP:DMG: { [1691473687.148936][175121:175123] CHIP:DMG: AttributeReportIBs = [1691473687.148941][175121:175123] CHIP:DMG: [ [1691473687.148944][175121:175123] CHIP:DMG: AttributeReportIB = [1691473687.148948][175121:175123] CHIP:DMG: { [1691473687.148952][175121:175123] CHIP:DMG: AttributeDataIB = [1691473687.148956][175121:175123] CHIP:DMG: { [1691473687.148959][175121:175123] CHIP:DMG: DataVersion = 0x220ec238, [1691473687.148963][175121:175123] CHIP:DMG: AttributePathIB = [1691473687.148966][175121:175123] CHIP:DMG: { [1691473687.148969][175121:175123] CHIP:DMG: Endpoint = 0x1, [1691473687.148972][175121:175123] CHIP:DMG: Cluster = 0x5c, [1691473687.148976][175121:175123] CHIP:DMG: Attribute = 0x0000_0000, [1691473687.148978][175121:175123] CHIP:DMG: } [1691473687.148982][175121:175123] CHIP:DMG: [1691473687.148986][175121:175123] CHIP:DMG: Data = 0, [1691473687.148989][175121:175123] CHIP:DMG: }, [1691473687.148994][175121:175123] CHIP:DMG: [1691473687.148997][175121:175123] CHIP:DMG: }, [1691473687.149001][175121:175123] CHIP:DMG: [1691473687.149004][175121:175123] CHIP:DMG: ], [1691473687.149009][175121:175123] CHIP:DMG: [1691473687.149013][175121:175123] CHIP:DMG: SuppressResponse = true, [1691473687.149016][175121:175123] CHIP:DMG: InteractionModelRevision = 1 [1691473687.149018][175121:175123] CHIP:DMG: } [1691473687.149082][175121:175123] CHIP:EM: <<< [E:31935i S:53893 M:111219988 (Ack:156510135)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473687.149091][175121:175123] CHIP:IN: (S) Sending msg 111219988 on secure session with LSID: 53893 [1691473687.149125][175121:175123] CHIP:EM: Flushed pending ack for MessageCounter:156510135 on exchange 31935i [1691473687.149136][175121:175123] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473687.149149][175121:175123] CHIP:TOO: **** Test Complete: Test_TC_SMOKECO_2_6 [1691473687.149336][175121:175121] CHIP:CTL: Shutting down the commissioner [1691473687.149385][175121:175121] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1691473687.149419][175121:175121] CHIP:CTL: Shutting down the controller [1691473687.149432][175121:175121] CHIP:IN: Expiring all sessions for fabric 0x1!! [1691473687.149435][175121:175121] CHIP:IN: SecureSession[0x7f6e1000b0e0]: MarkForEviction Type:2 LSID:53893 [1691473687.149438][175121:175121] CHIP:SC: SecureSession[0x7f6e1000b0e0, LSID:53893]: State change 'kActive' --> 'kPendingEviction' [1691473687.149442][175121:175121] CHIP:IN: SecureSession[0x7f6e1000b0e0]: Released - Type:2 LSID:53893 [1691473687.149446][175121:175121] CHIP:FP: Forgetting fabric 0x1 [1691473687.149452][175121:175121] CHIP:TS: Pending Last Known Good Time: 2023-08-07T11:26:55 [1691473687.149491][175121:175121] CHIP:TS: Previous Last Known Good Time: 2023-08-07T11:26:55 [1691473687.149509][175121:175121] CHIP:TS: Reverted Last Known Good Time to previous value [1691473687.149528][175121:175121] CHIP:CTL: Shutting down the commissioner [1691473687.149533][175121:175121] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1691473687.149543][175121:175121] CHIP:CTL: Shutting down the controller [1691473687.149545][175121:175121] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1691473687.149568][175121:175121] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1691473687.149601][175121:175121] CHIP:FP: Shutting down FabricTable [1691473687.149610][175121:175121] CHIP:TS: Pending Last Known Good Time: 2023-08-07T11:26:55 [1691473687.149639][175121:175121] CHIP:TS: Previous Last Known Good Time: 2023-08-07T11:26:55 [1691473687.149657][175121:175121] CHIP:TS: Reverted Last Known Good Time to previous value [1691473687.149714][175121:175121] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Egr2hq) [1691473687.149822][175121:175121] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1691473687.149853][175121:175121] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1691473687.149859][175121:175121] CHIP:DL: Inet Layer shutdown [1691473687.149862][175121:175121] CHIP:DL: BLE shutdown [1691473687.149865][175121:175121] CHIP:DL: System Layer shutdown