DUT LOG: ubuntu@ubuntu:~/cntrl13/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool doorlock set-week-day-schedule 2 1 2 15 45 16 55 1 1 [1655297629.687129][6687:6687] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655297629.687672][6687:6687] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655297629.687835][6687:6687] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655297629.687947][6687:6687] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655297629.688296][6687:6687] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-vThVnt) [1655297629.688945][6687:6687] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655297629.688998][6687:6687] CHIP:DL: NVS set: chip-counters/reboot-count = 17 (0x11) [1655297629.689855][6687:6687] CHIP:DL: Got Ethernet interface: eth0 [1655297629.690410][6687:6687] CHIP:DL: Found the primary Ethernet interface:eth0 [1655297629.691084][6687:6687] CHIP:DL: Got WiFi interface: wlan0 [1655297629.691235][6687:6687] CHIP:DL: Failed to reset WiFi statistic counts [1655297629.691354][6687:6687] CHIP:IN: UDP::Init bind&listen port=0 [1655297629.691516][6687:6687] CHIP:IN: UDP::Init bound to port=47115 [1655297629.691544][6687:6687] CHIP:IN: BLEBase::Init - setting/overriding transport [1655297629.691565][6687:6687] CHIP:IN: TransportMgr initialized [1655297629.691601][6687:6687] CHIP:FP: Initializing FabricTable from persistent storage [1655297629.691772][6687:6687] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655297629.691863][6687:6687] CHIP:FP: Loading from storage for fabric index 0x1 [1655297629.692327][6687:6687] CHIP:FP: Loading from storage for fabric index 0x2 [1655297629.692694][6687:6687] CHIP:FP: Loading from storage for fabric index 0x3 [1655297629.696663][6687:6687] CHIP:ZCL: Using ZAP configuration... [1655297629.700923][6687:6687] CHIP:DL: Avahi client registered [1655297629.702238][6687:6687] CHIP:CTL: System State Initialized... [1655297629.702338][6687:6687] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655297629.702400][6687:6687] CHIP:CTL: Setting attestation nonce to random value [1655297629.702481][6687:6687] CHIP:CTL: Setting CSR nonce to random value [1655297629.702561][6687:6687] CHIP:IN: UDP::Init bind&listen port=5550 [1655297629.702701][6687:6687] CHIP:IN: UDP::Init bound to port=5550 [1655297629.702728][6687:6687] CHIP:IN: TransportMgr initialized [1655297629.702807][6687:6687] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655297629.702837][6687:6687] CHIP:CTL: Setting attestation nonce to random value [1655297629.702888][6687:6687] CHIP:CTL: Setting CSR nonce to random value [1655297629.705942][6687:6687] CHIP:CTL: Generating NOC [1655297629.706902][6687:6687] CHIP:FP: Validating NOC chain [1655297629.708982][6687:6687] CHIP:FP: NOC chain validation successful [1655297629.709181][6687:6687] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655297629.709215][6687:6687] CHIP:FP: Assigned compressed fabric ID: 0xA928B8D2C6247E39, node ID: 0x000000000001B669 [1655297629.716231][6687:6687] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655297629.716293][6687:6687] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655297629.716324][6687:6687] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655297629.716351][6687:6687] CHIP:TS: Retaining current Last Known Good Time [1655297629.718050][6687:6687] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0xA928B8D2C6247E39 [1655297629.718126][6687:6687] CHIP:IN: UDP::Init bind&listen port=5550 [1655297629.718252][6687:6687] CHIP:IN: UDP::Init bound to port=5550 [1655297629.718277][6687:6687] CHIP:IN: TransportMgr initialized [1655297629.718374][6687:6687] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655297629.718414][6687:6687] CHIP:CTL: Setting attestation nonce to random value [1655297629.718493][6687:6687] CHIP:CTL: Setting CSR nonce to random value [1655297629.719359][6687:6687] CHIP:CTL: Generating NOC [1655297629.720257][6687:6687] CHIP:FP: Validating NOC chain [1655297629.722040][6687:6687] CHIP:FP: NOC chain validation successful [1655297629.722203][6687:6687] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655297629.722229][6687:6687] CHIP:FP: Assigned compressed fabric ID: 0x24AE67E4E4E24D4B, node ID: 0x000000000001B669 [1655297629.728577][6687:6687] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655297629.728632][6687:6687] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655297629.728656][6687:6687] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655297629.728677][6687:6687] CHIP:TS: Retaining current Last Known Good Time [1655297629.730289][6687:6687] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x24AE67E4E4E24D4B [1655297629.730360][6687:6687] CHIP:IN: UDP::Init bind&listen port=5550 [1655297629.730642][6687:6687] CHIP:IN: UDP::Init bound to port=5550 [1655297629.730669][6687:6687] CHIP:IN: TransportMgr initialized [1655297629.730778][6687:6687] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655297629.730820][6687:6687] CHIP:CTL: Setting attestation nonce to random value [1655297629.730882][6687:6687] CHIP:CTL: Setting CSR nonce to random value [1655297629.731790][6687:6687] CHIP:CTL: Generating NOC [1655297629.732639][6687:6687] CHIP:FP: Validating NOC chain [1655297629.734516][6687:6687] CHIP:FP: NOC chain validation successful [1655297629.734680][6687:6687] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655297629.734708][6687:6687] CHIP:FP: Assigned compressed fabric ID: 0xEEBE88FE4EF10BA6, node ID: 0x000000000001B669 [1655297629.744254][6687:6687] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655297629.744312][6687:6687] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655297629.744339][6687:6687] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655297629.744362][6687:6687] CHIP:TS: Retaining current Last Known Good Time [1655297629.745871][6687:6687] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xEEBE88FE4EF10BA6 [1655297629.745949][6687:6687] CHIP:IN: UDP::Init bind&listen port=5550 [1655297629.746096][6687:6687] CHIP:IN: UDP::Init bound to port=5550 [1655297629.746124][6687:6687] CHIP:IN: TransportMgr initialized [1655297629.789581][6687:6692] CHIP:DL: CHIP task running [1655297629.789845][6687:6692] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655297629.789890][6687:6692] CHIP:TOO: Sending command to node 0x1 [1655297629.789928][6687:6692] CHIP:CSM: FindOrEstablishSession: PeerId = A928B8D2C6247E39:0000000000000001 [1655297629.789956][6687:6692] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655297629.789996][6687:6692] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 1 --> 2 [1655297629.790031][6687:6692] CHIP:DIS: Resolving A928B8D2C6247E39:0000000000000001 ... [1655297629.792051][6687:6692] CHIP:DL: Avahi resolve found [1655297629.792140][6687:6692] CHIP:DIS: Node ID resolved for A928B8D2C6247E39:0000000000000001 [1655297629.792171][6687:6692] CHIP:DIS: Hostname: E45F01312CE50000 [1655297629.792224][6687:6692] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655297629.792251][6687:6692] CHIP:DIS: Port: 5540 [1655297629.792274][6687:6692] CHIP:DIS: Mrp Interval idle: 5000 ms [1655297629.792297][6687:6692] CHIP:DIS: Mrp Interval active: 300 ms [1655297629.792564][6687:6692] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655297629.792599][6687:6692] CHIP:DIS: Checking node lookup status after 3 ms [1655297629.792621][6687:6692] CHIP:DIS: Keeping DNSSD lookup active [1655297629.990094][6687:6692] CHIP:DIS: Checking node lookup status after 200 ms [1655297629.990379][6687:6692] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655297629.990500][6687:6692] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 2 --> 3 [1655297629.990889][6687:6692] CHIP:IN: SecureSession[0xaaaac6a7de70]: Allocated Type:2 LSID:30029 [1655297629.990972][6687:6692] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655297629.992467][6687:6692] CHIP:SC: Including MRP parameters [1655297629.992939][6687:6692] CHIP:IN: Prepared unauthenticated message 0xaaaac6a7c1d8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 57906i with MessageCounter:56376545. [1655297629.993040][6687:6692] CHIP:IN: Sending unauthenticated msg 0xaaaac6a7c1d8 with MessageCounter:56376545 to 0x0000000000000000 at monotonic time: 0000000001F9358A msec [1655297629.993366][6687:6692] CHIP:SC: Sent Sigma1 msg [1655297629.993434][6687:6692] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 3 --> 4 [1655297629.993500][6687:6692] CHIP:DIS: Discovery does not require any more timeouts [1655297629.995876][6687:6692] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:178518537 on exchange 57906i [1655297629.995951][6687:6692] CHIP:EM: Found matching exchange: 57906i, Delegate: 0xffff7c0011a0 [1655297629.996030][6687:6692] CHIP:EM: Rxd Ack; Removing MessageCounter:56376545 from Retrans Table on exchange 57906i [1655297629.996090][6687:6692] CHIP:EM: Removed CHIP MessageCounter:56376545 from RetransTable on exchange 57906i [1655297629.996161][6687:6692] CHIP:SC: Received Sigma2Resume msg [1655297629.996320][6687:6692] CHIP:SC: Found MRP parameters in the message [1655297629.996388][6687:6692] CHIP:SC: Peer assigned session session ID 34034 [1655297630.004656][6687:6692] CHIP:SC: Sending status report. Protocol code 0, exchange 57906 [1655297630.004734][6687:6692] CHIP:EM: Piggybacking Ack for MessageCounter:178518537 on exchange: 57906i [1655297630.004787][6687:6692] CHIP:IN: Prepared unauthenticated message 0xaaaac6a7c1d8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 57906i with MessageCounter:56376546. [1655297630.004842][6687:6692] CHIP:IN: Sending unauthenticated msg 0xaaaac6a7c1d8 with MessageCounter:56376546 to 0x0000000000000000 at monotonic time: 0000000001F93596 msec [1655297630.005111][6687:6692] CHIP:IN: SecureSession[0xaaaac6a7de70]: Activated - Type:2 LSID:30029 [1655297630.005148][6687:6692] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:30029 PSID:34034! [1655297630.005180][6687:6692] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 4 --> 5 [1655297630.005238][6687:6692] CHIP:TOO: Sending cluster (0x00000101) command (0x0000000B) on endpoint 1 [1655297630.005323][6687:6692] CHIP:DMG: ICR moving to [AddingComm] [1655297630.005377][6687:6692] CHIP:DMG: ICR moving to [AddedComma] [1655297630.005472][6687:6692] CHIP:IN: Prepared secure message 0xaaaac6a7c1f8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 57907i with MessageCounter:259817513. [1655297630.005516][6687:6692] CHIP:IN: Sending encrypted msg 0xaaaac6a7c1f8 with MessageCounter:259817513 to 0x0000000000000001 (1) at monotonic time: 0000000001F93597 msec [1655297630.005661][6687:6692] CHIP:DMG: ICR moving to [CommandSen] [1655297630.012068][6687:6692] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:178518538 on exchange 57906i [1655297630.012118][6687:6692] CHIP:EM: Found matching exchange: 57906i, Delegate: (nil) [1655297630.012167][6687:6692] CHIP:EM: Rxd Ack; Removing MessageCounter:56376546 from Retrans Table on exchange 57906i [1655297630.012197][6687:6692] CHIP:EM: Removed CHIP MessageCounter:56376546 from RetransTable on exchange 57906i [1655297630.014022][6687:6692] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:212801624 on exchange 57907i [1655297630.014067][6687:6692] CHIP:EM: Found matching exchange: 57907i, Delegate: 0xffff7c004190 [1655297630.014112][6687:6692] CHIP:EM: Rxd Ack; Removing MessageCounter:259817513 from Retrans Table on exchange 57907i [1655297630.014148][6687:6692] CHIP:EM: Removed CHIP MessageCounter:259817513 from RetransTable on exchange 57907i [1655297630.014191][6687:6692] CHIP:DMG: ICR moving to [ResponseRe] [1655297630.014257][6687:6692] CHIP:DMG: InvokeResponseMessage = [1655297630.014295][6687:6692] CHIP:DMG: { [1655297630.014330][6687:6692] CHIP:DMG: suppressResponse = false, [1655297630.014367][6687:6692] CHIP:DMG: InvokeResponseIBs = [1655297630.014413][6687:6692] CHIP:DMG: [ [1655297630.014479][6687:6692] CHIP:DMG: InvokeResponseIB = [1655297630.014532][6687:6692] CHIP:DMG: { [1655297630.014571][6687:6692] CHIP:DMG: CommandStatusIB = [1655297630.014617][6687:6692] CHIP:DMG: { [1655297630.014663][6687:6692] CHIP:DMG: CommandPathIB = [1655297630.014711][6687:6692] CHIP:DMG: { [1655297630.014761][6687:6692] CHIP:DMG: EndpointId = 0x1, [1655297630.014819][6687:6692] CHIP:DMG: ClusterId = 0x101, [1655297630.014870][6687:6692] CHIP:DMG: CommandId = 0xb, [1655297630.014916][6687:6692] CHIP:DMG: }, [1655297630.014974][6687:6692] CHIP:DMG: [1655297630.015015][6687:6692] CHIP:DMG: StatusIB = [1655297630.015067][6687:6692] CHIP:DMG: { [1655297630.015121][6687:6692] CHIP:DMG: status = 0x8b (NOT_FOUND), [1655297630.015169][6687:6692] CHIP:DMG: }, [1655297630.015214][6687:6692] CHIP:DMG: [1655297630.015257][6687:6692] CHIP:DMG: }, [1655297630.015308][6687:6692] CHIP:DMG: [1655297630.015346][6687:6692] CHIP:DMG: }, [1655297630.015391][6687:6692] CHIP:DMG: [1655297630.015426][6687:6692] CHIP:DMG: ], [1655297630.015470][6687:6692] CHIP:DMG: [1655297630.015507][6687:6692] CHIP:DMG: InteractionModelRevision = 1 [1655297630.015543][6687:6692] CHIP:DMG: }, [1655297630.015628][6687:6692] CHIP:DMG: Received Command Response Status for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_000B Status=0x8b [1655297630.015676][6687:6692] CHIP:TOO: Error: IM Error 0x0000058B: General error: 0x8b (NOT_FOUND) [1655297630.015729][6687:6692] CHIP:DMG: ICR moving to [AwaitingDe] [1655297630.015803][6687:6692] CHIP:EM: Sending Standalone Ack for MessageCounter:212801624 on exchange 57907i [1655297630.015895][6687:6692] CHIP:IN: Prepared secure message 0xffff91892958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 57907i with MessageCounter:259817514. [1655297630.015951][6687:6692] CHIP:IN: Sending encrypted msg 0xffff91892958 with MessageCounter:259817514 to 0x0000000000000001 (1) at monotonic time: 0000000001F935A1 msec [1655297630.016093][6687:6692] CHIP:EM: Flushed pending ack for MessageCounter:212801624 on exchange 57907i [1655297630.016341][6687:6687] CHIP:CTL: Shutting down the commissioner [1655297630.016458][6687:6687] CHIP:CTL: Shutting down the controller [1655297630.016505][6687:6687] CHIP:CTL: Shutting down the commissioner [1655297630.016580][6687:6687] CHIP:CTL: Shutting down the controller [1655297630.016624][6687:6687] CHIP:IN: Expiring all connections for fabric 1!! [1655297630.016658][6687:6687] CHIP:IN: SecureSession[0xaaaac6a7de70]: MarkForRemoval Type:2 LSID:30029 [1655297630.016693][6687:6687] CHIP:IN: SecureSession[0xaaaac6a7de70]: Released - Type:2 LSID:30029 [1655297630.016757][6687:6687] CHIP:CTL: Shutting down the commissioner [1655297630.016836][6687:6687] CHIP:CTL: Shutting down the controller [1655297630.016870][6687:6687] CHIP:IN: Expiring all connections for fabric 2!! [1655297630.016921][6687:6687] CHIP:CTL: Shutting down the commissioner [1655297630.017019][6687:6687] CHIP:CTL: Shutting down the controller [1655297630.017053][6687:6687] CHIP:IN: Expiring all connections for fabric 3!! [1655297630.017096][6687:6687] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655297630.018319][6687:6687] CHIP:DMG: IM WH moving to [Uninitialized] [1655297630.018369][6687:6687] CHIP:DMG: IM WH moving to [Uninitialized] [1655297630.018399][6687:6687] CHIP:DMG: IM WH moving to [Uninitialized] [1655297630.018455][6687:6687] CHIP:DMG: IM WH moving to [Uninitialized] [1655297630.018486][6687:6687] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655297630.018582][6687:6687] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655297630.018929][6687:6687] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-CKzjvs) [1655297630.019796][6687:6687] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655297630.019882][6687:6687] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655297630.019922][6687:6687] CHIP:DL: Inet Layer shutdown [1655297630.019955][6687:6687] CHIP:DL: BLE shutdown [1655297630.019988][6687:6687] CHIP:DL: System Layer shutdown [1655297630.020143][6687:6687] CHIP:TOO: Run command failure: IM Error 0x0000058B: General error: 0x8b (NOT_FOUND) TH LOG: [1655297626.739804][5807:5807] CHIP:DIS: Broadcasting mDns reply for query from fd01::e65f:1ff:fe0e:befc [1655297626.742152][5807:5807] CHIP:DIS: Broadcasting mDns reply for query from fd01::e65f:1ff:fe0e:befc [1655297626.742882][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.742940][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.742973][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.743005][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.743031][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.743057][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.743086][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.743113][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.743172][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.743209][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.743238][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.743266][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.743289][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.743314][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.743338][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.743361][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.743415][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.743451][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.743479][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.743504][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.743528][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.743554][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.743578][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.743599][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.743655][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.743691][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.743719][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.743745][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.743769][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.743794][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.743817][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.743838][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.743892][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.743926][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.743955][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.743980][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.744004][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.744028][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.744052][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.744073][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.744128][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.744163][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.744190][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.744216][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.744239][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.744264][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.744287][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.744308][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.744362][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.744396][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.744424][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.744450][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.744473][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.744498][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.744521][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.744542][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.744596][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.744630][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.744658][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.744683][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.744706][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.744731][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.744754][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.744775][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.744830][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.744866][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.744894][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.744919][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.744943][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.744968][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.744991][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.745012][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.745094][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.745129][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.745158][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745184][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.745207][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745228][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.745248][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.745265][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.745373][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.745400][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745423][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745482][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.745507][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745530][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745587][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.745612][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745634][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745692][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.745716][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745739][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745796][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.745821][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745843][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745901][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.745926][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.745949][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.746006][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.746031][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.746054][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.746112][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.746136][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.746159][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.746216][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.746241][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.746264][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.746323][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.746348][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.746371][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.793077][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.793205][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.793282][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.793352][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.793412][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.793475][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.793538][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.793596][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.793739][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.793827][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.793898][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.793963][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.794021][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.794080][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.794139][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.794193][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.794339][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.794432][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.794504][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.794568][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.794626][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.794687][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.794746][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.794800][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.794939][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.795026][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.795096][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.795160][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.795219][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.795281][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.795340][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.795394][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.795530][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.795616][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.795686][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.795750][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.795808][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.795870][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.795928][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.795982][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.796120][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.796208][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.796278][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.796342][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.796401][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.796468][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.796527][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.796582][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.796720][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.796808][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.796878][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.796941][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.796998][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.797090][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.797149][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.797203][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.797339][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.797428][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.797499][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.797562][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.797619][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.797681][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.797738][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.797791][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.797929][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.798014][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.798083][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.798147][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.798204][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.798268][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.798327][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.798379][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.798519][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.798605][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655297626.798674][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.798737][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.798795][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.798856][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655297626.798914][5807:5807] CHIP:DIS: Discovered node without a pending query [1655297626.798966][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655297626.799227][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.799294][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.799371][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.799520][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.799584][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.799642][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.799787][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.799849][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.799906][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.800049][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.800112][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.800168][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.800311][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.800373][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.800429][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.800572][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.800635][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.800699][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.800847][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.800909][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.800965][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.801082][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.801113][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.801139][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.801206][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.801234][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.801261][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.801328][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655297626.801357][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297626.801383][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655297629.964996][5807:5807] CHIP:EM: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:56376545 on exchange 57906r [1655297629.965176][5807:5807] CHIP:EM: Handling via exchange: 57906r, Delegate: 0xaaaab38c8948 [1655297629.965275][5807:5807] CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0xaaaab38c8f60 [1655297629.965334][5807:5807] CHIP:IN: CASE Server disabling CASE session setups [1655297629.965396][5807:5807] CHIP:SC: Received Sigma1 msg [1655297629.965502][5807:5807] CHIP:SC: Found MRP parameters in the message [1655297629.965577][5807:5807] CHIP:SC: Peer assigned session key ID 30029 [1655297629.966256][5807:5807] CHIP:SC: Including MRP parameters [1655297629.966357][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:56376545 on exchange: 57906r [1655297629.966445][5807:5807] CHIP:IN: Prepared unauthenticated message 0xaaaab38cd618 to 0x0000000000000000 (0) of type 0x33 and protocolId (0, 0) on exchange 57906r with MessageCounter:178518537. [1655297629.966530][5807:5807] CHIP:IN: Sending unauthenticated msg 0xaaaab38cd618 with MessageCounter:178518537 to 0x0000000000000000 at monotonic time: 0000000001FF1F39 msec [1655297629.966858][5807:5807] CHIP:SC: Sent Sigma2Resume msg [1655297629.976677][5807:5807] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:56376546 on exchange 57906r [1655297629.976777][5807:5807] CHIP:EM: Found matching exchange: 57906r, Delegate: 0xaaaab38c8980 [1655297629.976930][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:178518537 from Retrans Table on exchange 57906r [1655297629.976996][5807:5807] CHIP:EM: Removed CHIP MessageCounter:178518537 from RetransTable on exchange 57906r [1655297629.977205][5807:5807] CHIP:SC: Success status report received. Session was established [1655297629.977932][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-BspS70) [1655297629.979018][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655297629.979241][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-1dZHvL) [1655297629.980673][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655297629.980894][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-NSN0J9) [1655297629.982301][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655297629.982382][5807:5807] CHIP:IN: Expired/released previous local session ID 34033 for peer <000000000001B669, 2> [1655297629.982411][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: MarkForRemoval Type:2 LSID:34033 [1655297629.982435][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: Released - Type:2 LSID:34033 [1655297629.982519][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: Activated - Type:2 LSID:34034 [1655297629.982545][5807:5807] CHIP:IN: New secure session created for device <000000000001B669, 2>, LSID:34034 PSID:30029! [1655297629.982568][5807:5807] CHIP:IN: CASE Session established to peer: <000000000001B669, 2> [1655297629.982589][5807:5807] CHIP:IN: CASE Server enabling CASE session setups [1655297629.982671][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: Allocated Type:2 LSID:34035 [1655297629.982704][5807:5807] CHIP:SC: Allocated SecureSession (0xaaaab38c5c88) - waiting for Sigma1 msg [1655297629.982735][5807:5807] CHIP:EM: Sending Standalone Ack for MessageCounter:56376546 on exchange 57906r [1655297629.982787][5807:5807] CHIP:IN: Prepared unauthenticated message 0xffffc670da88 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 57906r with MessageCounter:178518538. [1655297629.982885][5807:5807] CHIP:IN: Sending unauthenticated msg 0xffffc670da88 with MessageCounter:178518538 to 0x0000000000000000 at monotonic time: 0000000001FF1F49 msec [1655297629.983064][5807:5807] CHIP:EM: Flushed pending ack for MessageCounter:56376546 on exchange 57906r [1655297629.983280][5807:5807] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:259817513 on exchange 57907r [1655297629.983323][5807:5807] CHIP:EM: Handling via exchange: 57907r, Delegate: 0xaaaab38c02b0 [1655297629.983399][5807:5807] CHIP:DMG: InvokeRequestMessage = [1655297629.983427][5807:5807] CHIP:DMG: { [1655297629.983457][5807:5807] CHIP:DMG: suppressResponse = false, [1655297629.983487][5807:5807] CHIP:DMG: timedRequest = false, [1655297629.983513][5807:5807] CHIP:DMG: InvokeRequests = [1655297629.983547][5807:5807] CHIP:DMG: [ [1655297629.983574][5807:5807] CHIP:DMG: CommandDataIB = [1655297629.983605][5807:5807] CHIP:DMG: { [1655297629.983631][5807:5807] CHIP:DMG: CommandPathIB = [1655297629.983667][5807:5807] CHIP:DMG: { [1655297629.983704][5807:5807] CHIP:DMG: EndpointId = 0x1, [1655297629.983742][5807:5807] CHIP:DMG: ClusterId = 0x101, [1655297629.983779][5807:5807] CHIP:DMG: CommandId = 0xb, [1655297629.983813][5807:5807] CHIP:DMG: }, [1655297629.983842][5807:5807] CHIP:DMG: [1655297629.983864][5807:5807] CHIP:DMG: CommandFields = [1655297629.983890][5807:5807] CHIP:DMG: { [1655297629.983923][5807:5807] CHIP:DMG: 0x0 = 2, [1655297629.983954][5807:5807] CHIP:DMG: 0x1 = 1, [1655297629.983991][5807:5807] CHIP:DMG: 0x2 = 2, [1655297629.984021][5807:5807] CHIP:DMG: 0x3 = 15, [1655297629.984058][5807:5807] CHIP:DMG: 0x4 = 45, [1655297629.984096][5807:5807] CHIP:DMG: 0x5 = 16, [1655297629.984132][5807:5807] CHIP:DMG: 0x6 = 55, [1655297629.984168][5807:5807] CHIP:DMG: }, [1655297629.984200][5807:5807] CHIP:DMG: }, [1655297629.984234][5807:5807] CHIP:DMG: [1655297629.984258][5807:5807] CHIP:DMG: ], [1655297629.984290][5807:5807] CHIP:DMG: [1655297629.984314][5807:5807] CHIP:DMG: InteractionModelRevision = 1 [1655297629.984340][5807:5807] CHIP:DMG: }, [1655297629.984409][5807:5807] CHIP:DMG: AccessControl: checking f=2 a=c s=0x000000000001B669 t= c=0x0000_0101 e=1 p=a [1655297629.984447][5807:5807] CHIP:DMG: AccessControl: allowed [1655297629.984475][5807:5807] CHIP:DMG: Received command for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_000B [1655297629.984522][5807:5807] CHIP:ZCL: [SetWeekDaySchedule] Incoming command [endpointId=1][1655297629.984556][5807:5807] CHIP:ZCL: Lock App: LockEndpoint::GetUser [endpoint=1,userIndex=1] [1655297629.984579][5807:5807] CHIP:ZCL: Found unoccupied user [endpoint=1,adjustedIndex=0] [1655297629.984600][5807:5807] CHIP:ZCL: [SetWeekDaySchedule] Unable to add schedule - user does not exist [endpointId=1,weekDayIndex=2,userIndex=1] [1655297629.984636][5807:5807] CHIP:DMG: ICR moving to [ Preparing] [1655297629.984669][5807:5807] CHIP:DMG: ICR moving to [AddingComm] [1655297629.984695][5807:5807] CHIP:DMG: ICR moving to [AddedComma] [1655297629.984737][5807:5807] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1655297629.984770][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:259817513 on exchange: 57907r [1655297629.984846][5807:5807] CHIP:IN: Prepared secure message 0xaaaab38cd618 to 0x000000000001B669 (2) of type 0x9 and protocolId (0, 1) on exchange 57907r with MessageCounter:212801624. [1655297629.984887][5807:5807] CHIP:IN: Sending encrypted msg 0xaaaab38cd618 with MessageCounter:212801624 to 0x000000000001B669 (2) at monotonic time: 0000000001FF1F4B msec [1655297629.985102][5807:5807] CHIP:DMG: ICR moving to [CommandSen] [1655297629.985131][5807:5807] CHIP:DMG: ICR moving to [AwaitingDe] [1655297629.987574][5807:5807] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:259817514 on exchange 57907r [1655297629.987625][5807:5807] CHIP:EM: Found matching exchange: 57907r, Delegate: (nil) [1655297629.987668][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:212801624 from Retrans Table on exchange 57907r [1655297629.987691][5807:5807] CHIP:EM: Removed CHIP MessageCounter:212801624 from RetransTable on exchange 57907r DUT LOG: ubuntu@ubuntu:~/cntrl13/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool doorlock get-week-day-schedule 1 1 1 1 [1655297814.296826][6702:6702] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655297814.297368][6702:6702] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655297814.297527][6702:6702] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655297814.297639][6702:6702] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655297814.298006][6702:6702] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-B700Bx) [1655297814.298690][6702:6702] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655297814.298749][6702:6702] CHIP:DL: NVS set: chip-counters/reboot-count = 18 (0x12) [1655297814.299662][6702:6702] CHIP:DL: Got Ethernet interface: eth0 [1655297814.300280][6702:6702] CHIP:DL: Found the primary Ethernet interface:eth0 [1655297814.300906][6702:6702] CHIP:DL: Got WiFi interface: wlan0 [1655297814.300988][6702:6702] CHIP:DL: Failed to reset WiFi statistic counts [1655297814.301080][6702:6702] CHIP:IN: UDP::Init bind&listen port=0 [1655297814.301215][6702:6702] CHIP:IN: UDP::Init bound to port=51723 [1655297814.301242][6702:6702] CHIP:IN: BLEBase::Init - setting/overriding transport [1655297814.301267][6702:6702] CHIP:IN: TransportMgr initialized [1655297814.301316][6702:6702] CHIP:FP: Initializing FabricTable from persistent storage [1655297814.301484][6702:6702] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655297814.301580][6702:6702] CHIP:FP: Loading from storage for fabric index 0x1 [1655297814.302178][6702:6702] CHIP:FP: Loading from storage for fabric index 0x2 [1655297814.302669][6702:6702] CHIP:FP: Loading from storage for fabric index 0x3 [1655297814.306315][6702:6702] CHIP:ZCL: Using ZAP configuration... [1655297814.310791][6702:6702] CHIP:DL: Avahi client registered [1655297814.312004][6702:6702] CHIP:CTL: System State Initialized... [1655297814.312090][6702:6702] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655297814.312149][6702:6702] CHIP:CTL: Setting attestation nonce to random value [1655297814.312198][6702:6702] CHIP:CTL: Setting CSR nonce to random value [1655297814.312279][6702:6702] CHIP:IN: UDP::Init bind&listen port=5550 [1655297814.312414][6702:6702] CHIP:IN: UDP::Init bound to port=5550 [1655297814.312439][6702:6702] CHIP:IN: TransportMgr initialized [1655297814.312510][6702:6702] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655297814.312538][6702:6702] CHIP:CTL: Setting attestation nonce to random value [1655297814.312585][6702:6702] CHIP:CTL: Setting CSR nonce to random value [1655297814.315446][6702:6702] CHIP:CTL: Generating NOC [1655297814.316266][6702:6702] CHIP:FP: Validating NOC chain [1655297814.318120][6702:6702] CHIP:FP: NOC chain validation successful [1655297814.318366][6702:6702] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655297814.318393][6702:6702] CHIP:FP: Assigned compressed fabric ID: 0xA928B8D2C6247E39, node ID: 0x000000000001B669 [1655297814.325542][6702:6702] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655297814.325599][6702:6702] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655297814.325627][6702:6702] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655297814.325651][6702:6702] CHIP:TS: Retaining current Last Known Good Time [1655297814.327314][6702:6702] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0xA928B8D2C6247E39 [1655297814.327391][6702:6702] CHIP:IN: UDP::Init bind&listen port=5550 [1655297814.327525][6702:6702] CHIP:IN: UDP::Init bound to port=5550 [1655297814.327554][6702:6702] CHIP:IN: TransportMgr initialized [1655297814.327670][6702:6702] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655297814.327713][6702:6702] CHIP:CTL: Setting attestation nonce to random value [1655297814.327783][6702:6702] CHIP:CTL: Setting CSR nonce to random value [1655297814.328712][6702:6702] CHIP:CTL: Generating NOC [1655297814.329797][6702:6702] CHIP:FP: Validating NOC chain [1655297814.331825][6702:6702] CHIP:FP: NOC chain validation successful [1655297814.332003][6702:6702] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655297814.332033][6702:6702] CHIP:FP: Assigned compressed fabric ID: 0x24AE67E4E4E24D4B, node ID: 0x000000000001B669 [1655297814.338215][6702:6702] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655297814.338268][6702:6702] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655297814.338295][6702:6702] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655297814.338317][6702:6702] CHIP:TS: Retaining current Last Known Good Time [1655297814.339830][6702:6702] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x24AE67E4E4E24D4B [1655297814.339903][6702:6702] CHIP:IN: UDP::Init bind&listen port=5550 [1655297814.340028][6702:6702] CHIP:IN: UDP::Init bound to port=5550 [1655297814.340055][6702:6702] CHIP:IN: TransportMgr initialized [1655297814.340138][6702:6702] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655297814.340179][6702:6702] CHIP:CTL: Setting attestation nonce to random value [1655297814.340242][6702:6702] CHIP:CTL: Setting CSR nonce to random value [1655297814.341189][6702:6702] CHIP:CTL: Generating NOC [1655297814.342114][6702:6702] CHIP:FP: Validating NOC chain [1655297814.343929][6702:6702] CHIP:FP: NOC chain validation successful [1655297814.344090][6702:6702] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655297814.344117][6702:6702] CHIP:FP: Assigned compressed fabric ID: 0xEEBE88FE4EF10BA6, node ID: 0x000000000001B669 [1655297814.350498][6702:6702] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655297814.350553][6702:6702] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655297814.350577][6702:6702] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655297814.350598][6702:6702] CHIP:TS: Retaining current Last Known Good Time [1655297814.352180][6702:6702] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xEEBE88FE4EF10BA6 [1655297814.352252][6702:6702] CHIP:IN: UDP::Init bind&listen port=5550 [1655297814.352375][6702:6702] CHIP:IN: UDP::Init bound to port=5550 [1655297814.352401][6702:6702] CHIP:IN: TransportMgr initialized [1655297814.396361][6702:6707] CHIP:DL: CHIP task running [1655297814.396618][6702:6707] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655297814.396657][6702:6707] CHIP:TOO: Sending command to node 0x1 [1655297814.396696][6702:6707] CHIP:CSM: FindOrEstablishSession: PeerId = A928B8D2C6247E39:0000000000000001 [1655297814.396726][6702:6707] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655297814.396769][6702:6707] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 1 --> 2 [1655297814.396804][6702:6707] CHIP:DIS: Resolving A928B8D2C6247E39:0000000000000001 ... [1655297814.506813][6702:6707] CHIP:DL: Avahi resolve found [1655297814.506901][6702:6707] CHIP:DIS: Node ID resolved for A928B8D2C6247E39:0000000000000001 [1655297814.506928][6702:6707] CHIP:DIS: Hostname: E45F01312CE50000 [1655297814.506957][6702:6707] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655297814.506981][6702:6707] CHIP:DIS: Port: 5540 [1655297814.507004][6702:6707] CHIP:DIS: Mrp Interval idle: 5000 ms [1655297814.507026][6702:6707] CHIP:DIS: Mrp Interval active: 300 ms [1655297814.507273][6702:6707] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655297814.507302][6702:6707] CHIP:DIS: Checking node lookup status after 110 ms [1655297814.507324][6702:6707] CHIP:DIS: Keeping DNSSD lookup active [1655297814.597345][6702:6707] CHIP:DIS: Checking node lookup status after 200 ms [1655297814.597609][6702:6707] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655297814.597671][6702:6707] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 2 --> 3 [1655297814.598055][6702:6707] CHIP:IN: SecureSession[0xaaaac5c6a6e0]: Allocated Type:2 LSID:63894 [1655297814.598137][6702:6707] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655297814.599692][6702:6707] CHIP:SC: Including MRP parameters [1655297814.600167][6702:6707] CHIP:IN: Prepared unauthenticated message 0xaaaac5c65de8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 42190i with MessageCounter:111614170. [1655297814.600271][6702:6707] CHIP:IN: Sending unauthenticated msg 0xaaaac5c65de8 with MessageCounter:111614170 to 0x0000000000000000 at monotonic time: 0000000001FC06A9 msec [1655297814.600605][6702:6707] CHIP:SC: Sent Sigma1 msg [1655297814.600673][6702:6707] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 3 --> 4 [1655297814.600738][6702:6707] CHIP:DIS: Discovery does not require any more timeouts [1655297814.602119][6702:6707] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:178518539 on exchange 42190i [1655297814.602192][6702:6707] CHIP:EM: Found matching exchange: 42190i, Delegate: 0xffff800011a0 [1655297814.602270][6702:6707] CHIP:EM: Rxd Ack; Removing MessageCounter:111614170 from Retrans Table on exchange 42190i [1655297814.602329][6702:6707] CHIP:EM: Removed CHIP MessageCounter:111614170 from RetransTable on exchange 42190i [1655297814.602398][6702:6707] CHIP:SC: Received Sigma2Resume msg [1655297814.602612][6702:6707] CHIP:SC: Found MRP parameters in the message [1655297814.602679][6702:6707] CHIP:SC: Peer assigned session session ID 34035 [1655297814.611373][6702:6707] CHIP:SC: Sending status report. Protocol code 0, exchange 42190 [1655297814.611448][6702:6707] CHIP:EM: Piggybacking Ack for MessageCounter:178518539 on exchange: 42190i [1655297814.611499][6702:6707] CHIP:IN: Prepared unauthenticated message 0xaaaac5c65de8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 42190i with MessageCounter:111614171. [1655297814.611550][6702:6707] CHIP:IN: Sending unauthenticated msg 0xaaaac5c65de8 with MessageCounter:111614171 to 0x0000000000000000 at monotonic time: 0000000001FC06B5 msec [1655297814.611808][6702:6707] CHIP:IN: SecureSession[0xaaaac5c6a6e0]: Activated - Type:2 LSID:63894 [1655297814.611840][6702:6707] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:63894 PSID:34035! [1655297814.611869][6702:6707] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 4 --> 5 [1655297814.611921][6702:6707] CHIP:TOO: Sending cluster (0x00000101) command (0x0000000C) on endpoint 1 [1655297814.611999][6702:6707] CHIP:DMG: ICR moving to [AddingComm] [1655297814.612047][6702:6707] CHIP:DMG: ICR moving to [AddedComma] [1655297814.612133][6702:6707] CHIP:IN: Prepared secure message 0xaaaac5c65e08 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 42191i with MessageCounter:163736979. [1655297814.612174][6702:6707] CHIP:IN: Sending encrypted msg 0xaaaac5c65e08 with MessageCounter:163736979 to 0x0000000000000001 (1) at monotonic time: 0000000001FC06B5 msec [1655297814.612299][6702:6707] CHIP:DMG: ICR moving to [CommandSen] [1655297814.618390][6702:6707] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:178518540 on exchange 42190i [1655297814.618451][6702:6707] CHIP:EM: Found matching exchange: 42190i, Delegate: (nil) [1655297814.618493][6702:6707] CHIP:EM: Rxd Ack; Removing MessageCounter:111614171 from Retrans Table on exchange 42190i [1655297814.618520][6702:6707] CHIP:EM: Removed CHIP MessageCounter:111614171 from RetransTable on exchange 42190i [1655297814.621607][6702:6707] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:171175746 on exchange 42191i [1655297814.621651][6702:6707] CHIP:EM: Found matching exchange: 42191i, Delegate: 0xffff800057a0 [1655297814.621694][6702:6707] CHIP:EM: Rxd Ack; Removing MessageCounter:163736979 from Retrans Table on exchange 42191i [1655297814.621729][6702:6707] CHIP:EM: Removed CHIP MessageCounter:163736979 from RetransTable on exchange 42191i [1655297814.621770][6702:6707] CHIP:DMG: ICR moving to [ResponseRe] [1655297814.621836][6702:6707] CHIP:DMG: InvokeResponseMessage = [1655297814.621871][6702:6707] CHIP:DMG: { [1655297814.621906][6702:6707] CHIP:DMG: suppressResponse = false, [1655297814.621942][6702:6707] CHIP:DMG: InvokeResponseIBs = [1655297814.621988][6702:6707] CHIP:DMG: [ [1655297814.622023][6702:6707] CHIP:DMG: InvokeResponseIB = [1655297814.622081][6702:6707] CHIP:DMG: { [1655297814.622121][6702:6707] CHIP:DMG: CommandDataIB = [1655297814.622166][6702:6707] CHIP:DMG: { [1655297814.622211][6702:6707] CHIP:DMG: CommandPathIB = [1655297814.622264][6702:6707] CHIP:DMG: { [1655297814.622318][6702:6707] CHIP:DMG: EndpointId = 0x1, [1655297814.622374][6702:6707] CHIP:DMG: ClusterId = 0x101, [1655297814.622452][6702:6707] CHIP:DMG: CommandId = 0xc, [1655297814.622502][6702:6707] CHIP:DMG: }, [1655297814.622551][6702:6707] CHIP:DMG: [1655297814.622596][6702:6707] CHIP:DMG: CommandFields = [1655297814.622648][6702:6707] CHIP:DMG: { [1655297814.622722][6702:6707] CHIP:DMG: 0x0 = 1, [1655297814.622774][6702:6707] CHIP:DMG: 0x1 = 1, [1655297814.622826][6702:6707] CHIP:DMG: 0x2 = 139, [1655297814.622876][6702:6707] CHIP:DMG: }, [1655297814.622921][6702:6707] CHIP:DMG: }, [1655297814.622970][6702:6707] CHIP:DMG: [1655297814.623010][6702:6707] CHIP:DMG: }, [1655297814.623055][6702:6707] CHIP:DMG: [1655297814.623090][6702:6707] CHIP:DMG: ], [1655297814.623136][6702:6707] CHIP:DMG: [1655297814.623171][6702:6707] CHIP:DMG: InteractionModelRevision = 1 [1655297814.623205][6702:6707] CHIP:DMG: }, [1655297814.623293][6702:6707] CHIP:DMG: Received Command Response Data, Endpoint=1 Cluster=0x0000_0101 Command=0x0000_000C [1655297814.623356][6702:6707] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0101 Command 0x0000_000C [1655297814.623428][6702:6707] CHIP:TOO: GetWeekDayScheduleResponse: { [1655297814.623478][6702:6707] CHIP:TOO: weekDayIndex: 1 [1655297814.623515][6702:6707] CHIP:TOO: userIndex: 1 [1655297814.623549][6702:6707] CHIP:TOO: status: 139 [1655297814.623584][6702:6707] CHIP:TOO: } [1655297814.623638][6702:6707] CHIP:DMG: ICR moving to [AwaitingDe] [1655297814.623705][6702:6707] CHIP:EM: Sending Standalone Ack for MessageCounter:171175746 on exchange 42191i [1655297814.623793][6702:6707] CHIP:IN: Prepared secure message 0xffff95c1f958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 42191i with MessageCounter:163736980. [1655297814.623848][6702:6707] CHIP:IN: Sending encrypted msg 0xffff95c1f958 with MessageCounter:163736980 to 0x0000000000000001 (1) at monotonic time: 0000000001FC06C1 msec [1655297814.623995][6702:6707] CHIP:EM: Flushed pending ack for MessageCounter:171175746 on exchange 42191i [1655297814.624289][6702:6702] CHIP:CTL: Shutting down the commissioner [1655297814.624408][6702:6702] CHIP:CTL: Shutting down the controller [1655297814.624453][6702:6702] CHIP:CTL: Shutting down the commissioner [1655297814.624526][6702:6702] CHIP:CTL: Shutting down the controller [1655297814.624613][6702:6702] CHIP:IN: Expiring all connections for fabric 1!! [1655297814.624652][6702:6702] CHIP:IN: SecureSession[0xaaaac5c6a6e0]: MarkForRemoval Type:2 LSID:63894 [1655297814.624684][6702:6702] CHIP:IN: SecureSession[0xaaaac5c6a6e0]: Released - Type:2 LSID:63894 [1655297814.624748][6702:6702] CHIP:CTL: Shutting down the commissioner [1655297814.624826][6702:6702] CHIP:CTL: Shutting down the controller [1655297814.624861][6702:6702] CHIP:IN: Expiring all connections for fabric 2!! [1655297814.624908][6702:6702] CHIP:CTL: Shutting down the commissioner [1655297814.625002][6702:6702] CHIP:CTL: Shutting down the controller [1655297814.625036][6702:6702] CHIP:IN: Expiring all connections for fabric 3!! [1655297814.625078][6702:6702] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655297814.626406][6702:6702] CHIP:DMG: IM WH moving to [Uninitialized] [1655297814.626504][6702:6702] CHIP:DMG: IM WH moving to [Uninitialized] [1655297814.626533][6702:6702] CHIP:DMG: IM WH moving to [Uninitialized] [1655297814.626565][6702:6702] CHIP:DMG: IM WH moving to [Uninitialized] [1655297814.626597][6702:6702] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655297814.626703][6702:6702] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655297814.627073][6702:6702] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-d5vbpg) [1655297814.627933][6702:6702] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655297814.628020][6702:6702] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655297814.628059][6702:6702] CHIP:DL: Inet Layer shutdown [1655297814.628092][6702:6702] CHIP:DL: BLE shutdown [1655297814.628124][6702:6702] CHIP:DL: System Layer shutdown TH LOG: [1655298013.127557][5807:5807] CHIP:DIS: Broadcasting mDns reply for query from fd01::e65f:1ff:fe0e:befc [1655298013.131483][5807:5807] CHIP:DIS: Broadcasting mDns reply for query from fd01::e65f:1ff:fe0e:befc [1655298013.132421][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.132494][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.132539][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.132581][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.132616][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.132652][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.132691][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.132725][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.132814][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.132864][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.132904][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.132940][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.132972][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.133006][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.133066][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.133097][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.133173][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.133222][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.133261][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.133296][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.133328][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.133362][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.133395][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.133424][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.133498][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.133545][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.133584][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.133619][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.133651][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.133685][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.133716][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.133745][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.133820][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.133867][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.133906][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.133940][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.133972][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.134005][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.134037][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.134065][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.134140][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.134187][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.134225][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.134260][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.134291][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.134325][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.134357][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.134386][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.134459][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.134506][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.134546][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.134581][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.134607][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.134635][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.134667][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.134698][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.134773][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.134821][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.134859][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.134893][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.134925][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.134958][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.134990][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.135019][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.135093][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.135141][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.135179][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.135213][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.135244][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.135278][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.135310][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.135339][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.135414][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.135461][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.135500][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.135535][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.135567][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.135600][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.135632][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.135661][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.135806][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.135842][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.135874][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.135954][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.135988][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136019][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136098][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.136132][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136163][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136242][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.136276][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136308][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136386][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.136421][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136453][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136532][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.136566][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136597][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136677][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.136711][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136742][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136820][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.136855][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136883][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.136956][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.136990][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.137037][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.137121][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.137155][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.137186][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.153919][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.154047][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.154129][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.154205][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.154273][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.154341][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.154409][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.154470][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.154618][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.154717][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.154791][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.154858][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.154918][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.154982][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.155042][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.155097][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.155235][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.155323][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.155395][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.155458][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.155517][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.155580][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.155639][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.155693][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.155831][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.155919][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.155989][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.156055][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.156114][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.156177][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.156236][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.156285][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.156424][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.156510][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.156582][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.156646][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.156705][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.156763][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.156820][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.156874][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.157007][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.157150][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.157223][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.157287][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.157346][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.157409][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.157469][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.157522][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.157662][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.157749][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.157822][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.157886][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.157945][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.158007][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.158067][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.158116][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.158253][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.158340][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.158410][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.158473][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.158531][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.158593][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.158651][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.158705][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.158844][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.158931][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.159001][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.159066][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.159124][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.159187][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.159245][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.159298][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.159440][5807:5807] CHIP:DIS: MINMDNS: received SRV record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.159526][5807:5807] CHIP:DIS: MINMDNS: Operational SRV for A928B8D2C6247E39-0000000000000001: E45F01312CE50000.local [1655298013.159595][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.159659][5807:5807] CHIP:DIS: MINMDNS: IP address fd01::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.159718][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.159780][5807:5807] CHIP:DIS: MINMDNS: IP address fe80::e65f:1ff:fe31:2ce5 found for E45F01312CE50000.local [1655298013.159838][5807:5807] CHIP:DIS: Discovered node without a pending query [1655298013.159892][5807:5807] CHIP:DIS: Discovery does not require any more timeouts [1655298013.160155][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.160221][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.160280][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.160425][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.160489][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.160546][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.160690][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.160754][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.160811][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.160956][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.161049][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.161112][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.161261][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.161324][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.161381][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.161525][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.161588][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.161645][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.161784][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.161847][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.161905][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.162049][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.162112][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.162169][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.162314][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.162377][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.162434][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.162579][5807:5807] CHIP:DIS: MINMDNS: received TXT record for A928B8D2C6247E39-0000000000000001._matter._tcp.local [1655298013.162642][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.162700][5807:5807] CHIP:DIS: MINMDNS: received AAAA record for E45F01312CE50000.local [1655298013.222192][5807:5807] CHIP:EM: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:238066582 on exchange 37765r [1655298013.222294][5807:5807] CHIP:EM: Handling via exchange: 37765r, Delegate: 0xaaaab38c8948 [1655298013.222387][5807:5807] CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0xaaaab38c8f60 [1655298013.222443][5807:5807] CHIP:IN: CASE Server disabling CASE session setups [1655298013.222504][5807:5807] CHIP:SC: Received Sigma1 msg [1655298013.222607][5807:5807] CHIP:SC: Found MRP parameters in the message [1655298013.222682][5807:5807] CHIP:SC: Peer assigned session key ID 49017 [1655298013.223371][5807:5807] CHIP:SC: Including MRP parameters [1655298013.223474][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:238066582 on exchange: 37765r [1655298013.223560][5807:5807] CHIP:IN: Prepared unauthenticated message 0xaaaab38cd618 to 0x0000000000000000 (0) of type 0x33 and protocolId (0, 0) on exchange 37765r with MessageCounter:178518541. [1655298013.223644][5807:5807] CHIP:IN: Sending unauthenticated msg 0xaaaab38cd618 with MessageCounter:178518541 to 0x0000000000000000 at monotonic time: 000000000204F852 msec [1655298013.223976][5807:5807] CHIP:SC: Sent Sigma2Resume msg [1655298013.234497][5807:5807] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:238066583 on exchange 37765r [1655298013.234572][5807:5807] CHIP:EM: Found matching exchange: 37765r, Delegate: 0xaaaab38c8980 [1655298013.234655][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:178518541 from Retrans Table on exchange 37765r [1655298013.234714][5807:5807] CHIP:EM: Removed CHIP MessageCounter:178518541 from RetransTable on exchange 37765r [1655298013.234795][5807:5807] CHIP:SC: Success status report received. Session was established [1655298013.235521][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-OrdpRE) [1655298013.237295][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655298013.237599][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-pOaDHL) [1655298013.239142][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655298013.239435][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-qQHMc7) [1655298013.240903][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655298013.241002][5807:5807] CHIP:IN: Expired/released previous local session ID 34035 for peer <000000000001B669, 2> [1655298013.241086][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: MarkForRemoval Type:2 LSID:34035 [1655298013.241131][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: Released - Type:2 LSID:34035 [1655298013.241253][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: Activated - Type:2 LSID:34036 [1655298013.241299][5807:5807] CHIP:IN: New secure session created for device <000000000001B669, 2>, LSID:34036 PSID:49017! [1655298013.241342][5807:5807] CHIP:IN: CASE Session established to peer: <000000000001B669, 2> [1655298013.241381][5807:5807] CHIP:IN: CASE Server enabling CASE session setups [1655298013.241509][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: Allocated Type:2 LSID:34037 [1655298013.241562][5807:5807] CHIP:SC: Allocated SecureSession (0xaaaab38c5c88) - waiting for Sigma1 msg [1655298013.241615][5807:5807] CHIP:EM: Sending Standalone Ack for MessageCounter:238066583 on exchange 37765r [1655298013.241693][5807:5807] CHIP:IN: Prepared unauthenticated message 0xffffc670da88 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 37765r with MessageCounter:178518542. [1655298013.241764][5807:5807] CHIP:IN: Sending unauthenticated msg 0xffffc670da88 with MessageCounter:178518542 to 0x0000000000000000 at monotonic time: 000000000204F864 msec [1655298013.242082][5807:5807] CHIP:EM: Flushed pending ack for MessageCounter:238066583 on exchange 37765r [1655298013.242387][5807:5807] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:203387785 on exchange 37766r [1655298013.242454][5807:5807] CHIP:EM: Handling via exchange: 37766r, Delegate: 0xaaaab38c02b0 [1655298013.242570][5807:5807] CHIP:DMG: InvokeRequestMessage = [1655298013.242619][5807:5807] CHIP:DMG: { [1655298013.242662][5807:5807] CHIP:DMG: suppressResponse = false, [1655298013.242711][5807:5807] CHIP:DMG: timedRequest = false, [1655298013.242756][5807:5807] CHIP:DMG: InvokeRequests = [1655298013.242813][5807:5807] CHIP:DMG: [ [1655298013.242858][5807:5807] CHIP:DMG: CommandDataIB = [1655298013.242909][5807:5807] CHIP:DMG: { [1655298013.242957][5807:5807] CHIP:DMG: CommandPathIB = [1655298013.243017][5807:5807] CHIP:DMG: { [1655298013.243077][5807:5807] CHIP:DMG: EndpointId = 0x1, [1655298013.243140][5807:5807] CHIP:DMG: ClusterId = 0x101, [1655298013.243201][5807:5807] CHIP:DMG: CommandId = 0xc, [1655298013.243258][5807:5807] CHIP:DMG: }, [1655298013.243317][5807:5807] CHIP:DMG: [1655298013.243369][5807:5807] CHIP:DMG: CommandFields = [1655298013.243431][5807:5807] CHIP:DMG: { [1655298013.243492][5807:5807] CHIP:DMG: 0x0 = 1, [1655298013.243554][5807:5807] CHIP:DMG: 0x1 = 1, [1655298013.243615][5807:5807] CHIP:DMG: }, [1655298013.243669][5807:5807] CHIP:DMG: }, [1655298013.243727][5807:5807] CHIP:DMG: [1655298013.243772][5807:5807] CHIP:DMG: ], [1655298013.243826][5807:5807] CHIP:DMG: [1655298013.243871][5807:5807] CHIP:DMG: InteractionModelRevision = 1 [1655298013.243915][5807:5807] CHIP:DMG: }, [1655298013.244020][5807:5807] CHIP:DMG: AccessControl: checking f=2 a=c s=0x000000000001B669 t= c=0x0000_0101 e=1 p=a [1655298013.244083][5807:5807] CHIP:DMG: AccessControl: allowed [1655298013.244133][5807:5807] CHIP:DMG: Received command for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_000C [1655298013.244199][5807:5807] CHIP:ZCL: [GetWeekDaySchedule] Incoming command [endpointId=1] [1655298013.244253][5807:5807] CHIP:ZCL: Lock App: LockEndpoint::GetUser [endpoint=1,userIndex=1] [1655298013.244295][5807:5807] CHIP:ZCL: Found unoccupied user [endpoint=1,adjustedIndex=0] [1655298013.244333][5807:5807] CHIP:ZCL: [GetWeekDaySchedule] User does not exist [endpointId=1,weekDayIndex=1,userIndex=1] [1655298013.244391][5807:5807] CHIP:DMG: ICR moving to [ Preparing] [1655298013.244444][5807:5807] CHIP:DMG: ICR moving to [AddingComm] [1655298013.244498][5807:5807] CHIP:DMG: ICR moving to [AddedComma] [1655298013.244567][5807:5807] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1655298013.244620][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:203387785 on exchange: 37766r [1655298013.244720][5807:5807] CHIP:IN: Prepared secure message 0xaaaab38cd618 to 0x000000000001B669 (2) of type 0x9 and protocolId (0, 1) on exchange 37766r with MessageCounter:47413204. [1655298013.244787][5807:5807] CHIP:IN: Sending encrypted msg 0xaaaab38cd618 with MessageCounter:47413204 to 0x000000000001B669 (2) at monotonic time: 000000000204F867 msec [1655298013.245066][5807:5807] CHIP:DMG: ICR moving to [CommandSen] [1655298013.245117][5807:5807] CHIP:DMG: ICR moving to [AwaitingDe] [1655298013.247715][5807:5807] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:203387786 on exchange 37766r [1655298013.247747][5807:5807] CHIP:EM: Found matching exchange: 37766r, Delegate: (nil) [1655298013.247782][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:47413204 from Retrans Table on exchange 37766r [1655298013.247806][5807:5807] CHIP:EM: Removed CHIP MessageCounter:47413204 from RetransTable on exchange 37766r DUT LOG: ubuntu@ubuntu:~/cntrl13/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool doorlock clear-week-day-schedule 1 1 1 1 [1655298126.168039][6729:6729] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655298126.168599][6729:6729] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655298126.168773][6729:6729] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655298126.168885][6729:6729] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655298126.169264][6729:6729] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-w2NGkp)[1655298126.169918][6729:6729] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655298126.169973][6729:6729] CHIP:DL: NVS set: chip-counters/reboot-count = 20 (0x14) [1655298126.170900][6729:6729] CHIP:DL: Got Ethernet interface: eth0 [1655298126.171486][6729:6729] CHIP:DL: Found the primary Ethernet interface:eth0 [1655298126.172123][6729:6729] CHIP:DL: Got WiFi interface: wlan0 [1655298126.172199][6729:6729] CHIP:DL: Failed to reset WiFi statistic counts [1655298126.172291][6729:6729] CHIP:IN: UDP::Init bind&listen port=0 [1655298126.172451][6729:6729] CHIP:IN: UDP::Init bound to port=52117 [1655298126.172477][6729:6729] CHIP:IN: BLEBase::Init - setting/overriding transport [1655298126.172499][6729:6729] CHIP:IN: TransportMgr initialized [1655298126.172548][6729:6729] CHIP:FP: Initializing FabricTable from persistent storage [1655298126.172756][6729:6729] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298126.172851][6729:6729] CHIP:FP: Loading from storage for fabric index 0x1 [1655298126.173316][6729:6729] CHIP:FP: Loading from storage for fabric index 0x2 [1655298126.173695][6729:6729] CHIP:FP: Loading from storage for fabric index 0x3 [1655298126.178142][6729:6729] CHIP:ZCL: Using ZAP configuration... [1655298126.183602][6729:6729] CHIP:DL: Avahi client registered [1655298126.185136][6729:6729] CHIP:CTL: System State Initialized... [1655298126.185240][6729:6729] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298126.185311][6729:6729] CHIP:CTL: Setting attestation nonce to random value [1655298126.185373][6729:6729] CHIP:CTL: Setting CSR nonce to random value [1655298126.185468][6729:6729] CHIP:IN: UDP::Init bind&listen port=5550 [1655298126.185625][6729:6729] CHIP:IN: UDP::Init bound to port=5550 [1655298126.185657][6729:6729] CHIP:IN: TransportMgr initialized [1655298126.185743][6729:6729] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298126.185778][6729:6729] CHIP:CTL: Setting attestation nonce to random value [1655298126.185837][6729:6729] CHIP:CTL: Setting CSR nonce to random value [1655298126.189172][6729:6729] CHIP:CTL: Generating NOC [1655298126.190138][6729:6729] CHIP:FP: Validating NOC chain [1655298126.192334][6729:6729] CHIP:FP: NOC chain validation successful [1655298126.192535][6729:6729] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655298126.192570][6729:6729] CHIP:FP: Assigned compressed fabric ID: 0xA928B8D2C6247E39, node ID: 0x000000000001B669 [1655298126.202630][6729:6729] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655298126.202685][6729:6729] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298126.202713][6729:6729] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655298126.202735][6729:6729] CHIP:TS: Retaining current Last Known Good Time [1655298126.204313][6729:6729] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0xA928B8D2C6247E39 [1655298126.204455][6729:6729] CHIP:IN: UDP::Init bind&listen port=5550 [1655298126.204594][6729:6729] CHIP:IN: UDP::Init bound to port=5550 [1655298126.204622][6729:6729] CHIP:IN: TransportMgr initialized [1655298126.204729][6729:6729] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298126.204770][6729:6729] CHIP:CTL: Setting attestation nonce to random value [1655298126.204835][6729:6729] CHIP:CTL: Setting CSR nonce to random value [1655298126.205819][6729:6729] CHIP:CTL: Generating NOC [1655298126.206888][6729:6729] CHIP:FP: Validating NOC chain [1655298126.209086][6729:6729] CHIP:FP: NOC chain validation successful [1655298126.209327][6729:6729] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655298126.209363][6729:6729] CHIP:FP: Assigned compressed fabric ID: 0x24AE67E4E4E24D4B, node ID: 0x000000000001B669 [1655298126.216502][6729:6729] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655298126.216555][6729:6729] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298126.216579][6729:6729] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655298126.216601][6729:6729] CHIP:TS: Retaining current Last Known Good Time [1655298126.218087][6729:6729] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x24AE67E4E4E24D4B [1655298126.218155][6729:6729] CHIP:IN: UDP::Init bind&listen port=5550 [1655298126.218280][6729:6729] CHIP:IN: UDP::Init bound to port=5550 [1655298126.218306][6729:6729] CHIP:IN: TransportMgr initialized [1655298126.218404][6729:6729] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298126.218520][6729:6729] CHIP:CTL: Setting attestation nonce to random value [1655298126.218582][6729:6729] CHIP:CTL: Setting CSR nonce to random value [1655298126.219470][6729:6729] CHIP:CTL: Generating NOC [1655298126.220423][6729:6729] CHIP:FP: Validating NOC chain [1655298126.222155][6729:6729] CHIP:FP: NOC chain validation successful [1655298126.222318][6729:6729] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655298126.222345][6729:6729] CHIP:FP: Assigned compressed fabric ID: 0xEEBE88FE4EF10BA6, node ID: 0x000000000001B669 [1655298126.229154][6729:6729] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655298126.229208][6729:6729] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298126.229233][6729:6729] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655298126.229254][6729:6729] CHIP:TS: Retaining current Last Known Good Time [1655298126.233784][6729:6729] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xEEBE88FE4EF10BA6 [1655298126.233856][6729:6729] CHIP:IN: UDP::Init bind&listen port=5550 [1655298126.233984][6729:6729] CHIP:IN: UDP::Init bound to port=5550 [1655298126.234010][6729:6729] CHIP:IN: TransportMgr initialized [1655298126.276972][6729:6734] CHIP:DL: CHIP task running [1655298126.277231][6729:6734] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655298126.277295][6729:6734] CHIP:TOO: Sending command to node 0x1 [1655298126.277338][6729:6734] CHIP:CSM: FindOrEstablishSession: PeerId = A928B8D2C6247E39:0000000000000001 [1655298126.277370][6729:6734] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655298126.277415][6729:6734] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 1 --> 2 [1655298126.277464][6729:6734] CHIP:DIS: Resolving A928B8D2C6247E39:0000000000000001 ... [1655298126.279611][6729:6734] CHIP:DL: Avahi resolve found [1655298126.279702][6729:6734] CHIP:DIS: Node ID resolved for A928B8D2C6247E39:0000000000000001 [1655298126.279735][6729:6734] CHIP:DIS: Hostname: E45F01312CE50000 [1655298126.279766][6729:6734] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655298126.279791][6729:6734] CHIP:DIS: Port: 5540 [1655298126.279815][6729:6734] CHIP:DIS: Mrp Interval idle: 5000 ms [1655298126.279910][6729:6734] CHIP:DIS: Mrp Interval active: 300 ms [1655298126.280176][6729:6734] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655298126.280207][6729:6734] CHIP:DIS: Checking node lookup status after 2 ms [1655298126.280230][6729:6734] CHIP:DIS: Keeping DNSSD lookup active [1655298126.478634][6729:6734] CHIP:DIS: Checking node lookup status after 201 ms [1655298126.478933][6729:6734] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655298126.478996][6729:6734] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 2 --> 3 [1655298126.479391][6729:6734] CHIP:IN: SecureSession[0xaaaae468ca70]: Allocated Type:2 LSID:23711 [1655298126.479473][6729:6734] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655298126.480963][6729:6734] CHIP:SC: Including MRP parameters [1655298126.481429][6729:6734] CHIP:IN: Prepared unauthenticated message 0xaaaae46882d8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 6032i with MessageCounter:17696939. [1655298126.481533][6729:6734] CHIP:IN: Sending unauthenticated msg 0xaaaae46882d8 with MessageCounter:17696939 to 0x0000000000000000 at monotonic time: 000000000200C8F3 msec [1655298126.481868][6729:6734] CHIP:SC: Sent Sigma1 msg [1655298126.481935][6729:6734] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 3 --> 4 [1655298126.482004][6729:6734] CHIP:DIS: Discovery does not require any more timeouts [1655298126.483353][6729:6734] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:178518543 on exchange 6032i [1655298126.483430][6729:6734] CHIP:EM: Found matching exchange: 6032i, Delegate: 0xffff680011a0[1655298126.483510][6729:6734] CHIP:EM: Rxd Ack; Removing MessageCounter:17696939 from Retrans Table on exchange 6032i [1655298126.483571][6729:6734] CHIP:EM: Removed CHIP MessageCounter:17696939 from RetransTable on exchange 6032i [1655298126.483644][6729:6734] CHIP:SC: Received Sigma2Resume msg [1655298126.483805][6729:6734] CHIP:SC: Found MRP parameters in the message [1655298126.483874][6729:6734] CHIP:SC: Peer assigned session session ID 34037 [1655298126.495986][6729:6734] CHIP:SC: Sending status report. Protocol code 0, exchange 6032 [1655298126.496058][6729:6734] CHIP:EM: Piggybacking Ack for MessageCounter:178518543 on exchange: 6032i [1655298126.496109][6729:6734] CHIP:IN: Prepared unauthenticated message 0xaaaae46882d8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 6032i with MessageCounter:17696940. [1655298126.496158][6729:6734] CHIP:IN: Sending unauthenticated msg 0xaaaae46882d8 with MessageCounter:17696940 to 0x0000000000000000 at monotonic time: 000000000200C901 msec [1655298126.496414][6729:6734] CHIP:IN: SecureSession[0xaaaae468ca70]: Activated - Type:2 LSID:23711 [1655298126.496448][6729:6734] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:23711 PSID:34037! [1655298126.496477][6729:6734] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 4 --> 5 [1655298126.496531][6729:6734] CHIP:TOO: Sending cluster (0x00000101) command (0x0000000D) on endpoint 1 [1655298126.496610][6729:6734] CHIP:DMG: ICR moving to [AddingComm] [1655298126.496659][6729:6734] CHIP:DMG: ICR moving to [AddedComma] [1655298126.496853][6729:6734] CHIP:IN: Prepared secure message 0xaaaae46882f8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 6033i with MessageCounter:177057665. [1655298126.496900][6729:6734] CHIP:IN: Sending encrypted msg 0xaaaae46882f8 with MessageCounter:177057665 to 0x0000000000000001 (1) at monotonic time: 000000000200C902 msec [1655298126.497038][6729:6734] CHIP:DMG: ICR moving to [CommandSen] [1655298126.505395][6729:6734] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:178518544 on exchange 6032i [1655298126.505451][6729:6734] CHIP:EM: Found matching exchange: 6032i, Delegate: (nil) [1655298126.505511][6729:6734] CHIP:EM: Rxd Ack; Removing MessageCounter:17696940 from Retrans Table on exchange 6032i [1655298126.505553][6729:6734] CHIP:EM: Removed CHIP MessageCounter:17696940 from RetransTable on exchange 6032i [1655298126.508533][6729:6734] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:204270317 on exchange 6033i [1655298126.508584][6729:6734] CHIP:EM: Found matching exchange: 6033i, Delegate: 0xffff68005910[1655298126.508633][6729:6734] CHIP:EM: Rxd Ack; Removing MessageCounter:177057665 from Retrans Table on exchange 6033i [1655298126.508674][6729:6734] CHIP:EM: Removed CHIP MessageCounter:177057665 from RetransTable on exchange 6033i [1655298126.508719][6729:6734] CHIP:DMG: ICR moving to [ResponseRe] [1655298126.508791][6729:6734] CHIP:DMG: InvokeResponseMessage = [1655298126.508832][6729:6734] CHIP:DMG: { [1655298126.508870][6729:6734] CHIP:DMG: suppressResponse = false, [1655298126.508911][6729:6734] CHIP:DMG: InvokeResponseIBs = [1655298126.508960][6729:6734] CHIP:DMG: [ [1655298126.509000][6729:6734] CHIP:DMG: InvokeResponseIB = [1655298126.509056][6729:6734] CHIP:DMG: { [1655298126.509099][6729:6734] CHIP:DMG: CommandStatusIB = [1655298126.509149][6729:6734] CHIP:DMG: { [1655298126.509198][6729:6734] CHIP:DMG: CommandPathIB = [1655298126.509252][6729:6734] CHIP:DMG: { [1655298126.509303][6729:6734] CHIP:DMG: EndpointId = 0x1, [1655298126.509360][6729:6734] CHIP:DMG: ClusterId = 0x101, [1655298126.509422][6729:6734] CHIP:DMG: CommandId = 0xd,[1655298126.509481][6729:6734] CHIP:DMG: }, [1655298126.509540][6729:6734] CHIP:DMG: [1655298126.509585][6729:6734] CHIP:DMG: StatusIB = [1655298126.509640][6729:6734] CHIP:DMG: { [1655298126.509695][6729:6734] CHIP:DMG: status = 0x8b (NOT_FOUND), [1655298126.509748][6729:6734] CHIP:DMG: }, [1655298126.509797][6729:6734] CHIP:DMG: [1655298126.509844][6729:6734] CHIP:DMG: }, [1655298126.509900][6729:6734] CHIP:DMG: [1655298126.509944][6729:6734] CHIP:DMG: }, [1655298126.509996][6729:6734] CHIP:DMG: [1655298126.510034][6729:6734] CHIP:DMG: ], [1655298126.510082][6729:6734] CHIP:DMG: [1655298126.510121][6729:6734] CHIP:DMG: InteractionModelRevision = 1 [1655298126.510160][6729:6734] CHIP:DMG: }, [1655298126.510251][6729:6734] CHIP:DMG: Received Command Response Status for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_000D Status=0x8b [1655298126.510303][6729:6734] CHIP:TOO: Error: IM Error 0x0000058B: General error: 0x8b (NOT_FOUND) [1655298126.510359][6729:6734] CHIP:DMG: ICR moving to [AwaitingDe] [1655298126.510470][6729:6734] CHIP:EM: Sending Standalone Ack for MessageCounter:204270317 on exchange 6033i [1655298126.510564][6729:6734] CHIP:IN: Prepared secure message 0xffff7de78958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 6033i with MessageCounter:177057666. [1655298126.510624][6729:6734] CHIP:IN: Sending encrypted msg 0xffff7de78958 with MessageCounter:177057666 to 0x0000000000000001 (1) at monotonic time: 000000000200C910 msec [1655298126.510772][6729:6734] CHIP:EM: Flushed pending ack for MessageCounter:204270317 on exchange 6033i [1655298126.511036][6729:6729] CHIP:CTL: Shutting down the commissioner [1655298126.511163][6729:6729] CHIP:CTL: Shutting down the controller [1655298126.511214][6729:6729] CHIP:CTL: Shutting down the commissioner [1655298126.511300][6729:6729] CHIP:CTL: Shutting down the controller [1655298126.511349][6729:6729] CHIP:IN: Expiring all connections for fabric 1!! [1655298126.511385][6729:6729] CHIP:IN: SecureSession[0xaaaae468ca70]: MarkForRemoval Type:2 LSID:23711 [1655298126.511423][6729:6729] CHIP:IN: SecureSession[0xaaaae468ca70]: Released - Type:2 LSID:23711 [1655298126.511489][6729:6729] CHIP:CTL: Shutting down the commissioner [1655298126.511577][6729:6729] CHIP:CTL: Shutting down the controller [1655298126.511616][6729:6729] CHIP:IN: Expiring all connections for fabric 2!! [1655298126.511671][6729:6729] CHIP:CTL: Shutting down the commissioner [1655298126.511753][6729:6729] CHIP:CTL: Shutting down the controller [1655298126.511791][6729:6729] CHIP:IN: Expiring all connections for fabric 3!! [1655298126.511840][6729:6729] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655298126.513171][6729:6729] CHIP:DMG: IM WH moving to [Uninitialized] [1655298126.513229][6729:6729] CHIP:DMG: IM WH moving to [Uninitialized] [1655298126.513261][6729:6729] CHIP:DMG: IM WH moving to [Uninitialized] [1655298126.513291][6729:6729] CHIP:DMG: IM WH moving to [Uninitialized] [1655298126.513327][6729:6729] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655298126.513426][6729:6729] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655298126.513789][6729:6729] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-oDfCHt)[1655298126.514809][6729:6729] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655298126.515167][6729:6729] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)[1655298126.515217][6729:6729] CHIP:DL: Inet Layer shutdown [1655298126.515251][6729:6729] CHIP:DL: BLE shutdown [1655298126.515319][6729:6729] CHIP:DL: System Layer shutdown [1655298126.515526][6729:6729] CHIP:TOO: Run command failure: IM Error 0x0000058B: General error: 0x8b (NOT_FOUND) TH LOG: [1655298126.464670][5807:5807] CHIP:EM: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:17696939 on exchange 6032r [1655298126.464747][5807:5807] CHIP:EM: Handling via exchange: 6032r, Delegate: 0xaaaab38c8948 [1655298126.464796][5807:5807] CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0xaaaab38c8f60 [1655298126.464821][5807:5807] CHIP:IN: CASE Server disabling CASE session setups [1655298126.464848][5807:5807] CHIP:SC: Received Sigma1 msg [1655298126.464904][5807:5807] CHIP:SC: Found MRP parameters in the message [1655298126.464936][5807:5807] CHIP:SC: Peer assigned session key ID 23711 [1655298126.465314][5807:5807] CHIP:SC: Including MRP parameters [1655298126.465365][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:17696939 on exchange: 6032r [1655298126.465406][5807:5807] CHIP:IN: Prepared unauthenticated message 0xaaaab38cd618 to 0x0000000000000000 (0) of type 0x33 and protocolId (0, 0) on exchange 6032r with MessageCounter:178518543. [1655298126.465446][5807:5807] CHIP:IN: Sending unauthenticated msg 0xaaaab38cd618 with MessageCounter:178518543 to 0x0000000000000000 at monotonic time: 000000000206B2AC msec [1655298126.465618][5807:5807] CHIP:SC: Sent Sigma2Resume msg [1655298126.479172][5807:5807] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:17696940 on exchange 6032r [1655298126.479250][5807:5807] CHIP:EM: Found matching exchange: 6032r, Delegate: 0xaaaab38c8980 [1655298126.479335][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:178518543 from Retrans Table on exchange 6032r [1655298126.479392][5807:5807] CHIP:EM: Removed CHIP MessageCounter:178518543 from RetransTable on exchange 6032r [1655298126.479473][5807:5807] CHIP:SC: Success status report received. Session was established [1655298126.480220][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-bl5Kov) [1655298126.482165][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655298126.482500][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-cUEGx4) [1655298126.484301][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655298126.484622][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-gWPZQN) [1655298126.486429][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655298126.486536][5807:5807] CHIP:IN: Expired/released previous local session ID 34036 for peer <000000000001B669, 2> [1655298126.486594][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: MarkForRemoval Type:2 LSID:34036 [1655298126.486643][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: Released - Type:2 LSID:34036 [1655298126.486776][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: Activated - Type:2 LSID:34037 [1655298126.486831][5807:5807] CHIP:IN: New secure session created for device <000000000001B669, 2>, LSID:34037 PSID:23711! [1655298126.486879][5807:5807] CHIP:IN: CASE Session established to peer: <000000000001B669, 2> [1655298126.486940][5807:5807] CHIP:IN: CASE Server enabling CASE session setups [1655298126.487083][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: Allocated Type:2 LSID:34038 [1655298126.487143][5807:5807] CHIP:SC: Allocated SecureSession (0xaaaab38c5ba0) - waiting for Sigma1 msg [1655298126.487204][5807:5807] CHIP:EM: Sending Standalone Ack for MessageCounter:17696940 on exchange 6032r [1655298126.487292][5807:5807] CHIP:IN: Prepared unauthenticated message 0xffffc670da88 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 6032r with MessageCounter:178518544. [1655298126.487372][5807:5807] CHIP:IN: Sending unauthenticated msg 0xffffc670da88 with MessageCounter:178518544 to 0x0000000000000000 at monotonic time: 000000000206B2C2 msec [1655298126.487723][5807:5807] CHIP:EM: Flushed pending ack for MessageCounter:17696940 on exchange 6032r [1655298126.488060][5807:5807] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:177057665 on exchange 6033r [1655298126.488139][5807:5807] CHIP:EM: Handling via exchange: 6033r, Delegate: 0xaaaab38c02b0 [1655298126.488269][5807:5807] CHIP:DMG: InvokeRequestMessage = [1655298126.488325][5807:5807] CHIP:DMG: { [1655298126.488374][5807:5807] CHIP:DMG: suppressResponse = false, [1655298126.488430][5807:5807] CHIP:DMG: timedRequest = false, [1655298126.488482][5807:5807] CHIP:DMG: InvokeRequests = [1655298126.488547][5807:5807] CHIP:DMG: [ [1655298126.488598][5807:5807] CHIP:DMG: CommandDataIB = [1655298126.488655][5807:5807] CHIP:DMG: { [1655298126.488711][5807:5807] CHIP:DMG: CommandPathIB = [1655298126.488776][5807:5807] CHIP:DMG: { [1655298126.488842][5807:5807] CHIP:DMG: EndpointId = 0x1, [1655298126.488919][5807:5807] CHIP:DMG: ClusterId = 0x101, [1655298126.488988][5807:5807] CHIP:DMG: CommandId = 0xd, [1655298126.489191][5807:5807] CHIP:DMG: }, [1655298126.489263][5807:5807] CHIP:DMG: [1655298126.489320][5807:5807] CHIP:DMG: CommandFields = [1655298126.489384][5807:5807] CHIP:DMG: { [1655298126.489450][5807:5807] CHIP:DMG: 0x0 = 1, [1655298126.489521][5807:5807] CHIP:DMG: 0x1 = 1, [1655298126.489586][5807:5807] CHIP:DMG: }, [1655298126.489648][5807:5807] CHIP:DMG: }, [1655298126.489711][5807:5807] CHIP:DMG: [1655298126.489762][5807:5807] CHIP:DMG: ], [1655298126.489825][5807:5807] CHIP:DMG: [1655298126.489876][5807:5807] CHIP:DMG: InteractionModelRevision = 1 [1655298126.489926][5807:5807] CHIP:DMG: }, [1655298126.490045][5807:5807] CHIP:DMG: AccessControl: checking f=2 a=c s=0x000000000001B669 t= c=0x0000_0101 e=1 p=a [1655298126.490115][5807:5807] CHIP:DMG: AccessControl: allowed [1655298126.490170][5807:5807] CHIP:DMG: Received command for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_000D [1655298126.490246][5807:5807] CHIP:ZCL: [ClearWeekDaySchedule] Incoming command [endpointId=1] [1655298126.490311][5807:5807] CHIP:ZCL: Lock App: LockEndpoint::GetUser [endpoint=1,userIndex=1] [1655298126.490359][5807:5807] CHIP:ZCL: Found unoccupied user [endpoint=1,adjustedIndex=0] [1655298126.490403][5807:5807] CHIP:ZCL: [ClearWeekDaySchedule] User does not exist [endpointId=1,weekDayIndex=1,userIndex=1] [1655298126.490467][5807:5807] CHIP:DMG: ICR moving to [ Preparing] [1655298126.490527][5807:5807] CHIP:DMG: ICR moving to [AddingComm] [1655298126.490558][5807:5807] CHIP:DMG: ICR moving to [AddedComma] [1655298126.490595][5807:5807] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1655298126.490625][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:177057665 on exchange: 6033r [1655298126.490744][5807:5807] CHIP:IN: Prepared secure message 0xaaaab38cd618 to 0x000000000001B669 (2) of type 0x9 and protocolId (0, 1) on exchange 6033r with MessageCounter:204270317. [1655298126.490782][5807:5807] CHIP:IN: Sending encrypted msg 0xaaaab38cd618 with MessageCounter:204270317 to 0x000000000001B669 (2) at monotonic time: 000000000206B2C5 msec [1655298126.490937][5807:5807] CHIP:DMG: ICR moving to [CommandSen] [1655298126.490964][5807:5807] CHIP:DMG: ICR moving to [AwaitingDe] [1655298126.493510][5807:5807] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:177057666 on exchange 6033r [1655298126.493543][5807:5807] CHIP:EM: Found matching exchange: 6033r, Delegate: (nil) [1655298126.493578][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:204270317 from Retrans Table on exchange 6033r [1655298126.493602][5807:5807] CHIP:EM: Removed CHIP MessageCounter:204270317 from RetransTable on exchange 6 DUT LOG: ubuntu@ubuntu:~/cntrl13/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool doorlock set-year-day-schedule 1 1 960 1980 1 1 [1655298760.941020][6969:6969] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655298760.941596][6969:6969] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655298760.941779][6969:6969] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655298760.941891][6969:6969] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655298760.942261][6969:6969] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-jtEtd6) [1655298760.942937][6969:6969] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655298760.942991][6969:6969] CHIP:DL: NVS set: chip-counters/reboot-count = 55 (0x37) [1655298760.943878][6969:6969] CHIP:DL: Got Ethernet interface: eth0 [1655298760.944469][6969:6969] CHIP:DL: Found the primary Ethernet interface:eth0 [1655298760.945153][6969:6969] CHIP:DL: Got WiFi interface: wlan0 [1655298760.945232][6969:6969] CHIP:DL: Failed to reset WiFi statistic counts [1655298760.945338][6969:6969] CHIP:IN: UDP::Init bind&listen port=0 [1655298760.945488][6969:6969] CHIP:IN: UDP::Init bound to port=35894 [1655298760.945515][6969:6969] CHIP:IN: BLEBase::Init - setting/overriding transport [1655298760.945537][6969:6969] CHIP:IN: TransportMgr initialized [1655298760.945586][6969:6969] CHIP:FP: Initializing FabricTable from persistent storage [1655298760.945798][6969:6969] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298760.945900][6969:6969] CHIP:FP: Loading from storage for fabric index 0x1 [1655298760.946411][6969:6969] CHIP:FP: Loading from storage for fabric index 0x2 [1655298760.946889][6969:6969] CHIP:FP: Loading from storage for fabric index 0x3 [1655298760.951736][6969:6969] CHIP:ZCL: Using ZAP configuration... [1655298760.956665][6969:6969] CHIP:DL: Avahi client registered [1655298760.958144][6969:6969] CHIP:CTL: System State Initialized... [1655298760.958244][6969:6969] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298760.958316][6969:6969] CHIP:CTL: Setting attestation nonce to random value [1655298760.958380][6969:6969] CHIP:CTL: Setting CSR nonce to random value [1655298760.958511][6969:6969] CHIP:IN: UDP::Init bind&listen port=5550 [1655298760.958671][6969:6969] CHIP:IN: UDP::Init bound to port=5550 [1655298760.958702][6969:6969] CHIP:IN: TransportMgr initialized [1655298760.958817][6969:6969] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298760.958855][6969:6969] CHIP:CTL: Setting attestation nonce to random value [1655298760.958916][6969:6969] CHIP:CTL: Setting CSR nonce to random value [1655298760.962202][6969:6969] CHIP:CTL: Generating NOC [1655298760.963211][6969:6969] CHIP:FP: Validating NOC chain [1655298760.965350][6969:6969] CHIP:FP: NOC chain validation successful [1655298760.965544][6969:6969] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655298760.965577][6969:6969] CHIP:FP: Assigned compressed fabric ID: 0xA928B8D2C6247E39, node ID: 0x000000000001B669 [1655298760.976146][6969:6969] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655298760.976200][6969:6969] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298760.976225][6969:6969] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655298760.976247][6969:6969] CHIP:TS: Retaining current Last Known Good Time [1655298760.977908][6969:6969] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0xA928B8D2C6247E39 [1655298760.977981][6969:6969] CHIP:IN: UDP::Init bind&listen port=5550 [1655298760.978106][6969:6969] CHIP:IN: UDP::Init bound to port=5550 [1655298760.978132][6969:6969] CHIP:IN: TransportMgr initialized [1655298760.978235][6969:6969] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298760.978276][6969:6969] CHIP:CTL: Setting attestation nonce to random value [1655298760.978338][6969:6969] CHIP:CTL: Setting CSR nonce to random value [1655298760.979381][6969:6969] CHIP:CTL: Generating NOC [1655298760.980358][6969:6969] CHIP:FP: Validating NOC chain [1655298760.982550][6969:6969] CHIP:FP: NOC chain validation successful [1655298760.982751][6969:6969] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655298760.982785][6969:6969] CHIP:FP: Assigned compressed fabric ID: 0x24AE67E4E4E24D4B, node ID: 0x000000000001B669 [1655298760.990469][6969:6969] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655298760.990522][6969:6969] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298760.990547][6969:6969] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655298760.990569][6969:6969] CHIP:TS: Retaining current Last Known Good Time [1655298760.992181][6969:6969] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x24AE67E4E4E24D4B [1655298760.992250][6969:6969] CHIP:IN: UDP::Init bind&listen port=5550 [1655298760.992372][6969:6969] CHIP:IN: UDP::Init bound to port=5550 [1655298760.992397][6969:6969] CHIP:IN: TransportMgr initialized [1655298760.992499][6969:6969] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298760.992539][6969:6969] CHIP:CTL: Setting attestation nonce to random value [1655298760.992600][6969:6969] CHIP:CTL: Setting CSR nonce to random value [1655298760.993424][6969:6969] CHIP:CTL: Generating NOC [1655298760.994257][6969:6969] CHIP:FP: Validating NOC chain [1655298760.996004][6969:6969] CHIP:FP: NOC chain validation successful [1655298760.996163][6969:6969] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655298760.996189][6969:6969] CHIP:FP: Assigned compressed fabric ID: 0xEEBE88FE4EF10BA6, node ID: 0x000000000001B669 [1655298761.003179][6969:6969] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655298761.003233][6969:6969] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298761.003257][6969:6969] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655298761.003279][6969:6969] CHIP:TS: Retaining current Last Known Good Time [1655298761.007936][6969:6969] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xEEBE88FE4EF10BA6 [1655298761.008011][6969:6969] CHIP:IN: UDP::Init bind&listen port=5550 [1655298761.008140][6969:6969] CHIP:IN: UDP::Init bound to port=5550 [1655298761.008166][6969:6969] CHIP:IN: TransportMgr initialized [1655298761.055584][6969:6974] CHIP:DL: CHIP task running [1655298761.055791][6969:6974] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655298761.055824][6969:6974] CHIP:TOO: Sending command to node 0x1 [1655298761.055862][6969:6974] CHIP:CSM: FindOrEstablishSession: PeerId = A928B8D2C6247E39:0000000000000001 [1655298761.055888][6969:6974] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655298761.055929][6969:6974] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 1 --> 2 [1655298761.055959][6969:6974] CHIP:DIS: Resolving A928B8D2C6247E39:0000000000000001 ... [1655298761.057730][6969:6974] CHIP:DL: Avahi resolve found [1655298761.057808][6969:6974] CHIP:DIS: Node ID resolved for A928B8D2C6247E39:0000000000000001 [1655298761.057835][6969:6974] CHIP:DIS: Hostname: E45F01312CE50000 [1655298761.057870][6969:6974] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655298761.057897][6969:6974] CHIP:DIS: Port: 5540 [1655298761.057920][6969:6974] CHIP:DIS: Mrp Interval idle: 5000 ms [1655298761.057943][6969:6974] CHIP:DIS: Mrp Interval active: 300 ms [1655298761.058189][6969:6974] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655298761.058217][6969:6974] CHIP:DIS: Checking node lookup status after 2 ms [1655298761.058239][6969:6974] CHIP:DIS: Keeping DNSSD lookup active [1655298761.256546][6969:6974] CHIP:DIS: Checking node lookup status after 201 ms [1655298761.256841][6969:6974] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655298761.256906][6969:6974] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 2 --> 3 [1655298761.257292][6969:6974] CHIP:IN: SecureSession[0xaaab0d501b50]: Allocated Type:2 LSID:49398 [1655298761.257375][6969:6974] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655298761.259051][6969:6974] CHIP:SC: Including MRP parameters [1655298761.259546][6969:6974] CHIP:IN: Prepared unauthenticated message 0xaaab0d4fcfc8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 43866i with MessageCounter:223030022. [1655298761.259649][6969:6974] CHIP:IN: Sending unauthenticated msg 0xaaab0d4fcfc8 with MessageCounter:223030022 to 0x0000000000000000 at monotonic time: 00000000020A788D msec [1655298761.259980][6969:6974] CHIP:SC: Sent Sigma1 msg [1655298761.260050][6969:6974] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 3 --> 4 [1655298761.260116][6969:6974] CHIP:DIS: Discovery does not require any more timeouts [1655298761.262289][6969:6974] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:178518573 on exchange 43866i [1655298761.262366][6969:6974] CHIP:EM: Found matching exchange: 43866i, Delegate: 0xffffac0011a0 [1655298761.262487][6969:6974] CHIP:EM: Rxd Ack; Removing MessageCounter:223030022 from Retrans Table on exchange 43866i [1655298761.262550][6969:6974] CHIP:EM: Removed CHIP MessageCounter:223030022 from RetransTable on exchange 43866i [1655298761.262622][6969:6974] CHIP:SC: Received Sigma2Resume msg [1655298761.262779][6969:6974] CHIP:SC: Found MRP parameters in the message [1655298761.262846][6969:6974] CHIP:SC: Peer assigned session session ID 34052 [1655298761.274718][6969:6974] CHIP:SC: Sending status report. Protocol code 0, exchange 43866 [1655298761.274798][6969:6974] CHIP:EM: Piggybacking Ack for MessageCounter:178518573 on exchange: 43866i [1655298761.274855][6969:6974] CHIP:IN: Prepared unauthenticated message 0xaaab0d4fcfc8 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 43866i with MessageCounter:223030023. [1655298761.274912][6969:6974] CHIP:IN: Sending unauthenticated msg 0xaaab0d4fcfc8 with MessageCounter:223030023 to 0x0000000000000000 at monotonic time: 00000000020A789C msec [1655298761.275199][6969:6974] CHIP:IN: SecureSession[0xaaab0d501b50]: Activated - Type:2 LSID:49398 [1655298761.275237][6969:6974] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:49398 PSID:34052! [1655298761.275271][6969:6974] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 4 --> 5 [1655298761.275329][6969:6974] CHIP:TOO: Sending cluster (0x00000101) command (0x0000000E) on endpoint 1 [1655298761.275511][6969:6974] CHIP:DMG: ICR moving to [AddingComm] [1655298761.275569][6969:6974] CHIP:DMG: ICR moving to [AddedComma] [1655298761.275673][6969:6974] CHIP:IN: Prepared secure message 0xaaab0d4fcfe8 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 43867i with MessageCounter:186325243. [1655298761.275721][6969:6974] CHIP:IN: Sending encrypted msg 0xaaab0d4fcfe8 with MessageCounter:186325243 to 0x0000000000000001 (1) at monotonic time: 00000000020A789D msec [1655298761.275873][6969:6974] CHIP:DMG: ICR moving to [CommandSen] [1655298761.285277][6969:6974] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:178518574 on exchange 43866i [1655298761.285322][6969:6974] CHIP:EM: Found matching exchange: 43866i, Delegate: (nil) [1655298761.285373][6969:6974] CHIP:EM: Rxd Ack; Removing MessageCounter:223030023 from Retrans Table on exchange 43866i [1655298761.285407][6969:6974] CHIP:EM: Removed CHIP MessageCounter:223030023 from RetransTable on exchange 43866i [1655298761.288508][6969:6974] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:224606854 on exchange 43867i [1655298761.288618][6969:6974] CHIP:EM: Found matching exchange: 43867i, Delegate: 0xffffac007720 [1655298761.288661][6969:6974] CHIP:EM: Rxd Ack; Removing MessageCounter:186325243 from Retrans Table on exchange 43867i [1655298761.288693][6969:6974] CHIP:EM: Removed CHIP MessageCounter:186325243 from RetransTable on exchange 43867i [1655298761.288731][6969:6974] CHIP:DMG: ICR moving to [ResponseRe] [1655298761.288793][6969:6974] CHIP:DMG: InvokeResponseMessage = [1655298761.288826][6969:6974] CHIP:DMG: { [1655298761.288858][6969:6974] CHIP:DMG: suppressResponse = false, [1655298761.288892][6969:6974] CHIP:DMG: InvokeResponseIBs = [1655298761.288933][6969:6974] CHIP:DMG: [ [1655298761.288966][6969:6974] CHIP:DMG: InvokeResponseIB = [1655298761.289017][6969:6974] CHIP:DMG: { [1655298761.289052][6969:6974] CHIP:DMG: CommandStatusIB = [1655298761.289095][6969:6974] CHIP:DMG: { [1655298761.289134][6969:6974] CHIP:DMG: CommandPathIB = [1655298761.289179][6969:6974] CHIP:DMG: { [1655298761.289225][6969:6974] CHIP:DMG: EndpointId = 0x1, [1655298761.289273][6969:6974] CHIP:DMG: ClusterId = 0x101, [1655298761.289319][6969:6974] CHIP:DMG: CommandId = 0xe, [1655298761.289364][6969:6974] CHIP:DMG: }, [1655298761.289413][6969:6974] CHIP:DMG: [1655298761.289453][6969:6974] CHIP:DMG: StatusIB = [1655298761.289504][6969:6974] CHIP:DMG: { [1655298761.289553][6969:6974] CHIP:DMG: status = 0x8b (NOT_FOUND), [1655298761.289597][6969:6974] CHIP:DMG: }, [1655298761.289646][6969:6974] CHIP:DMG: [1655298761.289686][6969:6974] CHIP:DMG: }, [1655298761.289730][6969:6974] CHIP:DMG: [1655298761.289765][6969:6974] CHIP:DMG: }, [1655298761.289805][6969:6974] CHIP:DMG: [1655298761.289837][6969:6974] CHIP:DMG: ], [1655298761.289877][6969:6974] CHIP:DMG: [1655298761.289909][6969:6974] CHIP:DMG: InteractionModelRevision = 1 [1655298761.289942][6969:6974] CHIP:DMG: }, [1655298761.290021][6969:6974] CHIP:DMG: Received Command Response Status for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_000E Status=0x8b [1655298761.290098][6969:6974] CHIP:TOO: Error: IM Error 0x0000058B: General error: 0x8b (NOT_FOUND) [1655298761.290182][6969:6974] CHIP:DMG: ICR moving to [AwaitingDe] [1655298761.290291][6969:6974] CHIP:EM: Sending Standalone Ack for MessageCounter:224606854 on exchange 43867i [1655298761.290608][6969:6974] CHIP:IN: Prepared secure message 0xffffb67cd958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 43867i with MessageCounter:186325244. [1655298761.290698][6969:6974] CHIP:IN: Sending encrypted msg 0xffffb67cd958 with MessageCounter:186325244 to 0x0000000000000001 (1) at monotonic time: 00000000020A78AC msec [1655298761.290904][6969:6974] CHIP:EM: Flushed pending ack for MessageCounter:224606854 on exchange 43867i [1655298761.291260][6969:6969] CHIP:CTL: Shutting down the commissioner [1655298761.291431][6969:6969] CHIP:CTL: Shutting down the controller [1655298761.291505][6969:6969] CHIP:CTL: Shutting down the commissioner [1655298761.291625][6969:6969] CHIP:CTL: Shutting down the controller [1655298761.291693][6969:6969] CHIP:IN: Expiring all connections for fabric 1!! [1655298761.291749][6969:6969] CHIP:IN: SecureSession[0xaaab0d501b50]: MarkForRemoval Type:2 LSID:49398 [1655298761.291806][6969:6969] CHIP:IN: SecureSession[0xaaab0d501b50]: Released - Type:2 LSID:49398 [1655298761.291900][6969:6969] CHIP:CTL: Shutting down the commissioner [1655298761.292023][6969:6969] CHIP:CTL: Shutting down the controller [1655298761.292080][6969:6969] CHIP:IN: Expiring all connections for fabric 2!! [1655298761.292162][6969:6969] CHIP:CTL: Shutting down the commissioner [1655298761.292286][6969:6969] CHIP:CTL: Shutting down the controller [1655298761.292343][6969:6969] CHIP:IN: Expiring all connections for fabric 3!! [1655298761.292417][6969:6969] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655298761.294264][6969:6969] CHIP:DMG: IM WH moving to [Uninitialized] [1655298761.294349][6969:6969] CHIP:DMG: IM WH moving to [Uninitialized] [1655298761.294399][6969:6969] CHIP:DMG: IM WH moving to [Uninitialized] [1655298761.294502][6969:6969] CHIP:DMG: IM WH moving to [Uninitialized] [1655298761.294561][6969:6969] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655298761.294707][6969:6969] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655298761.295163][6969:6969] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-8dMFcN) [1655298761.296473][6969:6969] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655298761.296602][6969:6969] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655298761.296667][6969:6969] CHIP:DL: Inet Layer shutdown [1655298761.296721][6969:6969] CHIP:DL: BLE shutdown [1655298761.296775][6969:6969] CHIP:DL: System Layer shutdown [1655298761.297003][6969:6969] CHIP:TOO: Run command failure: IM Error 0x0000058B: General error: 0x8b (NOT_FOUND) TH LOG: [1655301304.659852][5807:5807] CHIP:EM: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:268299486 on exchange 44363r [1655301304.659989][5807:5807] CHIP:EM: Handling via exchange: 44363r, Delegate: 0xaaaab38c8948 [1655301304.660089][5807:5807] CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0xaaaab38c8f60 [1655301304.660148][5807:5807] CHIP:IN: CASE Server disabling CASE session setups [1655301304.660210][5807:5807] CHIP:SC: Received Sigma1 msg [1655301304.660316][5807:5807] CHIP:SC: Found MRP parameters in the message [1655301304.660390][5807:5807] CHIP:SC: Peer assigned session key ID 29536 [1655301304.661373][5807:5807] CHIP:SC: Including MRP parameters [1655301304.661477][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:268299486 on exchange: 44363r [1655301304.661566][5807:5807] CHIP:IN: Prepared unauthenticated message 0xaaaab38cd618 to 0x0000000000000000 (0) of type 0x33 and protocolId (0, 0) on exchange 44363r with MessageCounter:178518587. [1655301304.661655][5807:5807] CHIP:IN: Sending unauthenticated msg 0xaaaab38cd618 with MessageCounter:178518587 to 0x0000000000000000 at monotonic time: 0000000002373180 msec [1655301304.662007][5807:5807] CHIP:SC: Sent Sigma2Resume msg [1655301304.669557][5807:5807] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:268299487 on exchange 44363r [1655301304.669745][5807:5807] CHIP:EM: Found matching exchange: 44363r, Delegate: 0xaaaab38c8980 [1655301304.669834][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:178518587 from Retrans Table on exchange 44363r [1655301304.669893][5807:5807] CHIP:EM: Removed CHIP MessageCounter:178518587 from RetransTable on exchange 44363r [1655301304.669977][5807:5807] CHIP:SC: Success status report received. Session was established [1655301304.671040][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-R5BD9q) [1655301304.673751][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655301304.674089][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-hwFOuQ) [1655301304.676389][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655301304.676760][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-utoWHC) [1655301304.679091][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655301304.679201][5807:5807] CHIP:IN: Expired/released previous local session ID 34058 for peer <000000000001B669, 2> [1655301304.679256][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: MarkForRemoval Type:2 LSID:34058 [1655301304.679382][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: Released - Type:2 LSID:34058 [1655301304.679516][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: Activated - Type:2 LSID:34059 [1655301304.679569][5807:5807] CHIP:IN: New secure session created for device <000000000001B669, 2>, LSID:34059 PSID:29536! [1655301304.679618][5807:5807] CHIP:IN: CASE Session established to peer: <000000000001B669, 2> [1655301304.679663][5807:5807] CHIP:IN: CASE Server enabling CASE session setups [1655301304.679803][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: Allocated Type:2 LSID:34060 [1655301304.679872][5807:5807] CHIP:SC: Allocated SecureSession (0xaaaab38c5ba0) - waiting for Sigma1 msg [1655301304.679931][5807:5807] CHIP:EM: Sending Standalone Ack for MessageCounter:268299487 on exchange 44363r [1655301304.680018][5807:5807] CHIP:IN: Prepared unauthenticated message 0xffffc670da88 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 44363r with MessageCounter:178518588. [1655301304.680098][5807:5807] CHIP:IN: Sending unauthenticated msg 0xffffc670da88 with MessageCounter:178518588 to 0x0000000000000000 at monotonic time: 0000000002373193 msec [1655301304.680329][5807:5807] CHIP:EM: Flushed pending ack for MessageCounter:268299487 on exchange 44363r [1655301304.680661][5807:5807] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:262384691 on exchange 44364r [1655301304.680738][5807:5807] CHIP:EM: Handling via exchange: 44364r, Delegate: 0xaaaab38c02b0 [1655301304.680868][5807:5807] CHIP:DMG: InvokeRequestMessage = [1655301304.680923][5807:5807] CHIP:DMG: { [1655301304.680972][5807:5807] CHIP:DMG: suppressResponse = false, [1655301304.681060][5807:5807] CHIP:DMG: timedRequest = false, [1655301304.681115][5807:5807] CHIP:DMG: InvokeRequests = [1655301304.681165][5807:5807] CHIP:DMG: [ [1655301304.681189][5807:5807] CHIP:DMG: CommandDataIB = [1655301304.681216][5807:5807] CHIP:DMG: { [1655301304.681242][5807:5807] CHIP:DMG: CommandPathIB = [1655301304.681273][5807:5807] CHIP:DMG: { [1655301304.681307][5807:5807] CHIP:DMG: EndpointId = 0x1, [1655301304.681343][5807:5807] CHIP:DMG: ClusterId = 0x101, [1655301304.681375][5807:5807] CHIP:DMG: CommandId = 0xe, [1655301304.681406][5807:5807] CHIP:DMG: }, [1655301304.681436][5807:5807] CHIP:DMG: [1655301304.681463][5807:5807] CHIP:DMG: CommandFields = [1655301304.681494][5807:5807] CHIP:DMG: { [1655301304.681526][5807:5807] CHIP:DMG: 0x0 = 1, [1655301304.681562][5807:5807] CHIP:DMG: 0x1 = 1, [1655301304.681595][5807:5807] CHIP:DMG: 0x2 = 960, [1655301304.681628][5807:5807] CHIP:DMG: 0x3 = 1980, [1655301304.681659][5807:5807] CHIP:DMG: }, [1655301304.681687][5807:5807] CHIP:DMG: }, [1655301304.681719][5807:5807] CHIP:DMG: [1655301304.681743][5807:5807] CHIP:DMG: ], [1655301304.681773][5807:5807] CHIP:DMG: [1655301304.681797][5807:5807] CHIP:DMG: InteractionModelRevision = 1 [1655301304.681820][5807:5807] CHIP:DMG: }, [1655301304.681884][5807:5807] CHIP:DMG: AccessControl: checking f=2 a=c s=0x000000000001B669 t= c=0x0000_0101 e=1 p=a [1655301304.681922][5807:5807] CHIP:DMG: AccessControl: allowed [1655301304.681949][5807:5807] CHIP:DMG: Received command for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_000E [1655301304.681990][5807:5807] CHIP:ZCL: [SetYearDaySchedule] incoming command [endpointId=1] [1655301304.682024][5807:5807] CHIP:ZCL: Lock App: LockEndpoint::GetUser [endpoint=1,userIndex=1] [1655301304.682046][5807:5807] CHIP:ZCL: Found unoccupied user [endpoint=1,adjustedIndex=0] [1655301304.682067][5807:5807] CHIP:ZCL: [SetYearDaySchedule] Unable to add schedule - user does not exist [endpointId=1,yearDayIndex=1,userIndex=1] [1655301304.682100][5807:5807] CHIP:DMG: ICR moving to [ Preparing] [1655301304.682131][5807:5807] CHIP:DMG: ICR moving to [AddingComm] [1655301304.682158][5807:5807] CHIP:DMG: ICR moving to [AddedComma] [1655301304.682196][5807:5807] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1655301304.682226][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:262384691 on exchange: 44364r [1655301304.682287][5807:5807] CHIP:IN: Prepared secure message 0xaaaab38cd618 to 0x000000000001B669 (2) of type 0x9 and protocolId (0, 1) on exchange 44364r with MessageCounter:182962022. [1655301304.682324][5807:5807] CHIP:IN: Sending encrypted msg 0xaaaab38cd618 with MessageCounter:182962022 to 0x000000000001B669 (2) at monotonic time: 0000000002373195 msec [1655301304.682488][5807:5807] CHIP:DMG: ICR moving to [CommandSen] [1655301304.682514][5807:5807] CHIP:DMG: ICR moving to [AwaitingDe] [1655301304.684187][5807:5807] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:262384692 on exchange 44364r [1655301304.684221][5807:5807] CHIP:EM: Found matching exchange: 44364r, Delegate: (nil) [1655301304.684256][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:182962022 from Retrans Table on exchange 44364r [1655301304.684280][5807:5807] CHIP:EM: Removed CHIP MessageCounter:182962022 from RetransTable on exchange 44364r DUT LOG: ubuntu@ubuntu:~/cntrl13/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool doorlock get-year-day-schedule 1 1 1 1 [1655298949.151471][6992:6992] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655298949.152024][6992:6992] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655298949.152189][6992:6992] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655298949.152303][6992:6992] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655298949.152657][6992:6992] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-d6r5XK) [1655298949.153294][6992:6992] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655298949.153346][6992:6992] CHIP:DL: NVS set: chip-counters/reboot-count = 58 (0x3A) [1655298949.154231][6992:6992] CHIP:DL: Got Ethernet interface: eth0 [1655298949.154870][6992:6992] CHIP:DL: Found the primary Ethernet interface:eth0 [1655298949.155470][6992:6992] CHIP:DL: Got WiFi interface: wlan0 [1655298949.155544][6992:6992] CHIP:DL: Failed to reset WiFi statistic counts [1655298949.155633][6992:6992] CHIP:IN: UDP::Init bind&listen port=0 [1655298949.155768][6992:6992] CHIP:IN: UDP::Init bound to port=32902 [1655298949.155794][6992:6992] CHIP:IN: BLEBase::Init - setting/overriding transport [1655298949.155815][6992:6992] CHIP:IN: TransportMgr initialized [1655298949.155850][6992:6992] CHIP:FP: Initializing FabricTable from persistent storage [1655298949.156049][6992:6992] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298949.156152][6992:6992] CHIP:FP: Loading from storage for fabric index 0x1 [1655298949.156662][6992:6992] CHIP:FP: Loading from storage for fabric index 0x2 [1655298949.157078][6992:6992] CHIP:FP: Loading from storage for fabric index 0x3 [1655298949.161339][6992:6992] CHIP:ZCL: Using ZAP configuration... [1655298949.165657][6992:6992] CHIP:DL: Avahi client registered [1655298949.167003][6992:6992] CHIP:CTL: System State Initialized... [1655298949.167106][6992:6992] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298949.167172][6992:6992] CHIP:CTL: Setting attestation nonce to random value [1655298949.167224][6992:6992] CHIP:CTL: Setting CSR nonce to random value [1655298949.167302][6992:6992] CHIP:IN: UDP::Init bind&listen port=5550 [1655298949.167441][6992:6992] CHIP:IN: UDP::Init bound to port=5550 [1655298949.167468][6992:6992] CHIP:IN: TransportMgr initialized [1655298949.167557][6992:6992] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298949.167588][6992:6992] CHIP:CTL: Setting attestation nonce to random value [1655298949.167638][6992:6992] CHIP:CTL: Setting CSR nonce to random value [1655298949.170714][6992:6992] CHIP:CTL: Generating NOC [1655298949.171626][6992:6992] CHIP:FP: Validating NOC chain [1655298949.174103][6992:6992] CHIP:FP: NOC chain validation successful [1655298949.174345][6992:6992] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655298949.174384][6992:6992] CHIP:FP: Assigned compressed fabric ID: 0xA928B8D2C6247E39, node ID: 0x000000000001B669 [1655298949.183837][6992:6992] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655298949.183898][6992:6992] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298949.183921][6992:6992] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655298949.183942][6992:6992] CHIP:TS: Retaining current Last Known Good Time [1655298949.185913][6992:6992] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0xA928B8D2C6247E39 [1655298949.186005][6992:6992] CHIP:IN: UDP::Init bind&listen port=5550 [1655298949.186142][6992:6992] CHIP:IN: UDP::Init bound to port=5550 [1655298949.186174][6992:6992] CHIP:IN: TransportMgr initialized [1655298949.186289][6992:6992] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298949.186333][6992:6992] CHIP:CTL: Setting attestation nonce to random value [1655298949.186397][6992:6992] CHIP:CTL: Setting CSR nonce to random value [1655298949.187453][6992:6992] CHIP:CTL: Generating NOC [1655298949.188377][6992:6992] CHIP:FP: Validating NOC chain [1655298949.190176][6992:6992] CHIP:FP: NOC chain validation successful [1655298949.190372][6992:6992] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655298949.190404][6992:6992] CHIP:FP: Assigned compressed fabric ID: 0x24AE67E4E4E24D4B, node ID: 0x000000000001B669 [1655298949.200567][6992:6992] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655298949.200636][6992:6992] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298949.200660][6992:6992] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655298949.200679][6992:6992] CHIP:TS: Retaining current Last Known Good Time [1655298949.202708][6992:6992] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x24AE67E4E4E24D4B [1655298949.202801][6992:6992] CHIP:IN: UDP::Init bind&listen port=5550 [1655298949.202935][6992:6992] CHIP:IN: UDP::Init bound to port=5550 [1655298949.202965][6992:6992] CHIP:IN: TransportMgr initialized [1655298949.203081][6992:6992] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655298949.203124][6992:6992] CHIP:CTL: Setting attestation nonce to random value [1655298949.203187][6992:6992] CHIP:CTL: Setting CSR nonce to random value [1655298949.204199][6992:6992] CHIP:CTL: Generating NOC [1655298949.205119][6992:6992] CHIP:FP: Validating NOC chain [1655298949.207021][6992:6992] CHIP:FP: NOC chain validation successful [1655298949.207220][6992:6992] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655298949.207252][6992:6992] CHIP:FP: Assigned compressed fabric ID: 0xEEBE88FE4EF10BA6, node ID: 0x000000000001B669 [1655298949.215085][6992:6992] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655298949.215151][6992:6992] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655298949.215176][6992:6992] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655298949.215197][6992:6992] CHIP:TS: Retaining current Last Known Good Time [1655298949.217149][6992:6992] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xEEBE88FE4EF10BA6 [1655298949.217239][6992:6992] CHIP:IN: UDP::Init bind&listen port=5550 [1655298949.217371][6992:6992] CHIP:IN: UDP::Init bound to port=5550 [1655298949.217401][6992:6992] CHIP:IN: TransportMgr initialized [1655298949.266295][6992:6997] CHIP:DL: CHIP task running [1655298949.266568][6992:6997] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655298949.266608][6992:6997] CHIP:TOO: Sending command to node 0x1 [1655298949.266646][6992:6997] CHIP:CSM: FindOrEstablishSession: PeerId = A928B8D2C6247E39:0000000000000001 [1655298949.266677][6992:6997] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655298949.266721][6992:6997] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 1 --> 2 [1655298949.266758][6992:6997] CHIP:DIS: Resolving A928B8D2C6247E39:0000000000000001 ... [1655298949.268720][6992:6997] CHIP:DL: Avahi resolve found [1655298949.268801][6992:6997] CHIP:DIS: Node ID resolved for A928B8D2C6247E39:0000000000000001 [1655298949.268831][6992:6997] CHIP:DIS: Hostname: E45F01312CE50000 [1655298949.268863][6992:6997] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655298949.268890][6992:6997] CHIP:DIS: Port: 5540 [1655298949.268915][6992:6997] CHIP:DIS: Mrp Interval idle: 5000 ms [1655298949.268941][6992:6997] CHIP:DIS: Mrp Interval active: 300 ms [1655298949.269213][6992:6997] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655298949.269246][6992:6997] CHIP:DIS: Checking node lookup status after 2 ms [1655298949.269271][6992:6997] CHIP:DIS: Keeping DNSSD lookup active [1655298949.467648][6992:6997] CHIP:DIS: Checking node lookup status after 201 ms [1655298949.467928][6992:6997] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655298949.467990][6992:6997] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 2 --> 3 [1655298949.468371][6992:6997] CHIP:IN: SecureSession[0xaaaae4555df0]: Allocated Type:2 LSID:29148 [1655298949.468452][6992:6997] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655298949.470047][6992:6997] CHIP:SC: Including MRP parameters [1655298949.470666][6992:6997] CHIP:IN: Prepared unauthenticated message 0xaaaae4554078 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 63543i with MessageCounter:123761282. [1655298949.470780][6992:6997] CHIP:IN: Sending unauthenticated msg 0xaaaae4554078 with MessageCounter:123761282 to 0x0000000000000000 at monotonic time: 00000000020D57C0 msec [1655298949.471113][6992:6997] CHIP:SC: Sent Sigma1 msg [1655298949.471182][6992:6997] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 3 --> 4 [1655298949.471249][6992:6997] CHIP:DIS: Discovery does not require any more timeouts [1655298949.472695][6992:6997] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:178518577 on exchange 63543i [1655298949.472780][6992:6997] CHIP:EM: Found matching exchange: 63543i, Delegate: 0xffff880011a0 [1655298949.472862][6992:6997] CHIP:EM: Rxd Ack; Removing MessageCounter:123761282 from Retrans Table on exchange 63543i [1655298949.472922][6992:6997] CHIP:EM: Removed CHIP MessageCounter:123761282 from RetransTable on exchange 63543i [1655298949.472995][6992:6997] CHIP:SC: Received Sigma2Resume msg [1655298949.473166][6992:6997] CHIP:SC: Found MRP parameters in the message [1655298949.473235][6992:6997] CHIP:SC: Peer assigned session session ID 34054 [1655298949.481691][6992:6997] CHIP:SC: Sending status report. Protocol code 0, exchange 63543 [1655298949.481791][6992:6997] CHIP:EM: Piggybacking Ack for MessageCounter:178518577 on exchange: 63543i [1655298949.481858][6992:6997] CHIP:IN: Prepared unauthenticated message 0xaaaae4554078 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 63543i with MessageCounter:123761283. [1655298949.481922][6992:6997] CHIP:IN: Sending unauthenticated msg 0xaaaae4554078 with MessageCounter:123761283 to 0x0000000000000000 at monotonic time: 00000000020D57CB msec [1655298949.482276][6992:6997] CHIP:IN: SecureSession[0xaaaae4555df0]: Activated - Type:2 LSID:29148 [1655298949.482328][6992:6997] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:29148 PSID:34054! [1655298949.482370][6992:6997] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 4 --> 5 [1655298949.482463][6992:6997] CHIP:TOO: Sending cluster (0x00000101) command (0x0000000F) on endpoint 1 [1655298949.482570][6992:6997] CHIP:DMG: ICR moving to [AddingComm] [1655298949.482633][6992:6997] CHIP:DMG: ICR moving to [AddedComma] [1655298949.482765][6992:6997] CHIP:IN: Prepared secure message 0xaaaae4554098 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 63544i with MessageCounter:153294564. [1655298949.482824][6992:6997] CHIP:IN: Sending encrypted msg 0xaaaae4554098 with MessageCounter:153294564 to 0x0000000000000001 (1) at monotonic time: 00000000020D57CC msec [1655298949.483027][6992:6997] CHIP:DMG: ICR moving to [CommandSen] [1655298949.488202][6992:6997] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:178518578 on exchange 63543i [1655298949.488248][6992:6997] CHIP:EM: Found matching exchange: 63543i, Delegate: (nil) [1655298949.488292][6992:6997] CHIP:EM: Rxd Ack; Removing MessageCounter:123761283 from Retrans Table on exchange 63543i [1655298949.488318][6992:6997] CHIP:EM: Removed CHIP MessageCounter:123761283 from RetransTable on exchange 63543i [1655298949.490128][6992:6997] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:168422727 on exchange 63544i [1655298949.490183][6992:6997] CHIP:EM: Found matching exchange: 63544i, Delegate: 0xaaaae4537d30 [1655298949.490222][6992:6997] CHIP:EM: Rxd Ack; Removing MessageCounter:153294564 from Retrans Table on exchange 63544i [1655298949.490247][6992:6997] CHIP:EM: Removed CHIP MessageCounter:153294564 from RetransTable on exchange 63544i [1655298949.490278][6992:6997] CHIP:DMG: ICR moving to [ResponseRe] [1655298949.490330][6992:6997] CHIP:DMG: InvokeResponseMessage = [1655298949.490356][6992:6997] CHIP:DMG: { [1655298949.490379][6992:6997] CHIP:DMG: suppressResponse = false, [1655298949.490403][6992:6997] CHIP:DMG: InvokeResponseIBs = [1655298949.490461][6992:6997] CHIP:DMG: [ [1655298949.490489][6992:6997] CHIP:DMG: InvokeResponseIB = [1655298949.490521][6992:6997] CHIP:DMG: { [1655298949.490547][6992:6997] CHIP:DMG: CommandDataIB = [1655298949.490581][6992:6997] CHIP:DMG: { [1655298949.490611][6992:6997] CHIP:DMG: CommandPathIB = [1655298949.490650][6992:6997] CHIP:DMG: { [1655298949.490688][6992:6997] CHIP:DMG: EndpointId = 0x1, [1655298949.490727][6992:6997] CHIP:DMG: ClusterId = 0x101, [1655298949.490765][6992:6997] CHIP:DMG: CommandId = 0xf, [1655298949.490801][6992:6997] CHIP:DMG: }, [1655298949.490835][6992:6997] CHIP:DMG: [1655298949.490864][6992:6997] CHIP:DMG: CommandFields = [1655298949.490897][6992:6997] CHIP:DMG: { [1655298949.490958][6992:6997] CHIP:DMG: 0x0 = 1, [1655298949.490993][6992:6997] CHIP:DMG: 0x1 = 1, [1655298949.491028][6992:6997] CHIP:DMG: 0x2 = 139, [1655298949.491061][6992:6997] CHIP:DMG: }, [1655298949.491092][6992:6997] CHIP:DMG: }, [1655298949.491125][6992:6997] CHIP:DMG: [1655298949.491150][6992:6997] CHIP:DMG: }, [1655298949.491180][6992:6997] CHIP:DMG: [1655298949.491203][6992:6997] CHIP:DMG: ], [1655298949.491234][6992:6997] CHIP:DMG: [1655298949.491258][6992:6997] CHIP:DMG: InteractionModelRevision = 1 [1655298949.491281][6992:6997] CHIP:DMG: }, [1655298949.491346][6992:6997] CHIP:DMG: Received Command Response Data, Endpoint=1 Cluster=0x0000_0101 Command=0x0000_000F [1655298949.491396][6992:6997] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0101 Command 0x0000_000F [1655298949.491454][6992:6997] CHIP:TOO: GetYearDayScheduleResponse: { [1655298949.491492][6992:6997] CHIP:TOO: yearDayIndex: 1 [1655298949.491517][6992:6997] CHIP:TOO: userIndex: 1 [1655298949.491541][6992:6997] CHIP:TOO: status: 139 [1655298949.491563][6992:6997] CHIP:TOO: } [1655298949.491602][6992:6997] CHIP:DMG: ICR moving to [AwaitingDe] [1655298949.491663][6992:6997] CHIP:EM: Sending Standalone Ack for MessageCounter:168422727 on exchange 63544i [1655298949.491743][6992:6997] CHIP:IN: Prepared secure message 0xffff8fffd958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 63544i with MessageCounter:153294565. [1655298949.491786][6992:6997] CHIP:IN: Sending encrypted msg 0xffff8fffd958 with MessageCounter:153294565 to 0x0000000000000001 (1) at monotonic time: 00000000020D57D5 msec [1655298949.491921][6992:6997] CHIP:EM: Flushed pending ack for MessageCounter:168422727 on exchange 63544i [1655298949.492130][6992:6992] CHIP:CTL: Shutting down the commissioner [1655298949.492232][6992:6992] CHIP:CTL: Shutting down the controller [1655298949.492266][6992:6992] CHIP:CTL: Shutting down the commissioner [1655298949.492318][6992:6992] CHIP:CTL: Shutting down the controller [1655298949.492350][6992:6992] CHIP:IN: Expiring all connections for fabric 1!! [1655298949.492373][6992:6992] CHIP:IN: SecureSession[0xaaaae4555df0]: MarkForRemoval Type:2 LSID:29148 [1655298949.492396][6992:6992] CHIP:IN: SecureSession[0xaaaae4555df0]: Released - Type:2 LSID:29148 [1655298949.492444][6992:6992] CHIP:CTL: Shutting down the commissioner [1655298949.492501][6992:6992] CHIP:CTL: Shutting down the controller [1655298949.492556][6992:6992] CHIP:IN: Expiring all connections for fabric 2!! [1655298949.492595][6992:6992] CHIP:CTL: Shutting down the commissioner [1655298949.492650][6992:6992] CHIP:CTL: Shutting down the controller [1655298949.492674][6992:6992] CHIP:IN: Expiring all connections for fabric 3!! [1655298949.492705][6992:6992] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655298949.493734][6992:6992] CHIP:DMG: IM WH moving to [Uninitialized] [1655298949.493825][6992:6992] CHIP:DMG: IM WH moving to [Uninitialized] [1655298949.493874][6992:6992] CHIP:DMG: IM WH moving to [Uninitialized] [1655298949.493917][6992:6992] CHIP:DMG: IM WH moving to [Uninitialized] [1655298949.493962][6992:6992] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655298949.494070][6992:6992] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655298949.494407][6992:6992] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-bJ2lYZ) [1655298949.495235][6992:6992] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655298949.495318][6992:6992] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655298949.495347][6992:6992] CHIP:DL: Inet Layer shutdown [1655298949.495370][6992:6992] CHIP:DL: BLE shutdown [1655298949.495393][6992:6992] CHIP:DL: System Layer shutdown TH LOG: [1655298949.483637][5807:5807] CHIP:EM: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:123761282 on exchange 63543r [1655298949.483720][5807:5807] CHIP:EM: Handling via exchange: 63543r, Delegate: 0xaaaab38c8948 [1655298949.483768][5807:5807] CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0xaaaab38c8f60 [1655298949.483793][5807:5807] CHIP:IN: CASE Server disabling CASE session setups [1655298949.483821][5807:5807] CHIP:SC: Received Sigma1 msg [1655298949.483877][5807:5807] CHIP:SC: Found MRP parameters in the message [1655298949.483911][5807:5807] CHIP:SC: Peer assigned session key ID 29148 [1655298949.484345][5807:5807] CHIP:SC: Including MRP parameters [1655298949.484409][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:123761282 on exchange: 63543r [1655298949.484457][5807:5807] CHIP:IN: Prepared unauthenticated message 0xaaaab38cd618 to 0x0000000000000000 (0) of type 0x33 and protocolId (0, 0) on exchange 63543r with MessageCounter:178518577. [1655298949.484498][5807:5807] CHIP:IN: Sending unauthenticated msg 0xaaaab38cd618 with MessageCounter:178518577 to 0x0000000000000000 at monotonic time: 0000000002134197 msec [1655298949.484682][5807:5807] CHIP:SC: Sent Sigma2Resume msg [1655298949.494636][5807:5807] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:123761283 on exchange 63543r [1655298949.494695][5807:5807] CHIP:EM: Found matching exchange: 63543r, Delegate: 0xaaaab38c8980 [1655298949.494742][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:178518577 from Retrans Table on exchange 63543r [1655298949.494767][5807:5807] CHIP:EM: Removed CHIP MessageCounter:178518577 from RetransTable on exchange 63543r [1655298949.494806][5807:5807] CHIP:SC: Success status report received. Session was established [1655298949.495329][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-gWwzVh) [1655298949.496593][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655298949.496842][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-BKOWNb) [1655298949.498140][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655298949.498398][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-or22lq) [1655298949.499606][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655298949.499685][5807:5807] CHIP:IN: Expired/released previous local session ID 34053 for peer <000000000001B669, 2> [1655298949.499714][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: MarkForRemoval Type:2 LSID:34053 [1655298949.499739][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: Released - Type:2 LSID:34053 [1655298949.499821][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: Activated - Type:2 LSID:34054 [1655298949.499847][5807:5807] CHIP:IN: New secure session created for device <000000000001B669, 2>, LSID:34054 PSID:29148! [1655298949.499871][5807:5807] CHIP:IN: CASE Session established to peer: <000000000001B669, 2> [1655298949.499892][5807:5807] CHIP:IN: CASE Server enabling CASE session setups [1655298949.499975][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: Allocated Type:2 LSID:34055 [1655298949.500008][5807:5807] CHIP:SC: Allocated SecureSession (0xaaaab38c5c88) - waiting for Sigma1 msg [1655298949.500041][5807:5807] CHIP:EM: Sending Standalone Ack for MessageCounter:123761283 on exchange 63543r [1655298949.500095][5807:5807] CHIP:IN: Prepared unauthenticated message 0xffffc670da88 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 63543r with MessageCounter:178518578. [1655298949.500138][5807:5807] CHIP:IN: Sending unauthenticated msg 0xffffc670da88 with MessageCounter:178518578 to 0x0000000000000000 at monotonic time: 00000000021341A7 msec [1655298949.500282][5807:5807] CHIP:EM: Flushed pending ack for MessageCounter:123761283 on exchange 63543r [1655298949.500494][5807:5807] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:153294564 on exchange 63544r [1655298949.500537][5807:5807] CHIP:EM: Handling via exchange: 63544r, Delegate: 0xaaaab38c02b0 [1655298949.500611][5807:5807] CHIP:DMG: InvokeRequestMessage = [1655298949.500638][5807:5807] CHIP:DMG: { [1655298949.500773][5807:5807] CHIP:DMG: suppressResponse = false, [1655298949.500807][5807:5807] CHIP:DMG: timedRequest = false, [1655298949.500832][5807:5807] CHIP:DMG: InvokeRequests = [1655298949.500864][5807:5807] CHIP:DMG: [ [1655298949.500890][5807:5807] CHIP:DMG: CommandDataIB = [1655298949.500918][5807:5807] CHIP:DMG: { [1655298949.500944][5807:5807] CHIP:DMG: CommandPathIB = [1655298949.500977][5807:5807] CHIP:DMG: { [1655298949.501012][5807:5807] CHIP:DMG: EndpointId = 0x1, [1655298949.501067][5807:5807] CHIP:DMG: ClusterId = 0x101, [1655298949.501105][5807:5807] CHIP:DMG: CommandId = 0xf, [1655298949.501140][5807:5807] CHIP:DMG: }, [1655298949.501180][5807:5807] CHIP:DMG: [1655298949.501209][5807:5807] CHIP:DMG: CommandFields = [1655298949.501239][5807:5807] CHIP:DMG: { [1655298949.501271][5807:5807] CHIP:DMG: 0x0 = 1, [1655298949.501304][5807:5807] CHIP:DMG: 0x1 = 1, [1655298949.501338][5807:5807] CHIP:DMG: }, [1655298949.501366][5807:5807] CHIP:DMG: }, [1655298949.501399][5807:5807] CHIP:DMG: [1655298949.501423][5807:5807] CHIP:DMG: ], [1655298949.501453][5807:5807] CHIP:DMG: [1655298949.501478][5807:5807] CHIP:DMG: InteractionModelRevision = 1 [1655298949.501501][5807:5807] CHIP:DMG: }, [1655298949.501568][5807:5807] CHIP:DMG: AccessControl: checking f=2 a=c s=0x000000000001B669 t= c=0x0000_0101 e=1 p=a [1655298949.501605][5807:5807] CHIP:DMG: AccessControl: allowed [1655298949.501632][5807:5807] CHIP:DMG: Received command for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_000F [1655298949.501673][5807:5807] CHIP:ZCL: [GetYearDaySchedule] incoming command [endpointId=1] [1655298949.501704][5807:5807] CHIP:ZCL: Lock App: LockEndpoint::GetUser [endpoint=1,userIndex=1] [1655298949.501726][5807:5807] CHIP:ZCL: Found unoccupied user [endpoint=1,adjustedIndex=0] [1655298949.501747][5807:5807] CHIP:ZCL: [GetYearDaySchedule] User does not exist [endpointId=1,yearDayIndex=1,userIndex=1] [1655298949.501784][5807:5807] CHIP:DMG: ICR moving to [ Preparing] [1655298949.501815][5807:5807] CHIP:DMG: ICR moving to [AddingComm] [1655298949.501844][5807:5807] CHIP:DMG: ICR moving to [AddedComma] [1655298949.501883][5807:5807] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1655298949.501917][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:153294564 on exchange: 63544r [1655298949.501999][5807:5807] CHIP:IN: Prepared secure message 0xaaaab38cd618 to 0x000000000001B669 (2) of type 0x9 and protocolId (0, 1) on exchange 63544r with MessageCounter:168422727. [1655298949.502039][5807:5807] CHIP:IN: Sending encrypted msg 0xaaaab38cd618 with MessageCounter:168422727 to 0x000000000001B669 (2) at monotonic time: 00000000021341A9 msec [1655298949.502233][5807:5807] CHIP:DMG: ICR moving to [CommandSen] [1655298949.502259][5807:5807] CHIP:DMG: ICR moving to [AwaitingDe] [1655298949.504395][5807:5807] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:153294565 on exchange 63544r [1655298949.504426][5807:5807] CHIP:EM: Found matching exchange: 63544r, Delegate: (nil) [1655298949.504461][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:168422727 from Retrans Table on exchange 63544r [1655298949.504485][5807:5807] CHIP:EM: Removed CHIP MessageCounter:168422727 from RetransTable on exchange 63544r DUT LOG: ubuntu@ubuntu:~/cntrl13/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool doorlock clear-year-day-schedule 1 1 1 1 [1655299032.380168][7007:7007] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1655299032.380711][7007:7007] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1655299032.380878][7007:7007] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1655299032.380990][7007:7007] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1655299032.381350][7007:7007] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-qFnQ5L) [1655299032.381992][7007:7007] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655299032.382043][7007:7007] CHIP:DL: NVS set: chip-counters/reboot-count = 59 (0x3B) [1655299032.383059][7007:7007] CHIP:DL: Got Ethernet interface: eth0 [1655299032.383750][7007:7007] CHIP:DL: Found the primary Ethernet interface:eth0 [1655299032.384343][7007:7007] CHIP:DL: Got WiFi interface: wlan0 [1655299032.384417][7007:7007] CHIP:DL: Failed to reset WiFi statistic counts [1655299032.384506][7007:7007] CHIP:IN: UDP::Init bind&listen port=0 [1655299032.384638][7007:7007] CHIP:IN: UDP::Init bound to port=36954 [1655299032.384663][7007:7007] CHIP:IN: BLEBase::Init - setting/overriding transport [1655299032.384684][7007:7007] CHIP:IN: TransportMgr initialized [1655299032.384765][7007:7007] CHIP:FP: Initializing FabricTable from persistent storage [1655299032.384966][7007:7007] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655299032.385072][7007:7007] CHIP:FP: Loading from storage for fabric index 0x1 [1655299032.385568][7007:7007] CHIP:FP: Loading from storage for fabric index 0x2 [1655299032.385988][7007:7007] CHIP:FP: Loading from storage for fabric index 0x3 [1655299032.390445][7007:7007] CHIP:ZCL: Using ZAP configuration... [1655299032.395070][7007:7007] CHIP:DL: Avahi client registered [1655299032.396382][7007:7007] CHIP:CTL: System State Initialized... [1655299032.396476][7007:7007] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655299032.396545][7007:7007] CHIP:CTL: Setting attestation nonce to random value [1655299032.396620][7007:7007] CHIP:CTL: Setting CSR nonce to random value [1655299032.396713][7007:7007] CHIP:IN: UDP::Init bind&listen port=5550 [1655299032.396896][7007:7007] CHIP:IN: UDP::Init bound to port=5550 [1655299032.396926][7007:7007] CHIP:IN: TransportMgr initialized [1655299032.397018][7007:7007] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655299032.397061][7007:7007] CHIP:CTL: Setting attestation nonce to random value [1655299032.397117][7007:7007] CHIP:CTL: Setting CSR nonce to random value [1655299032.400553][7007:7007] CHIP:CTL: Generating NOC [1655299032.401686][7007:7007] CHIP:FP: Validating NOC chain [1655299032.404317][7007:7007] CHIP:FP: NOC chain validation successful [1655299032.404568][7007:7007] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1 [1655299032.404609][7007:7007] CHIP:FP: Assigned compressed fabric ID: 0xA928B8D2C6247E39, node ID: 0x000000000001B669 [1655299032.412951][7007:7007] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage [1655299032.413006][7007:7007] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655299032.413030][7007:7007] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655299032.413052][7007:7007] CHIP:TS: Retaining current Last Known Good Time [1655299032.414757][7007:7007] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0xA928B8D2C6247E39 [1655299032.414832][7007:7007] CHIP:IN: UDP::Init bind&listen port=5550 [1655299032.414971][7007:7007] CHIP:IN: UDP::Init bound to port=5550 [1655299032.414997][7007:7007] CHIP:IN: TransportMgr initialized [1655299032.415117][7007:7007] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655299032.415156][7007:7007] CHIP:CTL: Setting attestation nonce to random value [1655299032.415218][7007:7007] CHIP:CTL: Setting CSR nonce to random value [1655299032.416088][7007:7007] CHIP:CTL: Generating NOC [1655299032.416916][7007:7007] CHIP:FP: Validating NOC chain [1655299032.418655][7007:7007] CHIP:FP: NOC chain validation successful [1655299032.418823][7007:7007] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1 [1655299032.418850][7007:7007] CHIP:FP: Assigned compressed fabric ID: 0x24AE67E4E4E24D4B, node ID: 0x000000000001B669 [1655299032.428258][7007:7007] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage [1655299032.428311][7007:7007] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655299032.428336][7007:7007] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655299032.428358][7007:7007] CHIP:TS: Retaining current Last Known Good Time [1655299032.430177][7007:7007] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x24AE67E4E4E24D4B [1655299032.430250][7007:7007] CHIP:IN: UDP::Init bind&listen port=5550 [1655299032.430379][7007:7007] CHIP:IN: UDP::Init bound to port=5550 [1655299032.430404][7007:7007] CHIP:IN: TransportMgr initialized [1655299032.430557][7007:7007] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1655299032.430695][7007:7007] CHIP:CTL: Setting attestation nonce to random value [1655299032.430784][7007:7007] CHIP:CTL: Setting CSR nonce to random value [1655299032.432083][7007:7007] CHIP:CTL: Generating NOC [1655299032.433269][7007:7007] CHIP:FP: Validating NOC chain [1655299032.435868][7007:7007] CHIP:FP: NOC chain validation successful [1655299032.436103][7007:7007] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1 [1655299032.436144][7007:7007] CHIP:FP: Assigned compressed fabric ID: 0xEEBE88FE4EF10BA6, node ID: 0x000000000001B669 [1655299032.444733][7007:7007] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage [1655299032.444787][7007:7007] CHIP:TS: Last Known Good Time: 2022-06-14T10:51:34 [1655299032.444811][7007:7007] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1655299032.444832][7007:7007] CHIP:TS: Retaining current Last Known Good Time [1655299032.446591][7007:7007] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0xEEBE88FE4EF10BA6 [1655299032.446665][7007:7007] CHIP:IN: UDP::Init bind&listen port=5550 [1655299032.446789][7007:7007] CHIP:IN: UDP::Init bound to port=5550 [1655299032.446816][7007:7007] CHIP:IN: TransportMgr initialized [1655299032.498404][7007:7012] CHIP:DL: CHIP task running [1655299032.498715][7007:7012] CHIP:DL: HandlePlatformSpecificBLEEvent 32787 [1655299032.498758][7007:7012] CHIP:TOO: Sending command to node 0x1 [1655299032.498797][7007:7012] CHIP:CSM: FindOrEstablishSession: PeerId = A928B8D2C6247E39:0000000000000001 [1655299032.498824][7007:7012] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1655299032.498864][7007:7012] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 1 --> 2 [1655299032.498894][7007:7012] CHIP:DIS: Resolving A928B8D2C6247E39:0000000000000001 ... [1655299032.500865][7007:7012] CHIP:DL: Avahi resolve found [1655299032.500956][7007:7012] CHIP:DIS: Node ID resolved for A928B8D2C6247E39:0000000000000001 [1655299032.500986][7007:7012] CHIP:DIS: Hostname: E45F01312CE50000 [1655299032.501037][7007:7012] CHIP:DIS: IP Address #1: fe80::e65f:1ff:fe31:2ce5 [1655299032.501064][7007:7012] CHIP:DIS: Port: 5540 [1655299032.501088][7007:7012] CHIP:DIS: Mrp Interval idle: 5000 ms [1655299032.501110][7007:7012] CHIP:DIS: Mrp Interval active: 300 ms [1655299032.501364][7007:7012] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3 [1655299032.501400][7007:7012] CHIP:DIS: Checking node lookup status after 2 ms [1655299032.501421][7007:7012] CHIP:DIS: Keeping DNSSD lookup active [1655299032.698926][7007:7012] CHIP:DIS: Checking node lookup status after 200 ms [1655299032.699209][7007:7012] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2 [1655299032.699271][7007:7012] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 2 --> 3 [1655299032.699659][7007:7012] CHIP:IN: SecureSession[0xaaaadaa1f800]: Allocated Type:2 LSID:33445 [1655299032.699740][7007:7012] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1655299032.701306][7007:7012] CHIP:SC: Including MRP parameters [1655299032.701829][7007:7012] CHIP:IN: Prepared unauthenticated message 0xaaaadaa1da78 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 30057i with MessageCounter:263018864. [1655299032.701933][7007:7012] CHIP:IN: Sending unauthenticated msg 0xaaaadaa1da78 with MessageCounter:263018864 to 0x0000000000000000 at monotonic time: 00000000020E9CDF msec [1655299032.702270][7007:7012] CHIP:SC: Sent Sigma1 msg [1655299032.702339][7007:7012] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 3 --> 4 [1655299032.702405][7007:7012] CHIP:DIS: Discovery does not require any more timeouts [1655299032.703939][7007:7012] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:178518579 on exchange 30057i [1655299032.704017][7007:7012] CHIP:EM: Found matching exchange: 30057i, Delegate: 0xffff940011a0 [1655299032.704096][7007:7012] CHIP:EM: Rxd Ack; Removing MessageCounter:263018864 from Retrans Table on exchange 30057i [1655299032.704154][7007:7012] CHIP:EM: Removed CHIP MessageCounter:263018864 from RetransTable on exchange 30057i [1655299032.704225][7007:7012] CHIP:SC: Received Sigma2Resume msg [1655299032.704382][7007:7012] CHIP:SC: Found MRP parameters in the message [1655299032.704448][7007:7012] CHIP:SC: Peer assigned session session ID 34055 [1655299032.714412][7007:7012] CHIP:SC: Sending status report. Protocol code 0, exchange 30057 [1655299032.714522][7007:7012] CHIP:EM: Piggybacking Ack for MessageCounter:178518579 on exchange: 30057i [1655299032.714573][7007:7012] CHIP:IN: Prepared unauthenticated message 0xaaaadaa1da78 to 0x0000000000000000 (0) of type 0x40 and protocolId (0, 0) on exchange 30057i with MessageCounter:263018865. [1655299032.714622][7007:7012] CHIP:IN: Sending unauthenticated msg 0xaaaadaa1da78 with MessageCounter:263018865 to 0x0000000000000000 at monotonic time: 00000000020E9CEC msec [1655299032.714881][7007:7012] CHIP:IN: SecureSession[0xaaaadaa1f800]: Activated - Type:2 LSID:33445 [1655299032.714914][7007:7012] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:33445 PSID:34055! [1655299032.714942][7007:7012] CHIP:CTL: OperationalDeviceProxy[A928B8D2C6247E39:0000000000000001]: State change 4 --> 5 [1655299032.714995][7007:7012] CHIP:TOO: Sending cluster (0x00000101) command (0x00000010) on endpoint 1 [1655299032.715072][7007:7012] CHIP:DMG: ICR moving to [AddingComm] [1655299032.715122][7007:7012] CHIP:DMG: ICR moving to [AddedComma] [1655299032.715212][7007:7012] CHIP:IN: Prepared secure message 0xaaaadaa1da98 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 30058i with MessageCounter:178240264. [1655299032.715254][7007:7012] CHIP:IN: Sending encrypted msg 0xaaaadaa1da98 with MessageCounter:178240264 to 0x0000000000000001 (1) at monotonic time: 00000000020E9CEC msec [1655299032.715385][7007:7012] CHIP:DMG: ICR moving to [CommandSen] [1655299032.724557][7007:7012] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:178518580 on exchange 30057i [1655299032.724600][7007:7012] CHIP:EM: Found matching exchange: 30057i, Delegate: (nil) [1655299032.724643][7007:7012] CHIP:EM: Rxd Ack; Removing MessageCounter:263018865 from Retrans Table on exchange 30057i [1655299032.724669][7007:7012] CHIP:EM: Removed CHIP MessageCounter:263018865 from RetransTable on exchange 30057i [1655299032.727212][7007:7012] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:226255281 on exchange 30058i [1655299032.727262][7007:7012] CHIP:EM: Found matching exchange: 30058i, Delegate: 0xffff94005be0 [1655299032.727311][7007:7012] CHIP:EM: Rxd Ack; Removing MessageCounter:178240264 from Retrans Table on exchange 30058i [1655299032.727350][7007:7012] CHIP:EM: Removed CHIP MessageCounter:178240264 from RetransTable on exchange 30058i [1655299032.727395][7007:7012] CHIP:DMG: ICR moving to [ResponseRe] [1655299032.727468][7007:7012] CHIP:DMG: InvokeResponseMessage = [1655299032.727508][7007:7012] CHIP:DMG: { [1655299032.727545][7007:7012] CHIP:DMG: suppressResponse = false, [1655299032.727585][7007:7012] CHIP:DMG: InvokeResponseIBs = [1655299032.727635][7007:7012] CHIP:DMG: [ [1655299032.727675][7007:7012] CHIP:DMG: InvokeResponseIB = [1655299032.727730][7007:7012] CHIP:DMG: { [1655299032.727772][7007:7012] CHIP:DMG: CommandStatusIB = [1655299032.727821][7007:7012] CHIP:DMG: { [1655299032.727868][7007:7012] CHIP:DMG: CommandPathIB = [1655299032.727921][7007:7012] CHIP:DMG: { [1655299032.727976][7007:7012] CHIP:DMG: EndpointId = 0x1, [1655299032.728031][7007:7012] CHIP:DMG: ClusterId = 0x101, [1655299032.728086][7007:7012] CHIP:DMG: CommandId = 0x10, [1655299032.728137][7007:7012] CHIP:DMG: }, [1655299032.728194][7007:7012] CHIP:DMG: [1655299032.728241][7007:7012] CHIP:DMG: StatusIB = [1655299032.728295][7007:7012] CHIP:DMG: { [1655299032.728347][7007:7012] CHIP:DMG: status = 0x8b (NOT_FOUND), [1655299032.728399][7007:7012] CHIP:DMG: }, [1655299032.728451][7007:7012] CHIP:DMG: [1655299032.728497][7007:7012] CHIP:DMG: }, [1655299032.728550][7007:7012] CHIP:DMG: [1655299032.728591][7007:7012] CHIP:DMG: }, [1655299032.728639][7007:7012] CHIP:DMG: [1655299032.728678][7007:7012] CHIP:DMG: ], [1655299032.728726][7007:7012] CHIP:DMG: [1655299032.728765][7007:7012] CHIP:DMG: InteractionModelRevision = 1 [1655299032.728803][7007:7012] CHIP:DMG: }, [1655299032.728894][7007:7012] CHIP:DMG: Received Command Response Status for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_0010 Status=0x8b [1655299032.728947][7007:7012] CHIP:TOO: Error: IM Error 0x0000058B: General error: 0x8b (NOT_FOUND) [1655299032.729004][7007:7012] CHIP:DMG: ICR moving to [AwaitingDe] [1655299032.729086][7007:7012] CHIP:EM: Sending Standalone Ack for MessageCounter:226255281 on exchange 30058i [1655299032.729176][7007:7012] CHIP:IN: Prepared secure message 0xffff9bffd958 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 30058i with MessageCounter:178240265. [1655299032.729236][7007:7012] CHIP:IN: Sending encrypted msg 0xffff9bffd958 with MessageCounter:178240265 to 0x0000000000000001 (1) at monotonic time: 00000000020E9CFA msec [1655299032.729384][7007:7012] CHIP:EM: Flushed pending ack for MessageCounter:226255281 on exchange 30058i [1655299032.729619][7007:7007] CHIP:CTL: Shutting down the commissioner [1655299032.729750][7007:7007] CHIP:CTL: Shutting down the controller [1655299032.729800][7007:7007] CHIP:CTL: Shutting down the commissioner [1655299032.729886][7007:7007] CHIP:CTL: Shutting down the controller [1655299032.729934][7007:7007] CHIP:IN: Expiring all connections for fabric 1!! [1655299032.729970][7007:7007] CHIP:IN: SecureSession[0xaaaadaa1f800]: MarkForRemoval Type:2 LSID:33445 [1655299032.730008][7007:7007] CHIP:IN: SecureSession[0xaaaadaa1f800]: Released - Type:2 LSID:33445 [1655299032.730075][7007:7007] CHIP:CTL: Shutting down the commissioner [1655299032.730162][7007:7007] CHIP:CTL: Shutting down the controller [1655299032.730200][7007:7007] CHIP:IN: Expiring all connections for fabric 2!! [1655299032.730255][7007:7007] CHIP:CTL: Shutting down the commissioner [1655299032.730339][7007:7007] CHIP:CTL: Shutting down the controller [1655299032.730377][7007:7007] CHIP:IN: Expiring all connections for fabric 3!! [1655299032.730453][7007:7007] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1655299032.731810][7007:7007] CHIP:DMG: IM WH moving to [Uninitialized] [1655299032.731871][7007:7007] CHIP:DMG: IM WH moving to [Uninitialized] [1655299032.731905][7007:7007] CHIP:DMG: IM WH moving to [Uninitialized] [1655299032.731938][7007:7007] CHIP:DMG: IM WH moving to [Uninitialized] [1655299032.731974][7007:7007] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1655299032.732077][7007:7007] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1655299032.732474][7007:7007] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-gip3ju) [1655299032.733462][7007:7007] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1655299032.733555][7007:7007] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1655299032.733599][7007:7007] CHIP:DL: Inet Layer shutdown [1655299032.733633][7007:7007] CHIP:DL: BLE shutdown [1655299032.733669][7007:7007] CHIP:DL: System Layer shutdown [1655299032.733838][7007:7007] CHIP:TOO: Run command failure: IM Error 0x0000058B: General error: 0x8b (NOT_FOUND) TH LOG: [1655299032.720811][5807:5807] CHIP:EM: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:263018864 on exchange 30057r [1655299032.720896][5807:5807] CHIP:EM: Handling via exchange: 30057r, Delegate: 0xaaaab38c8948 [1655299032.720945][5807:5807] CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0xaaaab38c8f60 [1655299032.720970][5807:5807] CHIP:IN: CASE Server disabling CASE session setups [1655299032.720999][5807:5807] CHIP:SC: Received Sigma1 msg [1655299032.721075][5807:5807] CHIP:SC: Found MRP parameters in the message [1655299032.721109][5807:5807] CHIP:SC: Peer assigned session key ID 33445 [1655299032.721558][5807:5807] CHIP:SC: Including MRP parameters [1655299032.721624][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:263018864 on exchange: 30057r [1655299032.721670][5807:5807] CHIP:IN: Prepared unauthenticated message 0xaaaab38cd618 to 0x0000000000000000 (0) of type 0x33 and protocolId (0, 0) on exchange 30057r with MessageCounter:178518579. [1655299032.721714][5807:5807] CHIP:IN: Sending unauthenticated msg 0xaaaab38cd618 with MessageCounter:178518579 to 0x0000000000000000 at monotonic time: 00000000021486BC msec [1655299032.721906][5807:5807] CHIP:SC: Sent Sigma2Resume msg [1655299032.733248][5807:5807] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:263018865 on exchange 30057r [1655299032.733303][5807:5807] CHIP:EM: Found matching exchange: 30057r, Delegate: 0xaaaab38c8980 [1655299032.733346][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:178518579 from Retrans Table on exchange 30057r [1655299032.733371][5807:5807] CHIP:EM: Removed CHIP MessageCounter:178518579 from RetransTable on exchange 30057r [1655299032.733410][5807:5807] CHIP:SC: Success status report received. Session was established [1655299032.733935][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-CrKIEQ) [1655299032.735448][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655299032.735716][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-JFfhor) [1655299032.739485][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655299032.739795][5807:5807] CHIP:DL: writing settings to file (/tmp/chip_kvs-mUZkxX) [1655299032.741585][5807:5807] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1655299032.741672][5807:5807] CHIP:IN: Expired/released previous local session ID 34054 for peer <000000000001B669, 2> [1655299032.741717][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: MarkForRemoval Type:2 LSID:34054 [1655299032.741755][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: Released - Type:2 LSID:34054 [1655299032.741865][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5c88]: Activated - Type:2 LSID:34055 [1655299032.741905][5807:5807] CHIP:IN: New secure session created for device <000000000001B669, 2>, LSID:34055 PSID:33445! [1655299032.741943][5807:5807] CHIP:IN: CASE Session established to peer: <000000000001B669, 2> [1655299032.741977][5807:5807] CHIP:IN: CASE Server enabling CASE session setups [1655299032.742094][5807:5807] CHIP:IN: SecureSession[0xaaaab38c5ba0]: Allocated Type:2 LSID:34056 [1655299032.742142][5807:5807] CHIP:SC: Allocated SecureSession (0xaaaab38c5ba0) - waiting for Sigma1 msg [1655299032.742302][5807:5807] CHIP:EM: Sending Standalone Ack for MessageCounter:263018865 on exchange 30057r [1655299032.742379][5807:5807] CHIP:IN: Prepared unauthenticated message 0xffffc670da88 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 30057r with MessageCounter:178518580. [1655299032.742442][5807:5807] CHIP:IN: Sending unauthenticated msg 0xffffc670da88 with MessageCounter:178518580 to 0x0000000000000000 at monotonic time: 00000000021486D1 msec [1655299032.742619][5807:5807] CHIP:EM: Flushed pending ack for MessageCounter:263018865 on exchange 30057r [1655299032.742900][5807:5807] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:178240264 on exchange 30058r [1655299032.742961][5807:5807] CHIP:EM: Handling via exchange: 30058r, Delegate: 0xaaaab38c02b0 [1655299032.743069][5807:5807] CHIP:DMG: InvokeRequestMessage = [1655299032.743113][5807:5807] CHIP:DMG: { [1655299032.743150][5807:5807] CHIP:DMG: suppressResponse = false, [1655299032.743300][5807:5807] CHIP:DMG: timedRequest = false, [1655299032.743345][5807:5807] CHIP:DMG: InvokeRequests = [1655299032.743397][5807:5807] CHIP:DMG: [ [1655299032.743438][5807:5807] CHIP:DMG: CommandDataIB = [1655299032.743483][5807:5807] CHIP:DMG: { [1655299032.743526][5807:5807] CHIP:DMG: CommandPathIB = [1655299032.743577][5807:5807] CHIP:DMG: { [1655299032.743631][5807:5807] CHIP:DMG: EndpointId = 0x1, [1655299032.743691][5807:5807] CHIP:DMG: ClusterId = 0x101, [1655299032.743749][5807:5807] CHIP:DMG: CommandId = 0x10, [1655299032.743803][5807:5807] CHIP:DMG: }, [1655299032.743855][5807:5807] CHIP:DMG: [1655299032.743901][5807:5807] CHIP:DMG: CommandFields = [1655299032.743950][5807:5807] CHIP:DMG: { [1655299032.744005][5807:5807] CHIP:DMG: 0x0 = 1, [1655299032.744065][5807:5807] CHIP:DMG: 0x1 = 1, [1655299032.744122][5807:5807] CHIP:DMG: }, [1655299032.744173][5807:5807] CHIP:DMG: }, [1655299032.744225][5807:5807] CHIP:DMG: [1655299032.744265][5807:5807] CHIP:DMG: ], [1655299032.744313][5807:5807] CHIP:DMG: [1655299032.744353][5807:5807] CHIP:DMG: InteractionModelRevision = 1 [1655299032.744395][5807:5807] CHIP:DMG: }, [1655299032.744491][5807:5807] CHIP:DMG: AccessControl: checking f=2 a=c s=0x000000000001B669 t= c=0x0000_0101 e=1 p=a [1655299032.744546][5807:5807] CHIP:DMG: AccessControl: allowed [1655299032.744590][5807:5807] CHIP:DMG: Received command for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_0010 [1655299032.744650][5807:5807] CHIP:ZCL: [ClearYearDaySchedule] incoming command [endpointId=1] [1655299032.744689][5807:5807] CHIP:ZCL: Lock App: LockEndpoint::GetUser [endpoint=1,userIndex=1] [1655299032.744715][5807:5807] CHIP:ZCL: Found unoccupied user [endpoint=1,adjustedIndex=0] [1655299032.744739][5807:5807] CHIP:ZCL: [ClearYearDaySchedule] User does not exist [endpointId=1,yearDayIndex=1,userIndex=1] [1655299032.744833][5807:5807] CHIP:DMG: ICR moving to [ Preparing] [1655299032.744870][5807:5807] CHIP:DMG: ICR moving to [AddingComm] [1655299032.744901][5807:5807] CHIP:DMG: ICR moving to [AddedComma] [1655299032.744943][5807:5807] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0 [1655299032.744979][5807:5807] CHIP:EM: Piggybacking Ack for MessageCounter:178240264 on exchange: 30058r [1655299032.745074][5807:5807] CHIP:IN: Prepared secure message 0xaaaab38cd618 to 0x000000000001B669 (2) of type 0x9 and protocolId (0, 1) on exchange 30058r with MessageCounter:226255281. [1655299032.745118][5807:5807] CHIP:IN: Sending encrypted msg 0xaaaab38cd618 with MessageCounter:226255281 to 0x000000000001B669 (2) at monotonic time: 00000000021486D4 msec [1655299032.745293][5807:5807] CHIP:DMG: ICR moving to [CommandSen] [1655299032.745324][5807:5807] CHIP:DMG: ICR moving to [AwaitingDe] [1655299032.747820][5807:5807] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:178240265 on exchange 30058r [1655299032.747854][5807:5807] CHIP:EM: Found matching exchange: 30058r, Delegate: (nil) [1655299032.747894][5807:5807] CHIP:EM: Rxd Ack; Removing MessageCounter:226255281 from Retrans Table on exchange 30058r [1655299032.747921][5807:5807] CHIP:EM: Removed CHIP MessageCounter:226255281 from RetransTable on exchange 30058r