Tasmota icon indicating copy to clipboard operation
Tasmota copied to clipboard
verified publisher icon arendst

MessageHandler::msg_received exception: type_error;unsupported operand type(s) for >: 'nil' and 'int'

Open lboue opened this issue 1 year ago • 2 comments

PROBLEM DESCRIPTION

Matter cluster discovery from Home Assistant doesn't work in my case. There is an exception in the Tasmota device logs. MessageHandler::msg_received exception: type_error;unsupported operand type(s) for >: 'nil' and 'int

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): _____
  • [x] Tasmota binary firmware version number used: 14.1.0.4 (d3f6d7d-tasmota32) / Build Date & Time 2024-08-10T15:20:43
    • [x] Pre-compiled
    • [ ] Self-compiled
  • [x] Flashing tools used: https://tasmota.github.io/install
  • [x] Provide the output of command: Backlog Template; Module; GPIO 255:
13:47:33.286 CMD: Grp 0, Cmd 'BACKLOG', Idx 1, Len 26, Pld -99, Data 'Template; Module; GPIO 255'
13:47:33.297 SRC: Backlog
13:47:33.298 CMD: Grp 0, Cmd 'TEMPLATE', Idx 1, Len 0, Pld -99, Data ''
13:47:33.302 MQT: stat/tasmota_482438/RESULT = {"NAME":"ESP32C6","GPIO":[1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,0,0,0,0,0,0,0],"FLAG":0,"BASE":1}
13:47:33.532 SRC: Backlog
13:47:33.533 CMD: Grp 0, Cmd 'MODULE', Idx 1, Len 0, Pld -99, Data ''
13:47:33.536 MQT: stat/tasmota_482438/RESULT = {"Module":{"1":"ESP32C6"}}
13:47:33.787 SRC: Backlog
13:47:33.788 CMD: Grp 0, Cmd 'GPIO', Idx 1, Len 3, Pld 255, Data '255'
13:47:33.794 MQT: stat/tasmota_482438/RESULT = {"GPIO0":{"0":"None"},"GPIO1":{"0":"None"},"GPIO2":{"0":"None"},"GPIO3":{"0":"None"},"GPIO4":{"0":"None"},"GPIO5":{"0":"None"},"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":{"0":"None"},"GPIO16":{"0":"None"},"GPIO17":{"0":"None"},"GPIO18":{"0":"None"},"GPIO19":{"0":"None"},"GPIO20":{"0":"None"},"GPIO21":{"0":"None"},"GPIO22":{"0":"None"},"GPIO23":{"0":"None"},"GPIO26":{"0":"None"},"GPIO28":{"0":"None"}}
13:47:33.851 BRY: GC from 32638 to 23157 bytes, objects freed 236/257 (in 2 ms) - slots from 620/653 to 228/532
  • [ ] If using rules, provide the output of this command: Backlog Rule1; Rule2; Rule3:
  Rules output here:
  • [x] Provide the output of this command: Status 0:
13:46:33.067 CMD: Grp 0, Cmd 'STATUS', Idx 1, Len 1, Pld 0, Data '0'
13:46:33.070 MQT: stat/tasmota_482438/STATUS = {"Status":{"Module":1,"DeviceName":"Sparkfun C6","FriendlyName":["Tasmota"],"Topic":"tasmota_482438","ButtonTopic":"0","Power":"0","PowerLock":"0","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}}
13:46:33.106 BRY: GC from 32836 to 23337 bytes, objects freed 242/268 (in 2 ms) - slots from 640/668 to 239/547
13:46:33.111 MQT: stat/tasmota_482438/STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"http://ota.tasmota.com/tasmota32/release/tasmota32c6.bin","RestartReason":"Software reset CPU","Uptime":"0T00:07:34","StartupUTC":"2024-08-11T12:38:59","Sleep":50,"CfgHolder":4617,"BootCount":14,"BCResetTime":"2024-08-02T10:44:32","SaveCount":25}}
13:46:33.149 MQT: stat/tasmota_482438/STATUS2 = {"StatusFWR":{"Version":"14.1.0.4(010ca34-tasmota32)","BuildDateTime":"2024-08-01T20:43:47","Core":"3_0_2","SDK":"5.1.4.240708","CpuFrequency":160,"Hardware":"ESP32-C6FH4 v0.0","CR":"403/699"}}
13:46:33.165 MQT: stat/tasmota_482438/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":4,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["SSID*****",""],"TelePeriod":300,"Resolution":"558180C0","SetOption":["00008009","2805C80001000600003C5A0A192800000000","00000080","00006000","00004000","00000020"]}}
13:46:33.209 MQT: stat/tasmota_482438/STATUS4 = {"StatusMEM":{"ProgramSize":2012,"Free":867,"Heap":257,"StackLowMark":2,"PsrMax":0,"PsrFree":0,"ProgramFlashSize":4096,"FlashSize":4096,"FlashChipId":"164020","FlashFrequency":80,"FlashMode":"QIO","Features":["0809","9F9AD7DF","0015A001","B7F7BFCF","05DA9BC4","E0360DC7","480840D2","20200000","D4BC482D","810A80B1","00000014"],"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,!73,82,!86,!87,!88,!121","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"}}
13:46:33.281 MQT: stat/tasmota_482438/STATUS5 = {"StatusNET":{"Hostname":"tasmota-482438-7752","IPAddress":"192.168.1.105","Gateway":"192.168.1.254","Subnetmask":"255.255.255.0","DNSServer1":"192.168.1.254","DNSServer2":"9.9.9.9","Mac":"40:4C:CA:48:24:38","IP6Global":"2a01:e0a:2b3:3990:424c:caff:fe48:2438","IP6Local":"fe80::424c:caff:fe48:2438%st1","Ethernet":{"Hostname":"","IPAddress":"0.0.0.0","Gateway":"0.0.0.0","Subnetmask":"0.0.0.0","DNSServer1":"192.168.1.254","DNSServer2":"9.9.9.9","Mac":"00:00:00:00:00:00","IP6Global":"","IP6Local":""},"Webserver":2,"HTTP_API":1,"WifiConfig":4,"WifiPower":16.0}}
13:46:33.341 MQT: stat/tasmota_482438/STATUS6 = {"StatusMQT":{"MqttHost":"homeassistant.local","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_482438","MqttUser":"lboue","MqttCount":1,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30,"SOCKET_TIMEOUT":4}}
13:46:33.367 MQT: stat/tasmota_482438/STATUS7 = {"StatusTIM":{"UTC":"2024-08-11T12:46:33Z","Local":"2024-08-11T13:46:33","StartDST":"2024-03-31T02:00:00","EndDST":"2024-10-27T03:00:00","Timezone":"+01:00","Sunrise":"05:38","Sunset":"20:12"}}
13:46:33.381 BRY: GC from 33589 to 23030 bytes, objects freed 92/265 (in 2 ms) - slots from 494/577 to 235/455
13:46:33.386 MQT: stat/tasmota_482438/STATUS10 = {"StatusSNS":{"Time":"2024-08-11T13:46:33"}}
13:46:33.391 BRY: GC from 24129 to 22328 bytes, objects freed 21/250 (in 1 ms) - slots from 279/455 to 218/455
13:46:33.393 MQT: stat/tasmota_482438/STATUS11 = {"StatusSTS":{"Time":"2024-08-11T13:46:33","Uptime":"0T00:07:34","UptimeSec":454,"Heap":258,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"Berry":{"HeapUsed":21,"Objects":250},"Wifi":{"AP":1,"SSId":"SSID*****","BSSId":"C0:8A:DE:22:C5:B8","Channel":4,"Mode":"HT20","RSSI":100,"Signal":-40,"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:
13:39:24.266 MTR: UDP received from [fe80::6a3a:58f8:9512:d44a%st1]:55930
13:39:24.268 MTR: decode header: local_session_id=64451 message_counter=36751386
13:39:24.271 MTR: >          Decrypted message: protocol_id:1 opcode=1 exchange_id=3691
13:39:24.273 MTR: .          Removed packet from sending list id=124563287
13:39:24.280 BRY: GC from 36676 to 26813 bytes, objects freed 72/283 (in 2 ms) - slots from 319/440 to 222/440
13:39:24.284 MTR: <Ack*      ( 64451) ack=36751386 id=124563290 
13:39:24.287 MTR: sending packet to '[fe80::6a3a:58f8:9512:d44a%st1]:55930'
13:39:24.369 BRY: GC from 37103 to 27027 bytes, objects freed 140/281 (in 3 ms) - slots from 409/440 to 221/425
13:39:24.465 BRY: GC from 37326 to 26256 bytes, objects freed 160/268 (in 3 ms) - slots from 378/440 to 219/440
13:39:24.543 BRY: GC from 37186 to 27009 bytes, objects freed 137/257 (in 3 ms) - slots from 376/440 to 214/425
13:39:24.547 MTR: sending packet to '[fe80::6a3a:58f8:9512:d44a%st1]:55930'
13:39:24.674 MTR: UDP received from [fe80::6a3a:58f8:9512:d44a%st1]:55930
13:39:24.676 MTR: decode header: local_session_id=64451 message_counter=36751387
13:39:24.680 MTR: >          Decrypted message: protocol_id:1 opcode=1 exchange_id=3691
13:39:24.681 MTR: .          Removed packet from sending list id=124563289
13:39:24.687 MTR: <Ack*      ( 64451) ack=36751387 id=124563292 
13:39:24.690 MTR: sending packet to '[fe80::6a3a:58f8:9512:d44a%st1]:55930'
13:39:24.763 BRY: GC from 37257 to 25352 bytes, objects freed 96/275 (in 2 ms) - slots from 364/425 to 233/425
13:39:24.862 BRY: GC from 35604 to 25609 bytes, objects freed 137/264 (in 3 ms) - slots from 376/425 to 223/425
13:39:24.953 BRY: GC from 36454 to 27031 bytes, objects freed 121/257 (in 2 ms) - slots from 350/425 to 214/425
13:39:24.957 MTR: sending packet to '[fe80::6a3a:58f8:9512:d44a%st1]:55930'
13:39:25.187 MTR: UDP received from [fe80::6a3a:58f8:9512:d44a%st1]:55930
13:39:25.189 MTR: decode header: local_session_id=64451 message_counter=36751388
13:39:25.193 MTR: >          Decrypted message: protocol_id:1 opcode=1 exchange_id=3691
13:39:25.195 MTR: .          Removed packet from sending list id=124563291
13:39:25.202 MTR: <Ack*      ( 64451) ack=36751388 id=124563294 
13:39:25.205 MTR: sending packet to '[fe80::6a3a:58f8:9512:d44a%st1]:55930'
13:39:25.263 BRY: GC from 37308 to 25700 bytes, objects freed 110/272 (in 2 ms) - slots from 352/425 to 223/425
13:39:25.364 BRY: GC from 35993 to 25547 bytes, objects freed 140/265 (in 3 ms) - slots from 412/455 to 224/455
13:39:25.451 MTR: MessageHandler::msg_received exception: type_error;unsupported operand type(s) for >: 'nil' and 'int'
13:39:44.321 WIF: Checking connection...
13:40:04.332 WIF: Checking connection...
13:40:15.269 HTP: Tools
13:40:17.627 HTP: Main Menu
13:40:18.988 HTP: Configuration
13:40:20.343 HTP: Configure Logging
13:40:24.298 WIF: Checking connection...
13:40:24.503 HTP: Configuration
13:40:44.312 WIF: Checking connection...

TO REPRODUCE

  1. Commissioning the Matter device with iOS Fabric
  2. Go to Matter section
  3. Add a Matter 'Rain' sensor
  4. Add a Shutter
  5. Add a Shutter
  6. Click "Save" button

EXPECTED BEHAVIOUR

Discovery works and there are no exceptions in the logs.

SCREENSHOTS

image

ADDITIONAL CONTEXT

Home Assistant matter_server log file

2024-08-11 17:28:28.312 (Dummy-2) CHIP_PROGRESS [chip.native.EM] <<< [E:4279i S:29968 M:165299129 (Ack:223193715)] (S) Msg TX to 1:0000000000000018 [D3B7] [UDP:[fda9:150:8b20:0:b7a5:b9d1:a80c:906a]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
2024-08-11 17:28:28.313 (Dummy-2) CHIP_DETAIL [chip.native.EM] Flushed pending ack for MessageCounter:223193715 on exchange 4279i with Node: <0000000000000018, 1>
2024-08-11 17:28:29.545 (Dummy-2) CHIP_ERROR [chip.native.DMG] Time out! failed to receive report data from Exchange: 4277i with Node: <000000000000002F, 1>
2024-08-11 17:28:29.546 (MainThread) ERROR [matter_server.server.client_handler] [139808106143376] Error while handling: interview_node (node 47): Failed to interview node 47
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/device_controller.py", line 566, in interview_node
    await self._chip_device_controller.read_attribute(
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/sdk.py", line 273, in read_attribute
    result = await self._chip_controller.Read(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/chip/ChipDeviceCtrl.py", line 1315, in Read
    return await future
           ^^^^^^^^^^^^
chip.exceptions.ChipStackError: src/app/ReadClient.cpp:682: CHIP Error 0x00000032: Timeout

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/client_handler.py", line 197, in _run_handler
    result = await result
             ^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/matter_server/server/device_controller.py", line 573, in interview_node
    raise NodeInterviewFailed(f"Failed to interview node {node_id}") from err
matter_server.common.errors.NodeInterviewFailed: Failed to interview node 47

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

lboue avatar Aug 11 '24 12:08 lboue

I'm off for two weeks. I will check when I return

s-hadinger avatar Aug 11 '24 17:08 s-hadinger

Thank you for your time. Have a nice vacation.

lboue avatar Aug 11 '24 17:08 lboue

Here are the console traces with debug mode enabled for 2 examples :

Tested with last dev version (today)

Program Version	14.2.0.3 (11ed655-tasmota32)
Build Date & Time	2024-08-29T15:01:36
Core/SDK Version	3_0_4/5.1.4.240822

lboue avatar Aug 29 '24 16:08 lboue