Hi,
I'm developing a Matter device based on the Window Covering sample. I have added another endpoint to the device containing some sensor clusters and it all works after commissioning. But after some time (sometimes minutes sometimes up to 20 hours). The device becomes unresponsive in Matter hubs. To debug this I used chip-tool to set up a subscription and that also works at first. But then after some time the subscription times out and after that happens the device no longer responds to chip-tool read commands with data. But what is weird is I can see in both chip-tool and device side logs that there is still communications happening. The packets still get ACK-ed. The device just fails to actually respond with data.
Here is a snippet of logs from the device:
[16:59:06.216,583] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1039,temp=2204,hum=4500 [17:00:11.451,721] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1061,temp=2205,hum=4500 [17:01:16.686,584] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1078,temp=2206,hum=4500 [17:02:21.922,088] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1048,temp=2207,hum=4500 [17:03:27.158,538] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1022,temp=2208,hum=4500 [17:04:32.393,463] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1022,temp=2210,hum=4500 [17:05:37.627,929] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1051,temp=2211,hum=4500 [17:06:42.861,511] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1079,temp=2211,hum=4500 [17:07:28.585,205] <inf> chip: [EM]>>> [E:63075r S:0 M:59733938] (U) Msg RX from 0:41503CC2AC3915F8 [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:234) [17:07:28.590,332] <inf> chip: [IN]CASE Server received Sigma1 message . Starting handshake. EC 0x20005c98 [17:07:28.593,383] <inf> chip: [EM]<<< [E:63075r S:0 M:41857777 (Ack:59733938)] (U) Msg TX from 0000000000000000 to 0:41503CC2AC3915F8 [0000] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26) [17:07:28.598,541] <inf> chip: [SC]Received Sigma1 msg [17:07:28.611,480] <inf> chip: [EM]<<< [E:63075r S:0 M:41857778 (Ack:59733938)] (U) Msg TX from 0000000000000000 to 0:41503CC2AC3915F8 [0000] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume) (B:100) [17:07:28.618,560] <inf> chip: [EM]??1 [E:63075r S:0 M:41857778] (U) Msg Retransmission to 0:0000000000000000 in 2047ms [State:Active II:500 AI:300 AT:4000] [17:07:28.652,954] <dbg> chip: LogV: [IN]Received a duplicate message with MessageCounter:59733938 on exchange 63075r [17:07:28.656,372] <inf> chip: [EM]>>> [E:63075r S:0 M:59733938] (U) Msg RX from 0:41503CC2AC3915F8 [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:234) [17:07:28.663,116] <inf> chip: [EM]<<< [E:63075r S:0 M:41857779 (Ack:59733938)] (U) Msg TX from 0000000000000000 to 0:41503CC2AC3915F8 [0000] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26) [17:07:28.813,659] <dbg> chip: LogV: [IN]Received a duplicate message with MessageCounter:59733938 on exchange 63075r [17:07:28.817,535] <inf> chip: [EM]>>> [E:63075r S:0 M:59733938] (U) Msg RX from 0:41503CC2AC3915F8 [0000] to 0000000000000000 --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:234) [17:07:28.821,807] <inf> chip: [EM]<<< [E:63075r S:0 M:41857780 (Ack:59733938)] (U) Msg TX from 0000000000000000 to 0:41503CC2AC3915F8 [0000] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26) [17:07:28.844,299] <inf> chip: [EM]>>> [E:63075r S:0 M:59733939 (Ack:41857778)] (U) Msg RX from 0:41503CC2AC3915F8 [0000] to 0000000000000000 --- Type 0000:40 (SecureChannel:StatusReport) (B:34) [17:07:28.849,731] <inf> chip: [SC]Success status report received. Session was established [17:07:28.873,382] <inf> chip: [SC]SecureSession[0x20003f98, LSID:20217]: State change 'kEstablishing' --> 'kActive' [17:07:28.875,885] <dbg> chip: LogV: [IN]SecureSession[0x20003f98]: Activated - Type:2 LSID:20217 [17:07:28.878,234] <dbg> chip: LogV: [IN]New secure session activated for device <000000000001B669, 1>, LSID:20217 PSID:53629! [17:07:28.880,950] <inf> chip: [IN]CASE Session established to peer: <000000000001B669, 1> [17:07:28.883,453] <dbg> chip: LogV: [IN]SecureSession[0x20004070]: Allocated Type:2 LSID:20218 [17:07:28.886,322] <inf> chip: [EM]<<< [E:63075r S:0 M:41857781 (Ack:59733939)] (U) Msg TX from 0000000000000000 to 0:41503CC2AC3915F8 [0000] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26) [17:07:28.891,723] <dbg> am_matter: am_matter_event_handler: Network provisioned [17:07:28.895,324] <inf> chip: [EM]>>> [E:63076r S:20217 M:132331946] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:03 (IM:SubscribeRequest) (B:60) [17:07:28.899,932] <dbg> chip: LogV: [IM]Received Subscribe request [17:07:28.901,947] <inf> chip: [IM]Deleting previous subscription from NodeId: 000000000001B669, FabricIndex: 1 [17:07:28.904,479] <inf> chip: [DMG]Subscription id 0x7f947a19 from node <000000000001B669, 1> torn down [17:07:28.907,745] <inf> chip: [DMG]Final negotiated min/max parameters: Min = 1s, Max = 120s [17:07:29.100,402] <inf> chip: [EM]<<< [E:63076r S:20217 M:55144915 (Ack:132331946)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [17:07:48.097,259] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1099,temp=2212,hum=4500 [17:08:53.328,857] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1107,temp=2210,hum=4500 [17:09:05.998,901] <inf> chip: [EM]>>> [E:63077r S:20217 M:132331947] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:03 (IM:SubscribeRequest) (B:60) [17:09:06.002,319] <dbg> chip: LogV: [IM]Received Subscribe request [17:09:06.004,333] <inf> chip: [IM]Deleting previous subscription from NodeId: 000000000001B669, FabricIndex: 1 [17:09:06.006,744] <inf> chip: [DMG]Subscription id 0x755fe4dd from node <000000000001B669, 1> torn down [17:09:06.010,040] <inf> chip: [DMG]Final negotiated min/max parameters: Min = 1s, Max = 120s [17:09:06.203,674] <inf> chip: [EM]<<< [E:63077r S:20217 M:55144916 (Ack:132331947)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [17:09:58.568,847] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1088,temp=2211,hum=4500 [17:11:03.800,384] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1070,temp=2214,hum=4500 [17:12:09.028,015] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1080,temp=2214,hum=4500 [17:12:16.272,369] <inf> chip: [EM]>>> [E:63078r S:20217 M:132331948] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:02 (IM:ReadRequest) (B:51) [17:12:16.275,726] <dbg> chip: LogV: [IM]Received Read request [17:12:16.476,470] <inf> chip: [EM]<<< [E:63078r S:20217 M:55144917 (Ack:132331948)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [17:13:14.256,835] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1093,temp=2216,hum=4500 [17:13:14.798,187] <inf> chip: [EM]>>> [E:63079r S:20217 M:132331949] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:02 (IM:ReadRequest) (B:51) [17:13:14.801,544] <dbg> chip: LogV: [IM]Received Read request [17:13:15.002,288] <inf> chip: [EM]<<< [E:63079r S:20217 M:55144918 (Ack:132331949)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
And here are the logs from chip-tool for the corresponding timeframe (including the end of the log where subscription failed):
[1759935542.471] [35841:35843] [EM] >>> [E:28029r S:53628 M:219337460] (S) Msg RX from 1:0000000000000001 [235E] to 000000000001B669 --- Type 0001:05 (IM:ReportData) (B:41)
[1759935542.471] [35841:35843] [EM] Handling via exchange: 28029r, Delegate: 0xaaaada80c320
[1759935542.471] [35841:35843] [DMG] ReportDataMessage =
[1759935542.471] [35841:35843] [DMG] {
[1759935542.471] [35841:35843] [DMG] SubscriptionId = 0x7f947a19,
[1759935542.471] [35841:35843] [DMG] InteractionModelRevision = 12
[1759935542.471] [35841:35843] [DMG] }
[1759935542.471] [35841:35843] [DMG] Refresh LivenessCheckTime for 160049 milliseconds with SubscriptionId = 0x7f947a19 Peer = 01:0000000000000001
[1759935542.471] [35841:35843] [EM] <<< [E:28029r S:53628 M:87260965 (Ack:219337460)] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [235E] [UDP:[fd11:35::a56a:73c7:6e10:f7a9]:5540] --- Type 0001:01 (IM:StatusResponse) (B:42)
[1759935542.471] [35841:35843] [EM] ??1 [E:28029r S:53628 M:87260965] (S) Msg Retransmission to 1:0000000000000001 in 2534ms [State:Active II:3000 AI:2200 AT:300]
[1759935542.901] [35841:35843] [EM] >>> [E:28029r S:53628 M:219337461 (Ack:87260965)] (S) Msg RX from 1:0000000000000001 [235E] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1759935542.901] [35841:35843] [EM] Found matching exchange: 28029r, Delegate: (nil)
[1759935542.901] [35841:35843] [EM] Rxd Ack; Removing MessageCounter:87260965 from Retrans Table on exchange 28029r
[1759935552.932] [35841:35843] [EM] >>> [E:28030r S:53628 M:219337462] (S) Msg RX from 1:0000000000000001 [235E] to 000000000001B669 --- Type 0001:05 (IM:ReportData) (B:72)
[1759935552.932] [35841:35843] [EM] Handling via exchange: 28030r, Delegate: 0xaaaada80c320
[1759935552.932] [35841:35843] [DMG] ReportDataMessage =
[1759935552.933] [35841:35843] [DMG] {
[1759935552.933] [35841:35843] [DMG] SubscriptionId = 0x7f947a19,
[1759935552.933] [35841:35843] [DMG] AttributeReportIBs =
[1759935552.933] [35841:35843] [DMG] [
[1759935552.933] [35841:35843] [DMG] AttributeReportIB =
[1759935552.933] [35841:35843] [DMG] {
[1759935552.933] [35841:35843] [DMG] AttributeDataIB =
[1759935552.933] [35841:35843] [DMG] {
[1759935552.933] [35841:35843] [DMG] DataVersion = 0xd289260d,
[1759935552.933] [35841:35843] [DMG] AttributePathIB =
[1759935552.933] [35841:35843] [DMG] {
[1759935552.933] [35841:35843] [DMG] Endpoint = 0x2,
[1759935552.933] [35841:35843] [DMG] Cluster = 0x402,
[1759935552.933] [35841:35843] [DMG] Attribute = 0x0000_0000,
[1759935552.933] [35841:35843] [DMG] }
[1759935552.933] [35841:35843] [DMG]
[1759935552.933] [35841:35843] [DMG] Data = 2317 (signed),
[1759935552.933] [35841:35843] [DMG] },
[1759935552.933] [35841:35843] [DMG]
[1759935552.933] [35841:35843] [DMG] },
[1759935552.933] [35841:35843] [DMG]
[1759935552.933] [35841:35843] [DMG] ],
[1759935552.933] [35841:35843] [DMG]
[1759935552.933] [35841:35843] [DMG] InteractionModelRevision = 12
[1759935552.933] [35841:35843] [DMG] }
[1759935552.933] [35841:35843] [TOO] Endpoint: 2 Cluster: 0x0000_0402 Attribute 0x0000_0000 DataVersion: 3532203533
[1759935552.933] [35841:35843] [TOO] MeasuredValue: 2317
[1759935552.933] [35841:35843] [DMG] Refresh LivenessCheckTime for 160049 milliseconds with SubscriptionId = 0x7f947a19 Peer = 01:0000000000000001
[1759935552.933] [35841:35843] [EM] <<< [E:28030r S:53628 M:87260966 (Ack:219337462)] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [235E] [UDP:[fd11:35::a56a:73c7:6e10:f7a9]:5540] --- Type 0001:01 (IM:StatusResponse) (B:42)
[1759935552.933] [35841:35843] [EM] ??1 [E:28030r S:53628 M:87260966] (S) Msg Retransmission to 1:0000000000000001 in 2799ms [State:Active II:3000 AI:2200 AT:300]
[1759935553.159] [35841:35843] [EM] >>> [E:28030r S:53628 M:219337463 (Ack:87260966)] (S) Msg RX from 1:0000000000000001 [235E] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1759935553.159] [35841:35843] [EM] Found matching exchange: 28030r, Delegate: (nil)
[1759935553.159] [35841:35843] [EM] Rxd Ack; Removing MessageCounter:87260966 from Retrans Table on exchange 28030r
[1759935618.153] [35841:35843] [EM] >>> [E:28031r S:53628 M:219337464] (S) Msg RX from 1:0000000000000001 [235E] to 000000000001B669 --- Type 0001:05 (IM:ReportData) (B:41)
[1759935618.153] [35841:35843] [EM] Handling via exchange: 28031r, Delegate: 0xaaaada80c320
[1759935618.153] [35841:35843] [DMG] ReportDataMessage =
[1759935618.153] [35841:35843] [DMG] {
[1759935618.153] [35841:35843] [DMG] SubscriptionId = 0x7f947a19,
[1759935618.153] [35841:35843] [DMG] InteractionModelRevision = 12
[1759935618.153] [35841:35843] [DMG] }
[1759935618.154] [35841:35843] [DMG] Refresh LivenessCheckTime for 160049 milliseconds with SubscriptionId = 0x7f947a19 Peer = 01:0000000000000001
[1759935618.154] [35841:35843] [EM] <<< [E:28031r S:53628 M:87260967 (Ack:219337464)] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [235E] [UDP:[fd11:35::a56a:73c7:6e10:f7a9]:5540] --- Type 0001:01 (IM:StatusResponse) (B:42)
[1759935618.154] [35841:35843] [EM] ??1 [E:28031r S:53628 M:87260967] (S) Msg Retransmission to 1:0000000000000001 in 2990ms [State:Active II:3000 AI:2200 AT:300]
[1759935618.386] [35841:35843] [EM] >>> [E:28031r S:53628 M:219337465 (Ack:87260967)] (S) Msg RX from 1:0000000000000001 [235E] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1759935618.386] [35841:35843] [EM] Found matching exchange: 28031r, Delegate: (nil)
[1759935618.386] [35841:35843] [EM] Rxd Ack; Removing MessageCounter:87260967 from Retrans Table on exchange 28031r
[1759935778.303] [35841:35843] [DMG] Subscription Liveness timeout with SubscriptionID = 0x7f947a19, Peer = 01:0000000000000001
[1759935778.303] [35841:35843] [IN] SecureSession[0xffff9c008a80]: MarkAsDefunct Type:2 LSID:53624
[1759935778.303] [35841:35843] [IN] SecureSession[0xffff9c009810]: MarkAsDefunct Type:2 LSID:53625
[1759935778.303] [35841:35843] [IN] SecureSession[0xffff9c011f90]: MarkAsDefunct Type:2 LSID:53626
[1759935778.303] [35841:35843] [IN] SecureSession[0xffff9c010bd0]: MarkAsDefunct Type:2 LSID:53627
[1759935778.303] [35841:35843] [IN] SecureSession[0xffff9c011c80]: MarkAsDefunct Type:2 LSID:53628
[1759935778.303] [35841:35843] [SC] SecureSession[0xffff9c011c80, LSID:53628]: State change 'kActive' --> 'kDefunct'
[1759935778.303] [35841:35843] [DMG] MoveToState ReadClient[0xffff9c00a060]: Moving to [ Idle]
[1759935778.303] [35841:35843] [TOO] Error: src/app/ReadClient.cpp:1022: CHIP Error 0x00000032: Timeout
[1759935778.303] [35841:35843] [TOO] Run command failure: src/app/ReadClient.cpp:1022: CHIP Error 0x00000032: Timeout
>>> temperaturemeasurement subscribe measured-value 1 120 1 2
[1759990114.900] [35841:35841] [TOO] Command: temperaturemeasurement subscribe measured-value 1 120 1 2
[1759990114.900] [35841:35843] [TOO] Sending command to node 0x1
[1759990114.900] [35841:35843] [CSM] FindOrEstablishSession: PeerId = [1:0000000000000001]
[1759990114.900] [35841:35843] [CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1759990114.901] [35841:35843] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1759990114.901] [35841:35843] [DIS] Resolving 4B8E19A91D81235E:0000000000000001 ...
[1759990114.901] [35841:35843] [DIS] Lookup started for 4B8E19A91D81235E-0000000000000001
[1759990115.003] [35841:35843] [DL] Avahi resolve found
[1759990115.003] [35841:35843] [DIS] Node ID resolved for 4B8E19A91D81235E-0000000000000001
[1759990115.003] [35841:35843] [DIS] Hostname: FAC836911C27B1C2
[1759990115.003] [35841:35843] [DIS] IP Address #1: fd11:35::a56a:73c7:6e10:f7a9
[1759990115.003] [35841:35843] [DIS] Port: 5540
[1759990115.003] [35841:35843] [DIS] Mrp Interval idle: 3000 ms
[1759990115.003] [35841:35843] [DIS] Mrp Interval active: 2200 ms
[1759990115.003] [35841:35843] [DIS] Mrp Active Threshold: 300 ms
[1759990115.003] [35841:35843] [DIS] TCP Client Supported: 0
[1759990115.003] [35841:35843] [DIS] TCP Server Supported: 0
[1759990115.003] [35841:35843] [DIS] ICD: not present
[1759990115.003] [35841:35843] [DIS] Lookup clearing interface for non LL address
[1759990115.003] [35841:35843] [DIS] UDP:[fd11:35::a56a:73c7:6e10:f7a9%veth97777be]:5540: new best score: 5 (for 4B8E19A91D81235E-0000000000000001)
[1759990115.003] [35841:35843] [DIS] Checking node lookup status for 4B8E19A91D81235E-0000000000000001 after 102 ms
[1759990115.003] [35841:35843] [DIS] Keeping DNSSD lookup active
[1759990115.101] [35841:35843] [DIS] Checking node lookup status for 4B8E19A91D81235E-0000000000000001 after 200 ms
[1759990115.101] [35841:35843] [DIS] OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::a56a:73c7:6e10:f7a9]:5540 while in state 2
[1759990115.101] [35841:35843] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1759990115.101] [35841:35843] [IN] SecureSession[0xffff9c011e50]: Allocated Type:2 LSID:53629
[1759990115.101] [35841:35843] [SC] Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1759990115.102] [35841:35843] [EM] <<< [E:63075i S:0 M:59733938] (U) Msg TX from 41503CC2AC3915F8 to 0:0000000000000000 [0000] [UDP:[fd11:35::a56a:73c7:6e10:f7a9]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:234)
[1759990115.102] [35841:35843] [EM] ??1 [E:63075i S:0 M:59733938] (U) Msg Retransmission to 0:0000000000000000 in 3713ms [State:Idle II:3000 AI:2200 AT:300]
[1759990115.102] [35841:35843] [SC] Sent Sigma1 msg to <0000000000000001, 1> [II:500ms AI:300ms AT:4000ms]
[1759990115.102] [35841:35843] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1759990118.818] [35841:35843] [EM] <<1 [E:63075i S:0 M:59733938] (U) Msg Retransmission to 0:0000000000000000
[1759990118.819] [35841:35843] [EM] ??2 [E:63075i S:0 M:59733938] (U) Msg Retransmission to 0:0000000000000000 in 3681ms [State:Idle II:3000 AI:2200 AT:300]
[1759990122.503] [35841:35843] [EM] <<2 [E:63075i S:0 M:59733938] (U) Msg Retransmission to 0:0000000000000000
[1759990122.503] [35841:35843] [EM] ??3 [E:63075i S:0 M:59733938] (U) Msg Retransmission to 0:0000000000000000 in 6441ms [State:Idle II:3000 AI:2200 AT:300]
[1759990125.474] [35841:35843] [EM] >>> [E:63075i S:0 M:41857777 (Ack:59733938)] (U) Msg RX from 0:0000000000000000 [0000] to 41503CC2AC3915F8 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1759990125.474] [35841:35843] [EM] Found matching exchange: 63075i, Delegate: 0xffff9c00c038
[1759990125.474] [35841:35843] [EM] Rxd Ack; Removing MessageCounter:59733938 from Retrans Table on exchange 63075i
[1759990125.522] [35841:35843] [EM] >>> [E:63075i S:0 M:41857778 (Ack:59733938)] (U) Msg RX from 0:0000000000000000 [0000] to 41503CC2AC3915F8 --- Type 0000:33 (SecureChannel:CASE_Sigma2Resume) (B:100)
[1759990125.522] [35841:35843] [EM] Found matching exchange: 63075i, Delegate: 0xffff9c00c038
[1759990125.522] [35841:35843] [EM] CHIP MessageCounter:59733938 not in RetransTable on exchange 63075i
[1759990125.522] [35841:35843] [SC] Received Sigma2Resume msg
[1759990125.522] [35841:35843] [SC] Found MRP parameters in the message
[1759990125.522] [35841:35843] [SC] Peer assigned session session ID 20217
[1759990125.530] [35841:35843] [SC] Sending status report. Protocol code 0, exchange 63075
[1759990125.530] [35841:35843] [EM] <<< [E:63075i S:0 M:59733939 (Ack:41857778)] (U) Msg TX from 41503CC2AC3915F8 to 0:0000000000000000 [0000] [UDP:[fd11:35::a56a:73c7:6e10:f7a9]:5540] --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
[1759990125.530] [35841:35843] [EM] ??1 [E:63075i S:0 M:59733939] (U) Msg Retransmission to 0:0000000000000000 in 2751ms [State:Active II:3000 AI:2200 AT:300]
[1759990125.530] [35841:35843] [SC] SecureSession[0xffff9c011e50, LSID:53629]: State change 'kEstablishing' --> 'kActive'
[1759990125.530] [35841:35843] [IN] SecureSession[0xffff9c011e50]: Activated - Type:2 LSID:53629
[1759990125.530] [35841:35843] [IN] New secure session activated for device <0000000000000001, 1>, LSID:53629 PSID:20217!
[1759990125.530] [35841:35843] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1759990125.530] [35841:35843] [TOO] Sending SubscribeAttribute to:
[1759990125.530] [35841:35843] [TOO] cluster 0x0000_0402, attribute: 0x0000_0000, endpoint 2
[1759990125.530] [35841:35843] [DMG] 0 data version filters provided, 0 not relevant, 0 encoded, 0 skipped due to lack of space
[1759990125.530] [35841:35843] [EM] <<< [E:63076i S:53629 M:132331946] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [235E] [UDP:[fd11:35::a56a:73c7:6e10:f7a9]:5540] --- Type 0001:03 (IM:SubscribeRequest) (B:60)
[1759990125.530] [35841:35843] [EM] ??1 [E:63076i S:53629 M:132331946] (S) Msg Retransmission to 1:0000000000000001 in 2491ms [State:Active II:3000 AI:2200 AT:300]
[1759990125.530] [35841:35843] [DMG] MoveToState ReadClient[0xffff9c00a060]: Moving to [AwaitingIn]
[1759990125.530] [35841:35843] [DL] HandlePlatformSpecificBLEEvent 32792
[1759990125.547] [35841:35843] [EM] >>> [E:63075i S:0 M:41857779 (Ack:59733938)] (U) Msg RX from 0:0000000000000000 [0000] to 41503CC2AC3915F8 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1759990125.547] [35841:35843] [EM] Found matching exchange: 63075i, Delegate: (nil)
[1759990125.547] [35841:35843] [EM] CHIP MessageCounter:59733938 not in RetransTable on exchange 63075i
[1759990125.713] [35841:35843] [EM] >>> [E:63075i S:0 M:41857780 (Ack:59733938)] (U) Msg RX from 0:0000000000000000 [0000] to 41503CC2AC3915F8 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1759990125.713] [35841:35843] [EM] Found matching exchange: 63075i, Delegate: (nil)
[1759990125.713] [35841:35843] [EM] CHIP MessageCounter:59733938 not in RetransTable on exchange 63075i
[1759990125.762] [35841:35843] [EM] >>> [E:63075i S:0 M:41857781 (Ack:59733939)] (U) Msg RX from 0:0000000000000000 [0000] to 41503CC2AC3915F8 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1759990125.762] [35841:35843] [EM] Found matching exchange: 63075i, Delegate: (nil)
[1759990125.762] [35841:35843] [EM] Rxd Ack; Removing MessageCounter:59733939 from Retrans Table on exchange 63075i
[1759990125.976] [35841:35843] [EM] >>> [E:63076i S:53629 M:55144915 (Ack:132331946)] (S) Msg RX from 1:0000000000000001 [235E] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1759990125.976] [35841:35843] [EM] Found matching exchange: 63076i, Delegate: 0xffff9c00a070
[1759990125.976] [35841:35843] [EM] Rxd Ack; Removing MessageCounter:132331946 from Retrans Table on exchange 63076i
[1759990172.943] [35841:35843] [DMG] Time out! failed to receive report data from Exchange: 63076i
[1759990172.943] [35841:35843] [DMG] MoveToState ReadClient[0xffff9c00a060]: Moving to [ Idle]
[1759990172.943] [35841:35843] [TOO] Error: src/app/ReadClient.cpp:723: CHIP Error 0x00000032: Timeout
[1759990172.943] [35841:35843] [TOO] Run command failure: src/app/ReadClient.cpp:723: CHIP Error 0x00000032: Timeout
>>>
[1759990172.943] [35841:35841] [TOO] Command:
[1759990172.943] [35841:35841] [TOO] Missing cluster or command set name
Usage:
cluster_name command_name [param1 param2 ...]
or:
command_set_name command_name [param1 param2 ...]
+-------------------------------------------------------------------------------------+
| Clusters: |
+-------------------------------------------------------------------------------------+
| * accesscontrol |
| * accountlogin |
| * actions |
| * activatedcarbonfiltermonitoring |
| * administratorcommissioning |
| * airquality |
| * applicationbasic |
| * applicationlauncher |
| * audiooutput |
| * ballastconfiguration |
| * basicinformation |
| * binding |
| * booleanstate |
| * booleanstateconfiguration |
| * bridgeddevicebasicinformation |
| * carbondioxideconcentrationmeasurement |
| * carbonmonoxideconcentrationmeasurement |
| * channel |
| * chime |
| * colorcontrol |
| * commissionercontrol |
| * contentappobserver |
| * contentcontrol |
| * contentlauncher |
| * demandresponseloadcontrol |
| * descriptor |
| * deviceenergymanagement |
| * deviceenergymanagementmode |
| * diagnosticlogs |
| * dishwasheralarm |
| * dishwashermode |
| * doorlock |
| * ecosysteminformation |
| * electricalenergymeasurement |
| * electricalpowermeasurement |
| * energyevse |
| * energyevsemode |
| * energypreference |
| * ethernetnetworkdiagnostics |
| * fancontrol |
| * faultinjection |
| * fixedlabel |
| * flowmeasurement |
| * formaldehydeconcentrationmeasurement |
| * generalcommissioning |
| * generaldiagnostics |
| * groupkeymanagement |
| * groups |
| * hepafiltermonitoring |
| * icdmanagement |
| * identify |
| * illuminancemeasurement |
| * keypadinput |
| * laundrydryercontrols |
| * laundrywashercontrols |
| * laundrywashermode |
| * levelcontrol |
| * localizationconfiguration |
| * lowpower |
| * mediainput |
| * mediaplayback |
| * messages |
| * microwaveovencontrol |
| * microwaveovenmode |
| * modeselect |
| * networkcommissioning |
| * nitrogendioxideconcentrationmeasurement |
| * occupancysensing |
| * onoff |
| * operationalcredentials |
| * operationalstate |
| * otasoftwareupdateprovider |
| * otasoftwareupdaterequestor |
| * ovencavityoperationalstate |
| * ovenmode |
| * ozoneconcentrationmeasurement |
| * pm10concentrationmeasurement |
| * pm1concentrationmeasurement |
| * pm25concentrationmeasurement |
| * powersource |
| * powersourceconfiguration |
| * powertopology |
| * pressuremeasurement |
| * proxyconfiguration |
| * proxydiscovery |
| * proxyvalid |
| * pulsewidthmodulation |
| * pumpconfigurationandcontrol |
| * radonconcentrationmeasurement |
| * refrigeratoralarm |
| * refrigeratorandtemperaturecontrolledcabinetmode |
| * relativehumiditymeasurement |
| * rvccleanmode |
| * rvcoperationalstate |
| * rvcrunmode |
| * samplemei |
| * scenesmanagement |
| * servicearea |
| * smokecoalarm |
| * softwarediagnostics |
| * switch |
| * targetnavigator |
| * temperaturecontrol |
| * temperaturemeasurement |
| * thermostat |
| * thermostatuserinterfaceconfiguration |
| * threadborderroutermanagement |
| * threadnetworkdiagnostics |
| * threadnetworkdirectory |
| * timeformatlocalization |
| * timesynchronization |
| * timer |
| * totalvolatileorganiccompoundsconcentrationmeasurement |
| * unitlocalization |
| * unittesting |
| * userlabel |
| * valveconfigurationandcontrol |
| * wakeonlan |
| * waterheatermanagement |
| * waterheatermode |
| * webrtctransportprovider |
| * wifinetworkdiagnostics |
| * wifinetworkmanagement |
| * windowcovering |
+-------------------------------------------------------------------------------------+
+-------------------------------------------------------------------------------------+
| Command sets: |
+-------------------------------------------------------------------------------------+
| * any |
| - Commands for sending IM messages based on cluster id, not cluster name. |
| * dcl |
| - Commands to interact with the DCL. |
| * delay |
| - Commands for waiting for something to happen. |
| * discover |
| - Commands for device discovery. |
| * groupsettings |
| - Commands for manipulating group keys and memberships for chip-tool itself. |
| * icd |
| - Commands for client-side ICD management. |
| * pairing |
| - Commands for commissioning devices. |
| * payload |
| - Commands for parsing and generating setup payloads. |
| * sessionmanagement |
| - Commands for managing CASE and PASE session state. |
| * subscriptions |
| - Commands for shutting down subscriptions. |
| * interactive |
| - Commands for starting long-lived interactive modes. |
| * storage |
| - Commands for managing persistent data stored by chip-tool. |
+-------------------------------------------------------------------------------------+
>>>
[1759990172.945] [35841:35841] [TOO] Command:
[1759990172.945] [35841:35841] [TOO] Missing cluster or command set name
Usage:
cluster_name command_name [param1 param2 ...]
or:
command_set_name command_name [param1 param2 ...]
+-------------------------------------------------------------------------------------+
| Clusters: |
+-------------------------------------------------------------------------------------+
| * accesscontrol |
| * accountlogin |
| * actions |
| * activatedcarbonfiltermonitoring |
| * administratorcommissioning |
| * airquality |
| * applicationbasic |
| * applicationlauncher |
| * audiooutput |
| * ballastconfiguration |
| * basicinformation |
| * binding |
| * booleanstate |
| * booleanstateconfiguration |
| * bridgeddevicebasicinformation |
| * carbondioxideconcentrationmeasurement |
| * carbonmonoxideconcentrationmeasurement |
| * channel |
| * chime |
| * colorcontrol |
| * commissionercontrol |
| * contentappobserver |
| * contentcontrol |
| * contentlauncher |
| * demandresponseloadcontrol |
| * descriptor |
| * deviceenergymanagement |
| * deviceenergymanagementmode |
| * diagnosticlogs |
| * dishwasheralarm |
| * dishwashermode |
| * doorlock |
| * ecosysteminformation |
| * electricalenergymeasurement |
| * electricalpowermeasurement |
| * energyevse |
| * energyevsemode |
| * energypreference |
| * ethernetnetworkdiagnostics |
| * fancontrol |
| * faultinjection |
| * fixedlabel |
| * flowmeasurement |
| * formaldehydeconcentrationmeasurement |
| * generalcommissioning |
| * generaldiagnostics |
| * groupkeymanagement |
| * groups |
| * hepafiltermonitoring |
| * icdmanagement |
| * identify |
| * illuminancemeasurement |
| * keypadinput |
| * laundrydryercontrols |
| * laundrywashercontrols |
| * laundrywashermode |
| * levelcontrol |
| * localizationconfiguration |
| * lowpower |
| * mediainput |
| * mediaplayback |
| * messages |
| * microwaveovencontrol |
| * microwaveovenmode |
| * modeselect |
| * networkcommissioning |
| * nitrogendioxideconcentrationmeasurement |
| * occupancysensing |
| * onoff |
| * operationalcredentials |
| * operationalstate |
| * otasoftwareupdateprovider |
| * otasoftwareupdaterequestor |
| * ovencavityoperationalstate |
| * ovenmode |
| * ozoneconcentrationmeasurement |
| * pm10concentrationmeasurement |
| * pm1concentrationmeasurement |
| * pm25concentrationmeasurement |
| * powersource |
| * powersourceconfiguration |
| * powertopology |
| * pressuremeasurement |
| * proxyconfiguration |
| * proxydiscovery |
| * proxyvalid |
| * pulsewidthmodulation |
| * pumpconfigurationandcontrol |
| * radonconcentrationmeasurement |
| * refrigeratoralarm |
| * refrigeratorandtemperaturecontrolledcabinetmode |
| * relativehumiditymeasurement |
| * rvccleanmode |
| * rvcoperationalstate |
| * rvcrunmode |
| * samplemei |
| * scenesmanagement |
| * servicearea |
| * smokecoalarm |
| * softwarediagnostics |
| * switch |
| * targetnavigator |
| * temperaturecontrol |
| * temperaturemeasurement |
| * thermostat |
| * thermostatuserinterfaceconfiguration |
| * threadborderroutermanagement |
| * threadnetworkdiagnostics |
| * threadnetworkdirectory |
| * timeformatlocalization |
| * timesynchronization |
| * timer |
| * totalvolatileorganiccompoundsconcentrationmeasurement |
| * unitlocalization |
| * unittesting |
| * userlabel |
| * valveconfigurationandcontrol |
| * wakeonlan |
| * waterheatermanagement |
| * waterheatermode |
| * webrtctransportprovider |
| * wifinetworkdiagnostics |
| * wifinetworkmanagement |
| * windowcovering |
+-------------------------------------------------------------------------------------+
+-------------------------------------------------------------------------------------+
| Command sets: |
+-------------------------------------------------------------------------------------+
| * any |
| - Commands for sending IM messages based on cluster id, not cluster name. |
| * dcl |
| - Commands to interact with the DCL. |
| * delay |
| - Commands for waiting for something to happen. |
| * discover |
| - Commands for device discovery. |
| * groupsettings |
| - Commands for manipulating group keys and memberships for chip-tool itself. |
| * icd |
| - Commands for client-side ICD management. |
| * pairing |
| - Commands for commissioning devices. |
| * payload |
| - Commands for parsing and generating setup payloads. |
| * sessionmanagement |
| - Commands for managing CASE and PASE session state. |
| * subscriptions |
| - Commands for shutting down subscriptions. |
| * interactive |
| - Commands for starting long-lived interactive modes. |
| * storage |
| - Commands for managing persistent data stored by chip-tool. |
+-------------------------------------------------------------------------------------+
>>> relativehumiditymeasurement subscribe measured-value 1 120 1 2
[1759990222.668] [35841:35841] [TOO] Command: relativehumiditymeasurement subscribe measured-value 1 120 1 2
[1759990222.668] [35841:35843] [TOO] Sending command to node 0x1
[1759990222.669] [35841:35843] [CSM] FindOrEstablishSession: PeerId = [1:0000000000000001]
[1759990222.669] [35841:35843] [CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1759990222.669] [35841:35843] [DIS] Found an existing secure session to [1:0000000000000001]!
[1759990222.669] [35841:35843] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5
[1759990222.669] [35841:35843] [TOO] Sending SubscribeAttribute to:
[1759990222.669] [35841:35843] [TOO] cluster 0x0000_0405, attribute: 0x0000_0000, endpoint 2
[1759990222.669] [35841:35843] [DMG] 0 data version filters provided, 0 not relevant, 0 encoded, 0 skipped due to lack of space
[1759990222.669] [35841:35843] [EM] <<< [E:63077i S:53629 M:132331947] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [235E] [UDP:[fd11:35::a56a:73c7:6e10:f7a9]:5540] --- Type 0001:03 (IM:SubscribeRequest) (B:60)
[1759990222.669] [35841:35843] [EM] ??1 [E:63077i S:53629 M:132331947] (S) Msg Retransmission to 1:0000000000000001 in 3707ms [State:Idle II:3000 AI:2200 AT:300]
[1759990222.669] [35841:35843] [DMG] MoveToState ReadClient[0xffff9c00a060]: Moving to [AwaitingIn]
[1759990223.064] [35841:35843] [EM] >>> [E:63077i S:53629 M:55144916 (Ack:132331947)] (S) Msg RX from 1:0000000000000001 [235E] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1759990223.064] [35841:35843] [EM] Found matching exchange: 63077i, Delegate: 0xffff9c00a070
[1759990223.064] [35841:35843] [EM] Rxd Ack; Removing MessageCounter:132331947 from Retrans Table on exchange 63077i
[1759990271.223] [35841:35843] [DMG] Time out! failed to receive report data from Exchange: 63077i
[1759990271.224] [35841:35843] [DMG] MoveToState ReadClient[0xffff9c00a060]: Moving to [ Idle]
[1759990271.224] [35841:35843] [TOO] Error: src/app/ReadClient.cpp:723: CHIP Error 0x00000032: Timeout
[1759990271.224] [35841:35843] [TOO] Run command failure: src/app/ReadClient.cpp:723: CHIP Error 0x00000032: Timeout
>>> descriptor read parts-list 1 0
[1759990411.384] [35841:35841] [TOO] Command: descriptor read parts-list 1 0
[1759990411.384] [35841:35843] [TOO] Sending command to node 0x1
[1759990411.384] [35841:35843] [CSM] FindOrEstablishSession: PeerId = [1:0000000000000001]
[1759990411.384] [35841:35843] [CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1759990411.384] [35841:35843] [DIS] Found an existing secure session to [1:0000000000000001]!
[1759990411.384] [35841:35843] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5
[1759990411.384] [35841:35843] [TOO] Sending ReadAttribute to:
[1759990411.384] [35841:35843] [TOO] cluster 0x0000_001D, attribute: 0x0000_0003, endpoint 0
[1759990411.384] [35841:35843] [DMG] SendReadRequest ReadClient[0xffff9c00a060]: Sending Read Request
[1759990411.384] [35841:35843] [DMG] 0 data version filters provided, 0 not relevant, 0 encoded, 0 skipped due to lack of space
[1759990411.384] [35841:35843] [EM] <<< [E:63078i S:53629 M:132331948] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [235E] [UDP:[fd11:35::a56a:73c7:6e10:f7a9]:5540] --- Type 0001:02 (IM:ReadRequest) (B:51)
[1759990411.385] [35841:35843] [EM] ??1 [E:63078i S:53629 M:132331948] (S) Msg Retransmission to 1:0000000000000001 in 3836ms [State:Idle II:3000 AI:2200 AT:300]
[1759990411.385] [35841:35843] [DMG] MoveToState ReadClient[0xffff9c00a060]: Moving to [AwaitingIn]
[1759990413.308] [35841:35843] [EM] >>> [E:63078i S:53629 M:55144917 (Ack:132331948)] (S) Msg RX from 1:0000000000000001 [235E] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1759990413.308] [35841:35843] [EM] Found matching exchange: 63078i, Delegate: 0xffff9c00a070
[1759990413.308] [35841:35843] [EM] Rxd Ack; Removing MessageCounter:132331948 from Retrans Table on exchange 63078i
[1759990459.931] [35841:35843] [DMG] Time out! failed to receive report data from Exchange: 63078i
[1759990459.931] [35841:35843] [TOO] Error: src/app/ReadClient.cpp:723: CHIP Error 0x00000032: Timeout
[1759990459.931] [35841:35843] [TOO] Run command failure: src/app/ReadClient.cpp:723: CHIP Error 0x00000032: Timeout
>>> descriptor read parts-list 1 0
[1759990471.406] [35841:35841] [TOO] Command: descriptor read parts-list 1 0
[1759990471.406] [35841:35843] [TOO] Sending command to node 0x1
[1759990471.406] [35841:35843] [CSM] FindOrEstablishSession: PeerId = [1:0000000000000001]
[1759990471.406] [35841:35843] [CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1759990471.406] [35841:35843] [DIS] Found an existing secure session to [1:0000000000000001]!
[1759990471.406] [35841:35843] [DIS] OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5
[1759990471.406] [35841:35843] [TOO] Sending ReadAttribute to:
[1759990471.406] [35841:35843] [TOO] cluster 0x0000_001D, attribute: 0x0000_0003, endpoint 0
[1759990471.406] [35841:35843] [DMG] SendReadRequest ReadClient[0xffff9c00a060]: Sending Read Request
[1759990471.406] [35841:35843] [DMG] 0 data version filters provided, 0 not relevant, 0 encoded, 0 skipped due to lack of space
[1759990471.406] [35841:35843] [EM] <<< [E:63079i S:53629 M:132331949] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [235E] [UDP:[fd11:35::a56a:73c7:6e10:f7a9]:5540] --- Type 0001:02 (IM:ReadRequest) (B:51)
[1759990471.407] [35841:35843] [EM] ??1 [E:63079i S:53629 M:132331949] (S) Msg Retransmission to 1:0000000000000001 in 3375ms [State:Idle II:3000 AI:2200 AT:300]
[1759990471.407] [35841:35843] [DMG] MoveToState ReadClient[0xffff9c00a060]: Moving to [AwaitingIn]
[1759990471.823] [35841:35843] [EM] >>> [E:63079i S:53629 M:55144918 (Ack:132331949)] (S) Msg RX from 1:0000000000000001 [235E] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1759990471.823] [35841:35843] [EM] Found matching exchange: 63079i, Delegate: 0xffff9c00a070
[1759990471.823] [35841:35843] [EM] Rxd Ack; Removing MessageCounter:132331949 from Retrans Table on exchange 63079i
[1759990519.961] [35841:35843] [DMG] Time out! failed to receive report data from Exchange: 63079i
[1759990519.961] [35841:35843] [TOO] Error: src/app/ReadClient.cpp:723: CHIP Error 0x00000032: Timeout
[1759990519.961] [35841:35843] [TOO] Run command failure: src/app/ReadClient.cpp:723: CHIP Error 0x00000032: Timeout
>>>
So I have two questions here:
1. Why does the device always delete the previous subscription when I add a new one? Is this expected behaviour?
2. Why does the device become unresponsive like this?
I'm using SDK/toolchain v3.0.1 and running on a custom board with 52840 SOC.
I know you will probably ask for this so here is the important part from conf regarding Thread and Matter:
CONFIG_OPENTHREAD_NORDIC_LIBRARY_MTD=y
CONFIG_OPENTHREAD_MTD=y
CONFIG_OPENTHREAD_FTD=n
CONFIG_CHIP_ENABLE_ICD_SUPPORT=y
CONFIG_CHIP_THREAD_SSED=y
CONFIG_CHIP_ICD_IDLE_MODE_DURATION=120
CONFIG_CHIP_ICD_ACTIVE_MODE_DURATION=300
CONFIG_CHIP_ICD_SLOW_POLL_INTERVAL=1000
CONFIG_CHIP_ICD_FAST_POLLING_INTERVAL=200
I don't think the Window Cover sample unchanged had this issue and I'm sure it would be possible to go back through Git history and find where this breaks but that would take a very long time as this issue usually takes hours to appear. If you can at least point me towards something to check that would help a lot. Could this be a memory issue with the Matter thread because I did add quite a few extra clusters and attributes. I also periodically update the attribute values (am_matter_loop calls) but I don't see any of the interactions fail in the logs at least. The device recovers nicely after a reboot and resubscribe but I don't want to have to restart all the time (I could set up a watchdog to do that but come on...).
I will add here the block of logs from the device side when the subscription failed at first:
[01:44:44.732,696] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1010,temp=2323,hum=4000 [01:45:49.965,209] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1017,temp=2323,hum=4000 [01:46:34.279,083] <inf> chip: [EM]<<< [E:28019i S:20216 M:219337440] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:41) [01:46:34.284,484] <inf> chip: [EM]??1 [E:28019i S:20216 M:219337440] (S) Msg Retransmission to 1:000000000001B669 in 2333ms [State:Idle II:500 AI:300 AT:4000] [01:46:34.498,840] <inf> chip: [EM]>>> [E:28019i S:20216 M:87260955 (Ack:219337440)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:46:34.502,563] <inf> chip: [IM]Received status response, status is 0x00 [01:46:34.505,615] <inf> chip: [EM]<<< [E:28019i S:20216 M:219337441 (Ack:87260955)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:46:55.198,333] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1020,temp=2321,hum=4000 [01:46:55.203,125] <inf> chip: [EM]<<< [E:28020i S:20216 M:219337442] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:72) [01:46:55.209,289] <inf> chip: [EM]??1 [E:28020i S:20216 M:219337442] (S) Msg Retransmission to 1:000000000001B669 in 2258ms [State:Idle II:500 AI:300 AT:4000] [01:46:55.425,048] <inf> chip: [EM]>>> [E:28020i S:20216 M:87260956 (Ack:219337442)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:46:55.428,802] <inf> chip: [IM]Received status response, status is 0x00 [01:46:55.431,854] <inf> chip: [EM]<<< [E:28020i S:20216 M:219337443 (Ack:87260956)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:48:00.433,502] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1007,temp=2322,hum=4000 [01:48:00.438,293] <inf> chip: [EM]<<< [E:28021i S:20216 M:219337444] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:72) [01:48:00.444,030] <inf> chip: [EM]??1 [E:28021i S:20216 M:219337444] (S) Msg Retransmission to 1:000000000001B669 in 2320ms [State:Idle II:500 AI:300 AT:4000] [01:48:00.857,177] <inf> chip: [EM]>>> [E:28021i S:20216 M:87260957 (Ack:219337444)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:48:00.860,900] <inf> chip: [IM]Received status response, status is 0x00 [01:48:00.863,952] <inf> chip: [EM]<<< [E:28021i S:20216 M:219337445 (Ack:87260957)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:49:05.667,663] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1014,temp=2323,hum=4000 [01:49:05.672,454] <inf> chip: [EM]<<< [E:28022i S:20216 M:219337446] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:72) [01:49:05.678,009] <inf> chip: [EM]??1 [E:28022i S:20216 M:219337446] (S) Msg Retransmission to 1:000000000001B669 in 2298ms [State:Idle II:500 AI:300 AT:4000] [01:49:06.296,264] <inf> chip: [EM]>>> [E:28022i S:20216 M:87260958 (Ack:219337446)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:49:06.299,987] <inf> chip: [IM]Received status response, status is 0x00 [01:49:06.303,039] <inf> chip: [EM]<<< [E:28022i S:20216 M:219337447 (Ack:87260958)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:50:10.900,970] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1046,temp=2322,hum=4000 [01:50:10.905,761] <inf> chip: [EM]<<< [E:28023i S:20216 M:219337448] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:72) [01:50:10.911,315] <inf> chip: [EM]??1 [E:28023i S:20216 M:219337448] (S) Msg Retransmission to 1:000000000001B669 in 2329ms [State:Idle II:500 AI:300 AT:4000] [01:50:11.231,750] <inf> chip: [EM]>>> [E:28023i S:20216 M:87260959 (Ack:219337448)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:50:11.235,473] <inf> chip: [IM]Received status response, status is 0x00 [01:50:11.238,555] <inf> chip: [EM]<<< [E:28023i S:20216 M:219337449 (Ack:87260959)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:51:16.133,453] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1080,temp=2322,hum=4000 [01:52:10.917,663] <inf> chip: [EM]<<< [E:28024i S:20216 M:219337450] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:41) [01:52:10.923,217] <inf> chip: [EM]??1 [E:28024i S:20216 M:219337450] (S) Msg Retransmission to 1:000000000001B669 in 2306ms [State:Idle II:500 AI:300 AT:4000] [01:52:11.139,007] <inf> chip: [EM]>>> [E:28024i S:20216 M:87260960 (Ack:219337450)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:52:11.142,730] <inf> chip: [IM]Received status response, status is 0x00 [01:52:11.145,782] <inf> chip: [EM]<<< [E:28024i S:20216 M:219337451 (Ack:87260960)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:52:21.372,955] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1079,temp=2321,hum=4000 [01:52:21.377,746] <inf> chip: [EM]<<< [E:28025i S:20216 M:219337452] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:72) [01:52:21.383,880] <inf> chip: [EM]??1 [E:28025i S:20216 M:219337452] (S) Msg Retransmission to 1:000000000001B669 in 2371ms [State:Idle II:500 AI:300 AT:4000] [01:52:21.998,657] <inf> chip: [EM]>>> [E:28025i S:20216 M:87260961 (Ack:219337452)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:52:22.002,655] <inf> chip: [IM]Received status response, status is 0x00 [01:52:22.005,706] <inf> chip: [EM]<<< [E:28025i S:20216 M:219337453 (Ack:87260961)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:53:26.616,241] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1059,temp=2322,hum=4000 [01:53:26.621,002] <inf> chip: [EM]<<< [E:28026i S:20216 M:219337454] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:72) [01:53:26.626,586] <inf> chip: [EM]??1 [E:28026i S:20216 M:219337454] (S) Msg Retransmission to 1:000000000001B669 in 2335ms [State:Idle II:500 AI:300 AT:4000] [01:53:27.047,210] <inf> chip: [EM]>>> [E:28026i S:20216 M:87260962 (Ack:219337454)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:53:27.050,933] <inf> chip: [IM]Received status response, status is 0x00 [01:53:27.053,985] <inf> chip: [EM]<<< [E:28026i S:20216 M:219337455 (Ack:87260962)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:54:31.859,588] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1040,temp=2322,hum=4000 [01:55:26.632,232] <inf> chip: [EM]<<< [E:28027i S:20216 M:219337456] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:41) [01:55:26.637,817] <inf> chip: [EM]??1 [E:28027i S:20216 M:219337456] (S) Msg Retransmission to 1:000000000001B669 in 2313ms [State:Idle II:500 AI:300 AT:4000] [01:55:26.853,302] <inf> chip: [EM]>>> [E:28027i S:20216 M:87260963 (Ack:219337456)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:55:26.857,055] <inf> chip: [IM]Received status response, status is 0x00 [01:55:26.860,107] <inf> chip: [EM]<<< [E:28027i S:20216 M:219337457 (Ack:87260963)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:55:37.090,881] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1036,temp=2321,hum=4000 [01:55:37.095,672] <inf> chip: [EM]<<< [E:28028i S:20216 M:219337458] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:72) [01:55:37.101,226] <inf> chip: [EM]??1 [E:28028i S:20216 M:219337458] (S) Msg Retransmission to 1:000000000001B669 in 2348ms [State:Idle II:500 AI:300 AT:4000] [01:55:37.314,422] <inf> chip: [EM]>>> [E:28028i S:20216 M:87260964 (Ack:219337458)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:55:37.318,145] <inf> chip: [IM]Received status response, status is 0x00 [01:55:37.321,197] <inf> chip: [EM]<<< [E:28028i S:20216 M:219337459 (Ack:87260964)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:56:42.322,357] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1076,temp=2321,hum=4000 [01:57:37.106,323] <inf> chip: [EM]<<< [E:28029i S:20216 M:219337460] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:41) [01:57:37.112,396] <inf> chip: [EM]??1 [E:28029i S:20216 M:219337460] (S) Msg Retransmission to 1:000000000001B669 in 2374ms [State:Idle II:500 AI:300 AT:4000] [01:57:37.528,472] <inf> chip: [EM]>>> [E:28029i S:20216 M:87260965 (Ack:219337460)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:57:37.532,226] <inf> chip: [IM]Received status response, status is 0x00 [01:57:37.535,278] <inf> chip: [EM]<<< [E:28029i S:20216 M:219337461 (Ack:87260965)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:57:47.562,103] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1100,temp=2317,hum=4000 [01:57:47.566,894] <inf> chip: [EM]<<< [E:28030i S:20216 M:219337462] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:72) [01:57:47.572,448] <inf> chip: [EM]??1 [E:28030i S:20216 M:219337462] (S) Msg Retransmission to 1:000000000001B669 in 2361ms [State:Idle II:500 AI:300 AT:4000] [01:57:47.788,177] <inf> chip: [EM]>>> [E:28030i S:20216 M:87260966 (Ack:219337462)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:57:47.791,931] <inf> chip: [IM]Received status response, status is 0x00 [01:57:47.794,982] <inf> chip: [EM]<<< [E:28030i S:20216 M:219337463 (Ack:87260966)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:57:58.551,635] <dbg> chip: LogV: [DL]SRP update succeeded [01:58:52.795,562] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1102,temp=2320,hum=4100 [01:58:52.800,201] <inf> chip: [EM]<<< [E:28031i S:20216 M:219337464] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0001:05 (IM:ReportData) (B:41) [01:58:52.805,755] <inf> chip: [EM]??1 [E:28031i S:20216 M:219337464] (S) Msg Retransmission to 1:000000000001B669 in 2368ms [State:Idle II:500 AI:300 AT:4000] [01:58:53.022,644] <inf> chip: [EM]>>> [E:28031i S:20216 M:87260967 (Ack:219337464)] (S) Msg RX from 1:000000000001B669 [235E] to 0000000000000001 --- Type 0001:01 (IM:StatusResponse) (B:42) [01:58:53.026,367] <inf> chip: [IM]Received status response, status is 0x00 [01:58:53.029,418] <inf> chip: [EM]<<< [E:28031i S:20216 M:219337465 (Ack:87260967)] (S) Msg TX from 0000000000000001 to 1:000000000001B669 [235E] [UDP:[fd11:35::18e8:20dc:4157:5f84]:51277] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [01:59:58.037,872] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1117,temp=2318,hum=4100 [02:01:03.268,585] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1116,temp=2319,hum=4100 [02:02:08.501,556] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1094,temp=2317,hum=4100 [02:03:13.736,022] <dbg> am_matter: am_matter_loop: Update matter sensors:bat=100,pos=100,chg=1,co2=1089,temp=2318,hum=4100
As you can see from the timestamp it took almost 2 hours this time for things to fail. Before this everything works perfectly with both chip-tool and all Matter hubs we have tried. I'm hoping there's enough information here for now.
Tiit
