Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[1.3] Persistent Subscription crash in LIT example app #30944

Open
yunhanw-google opened this issue Dec 12, 2023 · 2 comments
Open

[1.3] Persistent Subscription crash in LIT example app #30944

yunhanw-google opened this issue Dec 12, 2023 · 2 comments
Labels
bug Something isn't working crash icd Intermittently Connected Devices needs triage

Comments

@yunhanw-google
Copy link
Contributor

yunhanw-google commented Dec 12, 2023 •
edited
Loading

Reproduction steps

Controller side
./out/linux-x64-chip-tool/chip-tool interactive start
pairing onnetwork-long 1 20202021 3840
accesscontrol subscribe-event access-control-entry-changed 5 20 1 0

Server side
./out/linux-x64-lit-icd-ipv6only/lit-icd-app

After subscription is established, we restart lit-icd-app
then lit-icd-app crash wit the below log
Disabling chip_persist_subscriptions can workaround this issue.

Bug prevalence

consistent

GitHub hash of the SDK that was being used

918b92b

Platform

raspi, core

Platform Version(s)

No response

Type

Core SDK Crash

Anything else?

Client log: 
[1702343379.315277][75583:75585] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
[1702343379.315306][75583:75585] CHIP:CTL: Received certificate signing request from the device
[1702343379.315327][75583:75585] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest'
[1702343379.315346][75583:75585] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR'
[1702343379.315372][75583:75585] CHIP:CTL: Performing next commissioning step 'ValidateCSR'
[1702343379.316205][75583:75585] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR'
[1702343379.316225][75583:75585] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain'
[1702343379.316252][75583:75585] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain'
[1702343379.316271][75583:75585] CHIP:CTL: Getting certificate chain for the device from the issuer
[1702343379.316490][75583:75585] CHIP:CTL: Verifying Certificate Signing Request
[1702343379.317106][75583:75585] CHIP:CTL: Generating NOC
[1702343379.317304][75583:75585] CHIP:CTL: Providing certificate chain to the commissioner
[1702343379.317326][75583:75585] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status src/controller/ExampleOperationalCredentialsIssuer.cpp:395: Success
[1702343379.317348][75583:75585] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain'
[1702343379.317484][75583:75585] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert'
[1702343379.317503][75583:75585] CHIP:CTL: Sending root certificate to the device
[1702343379.317548][75583:75585] CHIP:DMG: ICR moving to [AddingComm]
[1702343379.317569][75583:75585] CHIP:DMG: ICR moving to [AddedComma]
[1702343379.317671][75583:75585] CHIP:EM: <<< [E:49788i S:61952 M:250313562] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[1702343379.317767][75583:75585] CHIP:DMG: ICR moving to [CommandSen]
[1702343379.317783][75583:75585] CHIP:CTL: Sent root certificate to the device
[1702343379.317944][75583:75585] CHIP:DMG: ICR moving to [AwaitingDe]
[1702343379.318011][75583:75585] CHIP:EM: <<< [E:49787i S:61952 M:250313563 (Ack:185061487)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1702343379.318059][75583:75585] CHIP:EM: Flushed pending ack for MessageCounter:185061487 on exchange 49787i
[1702343379.318790][75583:75585] CHIP:EM: >>> [E:49788i S:61952 M:185061488 (Ack:250313562)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1702343379.318808][75583:75585] CHIP:EM: Found matching exchange: 49788i, Delegate: 0x7f6e7c021f18
[1702343379.318829][75583:75585] CHIP:EM: Rxd Ack; Removing MessageCounter:250313562 from Retrans Table on exchange 49788i
[1702343379.319606][75583:75585] CHIP:EM: >>> [E:49788i S:61952 M:185061489 (Ack:250313562)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1702343379.319624][75583:75585] CHIP:EM: Found matching exchange: 49788i, Delegate: 0x7f6e7c021f18
[1702343379.319640][75583:75585] CHIP:EM: CHIP MessageCounter:250313562 not in RetransTable on exchange 49788i
[1702343379.319664][75583:75585] CHIP:DMG: ICR moving to [ResponseRe]
[1702343379.319691][75583:75585] CHIP:DMG: InvokeResponseMessage =
[1702343379.319704][75583:75585] CHIP:DMG: {
[1702343379.319720][75583:75585] CHIP:DMG: 	suppressResponse = false, 
[1702343379.319735][75583:75585] CHIP:DMG: 	InvokeResponseIBs =
[1702343379.319757][75583:75585] CHIP:DMG: 	[
[1702343379.319770][75583:75585] CHIP:DMG: 		InvokeResponseIB =
[1702343379.319792][75583:75585] CHIP:DMG: 		{
[1702343379.319806][75583:75585] CHIP:DMG: 			CommandStatusIB =
[1702343379.319824][75583:75585] CHIP:DMG: 			{
[1702343379.319839][75583:75585] CHIP:DMG: 				CommandPathIB =
[1702343379.319858][75583:75585] CHIP:DMG: 				{
[1702343379.319876][75583:75585] CHIP:DMG: 					EndpointId = 0x0,
[1702343379.319896][75583:75585] CHIP:DMG: 					ClusterId = 0x3e,
[1702343379.319917][75583:75585] CHIP:DMG: 					CommandId = 0xb,
[1702343379.319933][75583:75585] CHIP:DMG: 				},
[1702343379.319951][75583:75585] CHIP:DMG: 				
[1702343379.319966][75583:75585] CHIP:DMG: 				StatusIB =
[1702343379.319984][75583:75585] CHIP:DMG: 				{
[1702343379.319999][75583:75585] CHIP:DMG: 					status = 0x00 (SUCCESS),
[1702343379.320012][75583:75585] CHIP:DMG: 				},
[1702343379.320032][75583:75585] CHIP:DMG: 				
[1702343379.320048][75583:75585] CHIP:DMG: 			},
[1702343379.320070][75583:75585] CHIP:DMG: 			
[1702343379.320084][75583:75585] CHIP:DMG: 		},
[1702343379.320107][75583:75585] CHIP:DMG: 		
[1702343379.320134][75583:75585] CHIP:DMG: 	],
[1702343379.320154][75583:75585] CHIP:DMG: 	
[1702343379.320167][75583:75585] CHIP:DMG: 	InteractionModelRevision = 11
[1702343379.320181][75583:75585] CHIP:DMG: },
[1702343379.320226][75583:75585] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
[1702343379.320241][75583:75585] CHIP:CTL: Device confirmed that it has received the root certificate
[1702343379.320258][75583:75585] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert'
[1702343379.320271][75583:75585] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
[1702343379.320287][75583:75585] CHIP:CTL: Performing next commissioning step 'SendNOC'
[1702343379.320315][75583:75585] CHIP:DMG: ICR moving to [AddingComm]
[1702343379.320333][75583:75585] CHIP:DMG: ICR moving to [AddedComma]
[1702343379.320401][75583:75585] CHIP:EM: <<< [E:49789i S:61952 M:250313564] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[1702343379.320462][75583:75585] CHIP:DMG: ICR moving to [CommandSen]
[1702343379.320478][75583:75585] CHIP:CTL: Sent operational certificate to the device
[1702343379.320506][75583:75585] CHIP:DMG: ICR moving to [AwaitingDe]
[1702343379.320558][75583:75585] CHIP:EM: <<< [E:49788i S:61952 M:250313565 (Ack:185061489)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1702343379.320600][75583:75585] CHIP:EM: Flushed pending ack for MessageCounter:185061489 on exchange 49788i
[1702343379.321577][75583:75585] CHIP:EM: >>> [E:49789i S:61952 M:185061490 (Ack:250313564)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1702343379.321594][75583:75585] CHIP:EM: Found matching exchange: 49789i, Delegate: 0x7f6e7c02df38
[1702343379.321611][75583:75585] CHIP:EM: Rxd Ack; Removing MessageCounter:250313564 from Retrans Table on exchange 49789i
[1702343379.326670][75583:75585] CHIP:EM: >>> [E:49789i S:61952 M:185061491 (Ack:250313564)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1702343379.326692][75583:75585] CHIP:EM: Found matching exchange: 49789i, Delegate: 0x7f6e7c02df38
[1702343379.326705][75583:75585] CHIP:EM: CHIP MessageCounter:250313564 not in RetransTable on exchange 49789i
[1702343379.326721][75583:75585] CHIP:DMG: ICR moving to [ResponseRe]
[1702343379.326745][75583:75585] CHIP:DMG: InvokeResponseMessage =
[1702343379.326755][75583:75585] CHIP:DMG: {
[1702343379.326772][75583:75585] CHIP:DMG: 	suppressResponse = false, 
[1702343379.326791][75583:75585] CHIP:DMG: 	InvokeResponseIBs =
[1702343379.326815][75583:75585] CHIP:DMG: 	[
[1702343379.326831][75583:75585] CHIP:DMG: 		InvokeResponseIB =
[1702343379.326853][75583:75585] CHIP:DMG: 		{
[1702343379.326866][75583:75585] CHIP:DMG: 			CommandDataIB =
[1702343379.326883][75583:75585] CHIP:DMG: 			{
[1702343379.326899][75583:75585] CHIP:DMG: 				CommandPathIB =
[1702343379.326918][75583:75585] CHIP:DMG: 				{
[1702343379.326935][75583:75585] CHIP:DMG: 					EndpointId = 0x0,
[1702343379.326954][75583:75585] CHIP:DMG: 					ClusterId = 0x3e,
[1702343379.326973][75583:75585] CHIP:DMG: 					CommandId = 0x8,
[1702343379.326990][75583:75585] CHIP:DMG: 				},
[1702343379.327010][75583:75585] CHIP:DMG: 				
[1702343379.327027][75583:75585] CHIP:DMG: 				CommandFields = 
[1702343379.327046][75583:75585] CHIP:DMG: 				{
[1702343379.327064][75583:75585] CHIP:DMG: 					0x0 = 0, 
[1702343379.327083][75583:75585] CHIP:DMG: 					0x1 = 1, 
[1702343379.327101][75583:75585] CHIP:DMG: 				},
[1702343379.327118][75583:75585] CHIP:DMG: 			},
[1702343379.327141][75583:75585] CHIP:DMG: 			
[1702343379.327155][75583:75585] CHIP:DMG: 		},
[1702343379.327176][75583:75585] CHIP:DMG: 		
[1702343379.327189][75583:75585] CHIP:DMG: 	],
[1702343379.327209][75583:75585] CHIP:DMG: 	
[1702343379.327226][75583:75585] CHIP:DMG: 	InteractionModelRevision = 11
[1702343379.327240][75583:75585] CHIP:DMG: },
[1702343379.327298][75583:75585] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
[1702343379.327339][75583:75585] CHIP:CTL: Device returned status 0 on receiving the NOC
[1702343379.327355][75583:75585] CHIP:CTL: Operational credentials provisioned on device 0x7f6e7c02b200
[1702343379.327370][75583:75585] CHIP:TOO: Secure Pairing Success
[1702343379.327384][75583:75585] CHIP:TOO: CASE establishment successful
[1702343379.327403][75583:75585] CHIP:CTL: Successfully finished commissioning step 'SendNOC'
[1702343379.327418][75583:75585] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'ICDGetRegistrationInfo'
[1702343379.327440][75583:75585] CHIP:CTL: Performing next commissioning step 'ICDGetRegistrationInfo'
[1702343379.327674][75583:75585] CHIP:CTL: Successfully finished commissioning step 'ICDGetRegistrationInfo'
[1702343379.327692][75583:75585] CHIP:CTL: Commissioning stage next step: 'ICDGetRegistrationInfo' -> 'ICDRegistration'
[1702343379.327715][75583:75585] CHIP:CTL: Performing next commissioning step 'ICDRegistration'
[1702343379.327755][75583:75585] CHIP:DMG: ICR moving to [AddingComm]
[1702343379.327792][75583:75585] CHIP:DMG: ICR moving to [AddedComma]
[1702343379.327890][75583:75585] CHIP:EM: <<< [E:49790i S:61952 M:250313566] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[1702343379.327981][75583:75585] CHIP:DMG: ICR moving to [CommandSen]
[1702343379.328038][75583:75585] CHIP:DMG: ICR moving to [AwaitingDe]
[1702343379.328154][75583:75585] CHIP:EM: <<< [E:49789i S:61952 M:250313567 (Ack:185061491)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1702343379.328217][75583:75585] CHIP:EM: Flushed pending ack for MessageCounter:185061491 on exchange 49789i
[1702343379.331380][75583:75585] CHIP:EM: >>> [E:49790i S:61952 M:185061492 (Ack:250313566)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1702343379.331408][75583:75585] CHIP:EM: Found matching exchange: 49790i, Delegate: 0x7f6e7c021f18
[1702343379.331437][75583:75585] CHIP:EM: Rxd Ack; Removing MessageCounter:250313566 from Retrans Table on exchange 49790i
[1702343379.331469][75583:75585] CHIP:DMG: ICR moving to [ResponseRe]
[1702343379.331504][75583:75585] CHIP:DMG: InvokeResponseMessage =
[1702343379.331521][75583:75585] CHIP:DMG: {
[1702343379.331538][75583:75585] CHIP:DMG: 	suppressResponse = false, 
[1702343379.331555][75583:75585] CHIP:DMG: 	InvokeResponseIBs =
[1702343379.331584][75583:75585] CHIP:DMG: 	[
[1702343379.331600][75583:75585] CHIP:DMG: 		InvokeResponseIB =
[1702343379.331625][75583:75585] CHIP:DMG: 		{
[1702343379.331642][75583:75585] CHIP:DMG: 			CommandDataIB =
[1702343379.331660][75583:75585] CHIP:DMG: 			{
[1702343379.331678][75583:75585] CHIP:DMG: 				CommandPathIB =
[1702343379.331696][75583:75585] CHIP:DMG: 				{
[1702343379.331716][75583:75585] CHIP:DMG: 					EndpointId = 0x0,
[1702343379.331735][75583:75585] CHIP:DMG: 					ClusterId = 0x46,
[1702343379.331760][75583:75585] CHIP:DMG: 					CommandId = 0x1,
[1702343379.331778][75583:75585] CHIP:DMG: 				},
[1702343379.331800][75583:75585] CHIP:DMG: 				
[1702343379.331818][75583:75585] CHIP:DMG: 				CommandFields = 
[1702343379.331837][75583:75585] CHIP:DMG: 				{
[1702343379.331857][75583:75585] CHIP:DMG: 					0x0 = 1767614176, 
[1702343379.331876][75583:75585] CHIP:DMG: 				},
[1702343379.331894][75583:75585] CHIP:DMG: 			},
[1702343379.331919][75583:75585] CHIP:DMG: 			
[1702343379.331935][75583:75585] CHIP:DMG: 		},
[1702343379.331959][75583:75585] CHIP:DMG: 		
[1702343379.331974][75583:75585] CHIP:DMG: 	],
[1702343379.331999][75583:75585] CHIP:DMG: 	
[1702343379.332015][75583:75585] CHIP:DMG: 	InteractionModelRevision = 11
[1702343379.332031][75583:75585] CHIP:DMG: },
[1702343379.332094][75583:75585] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0046 Command=0x0000_0001
[1702343379.333797][75583:75585] CHIP:TOO: Saved ICD Symmetric key for 0000000000000001
[1702343379.333820][75583:75585] CHIP:TOO: ICD Registration Complete for device 0000000000000001 / Check-In NodeID: 000000000001B669 / Monitored Subject: 000000000001B669 / Symmetric Key: 19319a02445ea55898e401e107efe7fd
[1702343379.333844][75583:75585] CHIP:CTL: Successfully finished commissioning step 'ICDRegistration'
[1702343379.333861][75583:75585] CHIP:CTL: Commissioning stage next step: 'ICDRegistration' -> 'ICDSendStayActive'
[1702343379.333885][75583:75585] CHIP:CTL: Performing next commissioning step 'ICDSendStayActive'
[1702343379.333902][75583:75585] CHIP:CTL: Successfully finished commissioning step 'ICDSendStayActive'
[1702343379.333919][75583:75585] CHIP:CTL: Commissioning stage next step: 'ICDSendStayActive' -> 'FindOperational'
[1702343379.333939][75583:75585] CHIP:CTL: Performing next commissioning step 'FindOperational'
[1702343379.333955][75583:75585] CHIP:IN: Expiring all sessions for node <0000000000000001, 1>!!
[1702343379.333973][75583:75585] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1702343379.333991][75583:75585] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1702343379.334014][75583:75585] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1702343379.334196][75583:75585] CHIP:DMG: ICR moving to [AwaitingDe]
[1702343379.334285][75583:75585] CHIP:EM: <<< [E:49790i S:61952 M:250313568 (Ack:185061492)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1702343379.334337][75583:75585] CHIP:EM: Flushed pending ack for MessageCounter:185061492 on exchange 49790i
[1702343379.334675][75583:75585] CHIP:DIS: Lookup clearing interface for non LL address
[1702343379.334722][75583:75585] CHIP:DIS: UDP:[2001:db8:1::242:c0a8:902%eth0]:5540: new best score: 6
[1702343379.334882][75583:75585] CHIP:DIS: UDP:[fe80::42:c0ff:fea8:902%eth0]:5540: new best score: 7
[1702343379.334899][75583:75585] CHIP:DIS: Checking node lookup status after 1 ms
[1702343379.334915][75583:75585] CHIP:DIS: Keeping DNSSD lookup active
[1702343379.533392][75583:75585] CHIP:DIS: Checking node lookup status after 200 ms
[1702343379.533502][75583:75585] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::42:c0ff:fea8:902%eth0]:5540 while in state 2
[1702343379.533523][75583:75585] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1702343379.533611][75583:75585] CHIP:IN: SecureSession[0x7f6e7c02d040]: Allocated Type:2 LSID:61953
[1702343379.533638][75583:75585] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1702343379.534241][75583:75585] CHIP:EM: <<< [E:49791i S:0 M:195658323] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1702343379.534355][75583:75585] CHIP:SC: Sent Sigma1 msg
[1702343379.534373][75583:75585] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1702343379.535781][75583:75585] CHIP:EM: >>> [E:49791i S:0 M:229831622 (Ack:195658323)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1702343379.535813][75583:75585] CHIP:EM: Found matching exchange: 49791i, Delegate: 0x7f6e7c033588
[1702343379.535837][75583:75585] CHIP:EM: Rxd Ack; Removing MessageCounter:195658323 from Retrans Table on exchange 49791i
[1702343379.535867][75583:75585] CHIP:SC: Received Sigma2 msg
[1702343379.535890][75583:75585] CHIP:SC: Peer assigned session session ID 49724
[1702343379.537926][75583:75585] CHIP:SC: Found MRP parameters in the message
[1702343379.537960][75583:75585] CHIP:SC: Sending Sigma3
[1702343379.538294][75583:75585] CHIP:EM: <<< [E:49791i S:0 M:195658324 (Ack:229831622)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1702343379.538383][75583:75585] CHIP:SC: Sent Sigma3 msg
[1702343379.542547][75583:75585] CHIP:EM: >>> [E:49791i S:0 M:229831623 (Ack:195658324)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1702343379.542578][75583:75585] CHIP:EM: Found matching exchange: 49791i, Delegate: 0x7f6e7c033588
[1702343379.542601][75583:75585] CHIP:EM: Rxd Ack; Removing MessageCounter:195658324 from Retrans Table on exchange 49791i
[1702343379.542630][75583:75585] CHIP:SC: Success status report received. Session was established
[1702343379.544501][75583:75585] CHIP:SC: SecureSession[0x7f6e7c02d040, LSID:61953]: State change 'kEstablishing' --> 'kActive'
[1702343379.544526][75583:75585] CHIP:IN: SecureSession[0x7f6e7c02d040]: Activated - Type:2 LSID:61953
[1702343379.544541][75583:75585] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:61953 PSID:49724!
[1702343379.544560][75583:75585] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1702343379.544610][75583:75585] CHIP:CTL: Successfully finished commissioning step 'FindOperational'
[1702343379.544627][75583:75585] CHIP:CTL: Commissioning stage next step: 'FindOperational' -> 'SendComplete'
[1702343379.544650][75583:75585] CHIP:CTL: Performing next commissioning step 'SendComplete'
[1702343379.544692][75583:75585] CHIP:DMG: ICR moving to [AddingComm]
[1702343379.544710][75583:75585] CHIP:DMG: ICR moving to [AddedComma]
[1702343379.544807][75583:75585] CHIP:EM: <<< [E:49792i S:61953 M:207448110] (S) Msg TX to 1:0000000000000001 [B8EA] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[1702343379.544896][75583:75585] CHIP:DMG: ICR moving to [CommandSen]
[1702343379.544965][75583:75585] CHIP:EM: <<< [E:49791i S:0 M:195658325 (Ack:229831623)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1702343379.545012][75583:75585] CHIP:EM: Flushed pending ack for MessageCounter:229831623 on exchange 49791i
[1702343379.551374][75583:75585] CHIP:EM: >>> [E:49792i S:61953 M:129893396 (Ack:207448110)] (S) Msg RX from 1:0000000000000001 [B8EA] --- Type 0001:09 (IM:InvokeCommandResponse)
[1702343379.551405][75583:75585] CHIP:EM: Found matching exchange: 49792i, Delegate: 0x7f6e7c021f18
[1702343379.551428][75583:75585] CHIP:EM: Rxd Ack; Removing MessageCounter:207448110 from Retrans Table on exchange 49792i
[1702343379.551451][75583:75585] CHIP:DMG: ICR moving to [ResponseRe]
[1702343379.551486][75583:75585] CHIP:DMG: InvokeResponseMessage =
[1702343379.551502][75583:75585] CHIP:DMG: {
[1702343379.551517][75583:75585] CHIP:DMG: 	suppressResponse = false, 
[1702343379.551532][75583:75585] CHIP:DMG: 	InvokeResponseIBs =
[1702343379.551554][75583:75585] CHIP:DMG: 	[
[1702343379.551568][75583:75585] CHIP:DMG: 		InvokeResponseIB =
[1702343379.551589][75583:75585] CHIP:DMG: 		{
[1702343379.551605][75583:75585] CHIP:DMG: 			CommandDataIB =
[1702343379.551622][75583:75585] CHIP:DMG: 			{
[1702343379.551638][75583:75585] CHIP:DMG: 				CommandPathIB =
[1702343379.551655][75583:75585] CHIP:DMG: 				{
[1702343379.551673][75583:75585] CHIP:DMG: 					EndpointId = 0x0,
[1702343379.551691][75583:75585] CHIP:DMG: 					ClusterId = 0x30,
[1702343379.551707][75583:75585] CHIP:DMG: 					CommandId = 0x5,
[1702343379.551725][75583:75585] CHIP:DMG: 				},
[1702343379.551743][75583:75585] CHIP:DMG: 				
[1702343379.551759][75583:75585] CHIP:DMG: 				CommandFields = 
[1702343379.551776][75583:75585] CHIP:DMG: 				{
[1702343379.551794][75583:75585] CHIP:DMG: 					0x0 = 0, 
[1702343379.551813][75583:75585] CHIP:DMG: 					0x1 = "" (0 chars), 
[1702343379.551830][75583:75585] CHIP:DMG: 				},
[1702343379.551846][75583:75585] CHIP:DMG: 			},
[1702343379.551867][75583:75585] CHIP:DMG: 			
[1702343379.551892][75583:75585] CHIP:DMG: 		},
[1702343379.551928][75583:75585] CHIP:DMG: 		
[1702343379.551951][75583:75585] CHIP:DMG: 	],
[1702343379.551985][75583:75585] CHIP:DMG: 	
[1702343379.552010][75583:75585] CHIP:DMG: 	InteractionModelRevision = 11
[1702343379.552032][75583:75585] CHIP:DMG: },
[1702343379.552141][75583:75585] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005
[1702343379.552183][75583:75585] CHIP:CTL: Received CommissioningComplete response, errorCode=0
[1702343379.552207][75583:75585] CHIP:CTL: Successfully finished commissioning step 'SendComplete'
[1702343379.552230][75583:75585] CHIP:CTL: Commissioning stage next step: 'SendComplete' -> 'Cleanup'
[1702343379.552261][75583:75585] CHIP:CTL: Performing next commissioning step 'Cleanup'
[1702343379.552286][75583:75585] CHIP:IN: SecureSession[0x7f6e7c004020]: MarkForEviction Type:1 LSID:61952
[1702343379.552307][75583:75585] CHIP:SC: SecureSession[0x7f6e7c004020, LSID:61952]: State change 'kActive' --> 'kPendingEviction'
[1702343379.552354][75583:75585] CHIP:IN: SecureSession[0x7f6e7c004020]: Released - Type:1 LSID:61952
[1702343379.552380][75583:75585] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1702343379.552404][75583:75585] CHIP:TOO: Device commissioning completed with success
[1702343379.552466][75583:75585] CHIP:DMG: ICR moving to [AwaitingDe]
[1702343379.552575][75583:75585] CHIP:EM: <<< [E:49792i S:61953 M:207448111 (Ack:129893396)] (S) Msg TX to 1:0000000000000001 [B8EA] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1702343379.552655][75583:75585] CHIP:EM: Flushed pending ack for MessageCounter:129893396 on exchange 49792i
>>> accesscontrol subscribe-event access-control-entry-changed 5 20 1 0
[1702343393.860570][75583:75583] CHIP:TOO: Command: accesscontrol subscribe-event access-control-entry-changed 5 20 1 0 
[1702343393.861056][75583:75585] CHIP:TOO: Sending command to node 0x1
[1702343393.861359][75583:75585] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1702343393.861383][75583:75585] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1702343393.861415][75583:75585] CHIP:DIS: Found an existing secure session to [1:0000000000000001]!
[1702343393.861434][75583:75585] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5
[1702343393.861469][75583:75585] CHIP:TOO: Sending SubscribeEvent to:
[1702343393.861506][75583:75585] CHIP:TOO: 	cluster 0x0000_001F, event: 0x0000_0000, endpoint 0
[1702343393.861697][75583:75585] CHIP:EM: <<< [E:49793i S:61953 M:207448112] (S) Msg TX to 1:0000000000000001 [B8EA] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0001:03 (IM:SubscribeRequest)
[1702343393.861832][75583:75585] CHIP:DMG: MoveToState ReadClient[0x7f6e7c021f10]: Moving to [AwaitingIn]
[1702343393.865350][75583:75585] CHIP:EM: >>> [E:49793i S:61953 M:129893397 (Ack:207448112)] (S) Msg RX from 1:0000000000000001 [B8EA] --- Type 0001:05 (IM:ReportData)
[1702343393.865385][75583:75585] CHIP:EM: Found matching exchange: 49793i, Delegate: 0x7f6e7c021f20
[1702343393.865409][75583:75585] CHIP:EM: Rxd Ack; Removing MessageCounter:207448112 from Retrans Table on exchange 49793i
[1702343393.865464][75583:75585] CHIP:DMG: ReportDataMessage =
[1702343393.865481][75583:75585] CHIP:DMG: {
[1702343393.865497][75583:75585] CHIP:DMG: 	SubscriptionId = 0xa7ff7068,
[1702343393.865513][75583:75585] CHIP:DMG: 	EventReportIBs =
[1702343393.865540][75583:75585] CHIP:DMG: 	[
[1702343393.865556][75583:75585] CHIP:DMG: 		EventReportIB =
[1702343393.865583][75583:75585] CHIP:DMG: 		{
[1702343393.865602][75583:75585] CHIP:DMG: 			EventDataIB =
[1702343393.865635][75583:75585] CHIP:DMG: 			{
[1702343393.865660][75583:75585] CHIP:DMG: 				EventPath =
[1702343393.865689][75583:75585] CHIP:DMG: 				{
[1702343393.865715][75583:75585] CHIP:DMG: 					Endpoint = 0x0,
[1702343393.865741][75583:75585] CHIP:DMG: 					Cluster = 0x1f,
[1702343393.865758][75583:75585] CHIP:DMG: 					Event = 0x0,
[1702343393.865778][75583:75585] CHIP:DMG: 				},
[1702343393.865805][75583:75585] CHIP:DMG: 				
[1702343393.865830][75583:75585] CHIP:DMG: 				EventNumber = 0x0000000000000002,
[1702343393.865860][75583:75585] CHIP:DMG: 				PriorityLevel = 0x0000000000000001,
[1702343393.865891][75583:75585] CHIP:DMG: 				EpochTimestamp = 0x0000018C5B92897D,
[1702343393.865915][75583:75585] CHIP:DMG: 				EventData = 
[1702343393.865936][75583:75585] CHIP:DMG: 				{
[1702343393.865958][75583:75585] CHIP:DMG: 					0x1 = NULL
[1702343393.865982][75583:75585] CHIP:DMG: 					0x2 = 0, 
[1702343393.866012][75583:75585] CHIP:DMG: 					0x3 = 1, 
[1702343393.866040][75583:75585] CHIP:DMG: 					0x4 = 
[1702343393.866068][75583:75585] CHIP:DMG: 					{
[1702343393.866097][75583:75585] CHIP:DMG: 						0x1 = 5, 
[1702343393.866126][75583:75585] CHIP:DMG: 						0x2 = 2, 
[1702343393.866153][75583:75585] CHIP:DMG: 						0x3 = [
[1702343393.866185][75583:75585] CHIP:DMG: 								112233, 
[1702343393.866214][75583:75585] CHIP:DMG: 						],
[1702343393.866241][75583:75585] CHIP:DMG: 						0x4 = NULL
[1702343393.866265][75583:75585] CHIP:DMG: 						0xfe = 1, 
[1702343393.866296][75583:75585] CHIP:DMG: 					},
[1702343393.866325][75583:75585] CHIP:DMG: 					0xfe = 1, 
[1702343393.866352][75583:75585] CHIP:DMG: 				},
[1702343393.866377][75583:75585] CHIP:DMG: 			},
[1702343393.866421][75583:75585] CHIP:DMG: 			
[1702343393.866442][75583:75585] CHIP:DMG: 		},
[1702343393.866482][75583:75585] CHIP:DMG: 		
[1702343393.866500][75583:75585] CHIP:DMG: 	],
[1702343393.866538][75583:75585] CHIP:DMG: 	
[1702343393.866557][75583:75585] CHIP:DMG: 	InteractionModelRevision = 11
[1702343393.866575][75583:75585] CHIP:DMG: }
[1702343393.866801][75583:75585] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_001F Event 0x0000_0000
[1702343393.866822][75583:75585] CHIP:TOO:   Event number: 2
[1702343393.866838][75583:75585] CHIP:TOO:   Priority: Info
[1702343393.866854][75583:75585] CHIP:TOO:   Timestamp: 1702343379325
[1702343393.866947][75583:75585] CHIP:TOO:   AccessControlEntryChanged: {
[1702343393.866975][75583:75585] CHIP:TOO:     AdminNodeID: null
[1702343393.867015][75583:75585] CHIP:TOO:     AdminPasscodeID: 0
[1702343393.867037][75583:75585] CHIP:TOO:     ChangeType: 1
[1702343393.867057][75583:75585] CHIP:TOO:     LatestValue: {
[1702343393.867078][75583:75585] CHIP:TOO:       Privilege: 5
[1702343393.867099][75583:75585] CHIP:TOO:       AuthMode: 2
[1702343393.867127][75583:75585] CHIP:TOO:       Subjects: 1 entries
[1702343393.867155][75583:75585] CHIP:TOO:         [1]: 112233
[1702343393.867178][75583:75585] CHIP:TOO:       Targets: null
[1702343393.867198][75583:75585] CHIP:TOO:       FabricIndex: 1
[1702343393.867220][75583:75585] CHIP:TOO:      }
[1702343393.867245][75583:75585] CHIP:TOO:     FabricIndex: 1
[1702343393.867268][75583:75585] CHIP:TOO:    }
[1702343393.867352][75583:75585] CHIP:DMG: MoveToState ReadClient[0x7f6e7c021f10]: Moving to [AwaitingSu]
[1702343393.867478][75583:75585] CHIP:EM: <<< [E:49793i S:61953 M:207448113 (Ack:129893397)] (S) Msg TX to 1:0000000000000001 [B8EA] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0001:01 (IM:StatusResponse)
[1702343393.868106][75583:75585] CHIP:EM: >>> [E:49793i S:61953 M:129893398 (Ack:207448113)] (S) Msg RX from 1:0000000000000001 [B8EA] --- Type 0001:04 (IM:SubscribeResponse)
[1702343393.868176][75583:75585] CHIP:EM: Found matching exchange: 49793i, Delegate: 0x7f6e7c021f20
[1702343393.868198][75583:75585] CHIP:EM: Rxd Ack; Removing MessageCounter:207448113 from Retrans Table on exchange 49793i
[1702343393.868219][75583:75585] CHIP:DMG: SubscribeResponse is received
[1702343393.868242][75583:75585] CHIP:DMG: SubscribeResponseMessage =
[1702343393.868258][75583:75585] CHIP:DMG: {
[1702343393.868273][75583:75585] CHIP:DMG: 	SubscriptionId = 0xa7ff7068,
[1702343393.868289][75583:75585] CHIP:DMG: 	MaxInterval = 0x3c,
[1702343393.868310][75583:75585] CHIP:DMG: 	InteractionModelRevision = 11
[1702343393.868331][75583:75585] CHIP:DMG: }
[1702343393.868360][75583:75585] CHIP:DMG: Subscription established with SubscriptionID = 0xa7ff7068 MinInterval = 5s MaxInterval = 60s Peer = 01:0000000000000001
[1702343393.868393][75583:75585] CHIP:DMG: MoveToState ReadClient[0x7f6e7c021f10]: Moving to [Subscripti]
[1702343393.868425][75583:75585] CHIP:DMG: Refresh LivenessCheckTime for 64224 milliseconds with SubscriptionId = 0xa7ff7068 Peer = 01:0000000000000001
[1702343393.868503][75583:75585] CHIP:EM: <<< [E:49793i S:61953 M:207448114 (Ack:129893398)] (S) Msg TX to 1:0000000000000001 [B8EA] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1702343393.868562][75583:75585] CHIP:EM: Flushed pending ack for MessageCounter:129893398 on exchange 49793i
[1702343394.063335][75583:75585] CHIP:EM: >>> [E:48119r S:0 M:229831624] (U) Msg RX from 0:DF6124A86EC45645 [0000] --- Type 0000:50 (SecureChannel:----)
[1702343394.063382][75583:75585] CHIP:EM: Handling via exchange: 48119r, Delegate: 0x5635c21d2e28
[1702343394.063897][75583:75585] CHIP:EM: OnMessageReceived failed, err = src/app/icd/client/CheckInHandler.cpp:89: CHIP Error 0x00000014: Invalid signature
[1702343407.633343][75583:75585] CHIP:EM: >>> [E:48120r S:61953 M:129893399] (S) Msg RX from 1:0000000000000001 [B8EA] --- Type 0001:05 (IM:ReportData)
[1702343407.633400][75583:75585] CHIP:EM: Handling via exchange: 48120r, Delegate: 0x5635c18196c8
[1702343407.633451][75583:75585] CHIP:DMG: ReportDataMessage =
[1702343407.633469][75583:75585] CHIP:DMG: {
[1702343407.633486][75583:75585] CHIP:DMG: 	SubscriptionId = 0xa7ff7068,
[1702343407.633502][75583:75585] CHIP:DMG: 	InteractionModelRevision = 11
[1702343407.633517][75583:75585] CHIP:DMG: }
[1702343407.633568][75583:75585] CHIP:DMG: Refresh LivenessCheckTime for 64224 milliseconds with SubscriptionId = 0xa7ff7068 Peer = 01:0000000000000001
[1702343407.633710][75583:75585] CHIP:EM: <<< [E:48120r S:61953 M:207448115 (Ack:129893399)] (S) Msg TX to 1:0000000000000001 [B8EA] [UDP:[fe80::42:c0ff:fea8:902%eth0]:5540] --- Type 0001:01 (IM:StatusResponse)
[1702343408.189785][75583:75585] CHIP:EM: Retransmitting MessageCounter:207448115 on exchange 48120r Send Cnt 1
[1702343408.743610][75583:75585] CHIP:EM: Retransmitting MessageCounter:207448115 on exchange 48120r Send Cnt 2
[1702343409.704836][75583:75585] CHIP:EM: Retransmitting MessageCounter:207448115 on exchange 48120r Send Cnt 3
[1702343411.299706][75583:75585] CHIP:EM: Retransmitting MessageCounter:207448115 on exchange 48120r Send Cnt 4
[1702343413.617337][75583:75585] CHIP:EM: Failed to Send CHIP MessageCounter:207448115 on exchange 48120r sendCount: 4 max retries: 4
[1702343413.617387][75583:75585] CHIP:IN: SecureSession[0x7f6e7c02d040]: MarkAsDefunct Type:2 LSID:61953
[1702343413.617403][75583:75585] CHIP:SC: SecureSession[0x7f6e7c02d040, LSID:61953]: State change 'kActive' --> 'kDefunct'
[1702343471.900941][75583:75585] CHIP:DMG: Subscription Liveness timeout with SubscriptionID = 0xa7ff7068, Peer = 01:0000000000000001
[1702343471.900990][75583:75585] CHIP:DMG: Peer is not active now, mark the subscription as InactiveICDSubscription.
[1702343471.901006][75583:75585] CHIP:DMG: MoveToState ReadClient[0x7f6e7c021f10]: Moving to [InactiveIC]
[1702343471.901036][75583:75585] CHIP:TOO: Error: src/app/ReadClient.cpp:919: CHIP Error 0x00000016
[1702343471.901077][75583:75585] CHIP:TOO: Run command failure: src/app/ReadClient.cpp:919: CHIP Error 0x00000016


