[1691473586.496196][172872:172872] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1691473586.499122][172872:172872] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1691473586.499178][172872:172872] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1691473586.499196][172872:172872] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1691473586.499256][172872:172872] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-zOR5Gu) [1691473586.499364][172872:172872] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1691473586.499411][172872:172872] CHIP:DL: NVS set: chip-counters/reboot-count = 12 (0xC) [1691473586.499500][172872:172872] CHIP:DL: Got Ethernet interface: eth0 [1691473586.499562][172872:172872] CHIP:DL: Found the primary Ethernet interface:eth0 [1691473586.499603][172872:172872] CHIP:DL: Failed to get WiFi interface [1691473586.499620][172872:172872] CHIP:DL: Failed to reset WiFi statistic counts [1691473586.499632][172872:172872] CHIP:IN: UDP::Init bind&listen port=0 [1691473586.499645][172872:172872] CHIP:IN: UDP::Init bound to port=33008 [1691473586.499648][172872:172872] CHIP:IN: UDP::Init bind&listen port=0 [1691473586.499655][172872:172872] CHIP:IN: UDP::Init bound to port=58005 [1691473586.499657][172872:172872] CHIP:IN: BLEBase::Init - setting/overriding transport [1691473586.499659][172872:172872] CHIP:IN: TransportMgr initialized [1691473586.499666][172872:172872] CHIP:FP: Initializing FabricTable from persistent storage [1691473586.499712][172872:172872] CHIP:TS: Last Known Good Time: 2023-08-07T11:26:55 [1691473586.500070][172872:172872] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x5B53930E0EAEF3A1, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1691473586.500942][172872:172872] CHIP:ZCL: Using ZAP configuration... [1691473586.501224][172872:172872] CHIP:CTL: System State Initialized... [1691473586.501283][172872:172872] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1691473586.501296][172872:172872] CHIP:CTL: Setting attestation nonce to random value [1691473586.501303][172872:172872] CHIP:CTL: Setting CSR nonce to random value [1691473586.501313][172872:172872] CHIP:IN: UDP::Init bind&listen port=5550 [1691473586.501321][172872:172872] CHIP:IN: UDP::Init bound to port=5550 [1691473586.501324][172872:172872] CHIP:IN: UDP::Init bind&listen port=5550 [1691473586.501333][172872:172872] CHIP:IN: UDP::Init bound to port=5550 [1691473586.501336][172872:172872] CHIP:IN: TransportMgr initialized [1691473586.501389][172872:172874] CHIP:DL: CHIP task running [1691473586.501447][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1691473586.501498][172872:172874] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1691473586.501518][172872:172874] CHIP:CTL: Setting attestation nonce to random value [1691473586.501538][172872:172874] CHIP:CTL: Setting CSR nonce to random value [1691473586.501716][172872:172874] CHIP:CTL: Generating NOC [1691473586.501946][172872:172874] CHIP:FP: Validating NOC chain [1691473586.502272][172872:172874] CHIP:FP: NOC chain validation successful [1691473586.502329][172872:172874] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1691473586.502349][172872:172874] CHIP:TS: Last Known Good Time: 2023-08-07T11:26:55 [1691473586.502354][172872:172874] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1691473586.502356][172872:172874] CHIP:TS: Retaining current Last Known Good Time [1691473586.505210][172872:172874] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1691473586.508294][172872:172874] CHIP:TS: Committing Last Known Good Time to storage: 2023-08-07T11:26:55 [1691473586.508997][172872:172874] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 5B53930E0EAEF3A1) [1691473586.509029][172872:172874] CHIP:IN: UDP::Init bind&listen port=5550 [1691473586.509044][172872:172874] CHIP:IN: UDP::Init bound to port=5550 [1691473586.509051][172872:172874] CHIP:IN: UDP::Init bind&listen port=5550 [1691473586.509058][172872:172874] CHIP:IN: UDP::Init bound to port=5550 [1691473586.509060][172872:172874] CHIP:IN: TransportMgr initialized [1691473586.513875][172872:172874] CHIP:TOO: ***** Test Start : Test_TC_SMOKECO_2_2 [1691473586.513921][172872:172874] CHIP:TOO: ***** Test Step 0 : Commission DUT to TH [1691473586.513982][172872:172874] CHIP:IN: Expiring all sessions for node <0000000000000001, 1>!! [1691473586.514042][172872:172874] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1691473586.514062][172872:172874] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1691473586.514072][172872:172874] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1691473586.514513][172872:172874] CHIP:DIS: UDP:[fe80::215:5dff:fe83:df65%eth0]:5540: new best score: 7 [1691473586.514549][172872:172874] CHIP:DIS: UDP:172.20.0.6%eth0:5540: score has not improved: 2 [1691473586.514555][172872:172874] CHIP:DIS: Checking node lookup status after 1 ms [1691473586.514557][172872:172874] CHIP:DIS: Keeping DNSSD lookup active [1691473586.514740][172872:172874] CHIP:DIS: UDP:[fe80::215:5dff:fe83:df65%eth0]:5540: score has not improved: 7 [1691473586.514780][172872:172874] CHIP:DIS: UDP:172.20.0.6%eth0:5540: score has not improved: 2 [1691473586.514786][172872:172874] CHIP:DIS: Checking node lookup status after 1 ms [1691473586.514788][172872:172874] CHIP:DIS: Keeping DNSSD lookup active [1691473586.514925][172872:172874] CHIP:DIS: UDP:172.17.0.1%docker0:5540: score has not improved: 2 [1691473586.514955][172872:172874] CHIP:DIS: Checking node lookup status after 1 ms [1691473586.514962][172872:172874] CHIP:DIS: Keeping DNSSD lookup active [1691473586.713947][172872:172874] CHIP:DIS: Checking node lookup status after 200 ms [1691473586.714018][172872:172874] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::215:5dff:fe83:df65%eth0]:5540 while in state 2 [1691473586.714025][172872:172874] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1691473586.714071][172872:172874] CHIP:IN: SecureSession[0x7fc36c00b0e0]: Allocated Type:2 LSID:13846 [1691473586.714079][172872:172874] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1691473586.714303][172872:172874] CHIP:EM: <<< [E:58080i S:0 M:249042446] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1691473586.714345][172872:172874] CHIP:IN: (U) Sending msg 249042446 to IP address 'UDP:[fe80::215:5dff:fe83:df65%eth0]:5540' [1691473586.714390][172872:172874] CHIP:SC: Sent Sigma1 msg [1691473586.714424][172872:172874] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1691473586.714433][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.716486][172872:172874] CHIP:EM: >>> [E:58080i S:0 M:142776304 (Ack:249042446)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1691473586.716530][172872:172874] CHIP:EM: Found matching exchange: 58080i, Delegate: 0x7fc36c00e238 [1691473586.716540][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:249042446 from Retrans Table on exchange 58080i [1691473586.716549][172872:172874] CHIP:SC: Received Sigma2 msg [1691473586.716555][172872:172874] CHIP:SC: Peer assigned session session ID 33001 [1691473586.717341][172872:172874] CHIP:SC: Sending Sigma3 [1691473586.717487][172872:172874] CHIP:EM: <<< [E:58080i S:0 M:249042447 (Ack:142776304)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1691473586.717527][172872:172874] CHIP:IN: (U) Sending msg 249042447 to IP address 'UDP:[fe80::215:5dff:fe83:df65%eth0]:5540' [1691473586.717563][172872:172874] CHIP:SC: Sent Sigma3 msg [1691473586.717593][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.717600][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.720677][172872:172874] CHIP:EM: >>> [E:58080i S:0 M:142776305 (Ack:249042447)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1691473586.720723][172872:172874] CHIP:EM: Found matching exchange: 58080i, Delegate: 0x7fc36c00e238 [1691473586.720734][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:249042447 from Retrans Table on exchange 58080i [1691473586.720742][172872:172874] CHIP:SC: Success status report received. Session was established [1691473586.721951][172872:172874] CHIP:SC: SecureSession[0x7fc36c00b0e0, LSID:13846]: State change 'kEstablishing' --> 'kActive' [1691473586.721985][172872:172874] CHIP:IN: SecureSession[0x7fc36c00b0e0]: Activated - Type:2 LSID:13846 [1691473586.721992][172872:172874] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:13846 PSID:33001! [1691473586.721997][172872:172874] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1691473586.722011][172872:172874] CHIP:TOO: **** Test Setup: Device Connected [1691473586.722028][172872:172874] CHIP:EM: <<< [E:58080i S:0 M:249042448 (Ack:142776305)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473586.722045][172872:172874] CHIP:IN: (U) Sending msg 249042448 to IP address 'UDP:[fe80::215:5dff:fe83:df65%eth0]:5540' [1691473586.722079][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:142776305 on exchange 58080i [1691473586.722100][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.722113][172872:172874] CHIP:TOO: ***** Test Step 1 : Generate an event on the accessory [1691473586.722129][172872:172874] CHIP:DMG: ICR moving to [AddingComm] [1691473586.722153][172872:172874] CHIP:DMG: ICR moving to [AddedComma] [1691473586.722180][172872:172874] CHIP:EM: <<< [E:58081i S:13846 M:176486143] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473586.722202][172872:172874] CHIP:IN: (S) Sending msg 176486143 on secure session with LSID: 13846 [1691473586.722247][172872:172874] CHIP:DMG: ICR moving to [CommandSen] [1691473586.722291][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.723242][172872:172874] CHIP:EM: >>> [E:58081i S:13846 M:46254435 (Ack:176486143)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473586.723278][172872:172874] CHIP:EM: Found matching exchange: 58081i, Delegate: 0x7fc36c00a368 [1691473586.723289][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486143 from Retrans Table on exchange 58081i [1691473586.723295][172872:172874] CHIP:DMG: ICR moving to [ResponseRe] [1691473586.723306][172872:172874] CHIP:DMG: InvokeResponseMessage = [1691473586.723309][172872:172874] CHIP:DMG: { [1691473586.723312][172872:172874] CHIP:DMG: suppressResponse = false, [1691473586.723314][172872:172874] CHIP:DMG: InvokeResponseIBs = [1691473586.723318][172872:172874] CHIP:DMG: [ [1691473586.723320][172872:172874] CHIP:DMG: InvokeResponseIB = [1691473586.723323][172872:172874] CHIP:DMG: { [1691473586.723325][172872:172874] CHIP:DMG: CommandDataIB = [1691473586.723327][172872:172874] CHIP:DMG: { [1691473586.723329][172872:172874] CHIP:DMG: CommandPathIB = [1691473586.723332][172872:172874] CHIP:DMG: { [1691473586.723334][172872:172874] CHIP:DMG: EndpointId = 0x1, [1691473586.723336][172872:172874] CHIP:DMG: ClusterId = 0xfff1fc05, [1691473586.723338][172872:172874] CHIP:DMG: CommandId = 0xa, [1691473586.723340][172872:172874] CHIP:DMG: }, [1691473586.723343][172872:172874] CHIP:DMG: [1691473586.723345][172872:172874] CHIP:DMG: CommandFields = [1691473586.723347][172872:172874] CHIP:DMG: { [1691473586.723350][172872:172874] CHIP:DMG: 0x0 = 6, [1691473586.723352][172872:172874] CHIP:DMG: }, [1691473586.723354][172872:172874] CHIP:DMG: }, [1691473586.723357][172872:172874] CHIP:DMG: [1691473586.723359][172872:172874] CHIP:DMG: }, [1691473586.723362][172872:172874] CHIP:DMG: [1691473586.723364][172872:172874] CHIP:DMG: ], [1691473586.723372][172872:172874] CHIP:DMG: [1691473586.723375][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473586.723376][172872:172874] CHIP:DMG: }, [1691473586.723388][172872:172874] CHIP:DMG: Received Command Response Data, Endpoint=1 Cluster=0xFFF1_FC05 Command=0x0000_000A [1691473586.723410][172872:172874] CHIP:DMG: ICR moving to [AwaitingDe] [1691473586.723430][172872:172874] CHIP:EM: <<< [E:58081i S:13846 M:176486144 (Ack:46254435)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473586.723437][172872:172874] CHIP:IN: (S) Sending msg 176486144 on secure session with LSID: 13846 [1691473586.723464][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254435 on exchange 58081i [1691473586.723485][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.723496][172872:172874] CHIP:TOO: ***** Test Step 2 : TH subscribes to SmokeState attribute from DUT [1691473586.723507][172872:172874] CHIP:TOO: Sending SubscribeAttribute to: [1691473586.723518][172872:172874] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0001, endpoint 1 [1691473586.723546][172872:172874] CHIP:EM: <<< [E:58082i S:13846 M:176486145] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:03 (IM:SubscribeRequest) [1691473586.723552][172872:172874] CHIP:IN: (S) Sending msg 176486145 on secure session with LSID: 13846 [1691473586.723572][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c00fc20]: Moving to [AwaitingIn] [1691473586.723584][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.728061][172872:172874] CHIP:EM: >>> [E:58082i S:13846 M:46254436 (Ack:176486145)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473586.728200][172872:172874] CHIP:EM: Found matching exchange: 58082i, Delegate: 0x7fc36c00fc30 [1691473586.728239][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486145 from Retrans Table on exchange 58082i [1691473586.728306][172872:172874] CHIP:DMG: ReportDataMessage = [1691473586.728317][172872:172874] CHIP:DMG: { [1691473586.728323][172872:172874] CHIP:DMG: SubscriptionId = 0xad791327, [1691473586.728327][172872:172874] CHIP:DMG: AttributeReportIBs = [1691473586.728335][172872:172874] CHIP:DMG: [ [1691473586.728338][172872:172874] CHIP:DMG: AttributeReportIB = [1691473586.728345][172872:172874] CHIP:DMG: { [1691473586.728350][172872:172874] CHIP:DMG: AttributeDataIB = [1691473586.728355][172872:172874] CHIP:DMG: { [1691473586.728365][172872:172874] CHIP:DMG: DataVersion = 0x220ec223, [1691473586.728369][172872:172874] CHIP:DMG: AttributePathIB = [1691473586.728374][172872:172874] CHIP:DMG: { [1691473586.728377][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473586.728381][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473586.728385][172872:172874] CHIP:DMG: Attribute = 0x0000_0001, [1691473586.728388][172872:172874] CHIP:DMG: } [1691473586.728392][172872:172874] CHIP:DMG: [1691473586.728399][172872:172874] CHIP:DMG: Data = 0, [1691473586.728401][172872:172874] CHIP:DMG: }, [1691473586.728406][172872:172874] CHIP:DMG: [1691473586.728408][172872:172874] CHIP:DMG: }, [1691473586.728413][172872:172874] CHIP:DMG: [1691473586.728417][172872:172874] CHIP:DMG: ], [1691473586.728422][172872:172874] CHIP:DMG: [1691473586.728425][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473586.728429][172872:172874] CHIP:DMG: } [1691473586.728498][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c00fc20]: Moving to [AwaitingSu] [1691473586.728591][172872:172874] CHIP:EM: <<< [E:58082i S:13846 M:176486146 (Ack:46254436)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473586.728632][172872:172874] CHIP:IN: (S) Sending msg 176486146 on secure session with LSID: 13846 [1691473586.728701][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.728745][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.729328][172872:172874] CHIP:EM: >>> [E:58082i S:13846 M:46254437 (Ack:176486146)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:04 (IM:SubscribeResponse) [1691473586.729375][172872:172874] CHIP:EM: Found matching exchange: 58082i, Delegate: 0x7fc36c00fc30 [1691473586.729385][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486146 from Retrans Table on exchange 58082i [1691473586.729391][172872:172874] CHIP:DMG: SubscribeResponse is received [1691473586.729398][172872:172874] CHIP:DMG: SubscribeResponseMessage = [1691473586.729401][172872:172874] CHIP:DMG: { [1691473586.729404][172872:172874] CHIP:DMG: SubscriptionId = 0xad791327, [1691473586.729406][172872:172874] CHIP:DMG: MaxInterval = 0x1e, [1691473586.729408][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473586.729409][172872:172874] CHIP:DMG: } [1691473586.729413][172872:172874] CHIP:DMG: Subscription established with SubscriptionID = 0xad791327 MinInterval = 3s MaxInterval = 30s Peer = 01:0000000000000001 [1691473586.729416][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c00fc20]: Moving to [Subscripti] [1691473586.729424][172872:172874] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0xad791327 Peer = 01:0000000000000001 [1691473586.729437][172872:172874] CHIP:EM: <<< [E:58082i S:13846 M:176486147 (Ack:46254437)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473586.729456][172872:172874] CHIP:IN: (S) Sending msg 176486147 on secure session with LSID: 13846 [1691473586.729485][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254437 on exchange 58082i [1691473586.729506][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.729517][172872:172874] CHIP:TOO: ***** Test Step 3 : TH subscribes to SmokeState Event from DUT [1691473586.729540][172872:172874] CHIP:TOO: Sending SubscribeEvent to: [1691473586.729557][172872:172874] CHIP:TOO: cluster 0x0000_005C, event: 0x0000_0000, endpoint 1 [1691473586.729591][172872:172874] CHIP:EM: <<< [E:58083i S:13846 M:176486148] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:03 (IM:SubscribeRequest) [1691473586.729611][172872:172874] CHIP:IN: (S) Sending msg 176486148 on secure session with LSID: 13846 [1691473586.729643][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0122e0]: Moving to [AwaitingIn] [1691473586.729666][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.733855][172872:172874] CHIP:EM: >>> [E:58083i S:13846 M:46254438 (Ack:176486148)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473586.733917][172872:172874] CHIP:EM: Found matching exchange: 58083i, Delegate: 0x7fc36c0122f0 [1691473586.733943][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486148 from Retrans Table on exchange 58083i [1691473586.733967][172872:172874] CHIP:DMG: ReportDataMessage = [1691473586.733972][172872:172874] CHIP:DMG: { [1691473586.733974][172872:172874] CHIP:DMG: SubscriptionId = 0x62472c08, [1691473586.733977][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473586.733979][172872:172874] CHIP:DMG: } [1691473586.733986][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0122e0]: Moving to [AwaitingSu] [1691473586.734011][172872:172874] CHIP:EM: <<< [E:58083i S:13846 M:176486149 (Ack:46254438)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473586.734033][172872:172874] CHIP:IN: (S) Sending msg 176486149 on secure session with LSID: 13846 [1691473586.734076][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.734096][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.734478][172872:172874] CHIP:EM: >>> [E:58083i S:13846 M:46254439 (Ack:176486149)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:04 (IM:SubscribeResponse) [1691473586.734510][172872:172874] CHIP:EM: Found matching exchange: 58083i, Delegate: 0x7fc36c0122f0 [1691473586.734521][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486149 from Retrans Table on exchange 58083i [1691473586.734532][172872:172874] CHIP:DMG: SubscribeResponse is received [1691473586.734538][172872:172874] CHIP:DMG: SubscribeResponseMessage = [1691473586.734541][172872:172874] CHIP:DMG: { [1691473586.734543][172872:172874] CHIP:DMG: SubscriptionId = 0x62472c08, [1691473586.734545][172872:172874] CHIP:DMG: MaxInterval = 0x1e, [1691473586.734547][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473586.734549][172872:172874] CHIP:DMG: } [1691473586.734551][172872:172874] CHIP:DMG: Subscription established with SubscriptionID = 0x62472c08 MinInterval = 3s MaxInterval = 30s Peer = 01:0000000000000001 [1691473586.734555][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0122e0]: Moving to [Subscripti] [1691473586.734561][172872:172874] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x62472c08 Peer = 01:0000000000000001 [1691473586.734575][172872:172874] CHIP:EM: <<< [E:58083i S:13846 M:176486150 (Ack:46254439)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473586.734580][172872:172874] CHIP:IN: (S) Sending msg 176486150 on secure session with LSID: 13846 [1691473586.734606][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254439 on exchange 58083i [1691473586.734628][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.734639][172872:172874] CHIP:TOO: ***** Test Step 4 : TH reads ExpressedState attribute from DUT [1691473586.734654][172872:172874] CHIP:TOO: Sending ReadAttribute to: [1691473586.734674][172872:172874] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0000, endpoint 1 [1691473586.734684][172872:172874] CHIP:DMG: SendReadRequest ReadClient[0x7fc36c0111f0]: Sending Read Request [1691473586.734706][172872:172874] CHIP:EM: <<< [E:58084i S:13846 M:176486151] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473586.734747][172872:172874] CHIP:IN: (S) Sending msg 176486151 on secure session with LSID: 13846 [1691473586.734781][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0111f0]: Moving to [AwaitingIn] [1691473586.734795][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.735546][172872:172874] CHIP:EM: >>> [E:58084i S:13846 M:46254440 (Ack:176486151)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473586.735587][172872:172874] CHIP:EM: Found matching exchange: 58084i, Delegate: 0x7fc36c011200 [1691473586.735598][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486151 from Retrans Table on exchange 58084i [1691473586.735610][172872:172874] CHIP:DMG: ReportDataMessage = [1691473586.735613][172872:172874] CHIP:DMG: { [1691473586.735615][172872:172874] CHIP:DMG: AttributeReportIBs = [1691473586.735619][172872:172874] CHIP:DMG: [ [1691473586.735621][172872:172874] CHIP:DMG: AttributeReportIB = [1691473586.735625][172872:172874] CHIP:DMG: { [1691473586.735627][172872:172874] CHIP:DMG: AttributeDataIB = [1691473586.735629][172872:172874] CHIP:DMG: { [1691473586.735631][172872:172874] CHIP:DMG: DataVersion = 0x220ec223, [1691473586.735633][172872:172874] CHIP:DMG: AttributePathIB = [1691473586.735636][172872:172874] CHIP:DMG: { [1691473586.735638][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473586.735640][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473586.735642][172872:172874] CHIP:DMG: Attribute = 0x0000_0000, [1691473586.735644][172872:172874] CHIP:DMG: } [1691473586.735646][172872:172874] CHIP:DMG: [1691473586.735649][172872:172874] CHIP:DMG: Data = 0, [1691473586.735651][172872:172874] CHIP:DMG: }, [1691473586.735654][172872:172874] CHIP:DMG: [1691473586.735656][172872:172874] CHIP:DMG: }, [1691473586.735659][172872:172874] CHIP:DMG: [1691473586.735660][172872:172874] CHIP:DMG: ], [1691473586.735664][172872:172874] CHIP:DMG: [1691473586.735666][172872:172874] CHIP:DMG: SuppressResponse = true, [1691473586.735668][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473586.735675][172872:172874] CHIP:DMG: } [1691473586.735738][172872:172874] CHIP:EM: <<< [E:58084i S:13846 M:176486152 (Ack:46254440)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473586.735747][172872:172874] CHIP:IN: (S) Sending msg 176486152 on secure session with LSID: 13846 [1691473586.735760][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254440 on exchange 58084i [1691473586.735766][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.735774][172872:172874] CHIP:TOO: ***** Test Step 5 : TH reads TestEventTriggersEnabled attribute from General Diagnostics Cluster [1691473586.735783][172872:172874] CHIP:TOO: Sending ReadAttribute to: [1691473586.735788][172872:172874] CHIP:TOO: cluster 0x0000_0033, attribute: 0x0000_0008, endpoint 0 [1691473586.735793][172872:172874] CHIP:DMG: SendReadRequest ReadClient[0x7fc36c0111f0]: Sending Read Request [1691473586.735812][172872:172874] CHIP:EM: <<< [E:58085i S:13846 M:176486153] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473586.735817][172872:172874] CHIP:IN: (S) Sending msg 176486153 on secure session with LSID: 13846 [1691473586.735832][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0111f0]: Moving to [AwaitingIn] [1691473586.735838][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.740063][172872:172874] CHIP:EM: >>> [E:58085i S:13846 M:46254441 (Ack:176486153)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473586.740130][172872:172874] CHIP:EM: Found matching exchange: 58085i, Delegate: 0x7fc36c011200 [1691473586.740154][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486153 from Retrans Table on exchange 58085i [1691473586.740185][172872:172874] CHIP:DMG: ReportDataMessage = [1691473586.740192][172872:172874] CHIP:DMG: { [1691473586.740196][172872:172874] CHIP:DMG: AttributeReportIBs = [1691473586.740201][172872:172874] CHIP:DMG: [ [1691473586.740205][172872:172874] CHIP:DMG: AttributeReportIB = [1691473586.740211][172872:172874] CHIP:DMG: { [1691473586.740215][172872:172874] CHIP:DMG: AttributeDataIB = [1691473586.740219][172872:172874] CHIP:DMG: { [1691473586.740223][172872:172874] CHIP:DMG: DataVersion = 0x835b76d0, [1691473586.740227][172872:172874] CHIP:DMG: AttributePathIB = [1691473586.740231][172872:172874] CHIP:DMG: { [1691473586.740235][172872:172874] CHIP:DMG: Endpoint = 0x0, [1691473586.740238][172872:172874] CHIP:DMG: Cluster = 0x33, [1691473586.740242][172872:172874] CHIP:DMG: Attribute = 0x0000_0008, [1691473586.740245][172872:172874] CHIP:DMG: } [1691473586.740249][172872:172874] CHIP:DMG: [1691473586.740255][172872:172874] CHIP:DMG: Data = true, [1691473586.740258][172872:172874] CHIP:DMG: }, [1691473586.740263][172872:172874] CHIP:DMG: [1691473586.740266][172872:172874] CHIP:DMG: }, [1691473586.740270][172872:172874] CHIP:DMG: [1691473586.740273][172872:172874] CHIP:DMG: ], [1691473586.740278][172872:172874] CHIP:DMG: [1691473586.740282][172872:172874] CHIP:DMG: SuppressResponse = true, [1691473586.740286][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473586.740289][172872:172874] CHIP:DMG: } [1691473586.740359][172872:172874] CHIP:EM: <<< [E:58085i S:13846 M:176486154 (Ack:46254441)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473586.740389][172872:172874] CHIP:IN: (S) Sending msg 176486154 on secure session with LSID: 13846 [1691473586.740417][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254441 on exchange 58085i [1691473586.740429][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.740444][172872:172874] CHIP:TOO: ***** Test Step 6 : 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 [1691473586.740495][172872:172874] CHIP:DMG: ICR moving to [AddingComm] [1691473586.740511][172872:172874] CHIP:DMG: ICR moving to [AddedComma] [1691473586.740540][172872:172874] CHIP:EM: <<< [E:58086i S:13846 M:176486155] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473586.740565][172872:172874] CHIP:IN: (S) Sending msg 176486155 on secure session with LSID: 13846 [1691473586.740595][172872:172874] CHIP:DMG: ICR moving to [CommandSen] [1691473586.740605][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.745907][172872:172874] CHIP:EM: >>> [E:58086i S:13846 M:46254442 (Ack:176486155)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473586.745948][172872:172874] CHIP:EM: Found matching exchange: 58086i, Delegate: 0x7fc36c00a368 [1691473586.745962][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486155 from Retrans Table on exchange 58086i [1691473586.745969][172872:172874] CHIP:DMG: ICR moving to [ResponseRe] [1691473586.745982][172872:172874] CHIP:DMG: InvokeResponseMessage = [1691473586.745984][172872:172874] CHIP:DMG: { [1691473586.745987][172872:172874] CHIP:DMG: suppressResponse = false, [1691473586.745989][172872:172874] CHIP:DMG: InvokeResponseIBs = [1691473586.745993][172872:172874] CHIP:DMG: [ [1691473586.745995][172872:172874] CHIP:DMG: InvokeResponseIB = [1691473586.745998][172872:172874] CHIP:DMG: { [1691473586.746000][172872:172874] CHIP:DMG: CommandStatusIB = [1691473586.746003][172872:172874] CHIP:DMG: { [1691473586.746005][172872:172874] CHIP:DMG: CommandPathIB = [1691473586.746008][172872:172874] CHIP:DMG: { [1691473586.746010][172872:172874] CHIP:DMG: EndpointId = 0x0, [1691473586.746012][172872:172874] CHIP:DMG: ClusterId = 0x33, [1691473586.746014][172872:172874] CHIP:DMG: CommandId = 0x0, [1691473586.746016][172872:172874] CHIP:DMG: }, [1691473586.746019][172872:172874] CHIP:DMG: [1691473586.746021][172872:172874] CHIP:DMG: StatusIB = [1691473586.746024][172872:172874] CHIP:DMG: { [1691473586.746026][172872:172874] CHIP:DMG: status = 0x00 (SUCCESS), [1691473586.746028][172872:172874] CHIP:DMG: }, [1691473586.746030][172872:172874] CHIP:DMG: [1691473586.746032][172872:172874] CHIP:DMG: }, [1691473586.746035][172872:172874] CHIP:DMG: [1691473586.746037][172872:172874] CHIP:DMG: }, [1691473586.746040][172872:172874] CHIP:DMG: [1691473586.746042][172872:172874] CHIP:DMG: ], [1691473586.746045][172872:172874] CHIP:DMG: [1691473586.746047][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473586.746049][172872:172874] CHIP:DMG: }, [1691473586.746060][172872:172874] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473586.746082][172872:172874] CHIP:DMG: ICR moving to [AwaitingDe] [1691473586.746106][172872:172874] CHIP:EM: <<< [E:58086i S:13846 M:176486156 (Ack:46254442)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473586.746113][172872:172874] CHIP:IN: (S) Sending msg 176486156 on secure session with LSID: 13846 [1691473586.746141][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254442 on exchange 58086i [1691473586.746163][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473586.746175][172872:172874] CHIP:TOO: ***** Test Step 7 : TH waits for a report of SmokeState attribute from DUT with a timeout of 300 seconds [1691473589.730205][172872:172874] CHIP:EM: >>> [E:47133r S:13846 M:46254443] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473589.730285][172872:172874] CHIP:EM: Handling via exchange: 47133r, Delegate: 0x55c0b1d47508 [1691473589.730309][172872:172874] CHIP:DMG: ReportDataMessage = [1691473589.730314][172872:172874] CHIP:DMG: { [1691473589.730317][172872:172874] CHIP:DMG: SubscriptionId = 0xad791327, [1691473589.730319][172872:172874] CHIP:DMG: AttributeReportIBs = [1691473589.730323][172872:172874] CHIP:DMG: [ [1691473589.730332][172872:172874] CHIP:DMG: AttributeReportIB = [1691473589.730336][172872:172874] CHIP:DMG: { [1691473589.730338][172872:172874] CHIP:DMG: AttributeDataIB = [1691473589.730340][172872:172874] CHIP:DMG: { [1691473589.730343][172872:172874] CHIP:DMG: DataVersion = 0x220ec225, [1691473589.730344][172872:172874] CHIP:DMG: AttributePathIB = [1691473589.730347][172872:172874] CHIP:DMG: { [1691473589.730349][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473589.730351][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473589.730353][172872:172874] CHIP:DMG: Attribute = 0x0000_0001, [1691473589.730355][172872:172874] CHIP:DMG: } [1691473589.730358][172872:172874] CHIP:DMG: [1691473589.730360][172872:172874] CHIP:DMG: Data = 1, [1691473589.730362][172872:172874] CHIP:DMG: }, [1691473589.730365][172872:172874] CHIP:DMG: [1691473589.730367][172872:172874] CHIP:DMG: }, [1691473589.730370][172872:172874] CHIP:DMG: [1691473589.730371][172872:172874] CHIP:DMG: ], [1691473589.730375][172872:172874] CHIP:DMG: [1691473589.730377][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473589.730379][172872:172874] CHIP:DMG: } [1691473589.730421][172872:172874] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0xad791327 Peer = 01:0000000000000001 [1691473589.730463][172872:172874] CHIP:EM: <<< [E:47133r S:13846 M:176486157 (Ack:46254443)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473589.730484][172872:172874] CHIP:IN: (S) Sending msg 176486157 on secure session with LSID: 13846 [1691473589.730527][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473589.730563][172872:172874] CHIP:TOO: ***** Test Step 8 : TH reads ExpressedState attribute from DUT [1691473589.730581][172872:172874] CHIP:TOO: Sending ReadAttribute to: [1691473589.730589][172872:172874] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0000, endpoint 1 [1691473589.730596][172872:172874] CHIP:DMG: SendReadRequest ReadClient[0x7fc36c0111f0]: Sending Read Request [1691473589.730616][172872:172874] CHIP:EM: <<< [E:58087i S:13846 M:176486158] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473589.730636][172872:172874] CHIP:IN: (S) Sending msg 176486158 on secure session with LSID: 13846 [1691473589.730654][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0111f0]: Moving to [AwaitingIn] [1691473589.730663][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473589.730968][172872:172874] CHIP:EM: >>> [E:47133r S:13846 M:46254444 (Ack:176486157)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473589.731007][172872:172874] CHIP:EM: Found matching exchange: 47133r, Delegate: (nil) [1691473589.731019][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486157 from Retrans Table on exchange 47133r [1691473589.731025][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473589.731619][172872:172874] CHIP:EM: >>> [E:58087i S:13846 M:46254445 (Ack:176486158)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473589.731655][172872:172874] CHIP:EM: Found matching exchange: 58087i, Delegate: 0x7fc36c011200 [1691473589.731666][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486158 from Retrans Table on exchange 58087i [1691473589.731678][172872:172874] CHIP:DMG: ReportDataMessage = [1691473589.731682][172872:172874] CHIP:DMG: { [1691473589.731683][172872:172874] CHIP:DMG: AttributeReportIBs = [1691473589.731687][172872:172874] CHIP:DMG: [ [1691473589.731689][172872:172874] CHIP:DMG: AttributeReportIB = [1691473589.731693][172872:172874] CHIP:DMG: { [1691473589.731695][172872:172874] CHIP:DMG: AttributeDataIB = [1691473589.731697][172872:172874] CHIP:DMG: { [1691473589.731699][172872:172874] CHIP:DMG: DataVersion = 0x220ec225, [1691473589.731701][172872:172874] CHIP:DMG: AttributePathIB = [1691473589.731703][172872:172874] CHIP:DMG: { [1691473589.731711][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473589.731713][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473589.731715][172872:172874] CHIP:DMG: Attribute = 0x0000_0000, [1691473589.731717][172872:172874] CHIP:DMG: } [1691473589.731720][172872:172874] CHIP:DMG: [1691473589.731722][172872:172874] CHIP:DMG: Data = 1, [1691473589.731724][172872:172874] CHIP:DMG: }, [1691473589.731727][172872:172874] CHIP:DMG: [1691473589.731729][172872:172874] CHIP:DMG: }, [1691473589.731732][172872:172874] CHIP:DMG: [1691473589.731734][172872:172874] CHIP:DMG: ], [1691473589.731738][172872:172874] CHIP:DMG: [1691473589.731740][172872:172874] CHIP:DMG: SuppressResponse = true, [1691473589.731742][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473589.731743][172872:172874] CHIP:DMG: } [1691473589.731784][172872:172874] CHIP:EM: <<< [E:58087i S:13846 M:176486159 (Ack:46254445)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473589.731804][172872:172874] CHIP:IN: (S) Sending msg 176486159 on secure session with LSID: 13846 [1691473589.731821][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254445 on exchange 58087i [1691473589.731828][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473589.731834][172872:172874] CHIP:TOO: ***** Test Step 9 : TH waits for a report of SmokeState attribute from DUT with a timeout of 300 seconds [1691473616.735208][172872:172874] CHIP:EM: >>> [E:47134r S:13846 M:46254446] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473616.735266][172872:172874] CHIP:EM: Handling via exchange: 47134r, Delegate: 0x55c0b1d47508 [1691473616.735292][172872:172874] CHIP:DMG: ReportDataMessage = [1691473616.735297][172872:172874] CHIP:DMG: { [1691473616.735300][172872:172874] CHIP:DMG: SubscriptionId = 0x62472c08, [1691473616.735302][172872:172874] CHIP:DMG: EventReportIBs = [1691473616.735307][172872:172874] CHIP:DMG: [ [1691473616.735309][172872:172874] CHIP:DMG: EventReportIB = [1691473616.735313][172872:172874] CHIP:DMG: { [1691473616.735315][172872:172874] CHIP:DMG: EventDataIB = [1691473616.735318][172872:172874] CHIP:DMG: { [1691473616.735320][172872:172874] CHIP:DMG: EventPath = [1691473616.735323][172872:172874] CHIP:DMG: { [1691473616.735325][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473616.735327][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473616.735329][172872:172874] CHIP:DMG: Event = 0x0, [1691473616.735331][172872:172874] CHIP:DMG: }, [1691473616.735334][172872:172874] CHIP:DMG: [1691473616.735336][172872:172874] CHIP:DMG: EventNumber = 0x7, [1691473616.735338][172872:172874] CHIP:DMG: PriorityLevel = 0x2, [1691473616.735340][172872:172874] CHIP:DMG: EpochTimestamp = 0x189d3aeaa39, [1691473616.735342][172872:172874] CHIP:DMG: EventData = [1691473616.735345][172872:172874] CHIP:DMG: { [1691473616.735347][172872:172874] CHIP:DMG: 0x0 = 1, [1691473616.735349][172872:172874] CHIP:DMG: }, [1691473616.735351][172872:172874] CHIP:DMG: }, [1691473616.735354][172872:172874] CHIP:DMG: [1691473616.735356][172872:172874] CHIP:DMG: }, [1691473616.735360][172872:172874] CHIP:DMG: [1691473616.735361][172872:172874] CHIP:DMG: ], [1691473616.735366][172872:172874] CHIP:DMG: [1691473616.735368][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473616.735369][172872:172874] CHIP:DMG: } [1691473616.735434][172872:172874] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0x62472c08 Peer = 01:0000000000000001 [1691473616.735472][172872:172874] CHIP:EM: <<< [E:47134r S:13846 M:176486160 (Ack:46254446)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473616.735480][172872:172874] CHIP:IN: (S) Sending msg 176486160 on secure session with LSID: 13846 [1691473616.735524][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.735560][172872:172874] CHIP:TOO: ***** Test Step 10 : Start manually DUT self-test [1691473616.735577][172872:172874] CHIP:TOO: USER_PROMPT: Please enter 'y' for success [1691473616.735604][172872:172874] CHIP:TOO: ***** Test Step 11 : TH reads TestInProgress attribute from DUT [1691473616.735622][172872:172874] CHIP:TOO: Sending ReadAttribute to: [1691473616.735630][172872:172874] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0005, endpoint 1 [1691473616.735639][172872:172874] CHIP:DMG: SendReadRequest ReadClient[0x7fc36c0111f0]: Sending Read Request [1691473616.735660][172872:172874] CHIP:EM: <<< [E:58088i S:13846 M:176486161] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473616.735694][172872:172874] CHIP:IN: (S) Sending msg 176486161 on secure session with LSID: 13846 [1691473616.735721][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0111f0]: Moving to [AwaitingIn] [1691473616.735734][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.735922][172872:172874] CHIP:EM: >>> [E:47134r S:13846 M:46254447 (Ack:176486160)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473616.735958][172872:172874] CHIP:EM: Found matching exchange: 47134r, Delegate: (nil) [1691473616.735969][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486160 from Retrans Table on exchange 47134r [1691473616.735975][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.736417][172872:172874] CHIP:EM: >>> [E:58088i S:13846 M:46254448 (Ack:176486161)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473616.736452][172872:172874] CHIP:EM: Found matching exchange: 58088i, Delegate: 0x7fc36c011200 [1691473616.736462][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486161 from Retrans Table on exchange 58088i [1691473616.736473][172872:172874] CHIP:DMG: ReportDataMessage = [1691473616.736476][172872:172874] CHIP:DMG: { [1691473616.736478][172872:172874] CHIP:DMG: AttributeReportIBs = [1691473616.736482][172872:172874] CHIP:DMG: [ [1691473616.736484][172872:172874] CHIP:DMG: AttributeReportIB = [1691473616.736488][172872:172874] CHIP:DMG: { [1691473616.736490][172872:172874] CHIP:DMG: AttributeDataIB = [1691473616.736492][172872:172874] CHIP:DMG: { [1691473616.736495][172872:172874] CHIP:DMG: DataVersion = 0x220ec225, [1691473616.736496][172872:172874] CHIP:DMG: AttributePathIB = [1691473616.736499][172872:172874] CHIP:DMG: { [1691473616.736501][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473616.736503][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473616.736506][172872:172874] CHIP:DMG: Attribute = 0x0000_0005, [1691473616.736507][172872:172874] CHIP:DMG: } [1691473616.736510][172872:172874] CHIP:DMG: [1691473616.736512][172872:172874] CHIP:DMG: Data = false, [1691473616.736514][172872:172874] CHIP:DMG: }, [1691473616.736517][172872:172874] CHIP:DMG: [1691473616.736519][172872:172874] CHIP:DMG: }, [1691473616.736522][172872:172874] CHIP:DMG: [1691473616.736524][172872:172874] CHIP:DMG: ], [1691473616.736527][172872:172874] CHIP:DMG: [1691473616.736529][172872:172874] CHIP:DMG: SuppressResponse = true, [1691473616.736531][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473616.736533][172872:172874] CHIP:DMG: } [1691473616.736573][172872:172874] CHIP:EM: <<< [E:58088i S:13846 M:176486162 (Ack:46254448)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473616.736593][172872:172874] CHIP:IN: (S) Sending msg 176486162 on secure session with LSID: 13846 [1691473616.736608][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254448 on exchange 58088i [1691473616.736614][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.736621][172872:172874] CHIP:TOO: ***** Test Step 12 : TH sends SelfTestRequest command to DUT [1691473616.736631][172872:172874] CHIP:DMG: ICR moving to [AddingComm] [1691473616.736635][172872:172874] CHIP:DMG: ICR moving to [AddedComma] [1691473616.736655][172872:172874] CHIP:EM: <<< [E:58089i S:13846 M:176486163] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473616.736660][172872:172874] CHIP:IN: (S) Sending msg 176486163 on secure session with LSID: 13846 [1691473616.736674][172872:172874] CHIP:DMG: ICR moving to [CommandSen] [1691473616.736694][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.740349][172872:172874] CHIP:EM: >>> [E:58089i S:13846 M:46254449 (Ack:176486163)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473616.740395][172872:172874] CHIP:EM: Found matching exchange: 58089i, Delegate: 0x7fc36c00a368 [1691473616.740406][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486163 from Retrans Table on exchange 58089i [1691473616.740412][172872:172874] CHIP:DMG: ICR moving to [ResponseRe] [1691473616.740421][172872:172874] CHIP:DMG: InvokeResponseMessage = [1691473616.740423][172872:172874] CHIP:DMG: { [1691473616.740426][172872:172874] CHIP:DMG: suppressResponse = false, [1691473616.740427][172872:172874] CHIP:DMG: InvokeResponseIBs = [1691473616.740431][172872:172874] CHIP:DMG: [ [1691473616.740433][172872:172874] CHIP:DMG: InvokeResponseIB = [1691473616.740436][172872:172874] CHIP:DMG: { [1691473616.740438][172872:172874] CHIP:DMG: CommandStatusIB = [1691473616.740440][172872:172874] CHIP:DMG: { [1691473616.740442][172872:172874] CHIP:DMG: CommandPathIB = [1691473616.740445][172872:172874] CHIP:DMG: { [1691473616.740447][172872:172874] CHIP:DMG: EndpointId = 0x1, [1691473616.740449][172872:172874] CHIP:DMG: ClusterId = 0x5c, [1691473616.740451][172872:172874] CHIP:DMG: CommandId = 0x0, [1691473616.740453][172872:172874] CHIP:DMG: }, [1691473616.740456][172872:172874] CHIP:DMG: [1691473616.740458][172872:172874] CHIP:DMG: StatusIB = [1691473616.740461][172872:172874] CHIP:DMG: { [1691473616.740463][172872:172874] CHIP:DMG: status = 0x9c (BUSY), [1691473616.740465][172872:172874] CHIP:DMG: }, [1691473616.740467][172872:172874] CHIP:DMG: [1691473616.740469][172872:172874] CHIP:DMG: }, [1691473616.740472][172872:172874] CHIP:DMG: [1691473616.740474][172872:172874] CHIP:DMG: }, [1691473616.740478][172872:172874] CHIP:DMG: [1691473616.740480][172872:172874] CHIP:DMG: ], [1691473616.740483][172872:172874] CHIP:DMG: [1691473616.740485][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473616.740487][172872:172874] CHIP:DMG: }, [1691473616.740497][172872:172874] CHIP:DMG: Received Command Response Status for Endpoint=1 Cluster=0x0000_005C Command=0x0000_0000 Status=0x9c [1691473616.740508][172872:172874] CHIP:DMG: ICR moving to [AwaitingDe] [1691473616.740524][172872:172874] CHIP:EM: <<< [E:58089i S:13846 M:176486164 (Ack:46254449)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473616.740529][172872:172874] CHIP:IN: (S) Sending msg 176486164 on secure session with LSID: 13846 [1691473616.740556][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254449 on exchange 58089i [1691473616.740565][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.740573][172872:172874] CHIP:TOO: ***** Test Step 13 : TH reads TestInProgress attribute from DUT [1691473616.740581][172872:172874] CHIP:TOO: Sending ReadAttribute to: [1691473616.740586][172872:172874] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0005, endpoint 1 [1691473616.740591][172872:172874] CHIP:DMG: SendReadRequest ReadClient[0x7fc36c0111f0]: Sending Read Request [1691473616.740610][172872:172874] CHIP:EM: <<< [E:58090i S:13846 M:176486165] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473616.740616][172872:172874] CHIP:IN: (S) Sending msg 176486165 on secure session with LSID: 13846 [1691473616.740632][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0111f0]: Moving to [AwaitingIn] [1691473616.740639][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.741298][172872:172874] CHIP:EM: >>> [E:58090i S:13846 M:46254450 (Ack:176486165)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473616.741338][172872:172874] CHIP:EM: Found matching exchange: 58090i, Delegate: 0x7fc36c011200 [1691473616.741350][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486165 from Retrans Table on exchange 58090i [1691473616.741364][172872:172874] CHIP:DMG: ReportDataMessage = [1691473616.741369][172872:172874] CHIP:DMG: { [1691473616.741372][172872:172874] CHIP:DMG: AttributeReportIBs = [1691473616.741377][172872:172874] CHIP:DMG: [ [1691473616.741381][172872:172874] CHIP:DMG: AttributeReportIB = [1691473616.741386][172872:172874] CHIP:DMG: { [1691473616.741389][172872:172874] CHIP:DMG: AttributeDataIB = [1691473616.741393][172872:172874] CHIP:DMG: { [1691473616.741397][172872:172874] CHIP:DMG: DataVersion = 0x220ec225, [1691473616.741401][172872:172874] CHIP:DMG: AttributePathIB = [1691473616.741405][172872:172874] CHIP:DMG: { [1691473616.741409][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473616.741412][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473616.741416][172872:172874] CHIP:DMG: Attribute = 0x0000_0005, [1691473616.741419][172872:172874] CHIP:DMG: } [1691473616.741423][172872:172874] CHIP:DMG: [1691473616.741428][172872:172874] CHIP:DMG: Data = false, [1691473616.741432][172872:172874] CHIP:DMG: }, [1691473616.741436][172872:172874] CHIP:DMG: [1691473616.741440][172872:172874] CHIP:DMG: }, [1691473616.741445][172872:172874] CHIP:DMG: [1691473616.741448][172872:172874] CHIP:DMG: ], [1691473616.741453][172872:172874] CHIP:DMG: [1691473616.741457][172872:172874] CHIP:DMG: SuppressResponse = true, [1691473616.741460][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473616.741463][172872:172874] CHIP:DMG: } [1691473616.741518][172872:172874] CHIP:EM: <<< [E:58090i S:13846 M:176486166 (Ack:46254450)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473616.741546][172872:172874] CHIP:IN: (S) Sending msg 176486166 on secure session with LSID: 13846 [1691473616.741564][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254450 on exchange 58090i [1691473616.741571][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.741578][172872:172874] 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 Critical Smoke Alarm Test Event [1691473616.741589][172872:172874] CHIP:DMG: ICR moving to [AddingComm] [1691473616.741594][172872:172874] CHIP:DMG: ICR moving to [AddedComma] [1691473616.741611][172872:172874] CHIP:EM: <<< [E:58091i S:13846 M:176486167] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473616.741619][172872:172874] CHIP:IN: (S) Sending msg 176486167 on secure session with LSID: 13846 [1691473616.741634][172872:172874] CHIP:DMG: ICR moving to [CommandSen] [1691473616.741640][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.747288][172872:172874] CHIP:EM: >>> [E:58091i S:13846 M:46254451 (Ack:176486167)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473616.747336][172872:172874] CHIP:EM: Found matching exchange: 58091i, Delegate: 0x7fc36c00a368 [1691473616.747354][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486167 from Retrans Table on exchange 58091i [1691473616.747364][172872:172874] CHIP:DMG: ICR moving to [ResponseRe] [1691473616.747377][172872:172874] CHIP:DMG: InvokeResponseMessage = [1691473616.747379][172872:172874] CHIP:DMG: { [1691473616.747382][172872:172874] CHIP:DMG: suppressResponse = false, [1691473616.747384][172872:172874] CHIP:DMG: InvokeResponseIBs = [1691473616.747387][172872:172874] CHIP:DMG: [ [1691473616.747390][172872:172874] CHIP:DMG: InvokeResponseIB = [1691473616.747402][172872:172874] CHIP:DMG: { [1691473616.747406][172872:172874] CHIP:DMG: CommandStatusIB = [1691473616.747410][172872:172874] CHIP:DMG: { [1691473616.747413][172872:172874] CHIP:DMG: CommandPathIB = [1691473616.747417][172872:172874] CHIP:DMG: { [1691473616.747421][172872:172874] CHIP:DMG: EndpointId = 0x0, [1691473616.747425][172872:172874] CHIP:DMG: ClusterId = 0x33, [1691473616.747427][172872:172874] CHIP:DMG: CommandId = 0x0, [1691473616.747429][172872:172874] CHIP:DMG: }, [1691473616.747433][172872:172874] CHIP:DMG: [1691473616.747435][172872:172874] CHIP:DMG: StatusIB = [1691473616.747438][172872:172874] CHIP:DMG: { [1691473616.747440][172872:172874] CHIP:DMG: status = 0x00 (SUCCESS), [1691473616.747442][172872:172874] CHIP:DMG: }, [1691473616.747444][172872:172874] CHIP:DMG: [1691473616.747446][172872:172874] CHIP:DMG: }, [1691473616.747449][172872:172874] CHIP:DMG: [1691473616.747451][172872:172874] CHIP:DMG: }, [1691473616.747454][172872:172874] CHIP:DMG: [1691473616.747456][172872:172874] CHIP:DMG: ], [1691473616.747459][172872:172874] CHIP:DMG: [1691473616.747461][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473616.747463][172872:172874] CHIP:DMG: }, [1691473616.747475][172872:172874] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473616.747486][172872:172874] CHIP:DMG: ICR moving to [AwaitingDe] [1691473616.747518][172872:172874] CHIP:EM: <<< [E:58091i S:13846 M:176486168 (Ack:46254451)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473616.747543][172872:172874] CHIP:IN: (S) Sending msg 176486168 on secure session with LSID: 13846 [1691473616.747565][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254451 on exchange 58091i [1691473616.747576][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.747590][172872:172874] CHIP:TOO: ***** Test Step 15 : TH waits for a report of SmokeState attribute from DUT with a timeout of 300 seconds [1691473616.747631][172872:172874] CHIP:EM: >>> [E:47135r S:13846 M:46254452] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473616.747642][172872:172874] CHIP:EM: Handling via exchange: 47135r, Delegate: 0x55c0b1d47508 [1691473616.747655][172872:172874] CHIP:DMG: ReportDataMessage = [1691473616.747701][172872:172874] CHIP:DMG: { [1691473616.747708][172872:172874] CHIP:DMG: SubscriptionId = 0xad791327, [1691473616.747710][172872:172874] CHIP:DMG: AttributeReportIBs = [1691473616.747715][172872:172874] CHIP:DMG: [ [1691473616.747718][172872:172874] CHIP:DMG: AttributeReportIB = [1691473616.747724][172872:172874] CHIP:DMG: { [1691473616.747727][172872:172874] CHIP:DMG: AttributeDataIB = [1691473616.747730][172872:172874] CHIP:DMG: { [1691473616.747734][172872:172874] CHIP:DMG: DataVersion = 0x220ec226, [1691473616.747736][172872:172874] CHIP:DMG: AttributePathIB = [1691473616.747740][172872:172874] CHIP:DMG: { [1691473616.747744][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473616.747747][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473616.747750][172872:172874] CHIP:DMG: Attribute = 0x0000_0001, [1691473616.747751][172872:172874] CHIP:DMG: } [1691473616.747754][172872:172874] CHIP:DMG: [1691473616.747757][172872:172874] CHIP:DMG: Data = 2, [1691473616.747759][172872:172874] CHIP:DMG: }, [1691473616.747762][172872:172874] CHIP:DMG: [1691473616.747764][172872:172874] CHIP:DMG: }, [1691473616.747767][172872:172874] CHIP:DMG: [1691473616.747769][172872:172874] CHIP:DMG: ], [1691473616.747772][172872:172874] CHIP:DMG: [1691473616.747774][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473616.747776][172872:172874] CHIP:DMG: } [1691473616.747817][172872:172874] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0xad791327 Peer = 01:0000000000000001 [1691473616.747861][172872:172874] CHIP:EM: <<< [E:47135r S:13846 M:176486169 (Ack:46254452)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473616.747877][172872:172874] CHIP:IN: (S) Sending msg 176486169 on secure session with LSID: 13846 [1691473616.747937][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.747970][172872:172874] CHIP:TOO: ***** Test Step 16 : TH reads ExpressedState attribute from DUT [1691473616.747988][172872:172874] CHIP:TOO: Sending ReadAttribute to: [1691473616.747995][172872:172874] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0000, endpoint 1 [1691473616.748002][172872:172874] CHIP:DMG: SendReadRequest ReadClient[0x7fc36c0111f0]: Sending Read Request [1691473616.748023][172872:172874] CHIP:EM: <<< [E:58092i S:13846 M:176486170] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473616.748044][172872:172874] CHIP:IN: (S) Sending msg 176486170 on secure session with LSID: 13846 [1691473616.748065][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0111f0]: Moving to [AwaitingIn] [1691473616.748077][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.748417][172872:172874] CHIP:EM: >>> [E:47135r S:13846 M:46254453 (Ack:176486169)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473616.748455][172872:172874] CHIP:EM: Found matching exchange: 47135r, Delegate: (nil) [1691473616.748467][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486169 from Retrans Table on exchange 47135r [1691473616.748473][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.749176][172872:172874] CHIP:EM: >>> [E:58092i S:13846 M:46254454 (Ack:176486170)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473616.749203][172872:172874] CHIP:EM: Found matching exchange: 58092i, Delegate: 0x7fc36c011200 [1691473616.749213][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486170 from Retrans Table on exchange 58092i [1691473616.749226][172872:172874] CHIP:DMG: ReportDataMessage = [1691473616.749229][172872:172874] CHIP:DMG: { [1691473616.749231][172872:172874] CHIP:DMG: AttributeReportIBs = [1691473616.749236][172872:172874] CHIP:DMG: [ [1691473616.749238][172872:172874] CHIP:DMG: AttributeReportIB = [1691473616.749241][172872:172874] CHIP:DMG: { [1691473616.749243][172872:172874] CHIP:DMG: AttributeDataIB = [1691473616.749245][172872:172874] CHIP:DMG: { [1691473616.749248][172872:172874] CHIP:DMG: DataVersion = 0x220ec226, [1691473616.749250][172872:172874] CHIP:DMG: AttributePathIB = [1691473616.749252][172872:172874] CHIP:DMG: { [1691473616.749254][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473616.749256][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473616.749258][172872:172874] CHIP:DMG: Attribute = 0x0000_0000, [1691473616.749260][172872:172874] CHIP:DMG: } [1691473616.749263][172872:172874] CHIP:DMG: [1691473616.749266][172872:172874] CHIP:DMG: Data = 1, [1691473616.749268][172872:172874] CHIP:DMG: }, [1691473616.749271][172872:172874] CHIP:DMG: [1691473616.749273][172872:172874] CHIP:DMG: }, [1691473616.749275][172872:172874] CHIP:DMG: [1691473616.749277][172872:172874] CHIP:DMG: ], [1691473616.749281][172872:172874] CHIP:DMG: [1691473616.749283][172872:172874] CHIP:DMG: SuppressResponse = true, [1691473616.749285][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473616.749286][172872:172874] CHIP:DMG: } [1691473616.749332][172872:172874] CHIP:EM: <<< [E:58092i S:13846 M:176486171 (Ack:46254454)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473616.749365][172872:172874] CHIP:IN: (S) Sending msg 176486171 on secure session with LSID: 13846 [1691473616.749383][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254454 on exchange 58092i [1691473616.749390][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.749397][172872:172874] CHIP:TOO: ***** Test Step 17 : TH reads SmokeAlarm event from DUT [1691473616.749413][172872:172874] CHIP:TOO: Sending ReadEvent to: [1691473616.749430][172872:172874] CHIP:TOO: cluster 0x0000_005C, event: 0x0000_0000, endpoint 1 [1691473616.749439][172872:172874] CHIP:DMG: SendReadRequest ReadClient[0x7fc36c0111f0]: Sending Read Request [1691473616.749463][172872:172874] CHIP:EM: <<< [E:58093i S:13846 M:176486172] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473616.749469][172872:172874] CHIP:IN: (S) Sending msg 176486172 on secure session with LSID: 13846 [1691473616.749486][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0111f0]: Moving to [AwaitingIn] [1691473616.749508][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.754112][172872:172874] CHIP:EM: >>> [E:58093i S:13846 M:46254455 (Ack:176486172)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473616.754182][172872:172874] CHIP:EM: Found matching exchange: 58093i, Delegate: 0x7fc36c011200 [1691473616.754202][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486172 from Retrans Table on exchange 58093i [1691473616.754221][172872:172874] CHIP:DMG: ReportDataMessage = [1691473616.754226][172872:172874] CHIP:DMG: { [1691473616.754228][172872:172874] CHIP:DMG: EventReportIBs = [1691473616.754232][172872:172874] CHIP:DMG: [ [1691473616.754234][172872:172874] CHIP:DMG: EventReportIB = [1691473616.754238][172872:172874] CHIP:DMG: { [1691473616.754240][172872:172874] CHIP:DMG: EventDataIB = [1691473616.754243][172872:172874] CHIP:DMG: { [1691473616.754245][172872:172874] CHIP:DMG: EventPath = [1691473616.754249][172872:172874] CHIP:DMG: { [1691473616.754252][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473616.754254][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473616.754256][172872:172874] CHIP:DMG: Event = 0x0, [1691473616.754257][172872:172874] CHIP:DMG: }, [1691473616.754260][172872:172874] CHIP:DMG: [1691473616.754262][172872:172874] CHIP:DMG: EventNumber = 0x8, [1691473616.754264][172872:172874] CHIP:DMG: PriorityLevel = 0x2, [1691473616.754267][172872:172874] CHIP:DMG: EpochTimestamp = 0x189d3af1f6a, [1691473616.754269][172872:172874] CHIP:DMG: EventData = [1691473616.754272][172872:172874] CHIP:DMG: { [1691473616.754275][172872:172874] CHIP:DMG: 0x0 = 2, [1691473616.754277][172872:172874] CHIP:DMG: }, [1691473616.754279][172872:172874] CHIP:DMG: }, [1691473616.754282][172872:172874] CHIP:DMG: [1691473616.754284][172872:172874] CHIP:DMG: }, [1691473616.754288][172872:172874] CHIP:DMG: [1691473616.754290][172872:172874] CHIP:DMG: ], [1691473616.754294][172872:172874] CHIP:DMG: [1691473616.754297][172872:172874] CHIP:DMG: SuppressResponse = true, [1691473616.754299][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473616.754300][172872:172874] CHIP:DMG: } [1691473616.754369][172872:172874] CHIP:EM: <<< [E:58093i S:13846 M:176486173 (Ack:46254455)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473616.754416][172872:172874] CHIP:IN: (S) Sending msg 176486173 on secure session with LSID: 13846 [1691473616.754449][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254455 on exchange 58093i [1691473616.754460][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.754473][172872:172874] CHIP:TOO: ***** Test Step 18 : 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 [1691473616.754509][172872:172874] CHIP:DMG: ICR moving to [AddingComm] [1691473616.754518][172872:172874] CHIP:DMG: ICR moving to [AddedComma] [1691473616.754541][172872:172874] CHIP:EM: <<< [E:58094i S:13846 M:176486174] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:08 (IM:InvokeCommandRequest) [1691473616.754562][172872:172874] CHIP:IN: (S) Sending msg 176486174 on secure session with LSID: 13846 [1691473616.754594][172872:172874] CHIP:DMG: ICR moving to [CommandSen] [1691473616.754615][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.759894][172872:172874] CHIP:EM: >>> [E:58094i S:13846 M:46254456 (Ack:176486174)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:09 (IM:InvokeCommandResponse) [1691473616.759929][172872:172874] CHIP:EM: Found matching exchange: 58094i, Delegate: 0x7fc36c00a368 [1691473616.759943][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486174 from Retrans Table on exchange 58094i [1691473616.759951][172872:172874] CHIP:DMG: ICR moving to [ResponseRe] [1691473616.759963][172872:172874] CHIP:DMG: InvokeResponseMessage = [1691473616.759965][172872:172874] CHIP:DMG: { [1691473616.759968][172872:172874] CHIP:DMG: suppressResponse = false, [1691473616.759970][172872:172874] CHIP:DMG: InvokeResponseIBs = [1691473616.759973][172872:172874] CHIP:DMG: [ [1691473616.759975][172872:172874] CHIP:DMG: InvokeResponseIB = [1691473616.759979][172872:172874] CHIP:DMG: { [1691473616.759981][172872:172874] CHIP:DMG: CommandStatusIB = [1691473616.759984][172872:172874] CHIP:DMG: { [1691473616.759986][172872:172874] CHIP:DMG: CommandPathIB = [1691473616.759988][172872:172874] CHIP:DMG: { [1691473616.759991][172872:172874] CHIP:DMG: EndpointId = 0x0, [1691473616.759993][172872:172874] CHIP:DMG: ClusterId = 0x33, [1691473616.759995][172872:172874] CHIP:DMG: CommandId = 0x0, [1691473616.759997][172872:172874] CHIP:DMG: }, [1691473616.760000][172872:172874] CHIP:DMG: [1691473616.760002][172872:172874] CHIP:DMG: StatusIB = [1691473616.760005][172872:172874] CHIP:DMG: { [1691473616.760007][172872:172874] CHIP:DMG: status = 0x00 (SUCCESS), [1691473616.760009][172872:172874] CHIP:DMG: }, [1691473616.760011][172872:172874] CHIP:DMG: [1691473616.760013][172872:172874] CHIP:DMG: }, [1691473616.760016][172872:172874] CHIP:DMG: [1691473616.760017][172872:172874] CHIP:DMG: }, [1691473616.760021][172872:172874] CHIP:DMG: [1691473616.760022][172872:172874] CHIP:DMG: ], [1691473616.760026][172872:172874] CHIP:DMG: [1691473616.760028][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473616.760029][172872:172874] CHIP:DMG: }, [1691473616.760042][172872:172874] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0033 Command=0x0000_0000 Status=0x0 [1691473616.760050][172872:172874] CHIP:DMG: ICR moving to [AwaitingDe] [1691473616.760071][172872:172874] CHIP:EM: <<< [E:58094i S:13846 M:176486175 (Ack:46254456)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473616.760077][172872:172874] CHIP:IN: (S) Sending msg 176486175 on secure session with LSID: 13846 [1691473616.760109][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254456 on exchange 58094i [1691473616.760121][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473616.760130][172872:172874] CHIP:TOO: ***** Test Step 19 : TH waits for a report of SmokeState attribute from DUT with a timeout of 300 seconds [1691473619.751805][172872:172874] CHIP:EM: >>> [E:47136r S:13846 M:46254457] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473619.751879][172872:172874] CHIP:EM: Handling via exchange: 47136r, Delegate: 0x55c0b1d47508 [1691473619.751905][172872:172874] CHIP:DMG: ReportDataMessage = [1691473619.751909][172872:172874] CHIP:DMG: { [1691473619.751913][172872:172874] CHIP:DMG: SubscriptionId = 0xad791327, [1691473619.751915][172872:172874] CHIP:DMG: AttributeReportIBs = [1691473619.751919][172872:172874] CHIP:DMG: [ [1691473619.751921][172872:172874] CHIP:DMG: AttributeReportIB = [1691473619.751925][172872:172874] CHIP:DMG: { [1691473619.751927][172872:172874] CHIP:DMG: AttributeDataIB = [1691473619.751929][172872:172874] CHIP:DMG: { [1691473619.751932][172872:172874] CHIP:DMG: DataVersion = 0x220ec228, [1691473619.751934][172872:172874] CHIP:DMG: AttributePathIB = [1691473619.751977][172872:172874] CHIP:DMG: { [1691473619.751984][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473619.751988][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473619.751991][172872:172874] CHIP:DMG: Attribute = 0x0000_0001, [1691473619.751994][172872:172874] CHIP:DMG: } [1691473619.751998][172872:172874] CHIP:DMG: [1691473619.752003][172872:172874] CHIP:DMG: Data = 0, [1691473619.752006][172872:172874] CHIP:DMG: }, [1691473619.752010][172872:172874] CHIP:DMG: [1691473619.752013][172872:172874] CHIP:DMG: }, [1691473619.752018][172872:172874] CHIP:DMG: [1691473619.752021][172872:172874] CHIP:DMG: ], [1691473619.752027][172872:172874] CHIP:DMG: [1691473619.752030][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473619.752033][172872:172874] CHIP:DMG: } [1691473619.752095][172872:172874] CHIP:DMG: Refresh LivenessCheckTime for 34224 milliseconds with SubscriptionId = 0xad791327 Peer = 01:0000000000000001 [1691473619.752150][172872:172874] CHIP:EM: <<< [E:47136r S:13846 M:176486176 (Ack:46254457)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:01 (IM:StatusResponse) [1691473619.752166][172872:172874] CHIP:IN: (S) Sending msg 176486176 on secure session with LSID: 13846 [1691473619.752224][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473619.752260][172872:172874] CHIP:TOO: ***** Test Step 20 : TH reads ExpressedState attribute from DUT [1691473619.752282][172872:172874] CHIP:TOO: Sending ReadAttribute to: [1691473619.752292][172872:172874] CHIP:TOO: cluster 0x0000_005C, attribute: 0x0000_0000, endpoint 1 [1691473619.752301][172872:172874] CHIP:DMG: SendReadRequest ReadClient[0x7fc36c0111f0]: Sending Read Request [1691473619.752344][172872:172874] CHIP:EM: <<< [E:58095i S:13846 M:176486177] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473619.752369][172872:172874] CHIP:IN: (S) Sending msg 176486177 on secure session with LSID: 13846 [1691473619.752391][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0111f0]: Moving to [AwaitingIn] [1691473619.752420][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473619.752598][172872:172874] CHIP:EM: >>> [E:47136r S:13846 M:46254458 (Ack:176486176)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473619.752635][172872:172874] CHIP:EM: Found matching exchange: 47136r, Delegate: (nil) [1691473619.752649][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486176 from Retrans Table on exchange 47136r [1691473619.752656][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473619.753220][172872:172874] CHIP:EM: >>> [E:58095i S:13846 M:46254459 (Ack:176486177)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473619.753254][172872:172874] CHIP:EM: Found matching exchange: 58095i, Delegate: 0x7fc36c011200 [1691473619.753265][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486177 from Retrans Table on exchange 58095i [1691473619.753278][172872:172874] CHIP:DMG: ReportDataMessage = [1691473619.753283][172872:172874] CHIP:DMG: { [1691473619.753286][172872:172874] CHIP:DMG: AttributeReportIBs = [1691473619.753290][172872:172874] CHIP:DMG: [ [1691473619.753292][172872:172874] CHIP:DMG: AttributeReportIB = [1691473619.753295][172872:172874] CHIP:DMG: { [1691473619.753297][172872:172874] CHIP:DMG: AttributeDataIB = [1691473619.753299][172872:172874] CHIP:DMG: { [1691473619.753301][172872:172874] CHIP:DMG: DataVersion = 0x220ec228, [1691473619.753303][172872:172874] CHIP:DMG: AttributePathIB = [1691473619.753305][172872:172874] CHIP:DMG: { [1691473619.753308][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473619.753310][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473619.753312][172872:172874] CHIP:DMG: Attribute = 0x0000_0000, [1691473619.753314][172872:172874] CHIP:DMG: } [1691473619.753317][172872:172874] CHIP:DMG: [1691473619.753320][172872:172874] CHIP:DMG: Data = 0, [1691473619.753326][172872:172874] CHIP:DMG: }, [1691473619.753329][172872:172874] CHIP:DMG: [1691473619.753331][172872:172874] CHIP:DMG: }, [1691473619.753334][172872:172874] CHIP:DMG: [1691473619.753336][172872:172874] CHIP:DMG: ], [1691473619.753339][172872:172874] CHIP:DMG: [1691473619.753342][172872:172874] CHIP:DMG: SuppressResponse = true, [1691473619.753344][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473619.753345][172872:172874] CHIP:DMG: } [1691473619.753395][172872:172874] CHIP:EM: <<< [E:58095i S:13846 M:176486178 (Ack:46254459)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473619.753417][172872:172874] CHIP:IN: (S) Sending msg 176486178 on secure session with LSID: 13846 [1691473619.753439][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254459 on exchange 58095i [1691473619.753447][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473619.753454][172872:172874] CHIP:TOO: ***** Test Step 21 : TH reads AllClear event from DUT [1691473619.753463][172872:172874] CHIP:TOO: Sending ReadEvent to: [1691473619.753468][172872:172874] CHIP:TOO: cluster 0x0000_005C, event: 0x0000_000A, endpoint 1 [1691473619.753473][172872:172874] CHIP:DMG: SendReadRequest ReadClient[0x7fc36c0111f0]: Sending Read Request [1691473619.753494][172872:172874] CHIP:EM: <<< [E:58096i S:13846 M:176486179] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0001:02 (IM:ReadRequest) [1691473619.753515][172872:172874] CHIP:IN: (S) Sending msg 176486179 on secure session with LSID: 13846 [1691473619.753540][172872:172874] CHIP:DMG: MoveToState ReadClient[0x7fc36c0111f0]: Moving to [AwaitingIn] [1691473619.753548][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473619.758084][172872:172874] CHIP:EM: >>> [E:58096i S:13846 M:46254460 (Ack:176486179)] (S) Msg RX from 1:0000000000000001 [F3A1] --- Type 0001:05 (IM:ReportData) [1691473619.758142][172872:172874] CHIP:EM: Found matching exchange: 58096i, Delegate: 0x7fc36c011200 [1691473619.758155][172872:172874] CHIP:EM: Rxd Ack; Removing MessageCounter:176486179 from Retrans Table on exchange 58096i [1691473619.758174][172872:172874] CHIP:DMG: ReportDataMessage = [1691473619.758178][172872:172874] CHIP:DMG: { [1691473619.758180][172872:172874] CHIP:DMG: EventReportIBs = [1691473619.758184][172872:172874] CHIP:DMG: [ [1691473619.758186][172872:172874] CHIP:DMG: EventReportIB = [1691473619.758190][172872:172874] CHIP:DMG: { [1691473619.758192][172872:172874] CHIP:DMG: EventDataIB = [1691473619.758195][172872:172874] CHIP:DMG: { [1691473619.758197][172872:172874] CHIP:DMG: EventPath = [1691473619.758200][172872:172874] CHIP:DMG: { [1691473619.758202][172872:172874] CHIP:DMG: Endpoint = 0x1, [1691473619.758204][172872:172874] CHIP:DMG: Cluster = 0x5c, [1691473619.758206][172872:172874] CHIP:DMG: Event = 0xa, [1691473619.758208][172872:172874] CHIP:DMG: }, [1691473619.758211][172872:172874] CHIP:DMG: [1691473619.758213][172872:172874] CHIP:DMG: EventNumber = 0x9, [1691473619.758215][172872:172874] CHIP:DMG: PriorityLevel = 0x1, [1691473619.758217][172872:172874] CHIP:DMG: EpochTimestamp = 0x189d3af1f77, [1691473619.758219][172872:172874] CHIP:DMG: EventData = [1691473619.758221][172872:172874] CHIP:DMG: { [1691473619.758224][172872:172874] CHIP:DMG: }, [1691473619.758225][172872:172874] CHIP:DMG: }, [1691473619.758229][172872:172874] CHIP:DMG: [1691473619.758230][172872:172874] CHIP:DMG: }, [1691473619.758234][172872:172874] CHIP:DMG: [1691473619.758236][172872:172874] CHIP:DMG: ], [1691473619.758240][172872:172874] CHIP:DMG: [1691473619.758242][172872:172874] CHIP:DMG: SuppressResponse = true, [1691473619.758244][172872:172874] CHIP:DMG: InteractionModelRevision = 1 [1691473619.758245][172872:172874] CHIP:DMG: } [1691473619.758307][172872:172874] CHIP:EM: <<< [E:58096i S:13846 M:176486180 (Ack:46254460)] (S) Msg TX to 1:0000000000000001 [F3A1] --- Type 0000:10 (SecureChannel:StandaloneAck) [1691473619.758337][172872:172874] CHIP:IN: (S) Sending msg 176486180 on secure session with LSID: 13846 [1691473619.758358][172872:172874] CHIP:EM: Flushed pending ack for MessageCounter:46254460 on exchange 58096i [1691473619.758365][172872:172874] CHIP:DL: HandlePlatformSpecificBLEEvent 32793 [1691473619.758376][172872:172874] CHIP:TOO: **** Test Complete: Test_TC_SMOKECO_2_2 [1691473619.758554][172872:172872] CHIP:CTL: Shutting down the commissioner [1691473619.758599][172872:172872] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1691473619.758632][172872:172872] CHIP:CTL: Shutting down the controller [1691473619.758653][172872:172872] CHIP:IN: Expiring all sessions for fabric 0x1!! [1691473619.758660][172872:172872] CHIP:IN: SecureSession[0x7fc36c00b0e0]: MarkForEviction Type:2 LSID:13846 [1691473619.758664][172872:172872] CHIP:SC: SecureSession[0x7fc36c00b0e0, LSID:13846]: State change 'kActive' --> 'kPendingEviction' [1691473619.758668][172872:172872] CHIP:IN: SecureSession[0x7fc36c00b0e0]: Released - Type:2 LSID:13846 [1691473619.758674][172872:172872] CHIP:FP: Forgetting fabric 0x1 [1691473619.758684][172872:172872] CHIP:TS: Pending Last Known Good Time: 2023-08-07T11:26:55 [1691473619.758745][172872:172872] CHIP:TS: Previous Last Known Good Time: 2023-08-07T11:26:55 [1691473619.758764][172872:172872] CHIP:TS: Reverted Last Known Good Time to previous value [1691473619.758786][172872:172872] CHIP:CTL: Shutting down the commissioner [1691473619.758790][172872:172872] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1691473619.758803][172872:172872] CHIP:CTL: Shutting down the controller [1691473619.758806][172872:172872] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1691473619.758843][172872:172872] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1691473619.758881][172872:172872] CHIP:FP: Shutting down FabricTable [1691473619.758889][172872:172872] CHIP:TS: Pending Last Known Good Time: 2023-08-07T11:26:55 [1691473619.758920][172872:172872] CHIP:TS: Previous Last Known Good Time: 2023-08-07T11:26:55 [1691473619.758938][172872:172872] CHIP:TS: Reverted Last Known Good Time to previous value [1691473619.759024][172872:172872] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-DJXkzX) [1691473619.759181][172872:172872] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1691473619.759220][172872:172872] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1691473619.759227][172872:172872] CHIP:DL: Inet Layer shutdown [1691473619.759231][172872:172872] CHIP:DL: BLE shutdown [1691473619.759235][172872:172872] CHIP:DL: System Layer shutdown