Matter regression in 13.4

BluSyn commented 7 months ago

PROBLEM DESCRIPTION

Matter bridge becomes unresponsive. Stack trace shows in logs (see below). Device continues to work directly through web interface, but not through Matter controller.

REQUESTED INFORMATION

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

[x] Read the Contributing Guide and Policy and the Code of Conduct
[x] Searched the problem in issues
[x] Searched the problem in discussions
[x] Searched the problem in the docs
[x] Searched the problem in the chat
[x] Device used (e.g., Sonoff Basic): Sonoff M5-3C
[x] Tasmota binary firmware version number used: 13.4
- [x] Pre-compiled
- [ ] Self-compiled
[x] Flashing tools used: ESP-Flasher-macOS

[x] Provide the output of command: Backlog Template; Module; GPIO 255:


10:09:47.234 CMD: Backlog Template; Module; GPIO 255
10:09:47.237 SRC: WebConsole from 0.0.0.0
10:09:47.239 CMD: Grp 0, Cmd 'BACKLOG', Idx 1, Len 26, Pld -99, Data 'Template; Module; GPIO 255'
10:09:47.282 SRC: Backlog
10:09:47.284 CMD: Grp 0, Cmd 'TEMPLATE', Idx 1, Len 0, Pld -99, Data ''
10:09:47.289 RSL: RESULT = {"NAME":"Sonoff M5-3C","GPIO":[33,0,0,0,32,576,0,0,0,0,0,34,0,0,416,225,0,0,226,224,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0],"FLAG":0,"BASE":1}
10:09:47.493 SRC: Backlog
10:09:47.496 CMD: Grp 0, Cmd 'MODULE', Idx 1, Len 0, Pld -99, Data ''
10:09:47.499 RSL: RESULT = {"Module":{"0":"Sonoff M5-3C"}}
10:09:47.713 SRC: Backlog
10:09:47.715 CMD: Grp 0, Cmd 'GPIO', Idx 1, Len 3, Pld 255, Data '255'
10:09:47.725 RSL: RESULT = {"GPIO0":{"33":"Button2"},"GPIO1":{"0":"None"},"GPIO2":{"0":"None"},"GPIO3":{"0":"None"},"GPIO4":{"32":"Button1"},"GPIO5":{"576":"LedLink_i"},"GPIO6":{"0":"None"},"GPIO7":{"0":"None"},"GPIO8":{"0":"None"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO11":{"0":"None"},"GPIO12":{"0":"None"},"GPIO13":{"0":"None"},"GPIO14":{"0":"None"},"GPIO15":{"34":"Button3"},"GPIO16":{"0":"None"},"GPIO17":{"0":"None"},"GPIO18":{"416":"PWM1"},"GPIO19":{"225":"Relay2"},"GPIO20":{"0":"None"},"GPIO21":{"0":"None"},"GPIO22":{"226":"Relay3"},"GPIO23":{"224":"Relay1"},"GPIO24":{"0":"None"},"GPIO25":{"0":"None"},"GPIO26":{"0":"None"},"GPIO27":{"0":"None"},"GPIO32":{"0":"None"},"GPIO33":{"0":"None"},"GPIO34":{"0":"None"},"GPIO35":{"0":"None"},"GPIO36":{"0":"None"},"GPIO37":{"0":"None"},"GPIO38":{"0":"None"},"GPIO39":{"0":"None"}}

- [x] If using rules, provide the output of this command: `Backlog Rule1; Rule2; Rule3`:
```lua
(no rules)

[x] Provide the output of this command: Status 0:


10:10:32.096 CMD: Grp 0, Cmd 'STATUS', Idx 1, Len 1, Pld 0, Data '0'
10:10:32.099 RSL: STATUS = {"Status":{"Module":0,"DeviceName":"SW-11","FriendlyName":["SW-11-B1","SW-11-B2","SW-11-B3","SW-11-Backlight"],"Topic":"tasmota_11EEB4","ButtonTopic":"0","Power":8,"PowerOnState":3,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":1,"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}}
10:10:32.144 RSL: STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"https://ota.tasmota.com/tasmota32/release/tasmota32.bin","RestartReason":"Software reset CPU","Uptime":"0T00:04:19","StartupUTC":"2024-02-19T09:06:13","Sleep":50,"CfgHolder":4617,"BootCount":57,"BCResetTime":"2023-05-14T12:32:36","SaveCount":1716}}
10:10:32.186 RSL: STATUS2 = {"StatusFWR":{"Version":"13.3.0(tasmota32)","BuildDateTime":"2023-12-12T14:31:42","Core":"2_0_14","SDK":"4.4.6.231122","CpuFrequency":160,"Hardware":"ESP32-D0WD-V3 v3.0","CR":"432/699"}}
10:10:32.206 RSL: STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":3,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["TowerThings",""],"TelePeriod":300,"Resolution":"558180C0","SetOption":["0000A009","2805C80001000600003C5A0A192800000000","00000080","00006000","00004000","00000020"]}}
10:10:32.251 RSL: STATUS4 = {"StatusMEM":{"ProgramSize":1888,"Free":991,"Heap":88,"StackLowMark":2,"PsrMax":0,"PsrFree":0,"ProgramFlashSize":4096,"FlashSize":4096,"FlashChipId":"16405E","FlashFrequency":40,"FlashMode":"DIO","Features":["0809","9F9AD7DF","0015A001","B7F7BFCF","05DA9BC4","E0360DC7","480840D2","20200000","D4BC482D","810A80B1","00000000"],"Drivers":"1,2,3,4,5,7,8,9,10,11,12,14,16,17,20,21,24,26,27,29,34,35,38,50,52,59,60,62,63,66,67,68,82,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,109,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,82"}}
10:10:32.319 RSL: STATUS5 = {"StatusNET":{"Hostname":"tasmota-11EEB4-3764","IPAddress":"192.168.20.35","Gateway":"192.168.20.1","Subnetmask":"255.255.255.0","DNSServer1":"1.0.0.1","DNSServer2":"8.8.4.4","Mac":"C4:DE:E2:11:EE:B4","IP6Global":"<REMOVED>","IP6Local":"fe80::c6de:e2ff:fe11:eeb4%st1","Ethernet":{"Hostname":"","IPAddress":"0.0.0.0","Gateway":"0.0.0.0","Subnetmask":"0.0.0.0","DNSServer1":"1.0.0.1","DNSServer2":"8.8.4.4","Mac":"00:00:00:00:00:00","IP6Global":"","IP6Local":""},"Webserver":2,"HTTP_API":1,"WifiConfig":4,"WifiPower":17.0}}
10:10:32.376 RSL: STATUS6 = {"StatusMQT":{"MqttHost":"","MqttPort":1883,"MqttClientMask":"SW-11","MqttClient":"SW-11","MqttUser":"mqtt","MqttCount":0,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30,"SOCKET_TIMEOUT":4}}
10:10:32.395 RSL: STATUS7 = {"StatusTIM":{"UTC":"2024-02-19T09:10:32","Local":"2024-02-19T10:10:32","StartDST":"2024-03-31T02:00:00","EndDST":"2024-10-27T03:00:00","Timezone":"+01:00","Sunrise":"07:52","Sunset":"18:15"}}
10:10:32.418 RSL: STATUS10 = {"StatusSNS":{"Time":"2024-02-19T10:10:32"}}
10:10:32.433 RSL: STATUS11 = {"StatusSTS":{"Time":"2024-02-19T10:10:32","Uptime":"0T00:04:19","UptimeSec":259,"Heap":91,"SleepMode":"Dynamic","Sleep":10,"LoadAvg":99,"MqttCount":0,"Berry":{"HeapUsed":41,"Objects":529},"POWER1":"OFF","POWER2":"OFF","POWER3":"OFF","POWER4":"ON","Dimmer":10,"Fade":"OFF","Speed":1,"LedTable":"ON","Wifi":{"AP":1,"SSId":"TowerThings","BSSId":"62:22:32:35:C3:D5","Channel":1,"Mode":"11n","RSSI":74,"Signal":-63,"LinkCount":1,"Downtime":"0T00:00:04"}}}

- [x] Set `weblog` to 4 and then, when you experience your issue, provide the output of the Console log:
```lua
9:57:28.887 MTR: New Connection (CASE id=28552) from [192.168.1.23]:56945
09:57:28.923 MTR: >Received  (     0) CASE_Sigma3 rid=125498488 exch=54280 from [192.168.1.23]:56945
09:57:29.233 MTR: Sigma3 verified, computing new keys
09:57:29.244 MTR: <Replied   (     0) StatusReport
09:57:29.273 MTR: -Session   ( 36382) (removed)
09:57:29.276 MTR: -Session   ( 36382) (removed)
09:57:29.717 MTR: =Saved     2 fabric(s) and 6 session(s)
09:57:30.044 MTR: >Subscribe ( 28552) [**]****/**** (min=0, max=60, keep=1) sub=39096 fabric_filtered=false
09:57:30.046 MTR: >Subscribe (%6i) event_requests_size=1
09:57:30.053 MTR: >Read_Attr ( 28552) [**]****/****
09:57:30.561 BRY: top=3
09:57:30.563 stack traceback:
09:57:30.565    <native>: in native function
09:57:30.567    <unknown source>: in function `find_key_i`
09:57:30.569    <unknown source>: in function `match`
09:57:30.571    <unknown source>: in function `match`
09:57:30.583    <unknown source>: in function `try_rule`
09:57:30.585    <unknown source>: in function `exec_rules`
09:57:30.587    <unknown source>: in function `event`
09:57:30.598    <native>: in native function
09:57:30.600    <unknown source>: in function `cmd`
09:57:30.602    <unknown source>: in function `read_attribute`
09:57:30.603    ...
09:57:30.605    <unknown source>: in function `process_attribute_expansion`
09:57:30.617    <unknown source>: in function `_inner_process_read_request`
09:57:30.619    <unknown source>: in function `subscribe_request`
09:57:30.631    <unknown source>: in function `process_incoming`
09:57:30.633    <unknown source>: in function `msg_received`
09:57:30.635    <unknown source>: in function `msg_received`
09:57:30.647    <unknown source>: in function `<lambda>`
09:57:30.649    <unknown source>: in function `loop`
09:57:30.651    <unknown source>: in function `_anonymous_`
09:57:30.663    <unknown source>: in function `fast_loop`
09:57:30.665 BRY: stack[1] = type='instance' (Tasmota)
09:57:30.668 BRY: stack[2] = type='function' ()
09:57:30.669 BRY: stack[3] = type='instance' (Tasmota)

TO REPRODUCE

Enable Matter
Pair Matter with device (in my case, Homekit)
Device shows in Homekit
Device operates in Homekit as expected
After a few mins it shows as unresponsive in Homekit
Stack trace shows in logs
Upon rebooting device, this stack trace shows immediately on boot

EXPECTED BEHAVIOUR

Matter continues to work

ADDITIONAL CONTEXT

Potentially helpful notes:

No problems after downgrading to 13.3
Deleting Matter frabics and re-pairing does fix it, and then crashes again after few mins.

I walked through the stack trace in the code, but didn't see anything obvious. There were changes in this code path in latest 13.4 release.

(Please, remember to close the issue when the problem has been addressed)

s-hadinger commented 7 months ago

I will review next week

benjaminnestler commented 6 months ago

It seems this is not a general issue.

I've checked the behavior on an ESP32C3 device with a simple relay endpoint, as well as on a HomePod mini Matter Controller. My device is functioning correctly, and the Matter functions are working as expected.

By the way, @s-hadinger, perhaps you can fix the LOG line in Matter_IM.be (line 828):

tasmota.log(format("MTR: >Subscribe (%6i) event_requests_size=%i", msg.session.local_session_id, size(query.event_requests)), 3)

This should output the correct session ID.

@BluSyn what is your endpoint configuration?

BluSyn commented 6 months ago

Screenshot 2024-02-20 at 09 30 07

Not sure which config is relevant, so attached are screenshots of my full matter config, in case this is helpful.

Also I'm happy to load a custom binary with extra logging to help debug the issue.

s-hadinger commented 6 months ago

The exception above looks related to a berry rule for which lookup fails. Do you have berry rules configured?

benjaminnestler commented 6 months ago

That was also my assumption, that perhaps a filter for an endpoint is set, hence the inquiry about the endpoint configuration. But at least regarding the Matter endpoint config, it seems that no filter/rule is the cause of the stack trace.

@BluSyn, Do you have any other Berry scripts or Tasmota apps running?

benjaminnestler commented 6 months ago

I've configured my ESP32C3 device in the same way as @BluSyn. So far, no stack trace has occurred. Matter communication works in both directions - from the Home App to the device and vice versa.

s-hadinger commented 6 months ago

Can you check the value of tasmota._rules

The exception occurs when the controller reads all attributes. Some attributes are read via tasmota.cmd() that must fire a rule. So it's not necessarily linked to Matter but maybe some other code running. It's definitely a jug though

BluSyn commented 6 months ago

The mystery deepens.

I was able to reproduce this same issue on a second device, a Sonoff M5-2C (first device tested was -3C). So it's not a device-specific issue?
I have no custom Berry rules or apps configured. For both devices, I've only configured GPIO template, MQTT/WIFI settings, Matter, and SetOption13 1. Very simple setup.
Odd behavior note: After repeating the stack trace for a while, the device eventually becomes unresponsive to all network connections. I ended up power cycling, which restored network, but reset frabic keys (weird). I then downgraded to 13.3, re-connected matter, and has been working flawlessly since. This happened on both devices tested.

Running tasmota._rules from Berry Console (note the device is now on 13.3)

[<instance: <class: Trigger>([<Matcher key='Eth'>, <Matcher key='Connected'>], <function: 0x3ffd2984>, matter_start), <instance: <class: Trigger>([<Matcher key='Eth'>, <Matcher key='Connected'>], <function: 0x3ffe2360>, matter_mdns_host)]

Let me know what else I can check to help reproduce. I don't have any experience on the Berry scripting side, but can run something if needed.

s-hadinger commented 6 months ago

I have an idea. Maybe one of the element of the message is an int and not a string.

Please try again with the change I committed 2 minutes ago

BluSyn commented 6 months ago

@s-hadinger I compiled the latest development branch with tasmota32 profile.

Loading this still resulted in same behavior.

This log below shows 2 different stack traces back-to-back, which might provide helpful context.

(Note: 192.168.1.23 is my AppleTV acting as homekit hub)

02:04:01.506 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 0 ms
02:04:01.514 MTR: sending packet to '[192.168.1.23]:56945'
02:04:01.545 BRY: GC from 78487 to 72852 bytes, objects freed 87/1096 (in 4 ms) - slots from 1057/1078 to 807/985
02:04:01.585 BRY: GC from 83140 to 76364 bytes, objects freed 121/1193 (in 3 ms) - slots from 1219/1230 to 856/1075
02:04:01.604 MTR: >Subscribe (  1643) [**]****/**** (min=0, max=60, keep=1) sub=48046 fabric_filtered=false
02:04:01.606 MTR: >Subscribe (%6i) event_requests_size=1
02:04:01.612 MTR: >Read_Attr (  1643) [**]****/****
02:04:01.638 BRY: GC from 86621 to 82570 bytes, objects freed 55/1332 (in 4 ms) - slots from 1185/1197 to 1036/1166
02:04:01.683 BRY: GC from 92878 to 91582 bytes, objects freed 30/1538 (in 4 ms) - slots from 1394/1408 to 1333/1408
02:04:01.728 BRY: GC from 101838 to 100078 bytes, objects freed 37/1734 (in 4 ms) - slots from 1692/1696 to 1617/1696
02:04:01.776 BRY: GC from 110378 to 108938 bytes, objects freed 33/1937 (in 5 ms) - slots from 1976/1999 to 1911/1999
02:04:01.830 BRY: GC from 119196 to 117020 bytes, objects freed 45/2119 (in 6 ms) - slots from 2266/2272 to 2174/2272
02:04:01.833 BRY: Stack resized from 1144 to 1344 bytes
02:04:01.932 BRY: GC from 125189 to 117985 bytes, objects freed 114/2122 (in 6 ms) - slots from 2314/2317 to 2174/2302
02:04:02.032 BRY: GC from 125240 to 119117 bytes, objects freed 96/2119 (in 6 ms) - slots from 2331/2348 to 2169/2303
02:04:02.033 MTR: <Ack*      (  1643) ack=208999221 id=81373326 
02:04:02.039 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 1 ms
02:04:02.046 MTR: sending packet to '[192.168.1.23]:56945'
02:04:02.088 BRY: GC from 121622 to 119574 bytes, objects freed 22/2116 (in 6 ms) - slots from 2215/2303 to 2167/2303
02:04:02.090 BRY: top=3
02:04:02.092 stack traceback:
02:04:02.093    <native>: in native function
02:04:02.095    <unknown source>: in function `process_attribute_expansion`
02:04:02.097    <unknown source>: in function `_inner_process_read_request`
02:04:02.110    <unknown source>: in function `subscribe_request`
02:04:02.111    <unknown source>: in function `process_incoming`
02:04:02.114    <unknown source>: in function `msg_received`
02:04:02.125    <unknown source>: in function `msg_received`
02:04:02.128    <unknown source>: in function `<lambda>`
02:04:02.129    <unknown source>: in function `loop`
02:04:02.141    <unknown source>: in function `_anonymous_`
02:04:02.143    <unknown source>: in function `fast_loop`
02:04:02.145 BRY: stack[1] = type='instance' (Tasmota)
02:04:02.157 BRY: stack[2] = type='function' ()
02:04:02.159 BRY: stack[3] = type='instance' (Tasmota)
02:04:02.168 MTR: .          Resending packet id=141949237
02:04:02.171 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 1 ms
02:04:02.179 MTR: sending packet to '[192.168.1.23]:56945'
02:04:02.492 MTR: .          Resending packet id=141949237
02:04:02.495 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 0 ms
02:04:02.504 MTR: sending packet to '[192.168.1.23]:56945'
02:04:02.862 MTR: .          Resending packet id=141949237
02:04:02.865 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 1 ms
02:04:02.872 MTR: sending packet to '[192.168.1.23]:56945'
02:04:03.410 MTR: .          Resending packet id=141949237
02:04:03.414 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 0 ms
02:04:03.422 MTR: sending packet to '[192.168.1.23]:56945'
02:04:04.360 MTR: .          Resending packet id=141949237
02:04:04.364 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 1 ms
02:04:04.371 MTR: sending packet to '[192.168.1.23]:56945'
02:04:05.748 BRY: GC from 123417 to 44475 bytes, objects freed 1678/519 (in 14 ms) - slots from 2294/2333 to 391/684
02:04:05.761 MTR: UDP received from [192.168.1.23]:56945
02:04:05.771 MTR: .          Removed packet from sending list id=141949237
02:04:05.774 MTR: >rcv Ack   (  1643) rid=125499095 exch=0 ack=55728 141949237from [192.168.1.23]:56945
02:04:05.780 MTR: UDP received from [192.168.1.23]:56945
02:04:05.786 MTR: decode header: local_session_id=1643 message_counter=208999221
02:04:05.791 MTR: .          Duplicate encrypted message = 208999221 counter=208999221
02:04:05.795 MTR: UDP received from [192.168.1.23]:56945
02:04:05.803 MTR: decode header: local_session_id=1643 message_counter=208999221
02:04:05.807 MTR: .          Duplicate encrypted message = 208999221 counter=208999221
02:04:05.812 MTR: UDP received from [192.168.1.23]:56945
02:04:05.823 MTR: >rcv Ack   (  1643) rid=125499096 exch=0 ack=55728 141949237from [192.168.1.23]:56945
02:04:05.833 MTR: UDP received from [192.168.1.23]:56945
02:04:05.844 MTR: >rcv Ack   (  1643) rid=125499097 exch=0 ack=55728 141949237from [192.168.1.23]:56945
02:04:05.850 MTR: UDP received from [192.168.1.23]:56945
02:04:05.861 MTR: >rcv Ack   (  1643) rid=125499098 exch=0 ack=55728 141949237from [192.168.1.23]:56945
02:04:05.867 MTR: UDP received from [192.168.1.23]:56945
02:04:05.877 MTR: >rcv Ack   (  1643) rid=125499099 exch=0 ack=55728 141949237from [192.168.1.23]:56945
02:04:05.883 MTR: UDP received from [192.168.1.23]:56945
02:04:05.898 BRY: GC from 54755 to 44113 bytes, objects freed 66/520 (in 5 ms) - slots from 424/684 to 392/684
02:04:05.902 MTR: >rcv Ack   (  1643) rid=125499100 exch=0 ack=55728 141949237from [192.168.1.23]:56945
02:04:08.446 WIF: Checking connection...
02:04:15.756 BRY: GC from 54399 to 43756 bytes, objects freed 224/517 (in 4 ms) - slots from 708/759 to 392/668
02:04:42.896 BRY: GC from 67731 to 65950 bytes, objects freed 8/680 (in 2 ms) - slots from 499/713 to 489/713
02:04:42.902 BRY: GC from 77796 to 69269 bytes, objects freed 4/680 (in 1 ms) - slots from 489/713 to 489/713
02:04:42.937 BRY: GC from 79634 to 54475 bytes, objects freed 60/643 (in 3 ms) - slots from 618/713 to 470/698
02:04:42.975 BRY: GC from 64762 to 56219 bytes, objects freed 43/675 (in 3 ms) - slots from 631/698 to 494/698
02:04:43.081 MTR: =Saved     2 fabric(s) and 6 session(s)
02:04:43.095 BRY: GC from 66507 to 44476 bytes, objects freed 115/521 (in 5 ms) - slots from 501/698 to 393/623
02:04:43.098 MTR: UDP received from [192.168.1.23]:56945
02:04:43.106 MTR: .          Duplicate unencrypted message = 125499103 ref = 125499103
02:04:43.110 MTR: .          Resending packet id=266944253
02:04:43.113 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 0 ms
02:04:43.119 MTR: sending packet to '[192.168.1.23]:56945'
02:04:43.133 MTR: UDP received from [192.168.1.23]:56945
02:04:43.139 MTR: decode header: local_session_id=35260 message_counter=32333312
02:04:43.152 MTR: >          Decrypted message: protocol_id:1 opcode=3 exchange_id=55732
02:04:43.208 BRY: GC from 54733 to 51776 bytes, objects freed 34/647 (in 3 ms) - slots from 539/623 to 490/623
02:04:43.286 BRY: GC from 62096 to 61088 bytes, objects freed 28/815 (in 2 ms) - slots from 658/713 to 616/713
02:04:43.364 BRY: GC from 71408 to 70400 bytes, objects freed 28/983 (in 3 ms) - slots from 784/803 to 742/803
02:04:43.404 MTR: <Ack*      ( 35260) ack=32333312 id=69953607 
02:04:43.409 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 1 ms
02:04:43.419 MTR: sending packet to '[192.168.1.23]:56945'
02:04:43.447 BRY: GC from 80682 to 75748 bytes, objects freed 76/1093 (in 5 ms) - slots from 1028/1047 to 817/1016
02:04:43.487 BRY: GC from 86028 to 79252 bytes, objects freed 121/1191 (in 3 ms) - slots from 1230/1261 to 867/1106
02:04:43.508 MTR: >Subscribe ( 35260) [**]****/**** (min=0, max=60, keep=1) sub=57528 fabric_filtered=false
02:04:43.511 MTR: >Subscribe (%6i) event_requests_size=1
02:04:43.517 MTR: >Read_Attr ( 35260) [**]****/****
02:04:43.538 BRY: GC from 89505 to 84814 bytes, objects freed 65/1317 (in 5 ms) - slots from 1199/1213 to 1014/1151
02:04:43.585 BRY: GC from 95066 to 93842 bytes, objects freed 29/1524 (in 4 ms) - slots from 1373/1393 to 1316/1393
02:04:43.631 BRY: GC from 104118 to 102502 bytes, objects freed 35/1723 (in 5 ms) - slots from 1675/1681 to 1604/1681
02:04:43.680 BRY: GC from 112790 to 111062 bytes, objects freed 38/1919 (in 5 ms) - slots from 1963/1984 to 1887/1984
02:04:43.729 BRY: GC from 121390 to 119694 bytes, objects freed 37/2118 (in 5 ms) - slots from 2245/2272 to 2169/2272
02:04:43.787 BRY: GC from 124102 to 121844 bytes, objects freed 42/2145 (in 6 ms) - slots from 2262/2272 to 2187/2272
02:04:43.808 BRY: GC from 123328 to 120910 bytes, objects freed 35/2135 (in 6 ms) - slots from 2226/2272 to 2193/2272
02:04:43.840 BRY: GC from 123348 to 121593 bytes, objects freed 30/2139 (in 5 ms) - slots from 2228/2272 to 2187/2272
02:04:43.879 BRY: GC from 123053 to 121037 bytes, objects freed 31/2131 (in 5 ms) - slots from 2224/2272 to 2188/2272
02:04:43.913 BRY: GC from 123628 to 121291 bytes, objects freed 33/2131 (in 5 ms) - slots from 2259/2272 to 2189/2272
02:04:43.942 BRY: GC from 122435 to 122307 bytes, objects freed 3/2141 (in 5 ms) - slots from 2193/2272 to 2187/2272
02:04:43.944 BRY: top=3
02:04:43.945 stack traceback:
02:04:43.947    <native>: in native function
02:04:43.949    <unknown source>: in function `tlv2raw`
02:04:43.951    <unknown source>: in function `attributedata2raw`
02:04:43.963    <unknown source>: in function `read_single_attribute`
02:04:43.965    <unknown source>: in function `<lambda>`
02:04:44.002    <unknown source>: in function `process_attribute_expansion`
02:04:44.004    <unknown source>: in function `_inner_process_read_request`
02:04:44.005    <unknown source>: in function `subscribe_request`
02:04:44.007    <unknown source>: in function `process_incoming`
02:04:44.009    <unknown source>: in function `msg_received`
02:04:44.011    <unknown source>: in function `msg_received`
02:04:44.013    <unknown source>: in function `<lambda>`
02:04:44.025    <unknown source>: in function `loop`
02:04:44.027    <unknown source>: in function `_anonymous_`
02:04:44.029    <unknown source>: in function `fast_loop`
02:04:44.031 BRY: stack[1] = type='instance' (Tasmota)
02:04:44.042 BRY: stack[2] = type='function' ()
02:04:44.044 BRY: stack[3] = type='instance' (Tasmota)
02:04:44.093 BRY: GC from 122552 to 47168 bytes, objects freed 1602/542 (in 13 ms) - slots from 2195/2272 to 407/790
02:04:44.096 MTR: .          Resending packet id=266944253
02:04:44.099 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 0 ms
02:04:44.107 MTR: sending packet to '[192.168.1.23]:56945'
02:04:44.125 MTR: UDP received from [192.168.1.23]:56945
02:04:44.135 MTR: .          Removed packet from sending list id=266944253
02:04:44.139 MTR: >rcv Ack   ( 35260) rid=125499104 exch=0 ack=55731 266944253from [192.168.1.23]:56945
02:04:44.145 MTR: UDP received from [192.168.1.23]:56945
02:04:44.150 MTR: decode header: local_session_id=35260 message_counter=32333312
02:04:44.154 MTR: .          Duplicate encrypted message = 32333312 counter=32333312
02:04:44.160 MTR: UDP received from [192.168.1.23]:56945
02:04:44.171 MTR: >rcv Ack   ( 35260) rid=125499105 exch=0 ack=55731 266944253from [192.168.1.23]:56945
02:04:44.177 MTR: UDP received from [192.168.1.23]:56945
02:04:44.183 MTR: decode header: local_session_id=35260 message_counter=32333312
02:04:44.186 MTR: .          Duplicate encrypted message = 32333312 counter=32333312
02:04:44.197 MTR: UDP received from [192.168.1.23]:56945
02:04:44.209 MTR: >rcv Ack   ( 35260) rid=125499106 exch=0 ack=55731 266944253from [192.168.1.23]:56945
02:04:47.906 BRY: GC from 57465 to 45379 bytes, objects freed 141/526 (in 4 ms) - slots from 553/790 to 407/699
02:04:50.566 WIF: Checking connection...

benjaminnestler commented 6 months ago

I have an idea. Maybe one of the element of the message is an int and not a string.

Please try again with the change I committed 2 minutes ago

What do you mean with this? Do you mean one of the attributes the hub wants to read?

benjaminnestler commented 6 months ago

@BluSyn could you simplify your endpoint configuration? Maybe it's a little bit easier to debug/ analyse what happens if you clear all your endpoints, so Tasmota only creates the bridge endpoint and attributes? Is the behaviour still the same as with all of your four endpoints?

How do you execute the commissioning of your devices? In my experience the HomeKit device acting as hub don't deletes the Tasmota matter bridge if you clear your matter fabrics. It's an active doing I manually process every time in the apple Home App to start with a "fresh system setup".

Don't know if these hints could be useful.

s-hadinger commented 6 months ago

Ok. This is not the same error. Let me push a new change to have more logs.

s-hadinger commented 6 months ago

Please try again with new version. The bug is still there but I will know which attribute causes the error

s-hadinger commented 6 months ago

You don't need to simplify the endpoint configuration, the bug is probably related to the root node which is common to all configurations

s-hadinger commented 6 months ago

Argh. Looking more closely, it is most certainly a problem of "out of memory". The gc shows already 80kb of memory used before the request is triggered. I have plans to lower the memory consumption of those requests but it will take time.

BluSyn commented 6 months ago

Argh. Looking more closely, it is most certainly a problem of "out of memory". The gc shows already 80kb of memory used before the request is triggered. I have plans to lower the memory consumption of those requests but it will take time.

I had a feeling the GC log entries seemed unusual, and the stack traces are not consistent. This could also explain the issue of it disconnecting from network after a time. I left one device in this state overnight, and it appeared to reboot itself multiple times.

I can run again with new log commits in a few hours.

BluSyn commented 6 months ago

I tested with latest log commits. I don't see any obvious difference in logs, but sharing it anyway:

14:23:56.978 BRY: GC from 58272 to 49240 bytes, objects freed 80/569 (in 5 ms) - slots from 498/730 to 430/730
14:23:57.269 MTR: Sigma3 verified, computing new keys
14:23:57.280 MTR: <Replied   (     0) StatusReport
14:23:57.289 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 1 ms
14:23:57.298 MTR: sending packet to '[192.168.1.23]:56945'
14:23:57.308 BRY: GC from 59676 to 54964 bytes, objects freed 58/689 (in 4 ms) - slots from 587/730 to 522/730
14:23:57.322 MTR: -Session   (  1643) (removed)
14:23:57.325 MTR: -Session   (  1643) (removed)
14:23:57.399 BRY: GC from 65525 to 54582 bytes, objects freed 58/654 (in 4 ms) - slots from 684/775 to 486/775
14:23:57.457 BRY: GC from 64827 to 55269 bytes, objects freed 58/681 (in 3 ms) - slots from 670/775 to 515/775
14:23:57.498 BRY: GC from 65525 to 55681 bytes, objects freed 59/671 (in 3 ms) - slots from 662/775 to 503/775
14:23:57.558 BRY: GC from 65960 to 56895 bytes, objects freed 66/690 (in 3 ms) - slots from 677/775 to 515/775
14:23:57.567 BRY: GC from 67591 to 65686 bytes, objects freed 8/690 (in 2 ms) - slots from 517/775 to 505/775
14:23:57.571 BRY: GC from 77512 to 69005 bytes, objects freed 4/690 (in 2 ms) - slots from 505/775 to 505/775
14:23:57.606 BRY: GC from 79365 to 54235 bytes, objects freed 60/653 (in 3 ms) - slots from 634/775 to 486/745
14:23:57.642 BRY: GC from 64522 to 55979 bytes, objects freed 43/685 (in 3 ms) - slots from 647/760 to 510/745
14:23:57.792 MTR: =Saved     2 fabric(s) and 6 session(s)
14:23:57.806 BRY: GC from 66403 to 44461 bytes, objects freed 115/529 (in 5 ms) - slots from 515/745 to 408/715
14:23:57.808 MTR: UDP received from [192.168.1.23]:56945
14:23:57.814 MTR: decode header: local_session_id=38269 message_counter=140973423
14:23:57.826 MTR: >          Decrypted message: protocol_id:1 opcode=3 exchange_id=55899
14:23:57.890 BRY: GC from 54702 to 52724 bytes, objects freed 32/679 (in 3 ms) - slots from 572/715 to 523/715
14:23:57.968 BRY: GC from 62972 to 61964 bytes, objects freed 28/845 (in 2 ms) - slots from 689/790 to 647/790
14:23:58.043 BRY: GC from 72284 to 71276 bytes, objects freed 28/1013 (in 3 ms) - slots from 815/895 to 773/895
14:23:58.092 MTR: <Ack*      ( 38269) ack=140973423 id=192680100 
14:23:58.098 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 1 ms
14:23:58.105 MTR: sending packet to '[192.168.1.23]:56945'
14:23:58.127 BRY: GC from 81550 to 77152 bytes, objects freed 67/1129 (in 4 ms) - slots from 1037/1062 to 856/1031
14:23:58.170 BRY: GC from 87416 to 80640 bytes, objects freed 121/1225 (in 4 ms) - slots from 1266/1276 to 903/1121
14:23:58.199 MTR: >Subscribe ( 38269) [**]****/**** (min=0, max=60, keep=1) sub=19918 fabric_filtered=false
14:23:58.203 MTR: >Subscribe (%6i) event_requests_size=1
14:23:58.209 MTR: >Read_Attr ( 38269) [**]****/****
14:23:58.223 BRY: GC from 90889 to 84998 bytes, objects freed 85/1330 (in 5 ms) - slots from 1246/1259 to 995/1197
14:23:58.269 BRY: GC from 95282 to 93930 bytes, objects freed 32/1535 (in 4 ms) - slots from 1355/1378 to 1292/1378
14:23:58.316 BRY: GC from 104218 to 102730 bytes, objects freed 32/1737 (in 4 ms) - slots from 1650/1681 to 1585/1681
14:23:58.364 BRY: GC from 113018 to 111290 bytes, objects freed 38/1933 (in 5 ms) - slots from 1945/1969 to 1869/1969
14:23:58.411 BRY: GC from 121058 to 119690 bytes, objects freed 31/2127 (in 4 ms) - slots from 2210/2211 to 2148/2211
14:23:58.425 BRY: GC from 121070 to 120942 bytes, objects freed 3/2156 (in 4 ms) - slots from 2195/2211 to 2189/2211
14:23:58.433 BRY: GC from 121074 to 121018 bytes, objects freed 1/2158 (in 4 ms) - slots from 2193/2211 to 2190/2211
14:23:58.441 BRY: GC from 121050 to 121050 bytes, objects freed 0/2158 (in 4 ms) - slots from 2191/2211 to 2191/2211
14:23:58.443 BRY: top=3
14:23:58.444 stack traceback:
14:23:58.446    <native>: in native function
14:23:58.448    <unknown source>: in function `process_attribute_expansion`
14:23:58.450    <unknown source>: in function `_inner_process_read_request`
14:23:58.462    <unknown source>: in function `subscribe_request`
14:23:58.465    <unknown source>: in function `process_incoming`
14:23:58.467    <unknown source>: in function `msg_received`
14:23:58.478    <unknown source>: in function `msg_received`
14:23:58.480    <unknown source>: in function `<lambda>`
14:23:58.482    <unknown source>: in function `loop`
14:23:58.495    <unknown source>: in function `_anonymous_`
14:23:58.497    <unknown source>: in function `fast_loop`
14:23:58.498 BRY: stack[1] = type='instance' (Tasmota)
14:23:58.510 BRY: stack[2] = type='function' ()
14:23:58.512 BRY: stack[3] = type='instance' (Tasmota)
14:23:58.544 BRY: GC from 121050 to 44760 bytes, objects freed 1623/534 (in 13 ms) - slots from 2191/2211 to 412/807
14:23:58.621 MTR: UDP received from [192.168.1.23]:56945
14:23:58.631 MTR: .          Removed packet from sending list id=78995485
14:23:58.635 MTR: >rcv Ack   ( 38269) rid=125499128 exch=0 ack=55898 78995485from [192.168.1.23]:56945
14:23:58.640 MTR: UDP received from [192.168.1.23]:56945
14:23:58.645 MTR: decode header: local_session_id=38269 message_counter=140973423
14:23:58.649 MTR: .          Duplicate encrypted message = 140973423 counter=140973423
14:23:58.654 MTR: UDP received from [192.168.1.23]:56945
14:23:58.660 MTR: decode header: local_session_id=38269 message_counter=140973423
14:23:58.664 MTR: .          Duplicate encrypted message = 140973423 counter=140973423

Regarding GC, here is what logs show when running 13.3 (no crash):

14:34:58.938 WIF: Checking connection...
14:35:08.941 BRY: GC from 52693 to 42350 bytes, objects freed 242/525 (in 4 ms) - slots from 751/758 to 396/622
14:35:08.944 MTR: <Sub_Alive ( 23871) sub=20476
14:35:08.969 WIF: DNS resolved '192.168.1.23' (192.168.1.23) in 1 ms
14:35:08.977 MTR: sending packet to '[192.168.1.23]:56945'
14:35:08.981 MTR: remove IM message exch=108159
14:35:08.998 MTR: UDP received from [192.168.1.23]:56945
14:35:09.004 MTR: decode header: local_session_id=23871 message_counter=30036098
14:35:09.014 MTR: >          Decrypted message: protocol_id:0 opcode=16 exchange_id=42623
14:35:09.017 MTR: .          Removed packet from sending list id=55498401
14:35:15.240 BRY: GC from 52602 to 42474 bytes, objects freed 159/529 (in 4 ms) - slots from 624/637 to 401/607
14:35:18.927 WIF: Checking connection...
14:35:27.943 BRY: GC from 52761 to 42356 bytes, objects freed 243/525 (in 4 ms) - slots from 746/758 to 396/653
14:35:38.934 WIF: Checking connection...
14:35:40.695 BRY: GC from 52626 to 42356 bytes, objects freed 242/525 (in 4 ms) - slots from 747/758 to 396/622
14:35:52.944 BRY: GC from 52656 to 42356 bytes, objects freed 240/525 (in 4 ms) - slots from 741/758 to 396/653

Based on GC logs, it does appear memory consumption (at least for Matter operations) doubled between 13.3 -> 13.4.

s-hadinger commented 6 months ago

Thanks but you are not comparing the same requests so it's hard to jump to conclusions. I will need to troubleshoot but not before next week

s-hadinger commented 6 months ago

Please use the latest version with this fix: https://github.com/arendst/Tasmota/pull/20804

It will reduce dramatically the memory usage when subscriptions are triggered, and should solve the bug

BluSyn commented 6 months ago

@s-hadinger Confirmed, latest development branch solves the issue.

Thanks! Closing this issue.

arendst / Tasmota