[1702343393.865014][75580:75580] CHIP:DMG: <RE> Sending report (payload has 83 bytes)...
[1702343393.865123][75580:75580] CHIP:EM: <<< [E:49793r S:49724 M:129893397 (Ack:207448112)] (S) Msg TX to 1:000000000001B669 [B8EA] [UDP:[fe80::42:c0ff:fea8:902%eth0]:47137] --- Type 0001:05 (IM:ReportData)
[1702343393.865237][75580:75580] CHIP:DMG: IM RH moving to [AwaitingReportResponse]
[1702343393.865254][75580:75580] CHIP:DMG: <RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
[1702343393.865271][75580:75580] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1702343393.865574][75580:75580] CHIP:DIS: Lookup clearing interface for non LL address
[1702343393.865623][75580:75580] CHIP:DIS: UDP:[2001:db8:1::242:c0a8:902%eth0]:47137: new best score: 6
[1702343393.865790][75580:75580] CHIP:DIS: UDP:[fe80::42:c0ff:fea8:902%eth0]:47137: new best score: 7
[1702343393.865804][75580:75580] CHIP:DIS: Checking node lookup status after 3 ms
[1702343393.865820][75580:75580] CHIP:DIS: Keeping DNSSD lookup active
[1702343393.867697][75580:75580] CHIP:EM: >>> [E:49793r S:49724 M:207448113 (Ack:129893397)] (S) Msg RX from 1:000000000001B669 [B8EA] --- Type 0001:01 (IM:StatusResponse)
[1702343393.867733][75580:75580] CHIP:EM: Found matching exchange: 49793r, Delegate: 0x5637723b4158
[1702343393.867758][75580:75580] CHIP:EM: Rxd Ack; Removing MessageCounter:129893397 from Retrans Table on exchange 49793r
[1702343393.867795][75580:75580] CHIP:DMG: StatusResponseMessage =
[1702343393.867812][75580:75580] CHIP:DMG: {
[1702343393.867828][75580:75580] CHIP:DMG: 	Status = 0x00 (SUCCESS),
[1702343393.867844][75580:75580] CHIP:DMG: 	InteractionModelRevision = 11
[1702343393.867859][75580:75580] CHIP:DMG: }
[1702343393.867874][75580:75580] CHIP:IM: Received status response, status is 0x00 (SUCCESS)
[1702343393.867979][75580:75580] CHIP:EM: <<< [E:49793r S:49724 M:129893398 (Ack:207448113)] (S) Msg TX to 1:000000000001B669 [B8EA] [UDP:[fe80::42:c0ff:fea8:902%eth0]:47137] --- Type 0001:04 (IM:SubscribeResponse)
[1702343393.868077][75580:75580] CHIP:DMG: Registered a ReadHandler that will schedule a report between system Timestamp: 0x0000000083A28F77 and system Timestamp 0x0000000083A3664F.
[1702343393.868098][75580:75580] CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
[1702343393.868112][75580:75580] CHIP:DMG: IM RH moving to [CanStartReporting]
[1702343393.868613][75580:75580] CHIP:EM: >>> [E:49793r S:49724 M:207448114 (Ack:129893398)] (S) Msg RX from 1:000000000001B669 [B8EA] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1702343393.868635][75580:75580] CHIP:EM: Found matching exchange: 49793r, Delegate: (nil)
[1702343393.868655][75580:75580] CHIP:EM: Rxd Ack; Removing MessageCounter:129893398 from Retrans Table on exchange 49793r
[1702343394.062975][75580:75580] CHIP:DIS: Checking node lookup status after 200 ms
[1702343394.063155][75580:75580] CHIP:EM: <<< [E:48119i S:0 M:229831624] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::42:c0ff:fea8:902%eth0]:47137] --- Type 0000:50 (SecureChannel:----)
[1702343403.862180][75580:75580] CHIP:DL: Set ICD Polling on linux
[1702343403.862242][75580:75580] CHIP:SVR: Failed to set Slow Polling Interval: err src/platform/Linux/ThreadStackManagerImpl.cpp:526: CHIP Error 0x0000002D: Not Implemented
^C[1702343407.632265][75580:75580] CHIP:DL: Select failed: src/system/SystemLayerImplSelect.cpp:663: OS Error 0x02000004: Interrupted system call
[1702343407.632309][75580:75580] CHIP:ZCL: Emitting ShutDown event
[1702343407.632363][75580:75580] CHIP:EVL: LogEvent event number: 0x0000000000000003 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x1 Epoch timestamp: 0x0000018C5B92F810
[1702343407.632431][75580:75580] CHIP:DMG: Building Reports for ReadHandler with LastReportGeneration = 0x000000000000000A DirtyGeneration = 0x0000000000000000
[1702343407.632459][75580:75580] CHIP:DMG: AccessControl: checking f=1 a=c s=0x000000000001B669 t= c=0x0000_001F e=0 p=a
[1702343407.632485][75580:75580] CHIP:DMG: AccessControl: allowed
[1702343407.632615][75580:75580] CHIP:DMG: Fetched 0 events
[1702343407.632632][75580:75580] CHIP:DMG: <RE> Sending report (payload has 11 bytes)...
[1702343407.632671][75580:75580] CHIP:DL: Set ICD Polling on linux
[1702343407.632691][75580:75580] CHIP:SVR: Failed to set Fast Polling Interval: err src/platform/Linux/ThreadStackManagerImpl.cpp:526: CHIP Error 0x0000002D: Not Implemented
[1702343407.633016][75580:75580] CHIP:EM: <<< [E:48120i S:49724 M:129893399] (S) Msg TX to 1:000000000001B669 [B8EA] [UDP:[fe80::42:c0ff:fea8:902%eth0]:47137] --- Type 0001:05 (IM:ReportData)
[1702343407.633153][75580:75580] CHIP:DMG: IM RH moving to [AwaitingReportResponse]
[1702343407.633177][75580:75580] CHIP:DMG: <RE> ReportsInFlight = 1 with readHandler 0, RE has no more messages
[1702343407.633194][75580:75580] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1702343407.633225][75580:75580] CHIP:IN: SecureSession[0x5637723bac80]: Released - Type:2 LSID:49725
[1702343407.634085][75580:75580] CHIP:DMG: <RE> OnReportConfirm: NumReports = 0
[1702343407.634129][75580:75580] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1702343407.634166][75580:75580] CHIP:IN: SecureSession[0x5637723b5a80]: MarkForEviction Type:2 LSID:49724
[1702343407.634182][75580:75580] CHIP:SC: SecureSession[0x5637723b5a80, LSID:49724]: State change 'kActive' --> 'kPendingEviction'
[1702343407.634198][75580:75580] CHIP:IN: SecureSession[0x5637723b5a80]: Released - Type:2 LSID:49724
[1702343407.634232][75580:75580] CHIP:DMG: AccessControl: finishing
[1702343407.634247][75580:75580] CHIP:DMG: Examples::AccessControlDelegate::Finish
[1702343407.634654][75580:75580] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-pPOAva)
[1702343407.635026][75580:75580] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1702343407.635059][75580:75580] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1702343407.635076][75580:75580] CHIP:DL: Inet Layer shutdown
[1702343407.635091][75580:75580] CHIP:DL: BLE shutdown
[1702343407.635108][75580:75580] CHIP:DL: System Layer shutdown
[1]+  Done                    rm -rf /tmp/chip*
root@f13c574f0a5e:/connectedhomeip# gdb ./out/linux-x64-lit-icd-ipv6only/lit-icd-app
(gdb) r
Starting program: /connectedhomeip/out/linux-x64-lit-icd-ipv6only/lit-icd-app 
warning: Error disabling address space randomization: Operation not permitted
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[1702343423.200320][75588:75588] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[New Thread 0x7f383d009700 (LWP 75592)]
[1702343423.202058][75588:75588] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1702343423.202082][75588:75588] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1702343423.202288][75588:75588] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1702343423.202413][75588:75588] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1702343423.202525][75588:75588] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1702343423.202976][75588:75588] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-V4ueGM)
[1702343423.203343][75588:75588] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1702343423.203374][75588:75588] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1702343423.203730][75588:75588] CHIP:DL: Got Ethernet interface: eth0
[1702343423.203926][75588:75588] CHIP:DL: Found the primary Ethernet interface:eth0
[1702343423.204252][75588:75588] CHIP:DL: Failed to get WiFi interface
[1702343423.204268][75588:75588] CHIP:DL: Failed to reset WiFi statistic counts
[1702343423.204290][75588:75588] CHIP:SPT: *** WARNING: Using temporary passcode 20202021 due to no neither --passcode or --spake2p-verifier-base64 given on command line. This is temporary and will disappear. Please update your scripts to explicitly configure onboarding credentials. ***
[1702343423.204307][75588:75588] CHIP:SPT: *** WARNING: Using temporary test discriminator 3840 due to --discriminator not given on command line. This is temporary and will disappear. Please update your scripts to explicitly configure discriminator. ***
[1702343423.204322][75588:75588] CHIP:SPT: PASE PBKDF iterations set to 1000
[1702343423.204337][75588:75588] CHIP:SPT: LinuxCommissionableDataProvider didn't get a PASE salt, generating one.
[1702343423.209249][75588:75588] CHIP:DL: Device Configuration:
[1702343423.209274][75588:75588] CHIP:DL:   Serial Number: TEST_SN
[1702343423.209293][75588:75588] CHIP:DL:   Vendor Id: 65521 (0xFFF1)
[1702343423.209312][75588:75588] CHIP:DL:   Product Id: 32769 (0x8001)
[1702343423.209330][75588:75588] CHIP:DL:   Product Name: TEST_PRODUCT
[1702343423.209349][75588:75588] CHIP:DL:   Hardware Version: 0
[1702343423.209363][75588:75588] CHIP:DL:   Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
[1702343423.209376][75588:75588] CHIP:DL:   Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
[1702343423.209395][75588:75588] CHIP:DL:   Manufacturing Date: (not set)
[1702343423.209408][75588:75588] CHIP:DL:   Device Type: 65535 (0xFFFF)
[1702343423.209421][75588:75588] CHIP:-: ==== Onboarding payload for Standard Commissioning Flow ====
[1702343423.209450][75588:75588] CHIP:SVR: SetupQRCode: [MT:-24J042C00KA0648G00]
[1702343423.209468][75588:75588] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code:
[1702343423.209481][75588:75588] CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00
[1702343423.209502][75588:75588] CHIP:SVR: Manual pairing code: [34970112332]
[1702343423.209542][75588:75588] CHIP:SVR: Initializing subscription resumption storage...
[1702343423.209839][75588:75588] CHIP:DL: writing settings to file (/tmp/chip_kvs-MEaUHM)
[1702343423.210287][75588:75588] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1702343423.210323][75588:75588] CHIP:SVR: Server initializing...
[1702343423.210339][75588:75588] CHIP:FP: Initializing FabricTable from persistent storage
[1702343423.210414][75588:75588] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1702343423.210736][75588:75588] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xBA13D750586CB8EA, FabricId 0x0000000000000001, NodeId 0x0000000000000001, VendorId 0xFFF1
[1702343423.210778][75588:75588] CHIP:DMG: AccessControl: initializing
[1702343423.210792][75588:75588] CHIP:DMG: Examples::AccessControlDelegate::Init
[1702343423.210823][75588:75588] CHIP:DMG: AccessControl: setting
[1702343423.210838][75588:75588] CHIP:DMG: DefaultAclStorage: initializing
[1702343423.210912][75588:75588] CHIP:DMG: AccessControl: validating f=1 p=a a=c s=1 t=0
[1702343423.210928][75588:75588] CHIP:DMG:   validating subject 0x000000000001B669
[1702343423.210963][75588:75588] CHIP:DMG: DefaultAclStorage: 1 entries loaded
[1702343423.210982][75588:75588] CHIP:IN: UDP::Init bind&listen port=5540
[1702343423.211054][75588:75588] CHIP:IN: UDP::Init bound to port=5540
[1702343423.211069][75588:75588] CHIP:IN: BLEBase::Init - setting/overriding transport
[1702343423.211082][75588:75588] CHIP:IN: TransportMgr initialized
[1702343423.211405][75588:75588] CHIP:DL: writing settings to file (/tmp/chip_kvs-ve1yGO)
[1702343423.211824][75588:75588] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1702343423.212035][75588:75588] CHIP:DL: writing settings to file (/tmp/chip_kvs-BTQPmQ)
[1702343423.212446][75588:75588] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1702343423.213277][75588:75588] CHIP:DL: writing settings to file (/tmp/chip_kvs-w9D57P)
[1702343423.213691][75588:75588] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1702343423.213722][75588:75588] CHIP:ZCL: Using ZAP configuration...
[1702343423.213791][75588:75588] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1702343423.213835][75588:75588] CHIP:DMG: AccessControlCluster: initializing
[1702343423.213849][75588:75588] CHIP:ZCL: Initiating Admin Commissioning cluster.
[1702343423.213868][75588:75588] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 3f49bd5a
[1702343423.213903][75588:75588] CHIP:ZCL: GeneralDiagnostics: OnDeviceReboot
[1702343423.213918][75588:75588] CHIP:DMG: Endpoint 0, Cluster 0x0000_0033 update version to e12b9c00
[1702343423.213960][75588:75588] CHIP:EVL: LogEvent event number: 0x0000000000010000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Epoch timestamp: 0x0000018C5B9334ED
[1702343423.213989][75588:75588] CHIP:SVR: Fabric already commissioned. Disabling BLE advertisement
[1702343423.214011][75588:75588] CHIP:DIS: Updating services using commissioning mode 0
[1702343423.214390][75588:75588] CHIP:DIS: CHIP minimal mDNS started advertising.
[1702343423.214819][75588:75588] CHIP:DL: Using wifi MAC for hostname
[1702343423.214835][75588:75588] CHIP:DIS: Advertise operational node BA13D750586CB8EA-0000000000000001
[1702343423.214856][75588:75588] CHIP:DIS: Responding with _matter._tcp.local
[1702343423.214866][75588:75588] CHIP:DIS: Responding with BA13D750586CB8EA-0000000000000001._matter._tcp.local
[1702343423.214880][75588:75588] CHIP:DIS: Responding with BA13D750586CB8EA-0000000000000001._matter._tcp.local
[1702343423.214890][75588:75588] CHIP:DIS: Responding with 0242C0A809020000.local
[1702343423.214901][75588:75588] CHIP:DIS: Responding with 0242C0A809020000.local
[1702343423.214913][75588:75588] CHIP:DIS: Responding with _IBA13D750586CB8EA._sub._matter._tcp.local
[1702343423.214922][75588:75588] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: BA13D750586CB8EA-0000000000000001.
[1702343423.215322][75588:75588] CHIP:DIS: mDNS service published: _matter._tcp
[1702343423.215339][75588:75588] CHIP:IN: CASE Server enabling CASE session setups
[1702343423.215364][75588:75588] CHIP:IN: SecureSession[0x55c3cc762bf0]: Allocated Type:2 LSID:22590
[1702343423.215380][75588:75588] CHIP:SC: Allocated SecureSession (0x55c3cc762bf0) - waiting for Sigma1 msg
[1702343423.215572][75588:75588] CHIP:DL: writing settings to file (/tmp/chip_kvs-Y2Am5N)
[1702343423.215843][75588:75588] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1702343423.215905][75588:75588] CHIP:DIS: Updating services using commissioning mode 0
[1702343423.216202][75588:75588] CHIP:DIS: CHIP minimal mDNS started advertising.
[1702343423.217000][75588:75588] CHIP:DL: Using wifi MAC for hostname
[1702343423.217016][75588:75588] CHIP:DIS: Advertise operational node BA13D750586CB8EA-0000000000000001
[1702343423.217034][75588:75588] CHIP:DIS: Responding with _matter._tcp.local
[1702343423.217043][75588:75588] CHIP:DIS: Responding with BA13D750586CB8EA-0000000000000001._matter._tcp.local
[1702343423.217054][75588:75588] CHIP:DIS: Responding with BA13D750586CB8EA-0000000000000001._matter._tcp.local
[1702343423.217063][75588:75588] CHIP:DIS: Responding with 0242C0A809020000.local
[1702343423.217074][75588:75588] CHIP:DIS: Responding with 0242C0A809020000.local
[1702343423.217087][75588:75588] CHIP:DIS: Responding with _IBA13D750586CB8EA._sub._matter._tcp.local
[1702343423.217097][75588:75588] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: BA13D750586CB8EA-0000000000000001.
[1702343423.217445][75588:75588] CHIP:DIS: mDNS service published: _matter._tcp
[1702343423.217466][75588:75588] CHIP:DL: Set ICD Polling on linux
[1702343423.217478][75588:75588] CHIP:SVR: Failed to set Slow Polling Interval: err src/platform/Linux/ThreadStackManagerImpl.cpp:526: CHIP Error 0x0000002D: Not Implemented
[1702343423.217488][75588:75588] CHIP:SVR: Joining Multicast groups
[1702343423.217541][75588:75588] CHIP:ZCL: Emitting StartUp event
[1702343423.217564][75588:75588] CHIP:EVL: LogEvent event number: 0x0000000000010001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Epoch timestamp: 0x0000018C5B9334F1
[1702343423.217578][75588:75588] CHIP:SVR: Server initialization complete
[1702343423.217590][75588:75588] CHIP:SVR: Server Listening...
[1702343423.217599][75588:75588] CHIP:DL: Device Configuration:
[1702343423.217614][75588:75588] CHIP:DL:   Serial Number: TEST_SN
[1702343423.217632][75588:75588] CHIP:DL:   Vendor Id: 65521 (0xFFF1)
[1702343423.217646][75588:75588] CHIP:DL:   Product Id: 32769 (0x8001)
[1702343423.217655][75588:75588] CHIP:DL:   Product Name: TEST_PRODUCT
[1702343423.217668][75588:75588] CHIP:DL:   Hardware Version: 0
[1702343423.217678][75588:75588] CHIP:DL:   Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
[1702343423.217687][75588:75588] CHIP:DL:   Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
[1702343423.217699][75588:75588] CHIP:DL:   Manufacturing Date: (not set)
[1702343423.217709][75588:75588] CHIP:DL:   Device Type: 65535 (0xFFFF)
[1702343423.217723][75588:75588] CHIP:SVR: SetupQRCode: [MT:-24J042C00KA0648G00]
[1702343423.217734][75588:75588] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code:
[1702343423.217743][75588:75588] CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J042C00KA0648G00
[1702343423.217758][75588:75588] CHIP:SVR: Manual pairing code: [34970112332]
[New Thread 0x7f383c808700 (LWP 75593)]
[1702343423.219945][75588:75592] CHIP:DL: FAIL: get bus sync in StartupEndpointBindings, error: Could not connect: No such file or directory
[1702343423.220043][75588:75588] CHIP:DL: Failed to schedule endpoint initialization
[1702343423.220070][75588:75588] CHIP:DL: Disabling CHIPoBLE service due to error: src/platform/Linux/bluez/BluezEndpoint.cpp:617: CHIP Error 0x000000AC: Internal error
[1702343423.220083][75588:75588] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1702343423.220094][75588:75588] CHIP:DIS: Updating services using commissioning mode 0
[1702343423.220434][75588:75588] CHIP:DIS: CHIP minimal mDNS started advertising.
[1702343423.221245][75588:75588] CHIP:DL: Using wifi MAC for hostname
[1702343423.221261][75588:75588] CHIP:DIS: Advertise operational node BA13D750586CB8EA-0000000000000001
[1702343423.221279][75588:75588] CHIP:DIS: Responding with _matter._tcp.local
[1702343423.221288][75588:75588] CHIP:DIS: Responding with BA13D750586CB8EA-0000000000000001._matter._tcp.local
[1702343423.221300][75588:75588] CHIP:DIS: Responding with BA13D750586CB8EA-0000000000000001._matter._tcp.local
[1702343423.221309][75588:75588] CHIP:DIS: Responding with 0242C0A809020000.local
[1702343423.221321][75588:75588] CHIP:DIS: Responding with 0242C0A809020000.local
[1702343423.221333][75588:75588] CHIP:DIS: Responding with _IBA13D750586CB8EA._sub._matter._tcp.local
[1702343423.221342][75588:75588] CHIP:DIS: CHIP minimal mDNS configured as 'Operational device'; instance name: BA13D750586CB8EA-0000000000000001.
[1702343423.221691][75588:75588] CHIP:DIS: mDNS service published: _matter._tcp
[1702343423.221707][75588:75588] CHIP:DL: HandlePlatformSpecificBLEEvent 32790
[1702343423.222273][75588:75588] CHIP:IM: Resuming 1 subscriptions in 5 seconds
[1702343428.227695][75588:75588] CHIP:IM: Resuming subscriptionId 2818535528
[1702343428.227741][75588:75588] CHIP:CSM: FindOrEstablishSession: PeerId = [1:000000000001B669]
[1702343428.227760][75588:75588] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1702343428.227782][75588:75588] CHIP:DIS: OperationalSessionSetup[1:000000000001B669]: State change 1 --> 2
[1702343428.229613][75588:75588] CHIP:DIS: Lookup clearing interface for non LL address
[1702343428.229689][75588:75588] CHIP:DIS: UDP:[2001:db8:1::242:c0a8:902%eth0]:47137: new best score: 6
[1702343428.229868][75588:75588] CHIP:DIS: UDP:[fe80::42:c0ff:fea8:902%eth0]:47137: new best score: 7
[1702343428.229885][75588:75588] CHIP:DIS: Checking node lookup status after 2 ms
[1702343428.229899][75588:75588] CHIP:DIS: Keeping DNSSD lookup active
[1702343428.428249][75588:75588] CHIP:DIS: Checking node lookup status after 201 ms
[1702343428.428347][75588:75588] CHIP:DIS: OperationalSessionSetup[1:000000000001B669]: Updating device address to UDP:[fe80::42:c0ff:fea8:902%eth0]:47137 while in state 2
[1702343428.428369][75588:75588] CHIP:DIS: OperationalSessionSetup[1:000000000001B669]: State change 2 --> 3
[1702343428.428455][75588:75588] CHIP:DL: Set ICD Polling on linux
[1702343428.428480][75588:75588] CHIP:SVR: Failed to set Fast Polling Interval: err src/platform/Linux/ThreadStackManagerImpl.cpp:526: CHIP Error 0x0000002D: Not Implemented

