matter: Old sessions not cleaned up

[thatguystone]

PROBLEM DESCRIPTION

Google Home seems to create a new session every day (in my case, 2 devices are creating sessions), and old sessions are never cleaned up. After a while, the device runs out of memory and restarts.

From the berry console:

for s : matter_device.sessions.sessions
 print(s.peer_node_id.tob64(), s.created, s.last_used, s._persist)
end
print(matter_device.sessions.sessions.size())

AxGHlgAAAAA= 1686225158 1686301608 true
E3LnlQAAAAA= 1686301646 1686307778 true
AxGHlgAAAAA= 1686307791 1686390211 true
E3LnlQAAAAA= 1686390251 1686397872 true
AxGHlgAAAAA= 1686397933 1686476826 true
E3LnlQAAAAA= 1686476849 1686566922 true
AxGHlgAAAAA= 1686566960 1686656524 true
// ... snip ...
AxGHlgAAAAA= 1688080036 1688121807 true
AxGHlgAAAAA= 1688124882 1688211518 true
E3LnlQAAAAA= 1688211558 1688298200 true
AxGHlgAAAAA= 1688298236 1688376648 true
E3LnlQAAAAA= 1688299605 1688381344 true
AxGHlgAAAAA= 1688381377 1688432402 true
E3LnlQAAAAA= 1688406782 1688465280 true
AxGHlgAAAAA= 1688406850 1688462001 true
AxGHlgAAAAA= 1688465313 1688555236 true
E3LnlQAAAAA= 1688466526 1688518800 true
E3LnlQAAAAA= 1688555282 1688640481 true
AxGHlgAAAAA= 1688640509 1688642113 true
E3LnlQAAAAA= 1688642152 1688731096 true
AxGHlgAAAAA= 1688665344 1688727604 true
AxGHlgAAAAA= 1688731138 1688793849 true
56

REQUESTED INFORMATION

Make sure your have performed every step and checked the applicable boxes before submitting your issue. Thank you!

• Read the Contributing Guide and Policy and the Code of Conduct
• Searched the problem in issues
• Searched the problem in discussions
• Searched the problem in the docs
• Searched the problem in the chat
• Device used (e.g., Sonoff Basic): Switch Bot W1901400
• Tasmota binary firmware version number used: 12.5.0.4
  • Pre-compiled
  • Self-compiled
• Flashing tools used: _____
• Provide the output of command: Backlog Template; Module; GPIO 255:

22:34:21.822 CMD: Backlog Template; Module; GPIO 255
22:34:21.846 RSL: RESULT = {"NAME":"W1901400","GPIO":[0,0,32,0,0,0,224,320,321,0,0,0,0,0,0,0,0,0,2720,2656,2624,0],"FLAG":0,"BASE":1}
22:34:22.077 RSL: RESULT = {"Module":{"0":"W1901400"}}
22:34:22.283 RSL: RESULT = {"GPIO0":{"0":"None"},"GPIO1":{"0":"None"},"GPIO2":{"32":"Button1"},"GPIO3":{"0":"None"},"GPIO4":{"0":"None"},"GPIO5":{"0":"None"},"GPIO6":{"224":"Relay1"},"GPIO7":{"320":"Led_i1"},"GPIO8":{"321":"Led_i2"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO12":{"0":"None"},"GPIO13":{"0":"None"},"GPIO18":{"2720":"BL0937 CF"},"GPIO19":{"2656":"HLWBL CF1"},"GPIO20":{"2624":"HLWBL SEL_i"},"GPIO21":{"0":"None"}}

• Provide the output of this command: Status 0:

22:35:06.685 RSL: STATUS = {"Status":{"Module":0,"DeviceName":"grow-lights","FriendlyName":["grow-lights"],"Topic":"tasmota_32C554","ButtonTopic":"0","Power":0,"PowerOnState":0,"LedState":0,"LedMask":"FFFF","SaveData":1,"SaveState":0,"SwitchTopic":"0","SwitchMode":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0,"InfoRetain":0,"StateRetain":0,"StatusRetain":0}}
22:35:06.695 RSL: STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"http://ota.tasmota.com/tasmota32/release/tasmota32c3.bin","RestartReason":"Software reset digital core","Uptime":"30T09:26:04","StartupUTC":"2023-06-07T20:09:02","Sleep":50,"CfgHolder":4617,"BootCount":18,"BCResetTime":"2023-04-14T21:02:10","SaveCount":90}}
22:35:06.708 RSL: STATUS2 = {"StatusFWR":{"Version":"12.5.0.4(tasmota32)","BuildDateTime":"2023-06-07T20:06:40","Core":"2_0_9","SDK":"4.4.4.20230310","CpuFrequency":160,"Hardware":"ESP32-C3 rev.3","CR":"440/699"}}
22:35:06.716 RSL: STATUS3 = {"StatusLOG":{"SerialLog":0,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["",""],"TelePeriod":300,"Resolution":"558180C0","SetOption":["00008000","2805C80001000600003C5A0A192800000000","00000081","00006000","00004000","00000020"]}}
22:35:06.730 RSL: STATUS4 = {"StatusMEM":{"ProgramSize":1844,"Free":1856,"Heap":76,"StackLowMark":3,"PsrMax":0,"PsrFree":0,"ProgramFlashSize":4096,"FlashSize":4096,"FlashChipId":"164020","FlashFrequency":80,"FlashMode":"DOUT","Features":["00000809","9F8A55DF","0005A001","B7F7BFCF","05DA9BC0","E0360DC7","080840D2","20200000","D4BC482D","000A80B1"],"Drivers":"1,2,3,4,5,8,9,10,11,12,14,16,17,24,26,27,29,34,35,38,50,52,59,60,62,63,66,67,68,86,87,88","Sensors":"1,2,3,5,6,7,8,9,10,11,12,13,14,15,17,18,19,20,21,22,26,31,34,37,39,40,42,43,45,51,52,55,56,58,59,64,66,67,74,85,92,95,98,103,105,127","I2CDriver":"7,8,9,10,11,12,13,14,15,17,18,20,24,29,31,36,41,42,44,46,48,58,62,65,69,76,77"}}
22:35:06.743 RSL: STATUS5 = {"StatusNET":{"Hostname":"grow-lights","IPAddress":"192.168.1.191","Gateway":"192.168.1.1","Subnetmask":"255.255.255.0","DNSServer1":"192.168.1.1","DNSServer2":"0.0.0.0","Mac":"A0:76:4E:32:C5:54","IP6Global":"","IP6Local":"","Webserver":2,"HTTP_API":1,"WifiConfig":4,"WifiPower":17.0}}
22:35:06.753 RSL: STATUS7 = {"StatusTIM":{"UTC":"2023-07-08T05:35:06","Local":"2023-07-07T22:35:06","StartDST":"2023-03-12T02:00:00","EndDST":"2023-11-05T02:00:00","Timezone":99,"Sunrise":"20:55","Sunset":"12:54"}}
22:35:06.761 RSL: STATUS9 = {"StatusPTH":{"PowerDelta":[0,0,0,0,0,0,0,0],"PowerLow":0,"PowerHigh":0,"VoltageLow":0,"VoltageHigh":0,"CurrentLow":0,"CurrentHigh":0}}
22:35:06.772 RSL: STATUS10 = {"StatusSNS":{"Time":"2023-07-07T22:35:06","ENERGY":{"TotalStartTime":"2023-06-07T13:09:08","Total":13.866,"Yesterday":0.166,"Today":0.166,"Power":0,"ApparentPower":0,"ReactivePower":0,"Factor":0.00,"Voltage":0,"Current":0.000}}}
22:35:06.785 RSL: STATUS11 = {"StatusSTS":{"Time":"2023-07-07T22:35:06","Uptime":"30T09:26:04","UptimeSec":2625964,"Heap":71,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":20,"MqttCount":0,"Berry":{"HeapUsed":91,"Objects":1078},"POWER":"OFF","Wifi":{"AP":1,"SSId":"","BSSId":"","Channel":5,"Mode":"11n","RSSI":82,"Signal":-59,"LinkCount":2,"Downtime":"0T00:00:07"}}}

TO REPRODUCE

1. Setup matter with a Google Home device.
2. Wait a month (or so)
3. Observe the number of sessions

EXPECTED BEHAVIOUR

Older matter sessions should probably be cleaned up so that the device doesn't run out of memory.

[s-hadinger]

I will check this. It is unexpected, there is normally a limit of 5 persistent sessions per fabric. All non-persistent sessions are short-lived.

[s-hadinger]

Please use latest from development branch (after #19073) where saving of sessions is logged.

I tried to reproduce with my nest-mini and rebooting the hub, but the session number still maxes at 5 per fabric.

[thatguystone]

It looks like there are only 5 sessions per fabric being persisted (there are 5 in _matter_fabrics.json).

I extracted the relevant logging to a berry function and ran it directly so that the in-memory sessions are preserved for further debugging:

var fabs = []
var sessions_saved = 0

for f : matter_device.sessions.fabrics.persistables()
  for _ : f._sessions.persistables()    sessions_saved += 1   end   # count persitable sessions
  fabs.push(f.tojson())
end

print(fabs.size(), sessions_saved)

1 5

[thatguystone]

It looks like the list that's growing unbounded is Matter_Session_Store.sessions:

print(matter_device.sessions.sessions.size())
print(matter_device.sessions.fabrics[0]._sessions.size())

57
5

[s-hadinger]

Hmm. So it means that some sessions are marked as persisted but not associated to any fabric

[thatguystone]

Should sessions that are evicted from a fabric be marked as non-persistent? A quick search shows that set_persist(false) is never called.

[s-hadinger]

Yes you nailed it. The session is removed from the fabric but not from the session store. They are hence not removed from memory. Will fix now.

[s-hadinger]

Should be fixed now. Thanks for reporting.