[DNI CHIP][INFO][EventDispatcher in line 76] Exec event id 0 [1698642473.852192][62486:62490] CHIP:TOO: Discovered Device: fe80::e65f:1ff:feaf:e2f3:5540 [1698642473.852350][62486:62490] CHIP:IN: SecureSession[0x7fbfc40030b0]: Allocated Type:1 LSID:36413 [1698642473.852374][62486:62490] CHIP:SC: Assigned local session key ID 36413 [1698642473.852501][62486:62490] CHIP:EM: <<< [E:23294i S:0 M:267754306] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [1698642473.852579][62486:62490] CHIP:SC: Sent PBKDF param request [1698642473.852590][62486:62490] CHIP:CTL: Commission called for node ID 0x0000000000000001 [1698642473.852596][62486:62490] CHIP:CTL: Unknown filter type; all matches will fail [1698642473.860865][62486:62490] CHIP:EM: >>> [E:23294i S:0 M:17582554 (Ack:267754306)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [1698642473.860899][62486:62490] CHIP:EM: Found matching exchange: 23294i, Delegate: 0x7fbfc4002010 [1698642473.860928][62486:62490] CHIP:EM: Rxd Ack; Removing MessageCounter:267754306 from Retrans Table on exchange 23294i [1698642473.860976][62486:62490] CHIP:SC: Received PBKDF param response [1698642473.861003][62486:62490] CHIP:SC: Peer assigned session ID 40720 [1698642473.866382][62486:62490] CHIP:EM: <<< [E:23294i S:0 M:267754307 (Ack:17582554)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0000:22 (SecureChannel:PASE_Pake1) [1698642473.866588][62486:62490] CHIP:SC: Sent spake2p msg1 [1698642473.869406][62486:62490] CHIP:EM: >>> [E:23294i S:0 M:17582555 (Ack:267754307)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [1698642473.869437][62486:62490] CHIP:EM: Found matching exchange: 23294i, Delegate: 0x7fbfc4002010 [1698642473.869448][62486:62490] CHIP:EM: Rxd Ack; Removing MessageCounter:267754307 from Retrans Table on exchange 23294i [1698642473.869463][62486:62490] CHIP:SC: Received spake2p msg2 [1698642473.870529][62486:62490] CHIP:EM: <<< [E:23294i S:0 M:267754308 (Ack:17582555)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0000:24 (SecureChannel:PASE_Pake3) [1698642473.870721][62486:62490] CHIP:SC: Sent spake2p msg3 [1698642473.872014][62486:62490] CHIP:EM: >>> [E:23294i S:0 M:17582556 (Ack:267754308)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1698642473.872033][62486:62490] CHIP:EM: Found matching exchange: 23294i, Delegate: 0x7fbfc4002010 [1698642473.872040][62486:62490] CHIP:EM: Rxd Ack; Removing MessageCounter:267754308 from Retrans Table on exchange 23294i [1698642473.872133][62486:62490] CHIP:SC: SecureSession[0x7fbfc40030b0, LSID:36413]: State change 'kEstablishing' --> 'kActive' [1698642473.872235][62486:62490] CHIP:IN: SecureSession[0x7fbfc40030b0]: Activated - Type:1 LSID:36413 [1698642473.872240][62486:62490] CHIP:IN: New secure session activated for device , LSID:36413 PSID:40720! [1698642473.872248][62486:62490] CHIP:CTL: Remote device completed SPAKE2+ handshake [1698642473.872252][62486:62490] CHIP:CTL: PASE is established [1698642473.872257][62486:62490] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1698642473.872305][62486:62490] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1698642473.872308][62486:62490] CHIP:CTL: Sending read request for commissioning information [1698642473.872367][62486:62490] CHIP:DMG: SendReadRequest ReadClient[0x7fbfc4001cc0]: Sending Read Request [1698642473.872509][62486:62490] CHIP:EM: <<< [E:23295i S:36413 M:219369907] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0001:02 (IM:ReadRequest) [1698642473.872682][62486:62490] CHIP:DMG: MoveToState ReadClient[0x7fbfc4001cc0]: Moving to [AwaitingIn] [1698642473.872775][62486:62490] CHIP:EM: <<< [E:23294i S:0 M:267754309 (Ack:17582556)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698642473.872840][62486:62490] CHIP:EM: Flushed pending ack for MessageCounter:17582556 on exchange 23294i [1698642474.223130][62486:62490] CHIP:EM: Retransmitting MessageCounter:219369907 on exchange 23295i Send Cnt 1 [1698642474.281251][62486:62490] CHIP:EM: >>> [E:23295i S:36413 M:214752169 (Ack:219369907)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698642474.281295][62486:62490] CHIP:EM: Found matching exchange: 23295i, Delegate: 0x7fbfc4001cd0 [1698642474.281310][62486:62490] CHIP:EM: Rxd Ack; Removing MessageCounter:219369907 from Retrans Table on exchange 23295i [1698642474.281480][62486:62490] CHIP:IN: Received a duplicate message with MessageCounter:17582556 on exchange 23294i [1698642474.281499][62486:62490] CHIP:EM: >>> [E:23294i S:0 M:17582556 (Ack:267754308)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1698642474.281514][62486:62490] CHIP:EM: Generating StandaloneAck via exchange: 23294i [1698642474.281525][62486:62490] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:17582556 on exchange 23294i [1698642474.281603][62486:62490] CHIP:EM: <<< [E:23294i S:0 M:267754310 (Ack:17582556)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698642474.621328][62486:62490] CHIP:EM: >>> [E:23295i S:36413 M:214752170 (Ack:219369907)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1698642474.621372][62486:62490] CHIP:EM: Found matching exchange: 23295i, Delegate: 0x7fbfc4001cd0 [1698642474.621381][62486:62490] CHIP:EM: CHIP MessageCounter:219369907 not in RetransTable on exchange 23295i [1698642474.621473][62486:62490] CHIP:DMG: ReportDataMessage = [1698642474.621490][62486:62490] CHIP:DMG: { [1698642474.621496][62486:62490] CHIP:DMG: AttributeReportIBs = [1698642474.621503][62486:62490] CHIP:DMG: [ [1698642474.621530][62486:62490] CHIP:DMG: AttributeReportIB = [1698642474.621561][62486:62490] CHIP:DMG: { [1698642474.621581][62486:62490] CHIP:DMG: AttributeDataIB = [1698642474.621618][62486:62490] CHIP:DMG: { [1698642474.621633][62486:62490] CHIP:DMG: DataVersion = 0xa73fb95e, [1698642474.621638][62486:62490] CHIP:DMG: AttributePathIB = [1698642474.621648][62486:62490] CHIP:DMG: { [1698642474.621658][62486:62490] CHIP:DMG: Endpoint = 0x0, [1698642474.621664][62486:62490] CHIP:DMG: Cluster = 0x31, [1698642474.621670][62486:62490] CHIP:DMG: Attribute = 0x0000_0003, [1698642474.621680][62486:62490] CHIP:DMG: } [1698642474.621687][62486:62490] CHIP:DMG: [1698642474.621701][62486:62490] CHIP:DMG: Data = 0, [1698642474.621734][62486:62490] CHIP:DMG: }, [1698642474.621761][62486:62490] CHIP:DMG: [1698642474.621780][62486:62490] CHIP:DMG: }, [1698642474.621813][62486:62490] CHIP:DMG: [1698642474.621828][62486:62490] CHIP:DMG: AttributeReportIB = [1698642474.621835][62486:62490] CHIP:DMG: { [1698642474.621839][62486:62490] CHIP:DMG: AttributeDataIB = [1698642474.621844][62486:62490] CHIP:DMG: { [1698642474.621870][62486:62490] CHIP:DMG: DataVersion = 0xca07abc1, [1698642474.621902][62486:62490] CHIP:DMG: AttributePathIB = [1698642474.621963][62486:62490] CHIP:DMG: { [1698642474.621970][62486:62490] CHIP:DMG: Endpoint = 0x0, [1698642474.622012][62486:62490] CHIP:DMG: Cluster = 0x28, [1698642474.622050][62486:62490] CHIP:DMG: Attribute = 0x0000_0004, [1698642474.622087][62486:62490] CHIP:DMG: } [1698642474.622094][62486:62490] CHIP:DMG: [1698642474.622100][62486:62490] CHIP:DMG: Data = 32769, [1698642474.622105][62486:62490] CHIP:DMG: }, [1698642474.622134][62486:62490] CHIP:DMG: [1698642474.622165][62486:62490] CHIP:DMG: }, [1698642474.622201][62486:62490] CHIP:DMG: [1698642474.622219][62486:62490] CHIP:DMG: AttributeReportIB = [1698642474.622242][62486:62490] CHIP:DMG: { [1698642474.622262][62486:62490] CHIP:DMG: AttributeDataIB = [1698642474.622304][62486:62490] CHIP:DMG: { [1698642474.622320][62486:62490] CHIP:DMG: DataVersion = 0xca07abc1, [1698642474.622327][62486:62490] CHIP:DMG: AttributePathIB = [1698642474.622344][62486:62490] CHIP:DMG: { [1698642474.622386][62486:62490] CHIP:DMG: Endpoint = 0x0, [1698642474.622436][62486:62490] CHIP:DMG: Cluster = 0x28, [1698642474.622475][62486:62490] CHIP:DMG: Attribute = 0x0000_0002, [1698642474.622482][62486:62490] CHIP:DMG: } [1698642474.622528][62486:62490] CHIP:DMG: [1698642474.622570][62486:62490] CHIP:DMG: Data = 65521, [1698642474.622577][62486:62490] CHIP:DMG: }, [1698642474.622615][62486:62490] CHIP:DMG: [1698642474.622656][62486:62490] CHIP:DMG: }, [1698642474.622674][62486:62490] CHIP:DMG: [1698642474.622679][62486:62490] CHIP:DMG: AttributeReportIB = [1698642474.622715][62486:62490] CHIP:DMG: { [1698642474.622751][62486:62490] CHIP:DMG: AttributeDataIB = [1698642474.622759][62486:62490] CHIP:DMG: { [1698642474.622807][62486:62490] CHIP:DMG: DataVersion = 0x639d3b5a, [1698642474.622824][62486:62490] CHIP:DMG: AttributePathIB = [1698642474.622832][62486:62490] CHIP:DMG: { [1698642474.622875][62486:62490] CHIP:DMG: Endpoint = 0x0, [1698642474.622906][62486:62490] CHIP:DMG: Cluster = 0x30, [1698642474.622971][62486:62490] CHIP:DMG: Attribute = 0x0000_0003, [1698642474.623009][62486:62490] CHIP:DMG: } [1698642474.623040][62486:62490] CHIP:DMG: [1698642474.623075][62486:62490] CHIP:DMG: Data = 2, [1698642474.623105][62486:62490] CHIP:DMG: }, [1698642474.623134][62486:62490] CHIP:DMG: [1698642474.623156][62486:62490] CHIP:DMG: }, [1698642474.623181][62486:62490] CHIP:DMG: [1698642474.623200][62486:62490] CHIP:DMG: AttributeReportIB = [1698642474.623225][62486:62490] CHIP:DMG: { [1698642474.623250][62486:62490] CHIP:DMG: AttributeDataIB = [1698642474.623279][62486:62490] CHIP:DMG: { [1698642474.623317][62486:62490] CHIP:DMG: DataVersion = 0x639d3b5a, [1698642474.623345][62486:62490] CHIP:DMG: AttributePathIB = [1698642474.623376][62486:62490] CHIP:DMG: { [1698642474.623406][62486:62490] CHIP:DMG: Endpoint = 0x0, [1698642474.623437][62486:62490] CHIP:DMG: Cluster = 0x30, [1698642474.623469][62486:62490] CHIP:DMG: Attribute = 0x0000_0002, [1698642474.623502][62486:62490] CHIP:DMG: } [1698642474.623533][62486:62490] CHIP:DMG: [1698642474.623569][62486:62490] CHIP:DMG: Data = 0, [1698642474.623601][62486:62490] CHIP:DMG: }, [1698642474.623628][62486:62490] CHIP:DMG: [1698642474.623652][62486:62490] CHIP:DMG: }, [1698642474.623679][62486:62490] CHIP:DMG: [1698642474.623697][62486:62490] CHIP:DMG: AttributeReportIB = [1698642474.623722][62486:62490] CHIP:DMG: { [1698642474.623743][62486:62490] CHIP:DMG: AttributeDataIB = [1698642474.623774][62486:62490] CHIP:DMG: { [1698642474.623780][62486:62490] CHIP:DMG: DataVersion = 0x639d3b5a, [1698642474.623785][62486:62490] CHIP:DMG: AttributePathIB = [1698642474.623811][62486:62490] CHIP:DMG: { [1698642474.623841][62486:62490] CHIP:DMG: Endpoint = 0x0, [1698642474.623873][62486:62490] CHIP:DMG: Cluster = 0x30, [1698642474.623935][62486:62490] CHIP:DMG: Attribute = 0x0000_0001, [1698642474.623978][62486:62490] CHIP:DMG: } [1698642474.624010][62486:62490] CHIP:DMG: [1698642474.624040][62486:62490] CHIP:DMG: Data = [1698642474.624068][62486:62490] CHIP:DMG: { [1698642474.624137][62486:62490] CHIP:DMG: 0x0 = 60, [1698642474.624172][62486:62490] CHIP:DMG: 0x1 = 900, [1698642474.624204][62486:62490] CHIP:DMG: }, [1698642474.624232][62486:62490] CHIP:DMG: }, [1698642474.624267][62486:62490] CHIP:DMG: [1698642474.624291][62486:62490] CHIP:DMG: }, [1698642474.624305][62486:62490] CHIP:DMG: [1698642474.624309][62486:62490] CHIP:DMG: AttributeReportIB = [1698642474.624324][62486:62490] CHIP:DMG: { [1698642474.624344][62486:62490] CHIP:DMG: AttributeDataIB = [1698642474.624377][62486:62490] CHIP:DMG: { [1698642474.624387][62486:62490] CHIP:DMG: DataVersion = 0x639d3b5a, [1698642474.624392][62486:62490] CHIP:DMG: AttributePathIB = [1698642474.624397][62486:62490] CHIP:DMG: { [1698642474.624442][62486:62490] CHIP:DMG: Endpoint = 0x0, [1698642474.624449][62486:62490] CHIP:DMG: Cluster = 0x30, [1698642474.624482][62486:62490] CHIP:DMG: Attribute = 0x0000_0000, [1698642474.624518][62486:62490] CHIP:DMG: } [1698642474.624555][62486:62490] CHIP:DMG: [1698642474.624565][62486:62490] CHIP:DMG: Data = 0, [1698642474.624570][62486:62490] CHIP:DMG: }, [1698642474.624576][62486:62490] CHIP:DMG: [1698642474.624588][62486:62490] CHIP:DMG: }, [1698642474.624596][62486:62490] CHIP:DMG: [1698642474.624601][62486:62490] CHIP:DMG: AttributeReportIB = [1698642474.624612][62486:62490] CHIP:DMG: { [1698642474.624616][62486:62490] CHIP:DMG: AttributeDataIB = [1698642474.624620][62486:62490] CHIP:DMG: { [1698642474.624646][62486:62490] CHIP:DMG: DataVersion = 0xa73fb95e, [1698642474.624678][62486:62490] CHIP:DMG: AttributePathIB = [1698642474.624707][62486:62490] CHIP:DMG: { [1698642474.624736][62486:62490] CHIP:DMG: Endpoint = 0x0, [1698642474.624770][62486:62490] CHIP:DMG: Cluster = 0x31, [1698642474.624811][62486:62490] CHIP:DMG: Attribute = 0x0000_FFFC, [1698642474.624851][62486:62490] CHIP:DMG: } [1698642474.624914][62486:62490] CHIP:DMG: [1698642474.624969][62486:62490] CHIP:DMG: Data = 4, [1698642474.624986][62486:62490] CHIP:DMG: }, [1698642474.624995][62486:62490] CHIP:DMG: [1698642474.625027][62486:62490] CHIP:DMG: }, [1698642474.625066][62486:62490] CHIP:DMG: [1698642474.625102][62486:62490] CHIP:DMG: ], [1698642474.625150][62486:62490] CHIP:DMG: [1698642474.625171][62486:62490] CHIP:DMG: SuppressResponse = true, [1698642474.625199][62486:62490] CHIP:DMG: InteractionModelRevision = 1 [1698642474.625219][62486:62490] CHIP:DMG: } [1698642474.625579][62486:62490] CHIP:CTL: ----- NetworkCommissioning Features: has Ethernet. endpointid = 0 [1698642474.625649][62486:62490] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='ReadCommissioningInfo' error='src/controller/CHIPDeviceController.cpp:1898: Success' [1698642474.625663][62486:62490] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1698642474.625678][62486:62490] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe' [1698642474.625717][62486:62490] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1698642474.625730][62486:62490] CHIP:CTL: Arming failsafe (60 seconds) [1698642474.625767][62486:62490] CHIP:DMG: ICR moving to [AddingComm] [1698642474.625789][62486:62490] CHIP:DMG: ICR moving to [AddedComma] [1698642474.625991][62486:62490] CHIP:EM: <<< [E:23296i S:36413 M:219369908] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1698642474.626259][62486:62490] CHIP:DMG: ICR moving to [CommandSen] [1698642474.626346][62486:62490] CHIP:EM: <<< [E:23295i S:36413 M:219369909 (Ack:214752170)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698642474.626389][62486:62490] CHIP:EM: Flushed pending ack for MessageCounter:214752170 on exchange 23295i [1698642474.972273][62486:62490] CHIP:EM: >>> [E:23295i S:36413 M:214752171 (Ack:219369907)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698642474.980401][62486:62490] CHIP:IN: Received a duplicate message with MessageCounter:214752170 on exchange 23295i [1698642474.980463][62486:62490] CHIP:EM: >>> [E:23295i S:36413 M:214752170 (Ack:219369907)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1698642474.980482][62486:62490] CHIP:EM: Generating StandaloneAck via exchange: 23295i [1698642474.980493][62486:62490] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:214752170 on exchange 23295i [1698642474.980569][62486:62490] CHIP:EM: <<< [E:23295i S:36413 M:219369910 (Ack:214752170)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698642474.987560][62486:62490] CHIP:EM: >>> [E:23296i S:36413 M:214752172 (Ack:219369908)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1698642474.987622][62486:62490] CHIP:EM: Found matching exchange: 23296i, Delegate: 0x7fbfc4001cc8 [1698642474.987646][62486:62490] CHIP:EM: Rxd Ack; Removing MessageCounter:219369908 from Retrans Table on exchange 23296i [1698642474.987669][62486:62490] CHIP:DMG: ICR moving to [ResponseRe] [1698642474.987701][62486:62490] CHIP:DMG: InvokeResponseMessage = [1698642474.987723][62486:62490] CHIP:DMG: { [1698642474.987779][62486:62490] CHIP:DMG: suppressResponse = false, [1698642474.987817][62486:62490] CHIP:DMG: InvokeResponseIBs = [1698642474.987874][62486:62490] CHIP:DMG: [ [1698642474.987905][62486:62490] CHIP:DMG: InvokeResponseIB = [1698642474.987961][62486:62490] CHIP:DMG: { [1698642474.988026][62486:62490] CHIP:DMG: CommandDataIB = [1698642474.988068][62486:62490] CHIP:DMG: { [1698642474.988102][62486:62490] CHIP:DMG: CommandPathIB = [1698642474.988157][62486:62490] CHIP:DMG: { [1698642474.988170][62486:62490] CHIP:DMG: EndpointId = 0x0, [1698642474.988177][62486:62490] CHIP:DMG: ClusterId = 0x30, [1698642474.988184][62486:62490] CHIP:DMG: CommandId = 0x1, [1698642474.988190][62486:62490] CHIP:DMG: }, [1698642474.988198][62486:62490] CHIP:DMG: [1698642474.988252][62486:62490] CHIP:DMG: CommandFields = [1698642474.988313][62486:62490] CHIP:DMG: { [1698642474.988341][62486:62490] CHIP:DMG: 0x0 = 0, [1698642474.988372][62486:62490] CHIP:DMG: 0x1 = "" (0 chars), [1698642474.988402][62486:62490] CHIP:DMG: }, [1698642474.988434][62486:62490] CHIP:DMG: }, [1698642474.988482][62486:62490] CHIP:DMG: [1698642474.988512][62486:62490] CHIP:DMG: }, [1698642474.988597][62486:62490] CHIP:DMG: [1698642474.988615][62486:62490] CHIP:DMG: ], [1698642474.988636][62486:62490] CHIP:DMG: [1698642474.988650][62486:62490] CHIP:DMG: InteractionModelRevision = 1 [1698642474.988666][62486:62490] CHIP:DMG: }, [1698642474.988690][62486:62490] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1698642474.988718][62486:62490] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1698642474.988744][62486:62490] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='ArmFailSafe' error='src/controller/CHIPDeviceController.cpp:2188: Success' [1698642474.988754][62486:62490] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1698642474.988758][62486:62490] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1698642474.988770][62486:62490] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1698642474.988778][62486:62490] CHIP:CTL: Setting Regulatory Config [1698642474.988781][62486:62490] CHIP:CTL: No regulatory config supplied by controller, leaving as device default (0) [1698642474.988806][62486:62490] CHIP:DMG: ICR moving to [AddingComm] [1698642474.988818][62486:62490] CHIP:DMG: ICR moving to [AddedComma] [1698642474.988926][62486:62490] CHIP:EM: <<< [E:23297i S:36413 M:219369911] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1698642474.989067][62486:62490] CHIP:DMG: ICR moving to [CommandSen] [1698642474.989099][62486:62490] CHIP:DMG: ICR moving to [AwaitingDe] [1698642474.989221][62486:62490] CHIP:EM: <<< [E:23296i S:36413 M:219369912 (Ack:214752172)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698642474.989271][62486:62490] CHIP:EM: Flushed pending ack for MessageCounter:214752172 on exchange 23296i [1698642475.335515][62486:62490] CHIP:EM: >>> [E:23297i S:36413 M:214752173 (Ack:219369911)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1698642475.335582][62486:62490] CHIP:EM: Found matching exchange: 23297i, Delegate: 0x7fbfc4006c68 [1698642475.335607][62486:62490] CHIP:EM: Rxd Ack; Removing MessageCounter:219369911 from Retrans Table on exchange 23297i [1698642475.335630][62486:62490] CHIP:DMG: ICR moving to [ResponseRe] [1698642475.335663][62486:62490] CHIP:DMG: InvokeResponseMessage = [1698642475.335679][62486:62490] CHIP:DMG: { [1698642475.335695][62486:62490] CHIP:DMG: suppressResponse = false, [1698642475.335719][62486:62490] CHIP:DMG: InvokeResponseIBs = [1698642475.335755][62486:62490] CHIP:DMG: [ [1698642475.335778][62486:62490] CHIP:DMG: InvokeResponseIB = [1698642475.335813][62486:62490] CHIP:DMG: { [1698642475.335838][62486:62490] CHIP:DMG: CommandDataIB = [1698642475.335930][62486:62490] CHIP:DMG: { [1698642475.335943][62486:62490] CHIP:DMG: CommandPathIB = [1698642475.335951][62486:62490] CHIP:DMG: { [1698642475.335959][62486:62490] CHIP:DMG: EndpointId = 0x0, [1698642475.335995][62486:62490] CHIP:DMG: ClusterId = 0x30, [1698642475.336023][62486:62490] CHIP:DMG: CommandId = 0x3, [1698642475.336058][62486:62490] CHIP:DMG: }, [1698642475.336077][62486:62490] CHIP:DMG: [1698642475.336081][62486:62490] CHIP:DMG: CommandFields = [1698642475.336086][62486:62490] CHIP:DMG: { [1698642475.336092][62486:62490] CHIP:DMG: 0x0 = 0, [1698642475.336124][62486:62490] CHIP:DMG: 0x1 = "" (0 chars), [1698642475.336157][62486:62490] CHIP:DMG: }, [1698642475.336193][62486:62490] CHIP:DMG: }, [1698642475.336236][62486:62490] CHIP:DMG: [1698642475.336246][62486:62490] CHIP:DMG: }, [1698642475.336256][62486:62490] CHIP:DMG: [1698642475.336284][62486:62490] CHIP:DMG: ], [1698642475.336314][62486:62490] CHIP:DMG: [1698642475.336334][62486:62490] CHIP:DMG: InteractionModelRevision = 1 [1698642475.336357][62486:62490] CHIP:DMG: }, [1698642475.338972][62486:62490] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1698642475.339008][62486:62490] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0 [1698642475.339033][62486:62490] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='ConfigRegulatory' error='src/controller/CHIPDeviceController.cpp:2205: Success' [1698642475.339045][62486:62490] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1698642475.339056][62486:62490] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1698642475.339102][62486:62490] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1698642475.339160][62486:62490] CHIP:CTL: Sending request for PAI certificate [1698642475.339170][62486:62490] CHIP:CTL: Sending Certificate Chain request to 0x7fbfc4001fc0 device [1698642475.339201][62486:62490] CHIP:DMG: ICR moving to [AddingComm] [1698642475.339214][62486:62490] CHIP:DMG: ICR moving to [AddedComma] [1698642475.339342][62486:62490] CHIP:EM: <<< [E:23298i S:36413 M:219369913] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1698642475.339456][62486:62490] CHIP:DMG: ICR moving to [CommandSen] [1698642475.339496][62486:62490] CHIP:DMG: ICR moving to [AwaitingDe] [1698642475.339537][62486:62490] CHIP:EM: <<< [E:23297i S:36413 M:219369914 (Ack:214752173)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1698642475.339572][62486:62490] CHIP:EM: Flushed pending ack for MessageCounter:214752173 on exchange 23297i [1698642475.711053][62486:62490] CHIP:EM: Retransmitting MessageCounter:219369913 on exchange 23298i Send Cnt 1 [1698642476.048098][62486:62490] CHIP:EM: Retransmitting MessageCounter:219369913 on exchange 23298i Send Cnt 2 [1698642476.634636][62486:62490] CHIP:EM: Retransmitting MessageCounter:219369913 on exchange 23298i Send Cnt 3 [1698642477.643789][62486:62490] CHIP:EM: Retransmitting MessageCounter:219369913 on exchange 23298i Send Cnt 4 [1698642479.258226][62486:62490] CHIP:EM: Failed to Send CHIP MessageCounter:219369913 on exchange 23298i sendCount: 4 max retries: 4 [1698642505.343885][62486:62490] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 23298i [1698642505.343947][62486:62490] CHIP:CTL: Device failed to receive the Certificate Chain request Response: src/app/CommandSender.cpp:271: CHIP Error 0x00000032: Timeout [1698642505.343960][62486:62490] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='SendPAICertificateRequest' error='src/app/CommandSender.cpp:271: CHIP Error 0x00000032: Timeout' [1698642505.343970][62486:62490] CHIP:CTL: Error on commissioning step 'SendPAICertificateRequest': 'src/app/CommandSender.cpp:271: CHIP Error 0x00000032: Timeout' [1698642505.343975][62486:62490] CHIP:CTL: Failed to perform commissioning step 10 [1698642505.343981][62486:62490] CHIP:CTL: Going from commissioning step 'SendPAICertificateRequest' with lastErr = 'src/app/CommandSender.cpp:271: CHIP Error 0x00000032: Timeout' -> 'Cleanup' [1698642505.343994][62486:62490] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = 'src/app/CommandSender.cpp:271: CHIP Error 0x00000032: Timeout' [1698642505.344000][62486:62490] CHIP:CTL: Expiring failsafe on proxy 0x7fbfc4001fc0 [1698642505.344029][62486:62490] CHIP:DMG: ICR moving to [AddingComm] [1698642505.344046][62486:62490] CHIP:DMG: ICR moving to [AddedComma] [1698642505.344208][62486:62490] CHIP:EM: <<< [E:23299i S:36413 M:219369915] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e65f:1ff:feaf:e2f3%enp0s3]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1698642505.344268][62486:62490] CHIP:CTL: Failed to send command to disarm fail-safe: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000065: Network is unreachable [1698642505.344276][62486:62490] CHIP:CTL: OnCommissioningStatusUpdate - stageCompleted='Cleanup' error='src/controller/CHIPDeviceController.cpp:1691: Success' [1698642505.344281][62486:62490] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1698642505.344297][62486:62490] CHIP:CTL: Device commissioning Failure: src/app/CommandSender.cpp:271: CHIP Error 0x00000032: Timeout requestId = 1 HTTP/1.1 200 OK Content-Type: application/json Content-Length: 182 {"detail":{"error":50,"message":"src/app/CommandSender.cpp:271: CHIP Error 0x00000032: Timeout","nodeId":1},"error":{"code":-32603,"message":"Internal error"},"id":1,"jsonrpc":"2.0"} [1698642505.344524][62486:62490] CHIP:IN: SecureSession[0x7fbfc40030b0]: MarkForEviction Type:1 LSID:36413 [1698642505.344532][62486:62490] CHIP:SC: SecureSession[0x7fbfc40030b0, LSID:36413]: State change 'kActive' --> 'kPendingEviction' [1698642505.344551][62486:62490] CHIP:IN: SecureSession[0x7fbfc40030b0]: Released - Type:1 LSID:36413 [1698642505.344561][62486:62490] CHIP:DMG: ICR moving to [AwaitingDe]