Thread 1 "lit-icd-app" received signal SIGSEGV, Segmentation fault.
chip::app::ReadHandler::GetSubjectDescriptor (this=0x55c3cc764be0) at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/ReadHandler.h:401
401	    SubjectDescriptor GetSubjectDescriptor() const { return GetSession()->GetSubjectDescriptor(); }
(gdb) bt
#0  chip::app::ReadHandler::GetSubjectDescriptor() const (this=0x55c3cc764be0) at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/ReadHandler.h:401
#1  0x000055c3cb5f02f1 in chip::app::InteractionModelEngine::<lambda(chip::app::ReadHandler*)>::operator()(chip::app::ReadHandler *) const (__closure=0x7ffc48cccce0, handler=0x55c3cc764be0)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/InteractionModelEngine.cpp:330
#2  0x000055c3cb5f6e4b in chip::internal::LambdaProxy<chip::app::ReadHandler, chip::app::InteractionModelEngine::SubjectHasActiveSubscription(chip::FabricIndex, const NodeId&)::<lambda(chip::app::ReadHandler*)> >::Call(void *, void *) (context=0x7ffc48cccce0, target=0x55c3cc764be0) at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/lib/support/Pool.h:126
#3  0x000055c3cb63c0a3 in chip::internal::HeapObjectList::ForEachNode(void*, chip::Loop (*)(void*, void*))
    (this=0x55c3cb7dcce8 <chip::app::sInteractionModelEngine+1576>, context=0x7ffc48cccce0, lambda=0x55c3cb5f6e24 <chip::internal::LambdaProxy<chip::app::ReadHandler, chip::app::InteractionModelEngine::SubjectHasActiveSubscription(chip::FabricIndex, const NodeId&)::<lambda(chip::app::ReadHandler*)> >::Call(void *, void *)>)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/lib/support/Pool.cpp:153
