[1698369739.899680][149159:149161] CHIP:TOO: Discovered Device: fe80::e65f:1ff:feaf:e2f3:5540 [1698369739.899892][149159:149161] CHIP:IN: SecureSession[0x7fdd9c002db0]: Allocated Type:1 LSID:44553 [1698369739.899925][149159:149161] CHIP:SC: Assigned local session key ID 44553 [1698369739.899978][149159:149161] CHIP:EM: <<< [E:59826i S:0 M:242492448] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [1698369739.900144][149159:149161] CHIP:IN: (U) Sending msg 242492448 to IP address 'UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540' [1698369739.900222][149159:149161] CHIP:SC: Sent PBKDF param request [1698369739.900240][149159:149161] CHIP:CTL: Commission called for node ID 0x0000000000000001 [1698369739.900311][149159:149161] CHIP:CTL: Unknown filter type; all matches will fail [1698369739.915155][149159:149161] CHIP:EM: >>> [E:59826i S:0 M:101551705 (Ack:242492448)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [1698369739.915190][149159:149161] CHIP:EM: Found matching exchange: 59826i, Delegate: 0x7fdd9c002210 [1698369739.915202][149159:149161] CHIP:EM: Rxd Ack; Removing MessageCounter:242492448 from Retrans Table on exchange 59826i [1698369739.915214][149159:149161] CHIP:SC: Received PBKDF param response [1698369739.915231][149159:149161] CHIP:SC: Peer assigned session ID 50054 [1698369739.916781][149159:149161] CHIP:EM: <<< [E:59826i S:0 M:242492449 (Ack:101551705)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) [1698369739.916860][149159:149161] CHIP:IN: (U) Sending msg 242492449 to IP address 'UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540' [1698369739.916915][149159:149161] CHIP:SC: Sent spake2p msg1 [1698369739.919472][149159:149161] CHIP:EM: >>> [E:59826i S:0 M:101551706 (Ack:242492449)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [1698369739.919522][149159:149161] CHIP:EM: Found matching exchange: 59826i, Delegate: 0x7fdd9c002210 [1698369739.919546][149159:149161] CHIP:EM: Rxd Ack; Removing MessageCounter:242492449 from Retrans Table on exchange 59826i [1698369739.919561][149159:149161] CHIP:SC: Received spake2p msg2 [1698369739.919956][149159:149161] CHIP:EM: <<< [E:59826i S:0 M:242492450 (Ack:101551706)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) [1698369739.920051][149159:149161] CHIP:IN: (U) Sending msg 242492450 to IP address 'UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540' [1698369739.923755][149159:149161] CHIP:SC: Sent spake2p msg3 [1698369739.923878][149159:149161] CHIP:EM: >>> [E:59826i S:0 M:101551707 (Ack:242492450)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1698369739.923892][149159:149161] CHIP:EM: Found matching exchange: 59826i, Delegate: 0x7fdd9c002210 [1698369739.923899][149159:149161] CHIP:EM: Rxd Ack; Removing MessageCounter:242492450 from Retrans Table on exchange 59826i [1698369739.923999][149159:149161] CHIP:SC: SecureSession[0x7fdd9c002db0, LSID:44553]: State change 'kEstablishing' --> 'kActive' [1698369739.924008][149159:149161] CHIP:IN: SecureSession[0x7fdd9c002db0]: Activated - Type:1 LSID:44553 [1698369739.924011][149159:149161] CHIP:IN: New secure session activated for device , LSID:44553 PSID:50054! [1698369739.924021][149159:149161] CHIP:CTL: Remote device completed SPAKE2+ handshake [1698369739.924025][149159:149161] CHIP:CTL: PASE is established [1698369739.924033][149159:149161] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1698369739.924039][149159:149161] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1698369739.924044][149159:149161] CHIP:CTL: Sending request for commissioning information [1698369739.924059][149159:149161] CHIP:DMG: SendReadRequest ReadClient[0x7fdd9c005b30]: Sending Read Request [1698369739.924118][149159:149161] CHIP:EM: <<< [E:59827i S:44553 M:10708532] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) [1698369739.924129][149159:149161] CHIP:IN: (S) Sending msg 10708532 on secure session with LSID: 44553 [1698369739.924228][149159:149161] CHIP:DMG: MoveToState ReadClient[0x7fdd9c005b30]: Moving to [AwaitingIn] [1698369739.924245][149159:149161] CHIP:EM: <<< [E:59826i S:0 M:242492451 (Ack:101551707)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698369739.924309][149159:149161] CHIP:IN: (U) Sending msg 242492451 to IP address 'UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540' [1698369739.925475][149159:149161] CHIP:EM: Flushed pending ack for MessageCounter:101551707 on exchange 59826i [1698369740.321864][149159:149161] CHIP:EM: Retransmitting MessageCounter:10708532 on exchange 59827i Send Cnt 1 [1698369740.321957][149159:149161] CHIP:IN: (S) Sending msg 10708532 on secure session with LSID: 44553 [1698369740.328806][149159:149161] CHIP:EM: >>> [E:59827i S:44553 M:242605709 (Ack:10708532)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698369740.328835][149159:149161] CHIP:EM: Found matching exchange: 59827i, Delegate: 0x7fdd9c005b40 [1698369740.328889][149159:149161] CHIP:EM: Rxd Ack; Removing MessageCounter:10708532 from Retrans Table on exchange 59827i [1698369740.669896][149159:149161] CHIP:EM: >>> [E:59827i S:44553 M:242605710 (Ack:10708532)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1698369740.669922][149159:149161] CHIP:EM: Found matching exchange: 59827i, Delegate: 0x7fdd9c005b40 [1698369740.669927][149159:149161] CHIP:EM: CHIP MessageCounter:10708532 not in RetransTable on exchange 59827i [1698369740.669976][149159:149161] CHIP:DMG: ReportDataMessage = [1698369740.669982][149159:149161] CHIP:DMG: { [1698369740.669984][149159:149161] CHIP:DMG: AttributeReportIBs = [1698369740.669987][149159:149161] CHIP:DMG: [ [1698369740.669989][149159:149161] CHIP:DMG: AttributeReportIB = [1698369740.670011][149159:149161] CHIP:DMG: { [1698369740.670017][149159:149161] CHIP:DMG: AttributeDataIB = [1698369740.670038][149159:149161] CHIP:DMG: { [1698369740.670045][149159:149161] CHIP:DMG: DataVersion = 0x9ab379f9, [1698369740.670048][149159:149161] CHIP:DMG: AttributePathIB = [1698369740.670052][149159:149161] CHIP:DMG: { [1698369740.670055][149159:149161] CHIP:DMG: Endpoint = 0x0, [1698369740.670060][149159:149161] CHIP:DMG: Cluster = 0x31, [1698369740.670063][149159:149161] CHIP:DMG: Attribute = 0x0000_0003, [1698369740.670066][149159:149161] CHIP:DMG: } [1698369740.670070][149159:149161] CHIP:DMG: [1698369740.670075][149159:149161] CHIP:DMG: Data = 0, [1698369740.670078][149159:149161] CHIP:DMG: }, [1698369740.670081][149159:149161] CHIP:DMG: [1698369740.670083][149159:149161] CHIP:DMG: }, [1698369740.670088][149159:149161] CHIP:DMG: [1698369740.670092][149159:149161] CHIP:DMG: AttributeReportIB = [1698369740.670095][149159:149161] CHIP:DMG: { [1698369740.670097][149159:149161] CHIP:DMG: AttributeDataIB = [1698369740.670100][149159:149161] CHIP:DMG: { [1698369740.670104][149159:149161] CHIP:DMG: DataVersion = 0x74807d3c, [1698369740.670107][149159:149161] CHIP:DMG: AttributePathIB = [1698369740.670110][149159:149161] CHIP:DMG: { [1698369740.670112][149159:149161] CHIP:DMG: Endpoint = 0x0, [1698369740.670117][149159:149161] CHIP:DMG: Cluster = 0x28, [1698369740.670120][149159:149161] CHIP:DMG: Attribute = 0x0000_0004, [1698369740.670123][149159:149161] CHIP:DMG: } [1698369740.670128][149159:149161] CHIP:DMG: [1698369740.670132][149159:149161] CHIP:DMG: Data = 32769, [1698369740.670134][149159:149161] CHIP:DMG: }, [1698369740.670137][149159:149161] CHIP:DMG: [1698369740.670142][149159:149161] CHIP:DMG: }, [1698369740.670146][149159:149161] CHIP:DMG: [1698369740.670148][149159:149161] CHIP:DMG: AttributeReportIB = [1698369740.670153][149159:149161] CHIP:DMG: { [1698369740.670155][149159:149161] CHIP:DMG: AttributeDataIB = [1698369740.670158][149159:149161] CHIP:DMG: { [1698369740.670162][149159:149161] CHIP:DMG: DataVersion = 0x74807d3c, [1698369740.670165][149159:149161] CHIP:DMG: AttributePathIB = [1698369740.670168][149159:149161] CHIP:DMG: { [1698369740.670173][149159:149161] CHIP:DMG: Endpoint = 0x0, [1698369740.670176][149159:149161] CHIP:DMG: Cluster = 0x28, [1698369740.670179][149159:149161] CHIP:DMG: Attribute = 0x0000_0002, [1698369740.670183][149159:149161] CHIP:DMG: } [1698369740.670187][149159:149161] CHIP:DMG: [1698369740.670192][149159:149161] CHIP:DMG: Data = 65521, [1698369740.670194][149159:149161] CHIP:DMG: }, [1698369740.670198][149159:149161] CHIP:DMG: [1698369740.670202][149159:149161] CHIP:DMG: }, [1698369740.670206][149159:149161] CHIP:DMG: [1698369740.670208][149159:149161] CHIP:DMG: AttributeReportIB = [1698369740.670213][149159:149161] CHIP:DMG: { [1698369740.670215][149159:149161] CHIP:DMG: AttributeDataIB = [1698369740.670218][149159:149161] CHIP:DMG: { [1698369740.670222][149159:149161] CHIP:DMG: DataVersion = 0x2ac744de, [1698369740.670225][149159:149161] CHIP:DMG: AttributePathIB = [1698369740.670228][149159:149161] CHIP:DMG: { [1698369740.670239][149159:149161] CHIP:DMG: Endpoint = 0x0, [1698369740.670245][149159:149161] CHIP:DMG: Cluster = 0x30, [1698369740.670248][149159:149161] CHIP:DMG: Attribute = 0x0000_0003, [1698369740.670251][149159:149161] CHIP:DMG: } [1698369740.670256][149159:149161] CHIP:DMG: [1698369740.670259][149159:149161] CHIP:DMG: Data = 2, [1698369740.670264][149159:149161] CHIP:DMG: }, [1698369740.670267][149159:149161] CHIP:DMG: [1698369740.670270][149159:149161] CHIP:DMG: }, [1698369740.670275][149159:149161] CHIP:DMG: [1698369740.670279][149159:149161] CHIP:DMG: AttributeReportIB = [1698369740.670282][149159:149161] CHIP:DMG: { [1698369740.670284][149159:149161] CHIP:DMG: AttributeDataIB = [1698369740.670289][149159:149161] CHIP:DMG: { [1698369740.670292][149159:149161] CHIP:DMG: DataVersion = 0x2ac744de, [1698369740.670295][149159:149161] CHIP:DMG: AttributePathIB = [1698369740.670299][149159:149161] CHIP:DMG: { [1698369740.670302][149159:149161] CHIP:DMG: Endpoint = 0x0, [1698369740.670305][149159:149161] CHIP:DMG: Cluster = 0x30, [1698369740.670310][149159:149161] CHIP:DMG: Attribute = 0x0000_0002, [1698369740.670313][149159:149161] CHIP:DMG: } [1698369740.670316][149159:149161] CHIP:DMG: [1698369740.670321][149159:149161] CHIP:DMG: Data = 0, [1698369740.670324][149159:149161] CHIP:DMG: }, [1698369740.670327][149159:149161] CHIP:DMG: [1698369740.670331][149159:149161] CHIP:DMG: }, [1698369740.670341][149159:149161] CHIP:DMG: [1698369740.670347][149159:149161] CHIP:DMG: AttributeReportIB = [1698369740.670351][149159:149161] CHIP:DMG: { [1698369740.670353][149159:149161] CHIP:DMG: AttributeDataIB = [1698369740.670357][149159:149161] CHIP:DMG: { [1698369740.670360][149159:149161] CHIP:DMG: DataVersion = 0x2ac744de, [1698369740.670363][149159:149161] CHIP:DMG: AttributePathIB = [1698369740.670368][149159:149161] CHIP:DMG: { [1698369740.670370][149159:149161] CHIP:DMG: Endpoint = 0x0, [1698369740.670373][149159:149161] CHIP:DMG: Cluster = 0x30, [1698369740.670378][149159:149161] CHIP:DMG: Attribute = 0x0000_0001, [1698369740.670381][149159:149161] CHIP:DMG: } [1698369740.670384][149159:149161] CHIP:DMG: [1698369740.670389][149159:149161] CHIP:DMG: Data = [1698369740.670392][149159:149161] CHIP:DMG: { [1698369740.670409][149159:149161] CHIP:DMG: 0x0 = 60, [1698369740.670412][149159:149161] CHIP:DMG: 0x1 = 900, [1698369740.670415][149159:149161] CHIP:DMG: }, [1698369740.670417][149159:149161] CHIP:DMG: }, [1698369740.670421][149159:149161] CHIP:DMG: [1698369740.670432][149159:149161] CHIP:DMG: }, [1698369740.670440][149159:149161] CHIP:DMG: [1698369740.670442][149159:149161] CHIP:DMG: AttributeReportIB = [1698369740.670445][149159:149161] CHIP:DMG: { [1698369740.670447][149159:149161] CHIP:DMG: AttributeDataIB = [1698369740.670455][149159:149161] CHIP:DMG: { [1698369740.670458][149159:149161] CHIP:DMG: DataVersion = 0x2ac744de, [1698369740.670463][149159:149161] CHIP:DMG: AttributePathIB = [1698369740.670465][149159:149161] CHIP:DMG: { [1698369740.670475][149159:149161] CHIP:DMG: Endpoint = 0x0, [1698369740.670481][149159:149161] CHIP:DMG: Cluster = 0x30, [1698369740.670484][149159:149161] CHIP:DMG: Attribute = 0x0000_0000, [1698369740.670487][149159:149161] CHIP:DMG: } [1698369740.670492][149159:149161] CHIP:DMG: [1698369740.670495][149159:149161] CHIP:DMG: Data = 0, [1698369740.670497][149159:149161] CHIP:DMG: }, [1698369740.670503][149159:149161] CHIP:DMG: [1698369740.670505][149159:149161] CHIP:DMG: }, [1698369740.670509][149159:149161] CHIP:DMG: [1698369740.670513][149159:149161] CHIP:DMG: AttributeReportIB = [1698369740.670516][149159:149161] CHIP:DMG: { [1698369740.670518][149159:149161] CHIP:DMG: AttributeDataIB = [1698369740.670523][149159:149161] CHIP:DMG: { [1698369740.670526][149159:149161] CHIP:DMG: DataVersion = 0x9ab379f9, [1698369740.670528][149159:149161] CHIP:DMG: AttributePathIB = [1698369740.670531][149159:149161] CHIP:DMG: { [1698369740.670536][149159:149161] CHIP:DMG: Endpoint = 0x0, [1698369740.670539][149159:149161] CHIP:DMG: Cluster = 0x31, [1698369740.670542][149159:149161] CHIP:DMG: Attribute = 0x0000_FFFC, [1698369740.670547][149159:149161] CHIP:DMG: } [1698369740.670550][149159:149161] CHIP:DMG: [1698369740.670559][149159:149161] CHIP:DMG: Data = 4, [1698369740.670565][149159:149161] CHIP:DMG: }, [1698369740.670568][149159:149161] CHIP:DMG: [1698369740.670571][149159:149161] CHIP:DMG: }, [1698369740.670576][149159:149161] CHIP:DMG: [1698369740.670578][149159:149161] CHIP:DMG: ], [1698369740.670592][149159:149161] CHIP:DMG: [1698369740.670599][149159:149161] CHIP:DMG: SuppressResponse = true, [1698369740.670602][149159:149161] CHIP:DMG: InteractionModelRevision = 1 [1698369740.670603][149159:149161] CHIP:DMG: } [1698369740.670811][149159:149161] CHIP:CTL: ----- NetworkCommissioning Features: has Ethernet. endpointid = 0 [1698369740.670851][149159:149161] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='ReadCommissioningInfo' error='src/controller/CHIPDeviceController.cpp:1879: Success' [1698369740.670854][149159:149161] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1698369740.670859][149159:149161] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe' [1698369740.670865][149159:149161] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1698369740.670868][149159:149161] CHIP:CTL: Arming failsafe (60 seconds) [1698369740.670881][149159:149161] CHIP:DMG: ICR moving to [AddingComm] [1698369740.670885][149159:149161] CHIP:DMG: ICR moving to [AddedComma] [1698369740.670922][149159:149161] CHIP:EM: <<< [E:59828i S:44553 M:10708533] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1698369740.670928][149159:149161] CHIP:IN: (S) Sending msg 10708533 on secure session with LSID: 44553 [1698369740.671024][149159:149161] CHIP:DMG: ICR moving to [CommandSen] [1698369740.671061][149159:149161] CHIP:EM: <<< [E:59827i S:44553 M:10708534 (Ack:242605710)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698369740.671066][149159:149161] CHIP:IN: (S) Sending msg 10708534 on secure session with LSID: 44553 [1698369740.671080][149159:149161] CHIP:EM: Flushed pending ack for MessageCounter:242605710 on exchange 59827i [1698369741.020034][149159:149161] CHIP:EM: Retransmitting MessageCounter:10708533 on exchange 59828i Send Cnt 1 [1698369741.020168][149159:149161] CHIP:IN: (S) Sending msg 10708533 on secure session with LSID: 44553 [1698369741.020376][149159:149161] CHIP:EM: >>> [E:59827i S:44553 M:242605711 (Ack:10708532)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698369741.020401][149159:149161] CHIP:EM: OnMessageReceived failed, err = src/messaging/ExchangeMgr.cpp:304: CHIP Error 0x00000070: Unsolicited msg with originator bit clear [1698369741.028663][149159:149161] CHIP:EM: >>> [E:59828i S:44553 M:242605712 (Ack:10708533)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1698369741.028713][149159:149161] CHIP:EM: Found matching exchange: 59828i, Delegate: 0x7fdd9c001ea8 [1698369741.028749][149159:149161] CHIP:EM: Rxd Ack; Removing MessageCounter:10708533 from Retrans Table on exchange 59828i [1698369741.028765][149159:149161] CHIP:DMG: ICR moving to [ResponseRe] [1698369741.028796][149159:149161] CHIP:DMG: InvokeResponseMessage = [1698369741.028810][149159:149161] CHIP:DMG: { [1698369741.028818][149159:149161] CHIP:DMG: suppressResponse = false, [1698369741.028830][149159:149161] CHIP:DMG: InvokeResponseIBs = [1698369741.028847][149159:149161] CHIP:DMG: [ [1698369741.028859][149159:149161] CHIP:DMG: InvokeResponseIB = [1698369741.028878][149159:149161] CHIP:DMG: { [1698369741.028891][149159:149161] CHIP:DMG: CommandDataIB = [1698369741.028905][149159:149161] CHIP:DMG: { [1698369741.028919][149159:149161] CHIP:DMG: CommandPathIB = [1698369741.028934][149159:149161] CHIP:DMG: { [1698369741.028949][149159:149161] CHIP:DMG: EndpointId = 0x0, [1698369741.028965][149159:149161] CHIP:DMG: ClusterId = 0x30, [1698369741.028982][149159:149161] CHIP:DMG: CommandId = 0x1, [1698369741.028985][149159:149161] CHIP:DMG: }, [1698369741.028988][149159:149161] CHIP:DMG: [1698369741.028993][149159:149161] CHIP:DMG: CommandFields = [1698369741.028996][149159:149161] CHIP:DMG: { [1698369741.029000][149159:149161] CHIP:DMG: 0x0 = 0, [1698369741.029005][149159:149161] CHIP:DMG: 0x1 = "" (0 chars), [1698369741.029008][149159:149161] CHIP:DMG: }, [1698369741.029013][149159:149161] CHIP:DMG: }, [1698369741.029017][149159:149161] CHIP:DMG: [1698369741.029019][149159:149161] CHIP:DMG: }, [1698369741.029025][149159:149161] CHIP:DMG: [1698369741.029027][149159:149161] CHIP:DMG: ], [1698369741.029030][149159:149161] CHIP:DMG: [1698369741.029034][149159:149161] CHIP:DMG: InteractionModelRevision = 1 [1698369741.029036][149159:149161] CHIP:DMG: }, [1698369741.029047][149159:149161] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1698369741.029057][149159:149161] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1698369741.029066][149159:149161] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='ArmFailSafe' error='src/controller/CHIPDeviceController.cpp:2169: Success' [1698369741.029072][149159:149161] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1698369741.029074][149159:149161] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1698369741.029081][149159:149161] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1698369741.029085][149159:149161] CHIP:CTL: Setting Regulatory Config [1698369741.029087][149159:149161] CHIP:CTL: No regulatory config supplied by controller, leaving as device default (0) [1698369741.029103][149159:149161] CHIP:DMG: ICR moving to [AddingComm] [1698369741.029111][149159:149161] CHIP:DMG: ICR moving to [AddedComma] [1698369741.029131][149159:149161] CHIP:EM: <<< [E:59829i S:44553 M:10708535] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1698369741.029139][149159:149161] CHIP:IN: (S) Sending msg 10708535 on secure session with LSID: 44553 [1698369741.029200][149159:149161] CHIP:DMG: ICR moving to [CommandSen] [1698369741.029213][149159:149161] CHIP:DMG: ICR moving to [AwaitingDe] [1698369741.029222][149159:149161] CHIP:EM: <<< [E:59828i S:44553 M:10708536 (Ack:242605712)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698369741.029229][149159:149161] CHIP:IN: (S) Sending msg 10708536 on secure session with LSID: 44553 [1698369741.029240][149159:149161] CHIP:EM: Flushed pending ack for MessageCounter:242605712 on exchange 59828i [1698369741.378320][149159:149161] CHIP:EM: >>> [E:59828i S:44553 M:242605713 (Ack:10708533)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698369741.378348][149159:149161] CHIP:EM: OnMessageReceived failed, err = src/messaging/ExchangeMgr.cpp:304: CHIP Error 0x00000070: Unsolicited msg with originator bit clear [1698369741.395669][149159:149161] CHIP:EM: Retransmitting MessageCounter:10708535 on exchange 59829i Send Cnt 1 [1698369741.395738][149159:149161] CHIP:IN: (S) Sending msg 10708535 on secure session with LSID: 44553 [1698369741.639739][149159:149161] CHIP:EM: >>> [E:59829i S:44553 M:242605714 (Ack:10708535)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1698369741.639776][149159:149161] CHIP:EM: Found matching exchange: 59829i, Delegate: 0x7fdd9c006ae8 [1698369741.639788][149159:149161] CHIP:EM: Rxd Ack; Removing MessageCounter:10708535 from Retrans Table on exchange 59829i [1698369741.639798][149159:149161] CHIP:DMG: ICR moving to [ResponseRe] [1698369741.639813][149159:149161] CHIP:DMG: InvokeResponseMessage = [1698369741.639816][149159:149161] CHIP:DMG: { [1698369741.639819][149159:149161] CHIP:DMG: suppressResponse = false, [1698369741.639822][149159:149161] CHIP:DMG: InvokeResponseIBs = [1698369741.639827][149159:149161] CHIP:DMG: [ [1698369741.639830][149159:149161] CHIP:DMG: InvokeResponseIB = [1698369741.639835][149159:149161] CHIP:DMG: { [1698369741.639843][149159:149161] CHIP:DMG: CommandDataIB = [1698369741.639850][149159:149161] CHIP:DMG: { [1698369741.639854][149159:149161] CHIP:DMG: CommandPathIB = [1698369741.639873][149159:149161] CHIP:DMG: { [1698369741.639880][149159:149161] CHIP:DMG: EndpointId = 0x0, [1698369741.639884][149159:149161] CHIP:DMG: ClusterId = 0x30, [1698369741.639891][149159:149161] CHIP:DMG: CommandId = 0x3, [1698369741.639895][149159:149161] CHIP:DMG: }, [1698369741.639899][149159:149161] CHIP:DMG: [1698369741.639905][149159:149161] CHIP:DMG: CommandFields = [1698369741.639908][149159:149161] CHIP:DMG: { [1698369741.639913][149159:149161] CHIP:DMG: 0x0 = 0, [1698369741.639920][149159:149161] CHIP:DMG: 0x1 = "" (0 chars), [1698369741.639929][149159:149161] CHIP:DMG: }, [1698369741.639933][149159:149161] CHIP:DMG: }, [1698369741.639938][149159:149161] CHIP:DMG: [1698369741.639944][149159:149161] CHIP:DMG: }, [1698369741.639948][149159:149161] CHIP:DMG: [1698369741.639954][149159:149161] CHIP:DMG: ], [1698369741.639962][149159:149161] CHIP:DMG: [1698369741.639969][149159:149161] CHIP:DMG: InteractionModelRevision = 1 [1698369741.639974][149159:149161] CHIP:DMG: }, [1698369741.639990][149159:149161] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1698369741.640002][149159:149161] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0 [1698369741.640010][149159:149161] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='ConfigRegulatory' error='src/controller/CHIPDeviceController.cpp:2186: Success' [1698369741.640018][149159:149161] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1698369741.640022][149159:149161] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1698369741.640030][149159:149161] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1698369741.640035][149159:149161] CHIP:CTL: Sending request for PAI certificate [1698369741.640038][149159:149161] CHIP:CTL: Sending Certificate Chain request to 0x7fdd9c0021c0 device [1698369741.640056][149159:149161] CHIP:DMG: ICR moving to [AddingComm] [1698369741.640063][149159:149161] CHIP:DMG: ICR moving to [AddedComma] [1698369741.640089][149159:149161] CHIP:EM: <<< [E:59830i S:44553 M:10708537] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1698369741.640099][149159:149161] CHIP:IN: (S) Sending msg 10708537 on secure session with LSID: 44553 [1698369741.640164][149159:149161] CHIP:DMG: ICR moving to [CommandSen] [1698369741.640180][149159:149161] CHIP:DMG: ICR moving to [AwaitingDe] [1698369741.640197][149159:149161] CHIP:EM: <<< [E:59829i S:44553 M:10708538 (Ack:242605714)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698369741.640209][149159:149161] CHIP:IN: (S) Sending msg 10708538 on secure session with LSID: 44553 [1698369741.640239][149159:149161] CHIP:EM: Flushed pending ack for MessageCounter:242605714 on exchange 59829i [1698369742.050462][149159:149161] CHIP:EM: Retransmitting MessageCounter:10708537 on exchange 59830i Send Cnt 1 [1698369742.050529][149159:149161] CHIP:IN: (S) Sending msg 10708537 on secure session with LSID: 44553 [1698369742.433607][149159:149161] CHIP:EM: Retransmitting MessageCounter:10708537 on exchange 59830i Send Cnt 2 [1698369742.433682][149159:149161] CHIP:IN: (S) Sending msg 10708537 on secure session with LSID: 44553 [1698369743.035378][149159:149161] CHIP:EM: Retransmitting MessageCounter:10708537 on exchange 59830i Send Cnt 3 [1698369743.035452][149159:149161] CHIP:IN: (S) Sending msg 10708537 on secure session with LSID: 44553 [1698369743.922657][149159:149161] CHIP:EM: Retransmitting MessageCounter:10708537 on exchange 59830i Send Cnt 4 [1698369743.922730][149159:149161] CHIP:IN: (S) Sending msg 10708537 on secure session with LSID: 44553 [1698369745.451095][149159:149161] CHIP:EM: Failed to Send CHIP MessageCounter:10708537 on exchange 59830i sendCount: 4 max retries: 4 [1698369771.645656][149159:149161] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 59830i [1698369771.645699][149159:149161] CHIP:CTL: Device failed to receive the Certificate Chain request Response: src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout [1698369771.645707][149159:149161] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='SendPAICertificateRequest' error='src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout' [1698369771.645714][149159:149161] CHIP:CTL: Error on commissioning step 'SendPAICertificateRequest': 'src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout' [1698369771.645718][149159:149161] CHIP:CTL: Failed to perform commissioning step 10 [1698369771.645721][149159:149161] CHIP:CTL: Going from commissioning step 'SendPAICertificateRequest' with lastErr = 'src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout' -> 'Cleanup' [1698369771.645731][149159:149161] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = 'src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout' [1698369771.645734][149159:149161] CHIP:CTL: Expiring failsafe on proxy 0x7fdd9c0021c0 [1698369771.645757][149159:149161] CHIP:DMG: ICR moving to [AddingComm] [1698369771.645762][149159:149161] CHIP:DMG: ICR moving to [AddedComma] [1698369771.645814][149159:149161] CHIP:EM: <<< [E:59831i S:44553 M:10708539] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1698369771.645830][149159:149161] CHIP:IN: (S) Sending msg 10708539 on secure session with LSID: 44553 [1698369771.646094][149159:149161] CHIP:DMG: ICR moving to [CommandSen] [1698369771.646140][149159:149161] CHIP:DMG: ICR moving to [AwaitingDe] [1698369772.002093][149159:149161] CHIP:EM: Retransmitting MessageCounter:10708539 on exchange 59831i Send Cnt 1 [1698369772.002208][149159:149161] CHIP:IN: (S) Sending msg 10708539 on secure session with LSID: 44553 [1698369772.387395][149159:149161] CHIP:EM: Retransmitting MessageCounter:10708539 on exchange 59831i Send Cnt 2 [1698369772.387451][149159:149161] CHIP:IN: (S) Sending msg 10708539 on secure session with LSID: 44553 [1698369772.962330][149159:149161] CHIP:EM: Retransmitting MessageCounter:10708539 on exchange 59831i Send Cnt 3 [1698369772.962434][149159:149161] CHIP:IN: (S) Sending msg 10708539 on secure session with LSID: 44553 [1698369773.887160][149159:149161] CHIP:EM: Retransmitting MessageCounter:10708539 on exchange 59831i Send Cnt 4 [1698369773.887228][149159:149161] CHIP:IN: (S) Sending msg 10708539 on secure session with LSID: 44553 [1698369775.571683][149159:149161] CHIP:EM: Failed to Send CHIP MessageCounter:10708539 on exchange 59831i sendCount: 4 max retries: 4 [1698369777.872659][149159:149161] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 59831i [1698369777.872707][149159:149161] CHIP:CTL: Received failure response when disarming failsafesrc/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout [1698369777.872722][149159:149161] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='Cleanup' error='src/controller/CHIPDeviceController.cpp:1672: Success' [1698369777.872731][149159:149161] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1698369777.872739][149159:149161] CHIP:CTL: Device commissioning Failure: src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout