[1698370274.963999][149323:149325] CHIP:TOO: Discovered Device: fe80::e65f:1ff:feaf:e2f3:5540 [1698370274.964082][149323:149325] CHIP:IN: SecureSession[0x7ff8d4002db0]: Allocated Type:1 LSID:49873 [1698370274.964089][149323:149325] CHIP:SC: Assigned local session key ID 49873 [1698370274.964113][149323:149325] CHIP:EM: <<< [E:2648i S:0 M:89764267] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [1698370274.964156][149323:149325] CHIP:IN: (U) Sending msg 89764267 to IP address 'UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540' [1698370274.964216][149323:149325] CHIP:SC: Sent PBKDF param request [1698370274.964237][149323:149325] CHIP:CTL: Commission called for node ID 0x0000000000000001 [1698370274.964240][149323:149325] CHIP:CTL: Unknown filter type; all matches will fail [1698370274.976785][149323:149325] CHIP:EM: >>> [E:2648i S:0 M:138288965 (Ack:89764267)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [1698370274.976812][149323:149325] CHIP:EM: Found matching exchange: 2648i, Delegate: 0x7ff8d4002210 [1698370274.976820][149323:149325] CHIP:EM: Rxd Ack; Removing MessageCounter:89764267 from Retrans Table on exchange 2648i [1698370274.976829][149323:149325] CHIP:SC: Received PBKDF param response [1698370274.976862][149323:149325] CHIP:SC: Peer assigned session ID 36347 [1698370274.978607][149323:149325] CHIP:EM: <<< [E:2648i S:0 M:89764268 (Ack:138288965)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) [1698370274.978678][149323:149325] CHIP:IN: (U) Sending msg 89764268 to IP address 'UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540' [1698370274.978731][149323:149325] CHIP:SC: Sent spake2p msg1 [1698370274.981337][149323:149325] CHIP:EM: >>> [E:2648i S:0 M:138288966 (Ack:89764268)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [1698370274.981383][149323:149325] CHIP:EM: Found matching exchange: 2648i, Delegate: 0x7ff8d4002210 [1698370274.981406][149323:149325] CHIP:EM: Rxd Ack; Removing MessageCounter:89764268 from Retrans Table on exchange 2648i [1698370274.981419][149323:149325] CHIP:SC: Received spake2p msg2 [1698370274.981820][149323:149325] CHIP:EM: <<< [E:2648i S:0 M:89764269 (Ack:138288966)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) [1698370274.981930][149323:149325] CHIP:IN: (U) Sending msg 89764269 to IP address 'UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540' [1698370274.982027][149323:149325] CHIP:SC: Sent spake2p msg3 [1698370274.982836][149323:149325] CHIP:EM: >>> [E:2648i S:0 M:138288967 (Ack:89764269)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1698370274.982861][149323:149325] CHIP:EM: Found matching exchange: 2648i, Delegate: 0x7ff8d4002210 [1698370274.982891][149323:149325] CHIP:EM: Rxd Ack; Removing MessageCounter:89764269 from Retrans Table on exchange 2648i [1698370274.982970][149323:149325] CHIP:SC: SecureSession[0x7ff8d4002db0, LSID:49873]: State change 'kEstablishing' --> 'kActive' [1698370274.982978][149323:149325] CHIP:IN: SecureSession[0x7ff8d4002db0]: Activated - Type:1 LSID:49873 [1698370274.982981][149323:149325] CHIP:IN: New secure session activated for device , LSID:49873 PSID:36347! [1698370274.982988][149323:149325] CHIP:CTL: Remote device completed SPAKE2+ handshake [1698370274.982991][149323:149325] CHIP:CTL: PASE is established [1698370274.982996][149323:149325] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1698370274.983052][149323:149325] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1698370274.983064][149323:149325] CHIP:CTL: Sending request for commissioning information [1698370274.983079][149323:149325] CHIP:DMG: SendReadRequest ReadClient[0x7ff8d4005b00]: Sending Read Request [1698370274.983149][149323:149325] CHIP:EM: <<< [E:2649i S:49873 M:139577582] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) [1698370274.983161][149323:149325] CHIP:IN: (S) Sending msg 139577582 on secure session with LSID: 49873 [1698370274.983229][149323:149325] CHIP:DMG: MoveToState ReadClient[0x7ff8d4005b00]: Moving to [AwaitingIn] [1698370274.983246][149323:149325] CHIP:EM: <<< [E:2648i S:0 M:89764270 (Ack:138288967)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698370274.983350][149323:149325] CHIP:IN: (U) Sending msg 89764270 to IP address 'UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540' [1698370274.983383][149323:149325] CHIP:EM: Flushed pending ack for MessageCounter:138288967 on exchange 2648i [1698370275.389240][149323:149325] CHIP:EM: Retransmitting MessageCounter:139577582 on exchange 2649i Send Cnt 1 [1698370275.389322][149323:149325] CHIP:IN: (S) Sending msg 139577582 on secure session with LSID: 49873 [1698370275.389451][149323:149325] CHIP:EM: >>> [E:2649i S:49873 M:266755328 (Ack:139577582)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698370275.389462][149323:149325] CHIP:EM: Found matching exchange: 2649i, Delegate: 0x7ff8d4005b10 [1698370275.389469][149323:149325] CHIP:EM: Rxd Ack; Removing MessageCounter:139577582 from Retrans Table on exchange 2649i [1698370275.389547][149323:149325] CHIP:IN: Received a duplicate message with MessageCounter:138288967 on exchange 2648i [1698370275.389557][149323:149325] CHIP:EM: >>> [E:2648i S:0 M:138288967 (Ack:89764269)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1698370275.389566][149323:149325] CHIP:EM: Generating StandaloneAck via exchange: 2648i [1698370275.389569][149323:149325] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:138288967 on exchange 2648i [1698370275.389585][149323:149325] CHIP:EM: <<< [E:2648i S:0 M:89764271 (Ack:138288967)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698370275.389638][149323:149325] CHIP:IN: (U) Sending msg 89764271 to IP address 'UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540' [1698370275.731132][149323:149325] CHIP:EM: >>> [E:2649i S:49873 M:266755329 (Ack:139577582)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1698370275.731180][149323:149325] CHIP:EM: Found matching exchange: 2649i, Delegate: 0x7ff8d4005b10 [1698370275.731191][149323:149325] CHIP:EM: CHIP MessageCounter:139577582 not in RetransTable on exchange 2649i [1698370275.731225][149323:149325] CHIP:DMG: ReportDataMessage = [1698370275.731231][149323:149325] CHIP:DMG: { [1698370275.731233][149323:149325] CHIP:DMG: AttributeReportIBs = [1698370275.731237][149323:149325] CHIP:DMG: [ [1698370275.731242][149323:149325] CHIP:DMG: AttributeReportIB = [1698370275.731246][149323:149325] CHIP:DMG: { [1698370275.731249][149323:149325] CHIP:DMG: AttributeDataIB = [1698370275.731254][149323:149325] CHIP:DMG: { [1698370275.731258][149323:149325] CHIP:DMG: DataVersion = 0x6efc8e1b, [1698370275.731263][149323:149325] CHIP:DMG: AttributePathIB = [1698370275.731269][149323:149325] CHIP:DMG: { [1698370275.731272][149323:149325] CHIP:DMG: Endpoint = 0x0, [1698370275.731280][149323:149325] CHIP:DMG: Cluster = 0x31, [1698370275.731284][149323:149325] CHIP:DMG: Attribute = 0x0000_0003, [1698370275.731292][149323:149325] CHIP:DMG: } [1698370275.731299][149323:149325] CHIP:DMG: [1698370275.731306][149323:149325] CHIP:DMG: Data = 0, [1698370275.731309][149323:149325] CHIP:DMG: }, [1698370275.731316][149323:149325] CHIP:DMG: [1698370275.731320][149323:149325] CHIP:DMG: }, [1698370275.731327][149323:149325] CHIP:DMG: [1698370275.731332][149323:149325] CHIP:DMG: AttributeReportIB = [1698370275.731337][149323:149325] CHIP:DMG: { [1698370275.731339][149323:149325] CHIP:DMG: AttributeDataIB = [1698370275.731342][149323:149325] CHIP:DMG: { [1698370275.731347][149323:149325] CHIP:DMG: DataVersion = 0xa67f901d, [1698370275.731350][149323:149325] CHIP:DMG: AttributePathIB = [1698370275.731353][149323:149325] CHIP:DMG: { [1698370275.731358][149323:149325] CHIP:DMG: Endpoint = 0x0, [1698370275.731361][149323:149325] CHIP:DMG: Cluster = 0x28, [1698370275.731369][149323:149325] CHIP:DMG: Attribute = 0x0000_0004, [1698370275.731372][149323:149325] CHIP:DMG: } [1698370275.731375][149323:149325] CHIP:DMG: [1698370275.731380][149323:149325] CHIP:DMG: Data = 32769, [1698370275.731383][149323:149325] CHIP:DMG: }, [1698370275.731386][149323:149325] CHIP:DMG: [1698370275.731391][149323:149325] CHIP:DMG: }, [1698370275.731396][149323:149325] CHIP:DMG: [1698370275.731400][149323:149325] CHIP:DMG: AttributeReportIB = [1698370275.731406][149323:149325] CHIP:DMG: { [1698370275.731408][149323:149325] CHIP:DMG: AttributeDataIB = [1698370275.731414][149323:149325] CHIP:DMG: { [1698370275.731419][149323:149325] CHIP:DMG: DataVersion = 0xa67f901d, [1698370275.731424][149323:149325] CHIP:DMG: AttributePathIB = [1698370275.731430][149323:149325] CHIP:DMG: { [1698370275.731435][149323:149325] CHIP:DMG: Endpoint = 0x0, [1698370275.731438][149323:149325] CHIP:DMG: Cluster = 0x28, [1698370275.731446][149323:149325] CHIP:DMG: Attribute = 0x0000_0002, [1698370275.731449][149323:149325] CHIP:DMG: } [1698370275.731455][149323:149325] CHIP:DMG: [1698370275.731460][149323:149325] CHIP:DMG: Data = 65521, [1698370275.731465][149323:149325] CHIP:DMG: }, [1698370275.731469][149323:149325] CHIP:DMG: [1698370275.731476][149323:149325] CHIP:DMG: }, [1698370275.731481][149323:149325] CHIP:DMG: [1698370275.731485][149323:149325] CHIP:DMG: AttributeReportIB = [1698370275.731491][149323:149325] CHIP:DMG: { [1698370275.731493][149323:149325] CHIP:DMG: AttributeDataIB = [1698370275.731498][149323:149325] CHIP:DMG: { [1698370275.731503][149323:149325] CHIP:DMG: DataVersion = 0xdc92b85, [1698370275.731506][149323:149325] CHIP:DMG: AttributePathIB = [1698370275.731512][149323:149325] CHIP:DMG: { [1698370275.731514][149323:149325] CHIP:DMG: Endpoint = 0x0, [1698370275.731518][149323:149325] CHIP:DMG: Cluster = 0x30, [1698370275.731526][149323:149325] CHIP:DMG: Attribute = 0x0000_0003, [1698370275.731529][149323:149325] CHIP:DMG: } [1698370275.731535][149323:149325] CHIP:DMG: [1698370275.731538][149323:149325] CHIP:DMG: Data = 2, [1698370275.731543][149323:149325] CHIP:DMG: }, [1698370275.731549][149323:149325] CHIP:DMG: [1698370275.731551][149323:149325] CHIP:DMG: }, [1698370275.731557][149323:149325] CHIP:DMG: [1698370275.731562][149323:149325] CHIP:DMG: AttributeReportIB = [1698370275.731568][149323:149325] CHIP:DMG: { [1698370275.731570][149323:149325] CHIP:DMG: AttributeDataIB = [1698370275.731576][149323:149325] CHIP:DMG: { [1698370275.731581][149323:149325] CHIP:DMG: DataVersion = 0xdc92b85, [1698370275.731586][149323:149325] CHIP:DMG: AttributePathIB = [1698370275.731592][149323:149325] CHIP:DMG: { [1698370275.731597][149323:149325] CHIP:DMG: Endpoint = 0x0, [1698370275.731603][149323:149325] CHIP:DMG: Cluster = 0x30, [1698370275.731608][149323:149325] CHIP:DMG: Attribute = 0x0000_0002, [1698370275.731612][149323:149325] CHIP:DMG: } [1698370275.731620][149323:149325] CHIP:DMG: [1698370275.731623][149323:149325] CHIP:DMG: Data = 0, [1698370275.731631][149323:149325] CHIP:DMG: }, [1698370275.731634][149323:149325] CHIP:DMG: [1698370275.731639][149323:149325] CHIP:DMG: }, [1698370275.731646][149323:149325] CHIP:DMG: [1698370275.731650][149323:149325] CHIP:DMG: AttributeReportIB = [1698370275.731656][149323:149325] CHIP:DMG: { [1698370275.731661][149323:149325] CHIP:DMG: AttributeDataIB = [1698370275.731666][149323:149325] CHIP:DMG: { [1698370275.731669][149323:149325] CHIP:DMG: DataVersion = 0xdc92b85, [1698370275.731675][149323:149325] CHIP:DMG: AttributePathIB = [1698370275.731680][149323:149325] CHIP:DMG: { [1698370275.731685][149323:149325] CHIP:DMG: Endpoint = 0x0, [1698370275.731690][149323:149325] CHIP:DMG: Cluster = 0x30, [1698370275.731695][149323:149325] CHIP:DMG: Attribute = 0x0000_0001, [1698370275.731701][149323:149325] CHIP:DMG: } [1698370275.731706][149323:149325] CHIP:DMG: [1698370275.731711][149323:149325] CHIP:DMG: Data = [1698370275.731717][149323:149325] CHIP:DMG: { [1698370275.731737][149323:149325] CHIP:DMG: 0x0 = 60, [1698370275.731740][149323:149325] CHIP:DMG: 0x1 = 900, [1698370275.731743][149323:149325] CHIP:DMG: }, [1698370275.731747][149323:149325] CHIP:DMG: }, [1698370275.731750][149323:149325] CHIP:DMG: [1698370275.731753][149323:149325] CHIP:DMG: }, [1698370275.731757][149323:149325] CHIP:DMG: [1698370275.731759][149323:149325] CHIP:DMG: AttributeReportIB = [1698370275.731765][149323:149325] CHIP:DMG: { [1698370275.731767][149323:149325] CHIP:DMG: AttributeDataIB = [1698370275.731770][149323:149325] CHIP:DMG: { [1698370275.731775][149323:149325] CHIP:DMG: DataVersion = 0xdc92b85, [1698370275.731778][149323:149325] CHIP:DMG: AttributePathIB = [1698370275.731781][149323:149325] CHIP:DMG: { [1698370275.731784][149323:149325] CHIP:DMG: Endpoint = 0x0, [1698370275.731789][149323:149325] CHIP:DMG: Cluster = 0x30, [1698370275.731792][149323:149325] CHIP:DMG: Attribute = 0x0000_0000, [1698370275.731795][149323:149325] CHIP:DMG: } [1698370275.731802][149323:149325] CHIP:DMG: [1698370275.731805][149323:149325] CHIP:DMG: Data = 0, [1698370275.731812][149323:149325] CHIP:DMG: }, [1698370275.731827][149323:149325] CHIP:DMG: [1698370275.731829][149323:149325] CHIP:DMG: }, [1698370275.731833][149323:149325] CHIP:DMG: [1698370275.731838][149323:149325] CHIP:DMG: AttributeReportIB = [1698370275.731841][149323:149325] CHIP:DMG: { [1698370275.731844][149323:149325] CHIP:DMG: AttributeDataIB = [1698370275.731851][149323:149325] CHIP:DMG: { [1698370275.731854][149323:149325] CHIP:DMG: DataVersion = 0x6efc8e1b, [1698370275.731856][149323:149325] CHIP:DMG: AttributePathIB = [1698370275.731864][149323:149325] CHIP:DMG: { [1698370275.731866][149323:149325] CHIP:DMG: Endpoint = 0x0, [1698370275.731871][149323:149325] CHIP:DMG: Cluster = 0x31, [1698370275.731876][149323:149325] CHIP:DMG: Attribute = 0x0000_FFFC, [1698370275.731879][149323:149325] CHIP:DMG: } [1698370275.731882][149323:149325] CHIP:DMG: [1698370275.731888][149323:149325] CHIP:DMG: Data = 4, [1698370275.731893][149323:149325] CHIP:DMG: }, [1698370275.731896][149323:149325] CHIP:DMG: [1698370275.731901][149323:149325] CHIP:DMG: }, [1698370275.731907][149323:149325] CHIP:DMG: [1698370275.731909][149323:149325] CHIP:DMG: ], [1698370275.731920][149323:149325] CHIP:DMG: [1698370275.731925][149323:149325] CHIP:DMG: SuppressResponse = true, [1698370275.731927][149323:149325] CHIP:DMG: InteractionModelRevision = 1 [1698370275.731929][149323:149325] CHIP:DMG: } [1698370275.732095][149323:149325] CHIP:CTL: ----- NetworkCommissioning Features: has Ethernet. endpointid = 0 [1698370275.732130][149323:149325] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='ReadCommissioningInfo' error='src/controller/CHIPDeviceController.cpp:1879: Success' [1698370275.732136][149323:149325] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1698370275.732141][149323:149325] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe' [1698370275.732150][149323:149325] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1698370275.732154][149323:149325] CHIP:CTL: Arming failsafe (60 seconds) [1698370275.732169][149323:149325] CHIP:DMG: ICR moving to [AddingComm] [1698370275.732175][149323:149325] CHIP:DMG: ICR moving to [AddedComma] [1698370275.732196][149323:149325] CHIP:EM: <<< [E:2650i S:49873 M:139577583] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1698370275.732206][149323:149325] CHIP:IN: (S) Sending msg 139577583 on secure session with LSID: 49873 [1698370275.732269][149323:149325] CHIP:DMG: ICR moving to [CommandSen] [1698370275.732297][149323:149325] CHIP:EM: <<< [E:2649i S:49873 M:139577584 (Ack:266755329)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698370275.732301][149323:149325] CHIP:IN: (S) Sending msg 139577584 on secure session with LSID: 49873 [1698370275.732319][149323:149325] CHIP:EM: Flushed pending ack for MessageCounter:266755329 on exchange 2649i [1698370276.086069][149323:149325] CHIP:EM: Retransmitting MessageCounter:139577583 on exchange 2650i Send Cnt 1 [1698370276.086131][149323:149325] CHIP:IN: (S) Sending msg 139577583 on secure session with LSID: 49873 [1698370276.086290][149323:149325] CHIP:EM: >>> [E:2649i S:49873 M:266755330 (Ack:139577582)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698370276.086313][149323:149325] CHIP:EM: OnMessageReceived failed, err = src/messaging/ExchangeMgr.cpp:304: CHIP Error 0x00000070: Unsolicited msg with originator bit clear [1698370276.439282][149323:149325] CHIP:EM: >>> [E:2650i S:49873 M:266755331 (Ack:139577583)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1698370276.439308][149323:149325] CHIP:EM: Found matching exchange: 2650i, Delegate: 0x7ff8d4001db8 [1698370276.439316][149323:149325] CHIP:EM: Rxd Ack; Removing MessageCounter:139577583 from Retrans Table on exchange 2650i [1698370276.439328][149323:149325] CHIP:DMG: ICR moving to [ResponseRe] [1698370276.439342][149323:149325] CHIP:DMG: InvokeResponseMessage = [1698370276.439347][149323:149325] CHIP:DMG: { [1698370276.439349][149323:149325] CHIP:DMG: suppressResponse = false, [1698370276.439354][149323:149325] CHIP:DMG: InvokeResponseIBs = [1698370276.439358][149323:149325] CHIP:DMG: [ [1698370276.439360][149323:149325] CHIP:DMG: InvokeResponseIB = [1698370276.439364][149323:149325] CHIP:DMG: { [1698370276.439368][149323:149325] CHIP:DMG: CommandDataIB = [1698370276.439372][149323:149325] CHIP:DMG: { [1698370276.439374][149323:149325] CHIP:DMG: CommandPathIB = [1698370276.439378][149323:149325] CHIP:DMG: { [1698370276.439385][149323:149325] CHIP:DMG: EndpointId = 0x0, [1698370276.439388][149323:149325] CHIP:DMG: ClusterId = 0x30, [1698370276.439391][149323:149325] CHIP:DMG: CommandId = 0x1, [1698370276.439397][149323:149325] CHIP:DMG: }, [1698370276.439402][149323:149325] CHIP:DMG: [1698370276.439405][149323:149325] CHIP:DMG: CommandFields = [1698370276.439408][149323:149325] CHIP:DMG: { [1698370276.439411][149323:149325] CHIP:DMG: 0x0 = 0, [1698370276.439419][149323:149325] CHIP:DMG: 0x1 = "" (0 chars), [1698370276.439422][149323:149325] CHIP:DMG: }, [1698370276.439424][149323:149325] CHIP:DMG: }, [1698370276.439428][149323:149325] CHIP:DMG: [1698370276.439430][149323:149325] CHIP:DMG: }, [1698370276.439433][149323:149325] CHIP:DMG: [1698370276.439437][149323:149325] CHIP:DMG: ], [1698370276.439441][149323:149325] CHIP:DMG: [1698370276.439443][149323:149325] CHIP:DMG: InteractionModelRevision = 1 [1698370276.439445][149323:149325] CHIP:DMG: }, [1698370276.439455][149323:149325] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1698370276.439464][149323:149325] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1698370276.439471][149323:149325] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='ArmFailSafe' error='src/controller/CHIPDeviceController.cpp:2169: Success' [1698370276.439475][149323:149325] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1698370276.439477][149323:149325] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1698370276.439484][149323:149325] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1698370276.439488][149323:149325] CHIP:CTL: Setting Regulatory Config [1698370276.439490][149323:149325] CHIP:CTL: No regulatory config supplied by controller, leaving as device default (0) [1698370276.439505][149323:149325] CHIP:DMG: ICR moving to [AddingComm] [1698370276.439512][149323:149325] CHIP:DMG: ICR moving to [AddedComma] [1698370276.439528][149323:149325] CHIP:EM: <<< [E:2651i S:49873 M:139577585] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1698370276.439535][149323:149325] CHIP:IN: (S) Sending msg 139577585 on secure session with LSID: 49873 [1698370276.439625][149323:149325] CHIP:DMG: ICR moving to [CommandSen] [1698370276.439637][149323:149325] CHIP:DMG: ICR moving to [AwaitingDe] [1698370276.439646][149323:149325] CHIP:EM: <<< [E:2650i S:49873 M:139577586 (Ack:266755331)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698370276.439654][149323:149325] CHIP:IN: (S) Sending msg 139577586 on secure session with LSID: 49873 [1698370276.439699][149323:149325] CHIP:EM: Flushed pending ack for MessageCounter:266755331 on exchange 2650i [1698370276.441109][149323:149325] CHIP:IN: Received a duplicate message with MessageCounter:266755329 on exchange 2649i [1698370276.441132][149323:149325] CHIP:EM: >>> [E:2649i S:49873 M:266755329 (Ack:139577582)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1698370276.441140][149323:149325] CHIP:EM: Generating StandaloneAck via exchange: 2649i [1698370276.441143][149323:149325] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:266755329 on exchange 2649i [1698370276.441172][149323:149325] CHIP:EM: <<< [E:2649i S:49873 M:139577587 (Ack:266755329)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698370276.441186][149323:149325] CHIP:IN: (S) Sending msg 139577587 on secure session with LSID: 49873 [1698370276.444038][149323:149325] CHIP:EM: >>> [E:2650i S:49873 M:266755332 (Ack:139577583)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698370276.444062][149323:149325] CHIP:EM: OnMessageReceived failed, err = src/messaging/ExchangeMgr.cpp:304: CHIP Error 0x00000070: Unsolicited msg with originator bit clear [1698370276.452589][149323:149325] CHIP:EM: >>> [E:2651i S:49873 M:266755333 (Ack:139577585)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1698370276.452619][149323:149325] CHIP:EM: Found matching exchange: 2651i, Delegate: 0x7ff8d4006af8 [1698370276.452629][149323:149325] CHIP:EM: Rxd Ack; Removing MessageCounter:139577585 from Retrans Table on exchange 2651i [1698370276.452638][149323:149325] CHIP:DMG: ICR moving to [ResponseRe] [1698370276.452654][149323:149325] CHIP:DMG: InvokeResponseMessage = [1698370276.452662][149323:149325] CHIP:DMG: { [1698370276.452668][149323:149325] CHIP:DMG: suppressResponse = false, [1698370276.452672][149323:149325] CHIP:DMG: InvokeResponseIBs = [1698370276.452678][149323:149325] CHIP:DMG: [ [1698370276.452681][149323:149325] CHIP:DMG: InvokeResponseIB = [1698370276.452691][149323:149325] CHIP:DMG: { [1698370276.452700][149323:149325] CHIP:DMG: CommandDataIB = [1698370276.452705][149323:149325] CHIP:DMG: { [1698370276.452712][149323:149325] CHIP:DMG: CommandPathIB = [1698370276.452717][149323:149325] CHIP:DMG: { [1698370276.452724][149323:149325] CHIP:DMG: EndpointId = 0x0, [1698370276.452729][149323:149325] CHIP:DMG: ClusterId = 0x30, [1698370276.452736][149323:149325] CHIP:DMG: CommandId = 0x3, [1698370276.452740][149323:149325] CHIP:DMG: }, [1698370276.452748][149323:149325] CHIP:DMG: [1698370276.452752][149323:149325] CHIP:DMG: CommandFields = [1698370276.452759][149323:149325] CHIP:DMG: { [1698370276.452764][149323:149325] CHIP:DMG: 0x0 = 0, [1698370276.452772][149323:149325] CHIP:DMG: 0x1 = "" (0 chars), [1698370276.452776][149323:149325] CHIP:DMG: }, [1698370276.452782][149323:149325] CHIP:DMG: }, [1698370276.452787][149323:149325] CHIP:DMG: [1698370276.452793][149323:149325] CHIP:DMG: }, [1698370276.452799][149323:149325] CHIP:DMG: [1698370276.452804][149323:149325] CHIP:DMG: ], [1698370276.452810][149323:149325] CHIP:DMG: [1698370276.452813][149323:149325] CHIP:DMG: InteractionModelRevision = 1 [1698370276.452816][149323:149325] CHIP:DMG: }, [1698370276.452832][149323:149325] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1698370276.452844][149323:149325] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0 [1698370276.452857][149323:149325] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='ConfigRegulatory' error='src/controller/CHIPDeviceController.cpp:2186: Success' [1698370276.452865][149323:149325] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1698370276.452868][149323:149325] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1698370276.452879][149323:149325] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1698370276.452885][149323:149325] CHIP:CTL: Sending request for PAI certificate [1698370276.452908][149323:149325] CHIP:CTL: Sending Certificate Chain request to 0x7ff8d40021c0 device [1698370276.452944][149323:149325] CHIP:DMG: ICR moving to [AddingComm] [1698370276.452954][149323:149325] CHIP:DMG: ICR moving to [AddedComma] [1698370276.452993][149323:149325] CHIP:EM: <<< [E:2652i S:49873 M:139577588] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1698370276.453003][149323:149325] CHIP:IN: (S) Sending msg 139577588 on secure session with LSID: 49873 [1698370276.453083][149323:149325] CHIP:DMG: ICR moving to [CommandSen] [1698370276.453104][149323:149325] CHIP:DMG: ICR moving to [AwaitingDe] [1698370276.453123][149323:149325] CHIP:EM: <<< [E:2651i S:49873 M:139577589 (Ack:266755333)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698370276.453132][149323:149325] CHIP:IN: (S) Sending msg 139577589 on secure session with LSID: 49873 [1698370276.453153][149323:149325] CHIP:EM: Flushed pending ack for MessageCounter:266755333 on exchange 2651i [1698370276.819754][149323:149325] CHIP:EM: Retransmitting MessageCounter:139577588 on exchange 2652i Send Cnt 1 [1698370276.819835][149323:149325] CHIP:IN: (S) Sending msg 139577588 on secure session with LSID: 49873 [1698370277.169520][149323:149325] CHIP:EM: Retransmitting MessageCounter:139577588 on exchange 2652i Send Cnt 2 [1698370277.169571][149323:149325] CHIP:IN: (S) Sending msg 139577588 on secure session with LSID: 49873 [1698370277.737317][149323:149325] CHIP:EM: Retransmitting MessageCounter:139577588 on exchange 2652i Send Cnt 3 [1698370277.737404][149323:149325] CHIP:IN: (S) Sending msg 139577588 on secure session with LSID: 49873 [1698370278.670583][149323:149325] CHIP:EM: Retransmitting MessageCounter:139577588 on exchange 2652i Send Cnt 4 [1698370278.670647][149323:149325] CHIP:IN: (S) Sending msg 139577588 on secure session with LSID: 49873 [1698370280.253995][149323:149325] CHIP:EM: Failed to Send CHIP MessageCounter:139577588 on exchange 2652i sendCount: 4 max retries: 4 [1698370306.475282][149323:149325] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 2652i [1698370306.475337][149323:149325] CHIP:CTL: Device failed to receive the Certificate Chain request Response: src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout [1698370306.475347][149323:149325] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='SendPAICertificateRequest' error='src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout' [1698370306.475362][149323:149325] CHIP:CTL: Error on commissioning step 'SendPAICertificateRequest': 'src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout' [1698370306.475366][149323:149325] CHIP:CTL: Failed to perform commissioning step 10 [1698370306.475372][149323:149325] CHIP:CTL: Going from commissioning step 'SendPAICertificateRequest' with lastErr = 'src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout' -> 'Cleanup' [1698370306.475386][149323:149325] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = 'src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout' [1698370306.475392][149323:149325] CHIP:CTL: Expiring failsafe on proxy 0x7ff8d40021c0 [1698370306.475424][149323:149325] CHIP:DMG: ICR moving to [AddingComm] [1698370306.475438][149323:149325] CHIP:DMG: ICR moving to [AddedComma] [1698370306.475507][149323:149325] CHIP:EM: <<< [E:2653i S:49873 M:139577590] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1698370306.475523][149323:149325] CHIP:IN: (S) Sending msg 139577590 on secure session with LSID: 49873 [1698370306.475567][149323:149325] CHIP:DMG: ICR moving to [AwaitingDe]