#4  0x000055c3cb5f5b77 in chip::HeapObjectPool<chip::app::ReadHandler>::ForEachActiveObject<chip::app::InteractionModelEngine::SubjectHasActiveSubscription(chip::FabricIndex, const NodeId&)::<lambda(chip::app::ReadHandler*)> >(chip::app::InteractionModelEngine::<lambda(chip::app::ReadHandler*)> &&) (this=0x55c3cb7dccd8 <chip::app::sInteractionModelEngine+1560>, function=...)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/lib/support/Pool.h:426
#5  0x000055c3cb5f03fc in chip::app::InteractionModelEngine::SubjectHasActiveSubscription(unsigned char, unsigned long const&)
    (this=0x55c3cb7dc6c0 <chip::app::sInteractionModelEngine>, aFabricIndex=1 '\001', subjectID=@0x7ffc48ccceb8: 112233)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/InteractionModelEngine.cpp:324
#6  0x000055c3cb42891c in chip::app::ICDManager::SendCheckInMsgs() (this=0x55c3cb7e4a20 <chip::Server::sServer+11456>)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/icd/ICDManager.cpp:141
#7  0x000055c3cb4295a1 in chip::app::ICDManager::UpdateOperationState(chip::app::ICDManager::OperationalState)
    (this=0x55c3cb7e4a20 <chip::Server::sServer+11456>, state=chip::app::ICDManager::OperationalState::ActiveMode)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/icd/ICDManager.cpp:329
#8  0x000055c3cb429772 in chip::app::ICDManager::SetKeepActiveModeRequirements(chip::BitFlags<chip::app::ICDListener::KeepActiveFlagsValues, unsigned char>, bool)
    (this=0x55c3cb7e4a20 <chip::Server::sServer+11456>, flag=..., state=true) at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/icd/ICDManager.cpp:356
#9  0x000055c3cb429943 in chip::app::ICDManager::OnKeepActiveRequest(chip::BitFlags<chip::app::ICDListener::KeepActiveFlagsValues, unsigned char>)
    (this=0x55c3cb7e4a20 <chip::Server::sServer+11456>, request=...) at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/icd/ICDManager.cpp:418
#10 0x000055c3cb5c8e09 in chip::app::ICDNotifier::BroadcastActiveRequestNotification(chip::BitFlags<chip::app::ICDListener::KeepActiveFlagsValues, unsigned char>)Python Exception <class 'RecursionError'> decoding with 'ANSI_X3.4-1968' codec failed (RecursionError: maximum recursion depth exceeded while calling a Python object): 

    (this=0x55c3cb7dc5e8 <chip::app::ICDNotifier::sICDNotifier>, request=...) at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/icd/ICDNotifier.cpp:76
#11 0x000055c3cb63e287 in chip::Messaging::ExchangeContext::ExchangeContext(chip::Messaging::ExchangeManager*, unsigned short, chip::SessionHandle const&, bool, chip::Messaging::ExchangeDelegate*, bool) (this=0x55c3cc763ba0, em=0x55c3cb7e22d8 <chip::Server::sServer+1400>, ExchangeId=38391, session=..., Initiator=true, delegate=0x55c3cc767038, isEphemeralExchange=false)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/messaging/ExchangeContext.cpp:332
#12 0x000055c3cb6423fe in chip::Platform::New<chip::Messaging::ExchangeContext, chip::Messaging::ExchangeManager*, unsigned short, chip::SessionHandle const&, bool&, chip::Messaging::ExchangeDelegate*&>(chip::Messaging::ExchangeManager*&&, unsigned short&&, chip::SessionHandle const&, bool&, chip::Messaging::ExchangeDelegate*&) ()
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/lib/support/CHIPMem.h:148
#13 0x000055c3cb641e3f in chip::HeapObjectPool<chip::Messaging::ExchangeContext>::CreateObject<chip::Messaging::ExchangeManager*, unsigned short, chip::SessionHandle const&, bool&, chip::Messaging::ExchangeDelegate*&>(chip::Messaging::ExchangeManager*&&, unsigned short&&, chip::SessionHandle const&, bool&, chip::Messaging::ExchangeDelegate*&)
    (this=0x55c3cb7e22f0 <chip::Server::sServer+1424>) at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/lib/support/Pool.h:349
#14 0x000055c3cb640a55 in chip::Messaging::ExchangeManager::NewContext(chip::SessionHandle const&, chip::Messaging::ExchangeDelegate*, bool)
    (this=0x55c3cb7e22d8 <chip::Server::sServer+1400>, session=..., delegate=0x55c3cc767038, isInitiator=true)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/messaging/ExchangeMgr.cpp:118
#15 0x000055c3cb7257f4 in chip::CASEClient::EstablishSession(chip::CASEClientInitParams const&, chip::ScopedNodeId const&, chip::Transport::PeerAddress const&, chip::ReliableMessageProtocolConfig const&, chip::SessionEstablishmentDelegate*) (this=0x55c3cc767030, params=..., peer=..., peerAddress=..., remoteMRPConfig=..., delegate=0x55c3cc75fc00)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/CASEClient.cpp:49
#16 0x000055c3cb60d37c in chip::OperationalSessionSetup::EstablishConnection(chip::ReliableMessageProtocolConfig const&) (this=0x55c3cc75fc00, config=...)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/OperationalSessionSetup.cpp:281
#17 0x000055c3cb60d071 in chip::OperationalSessionSetup::UpdateDeviceData(chip::Transport::PeerAddress const&, chip::ReliableMessageProtocolConfig const&)
    (this=0x55c3cc75fc00, addr=..., config=...) at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/OperationalSessionSetup.cpp:232
#18 0x000055c3cb60e32b in chip::OperationalSessionSetup::OnNodeAddressResolved(chip::PeerId const&, chip::AddressResolve::ResolveResult const&) (this=0x55c3cc75fc00, peerId=..., result=...)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/app/OperationalSessionSetup.cpp:572
#19 0x000055c3cb6cc4f6 in chip::AddressResolve::Impl::Resolver::HandleAction(chip::IntrusiveList<chip::AddressResolve::Impl::NodeLookupHandle, (chip::IntrusiveMode)0, chip::IntrusiveListBase--Type <RET> for more, q to quit, c to continue without paging--
Hook<chip::AddressResolve::Impl::NodeLookupHandle, (chip::IntrusiveMode)0> >::Iterator&) (this=0x55c3cb7e1ce0 <chip::AddressResolve::Resolver::Instance()::gResolver>, current=...)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:342
#20 0x000055c3cb6cc5cc in chip::AddressResolve::Impl::Resolver::HandleTimer() (this=0x55c3cb7e1ce0 <chip::AddressResolve::Resolver::Instance()::gResolver>)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:358
#21 0x000055c3cb6cb154 in chip::AddressResolve::Impl::Resolver::OnResolveTimer(chip::System::Layer*, void*)
    (layer=0x55c3cb7dd4a0 <chip::DeviceLayer::SystemLayerImpl()::gSystemLayerImpl>, context=0x55c3cb7e1ce0 <chip::AddressResolve::Resolver::Instance()::gResolver>)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/lib/address_resolve/AddressResolve_DefaultImpl.h:185
#22 0x000055c3cb6492cf in chip::System::TimerData::Callback::Invoke() const (this=0x7ffc48ccd590) at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/system/SystemTimer.h:61
#23 0x000055c3cb64adb6 in chip::System::TimerPool<chip::System::TimerList::Node>::Invoke(chip::System::TimerList::Node*)
    (this=0x55c3cb7ddaa8 <chip::DeviceLayer::SystemLayerImpl()::gSystemLayerImpl+1544>, timer=0x55c3cc763d30)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/system/SystemTimer.h:237
#24 0x000055c3cb64a964 in chip::System::LayerImplSelect::HandleEvents() (this=0x55c3cb7dd4a0 <chip::DeviceLayer::SystemLayerImpl()::gSystemLayerImpl>)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/system/SystemLayerImplSelect.cpp:678
#25 0x000055c3cb689eb4 in chip::DeviceLayer::Internal::GenericPlatformManagerImpl_POSIX<chip::DeviceLayer::PlatformManagerImpl>::_RunEventLoop()
    (this=0x55c3cb7e1350 <chip::DeviceLayer::PlatformManagerImpl::sInstance+16>)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/include/platform/internal/GenericPlatformManagerImpl_POSIX.ipp:225
#26 0x000055c3cb41c6d8 in chip::DeviceLayer::PlatformManager::RunEventLoop() (this=0x55c3cb7e1340 <chip::DeviceLayer::PlatformManagerImpl::sInstance>)
    at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/src/include/platform/PlatformManager.h:403
#27 0x000055c3cb41f1bf in ChipLinuxAppMainLoop(AppMainLoopImplementation*) (impl=0x0) at ../../examples/lit-icd-app/linux/third_party/connectedhomeip/examples/platform/linux/AppMain.cpp:609
#28 0x000055c3cb3c21eb in main(int, char**) (argc=1, argv=0x7ffc48ccdaa8) at ../../examples/lit-icd-app/linux/main.cpp:32
```

</summary>
@yunhanw-google yunhanw-google added bug Something isn't working needs triage labels Dec 12, 2023
@bzbarsky-apple
Copy link
Contributor

Pinging @jtung-apple

That said, @yunhanw-google this sounds like "some code is asking for subjects on subscriptions that don't have a CASE session", which is a problem in that code, no? CASE sessions can be evicted for existing subscriptions completely independent of persistent subscriptions, right? Or does that case immediately tear down the subscription?

Note that #30491 may well fix this for the persistent subscription case, but might not fix the real underlying issue.

@mkardous-silabs
Copy link
Contributor

Could this be related to #30518?

@mkardous-silabs mkardous-silabs added the icd Intermittently Connected Devices label Oct 24, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working crash icd Intermittently Connected Devices needs triage
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@andy31415 @yunhanw-google @bzbarsky-apple @mkardous-silabs