Closed nohn closed 2 years ago
I've added a frame dump when an error occurs. Could you update to the latest version and observe the logs and report back with the frame please?
Sure, I'll do. Will you push it to PyPI?
Hm - I'll check the mqtt issue first. Maybe I can include the reconnect in the new version, too. Would it be possible that you replace the sources in site-packages?
Done.
[2021-10-14 12:54:41,439] [sml.device.ttyUSB0 ] ERROR | Received Frame
[2021-10-14 12:54:41,519] [sml.device.ttyUSB0 ] ERROR | -> b'7607001303efb13d62006200726301017601010700130652e5bf0b0901454d480000742854010163b33c007607001303efb13e620062007263070177010b0901454d480000742854070100620affff726201650652fd3d7a77078181c78203ff0101010104454d480177070100000009ff010101010b0901454d4800007428540177070100010800ff6401018201621e52ff560006c977070177070100020800ff6401018201621e52ff5600000006870177070100010801ff0101621e52ff560006c977070177070100020801ff0101621e52ff5600000006870177070100010802ff0101621e52ff5600000000000177070100020802ff0101621e52ff5600000000000177070100100700ff0101621b52ff55000006a20177078181c78205ff010101018302027b1e128fbe04a02f2ed66ac2ff64fb7c8f54957061e878e639c892aba7ff8f82b0888ee708fd9c4d511d2e741f25860101016389d6007607001303efb1416200620072630201710163c34f00'
[2021-10-14 12:54:41,741] [sml.device.ttyUSB0 ] ERROR | Traceback (most recent call last):
[2021-10-14 12:54:41,744] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.9/site-packages/sml2mqtt/sml_device.py", line 91, in read
[2021-10-14 12:54:41,746] [sml.device.ttyUSB0 ] ERROR | for sml_obj in frame.get_obis():
[2021-10-14 12:54:41,748] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.9/site-packages/smllib/sml_frame.py", line 113, in get_obis
[2021-10-14 12:54:41,750] [sml.device.ttyUSB0 ] ERROR | ret.append(SmlListEntry.from_list(data))
[2021-10-14 12:54:41,811] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.9/site-packages/smllib/sml_fields.py", line 146, in from_list
[2021-10-14 12:54:41,814] [sml.device.ttyUSB0 ] ERROR | raise ValueError('value is required!')
[2021-10-14 12:54:41,816] [sml.device.ttyUSB0 ] ERROR | ValueError: value is required!
[2021-10-14 12:54:41,818] [sml.device.ttyUSB0 ] INFO | ERROR
[2021-10-14 12:54:41,910] [sml.serial ] INFO | Port /dev/ttyUSB0 was closed
[2021-10-14 12:54:41,913] [sml.device.ttyUSB0 ] INFO | PORT_CLOSED
[2021-10-14 12:54:43,484] [asyncio ] ERROR | Task was destroyed but it is pending!
task: <Task pending name='Task-415035' coro=<stop_loop() done, defined at /opt/sml2mqtt/venv/lib/python3.9/site-packages/sml2mqtt/_signals.py:10> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xb5c15988>()]>>
Apparently the workaround in #3 does not work. Only explanation I have is that in case of this exception, the application exits with return code 0. Could that be possible?
I've made an update which should fix the mqtt reconnect issue and reworked some of the shutdown logic. The app should now properly exit with != 0 on error. Could you try again?
I've updated the code and give feedback in a few days.
Thank you. The Application should shut properly shut down on error and log the return code.
Proper shut down works now, so systemd can restart the service:
[2021-10-17 13:02:57,810] [sml ] INFO | Starting V0.6
[2021-10-17 13:02:58,057] [sml.device.ttyUSB0 ] INFO | PORT_OPENED
[2021-10-17 13:02:59,891] [sml.device.ttyUSB0 ] INFO | OK
[2021-10-20 13:07:54,797] [sml.device.ttyUSB0 ] ERROR | Received Frame
[2021-10-20 13:07:54,801] [sml.device.ttyUSB0 ] ERROR | -> b'760700130408da496200620072630101760101070013065a48c30b0901454d480000742854010163e7b400760700130408da4a620062007263070177010b0901454d480000742854070100620affff72620165065ae9647a77078181c78203ff0101010104454d480177070100000009ff010101010b0901454d4800007428540177070100010800ff6401018201621e52ff560006d277070177070100020800ff6401018201621e52ff5600000006870177070100010801ff0101621e52ff560006d277070177070100020801ff0101621e52ff5600000006870177070100010802ff0101621e52ff5600000000000177070100020802ff0101621e52ff5600000000000177070100100700ff0101621b52ff5500000ac20177078181c78205ff010101018302027b1e128fbe04a02f2ed66ac2ff64fb7c8f54957061e878e639c892aba7ff8f82b0888ee708fd9c4d511d2e741f258601010163c19600760700130408da4d6200620072630201710163792400'
[2021-10-20 13:07:54,825] [sml.device.ttyUSB0 ] ERROR | Traceback (most recent call last):
[2021-10-20 13:07:54,828] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.9/site-packages/sml2mqtt/sml_device.py", line 95, in read
[2021-10-20 13:07:54,830] [sml.device.ttyUSB0 ] ERROR | for sml_obj in frame.get_obis():
[2021-10-20 13:07:54,832] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.9/site-packages/smllib/sml_frame.py", line 113, in get_obis
[2021-10-20 13:07:54,835] [sml.device.ttyUSB0 ] ERROR | ret.append(SmlListEntry.from_list(data))
[2021-10-20 13:07:54,837] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.9/site-packages/smllib/sml_fields.py", line 146, in from_list
[2021-10-20 13:07:54,839] [sml.device.ttyUSB0 ] ERROR | raise ValueError('value is required!')
[2021-10-20 13:07:54,842] [sml.device.ttyUSB0 ] ERROR | ValueError: value is required!
[2021-10-20 13:07:54,844] [sml.device.ttyUSB0 ] INFO | ERROR
[2021-10-20 13:07:54,858] [sml.serial ] INFO | Port /dev/ttyUSB0 was closed
[2021-10-20 13:07:54,861] [sml.device.ttyUSB0 ] INFO | PORT_CLOSED
[2021-10-20 13:07:55,060] [asyncio ] ERROR | Task was destroyed but it is pending!
task: <Task pending name='Task-1031205' coro=<stop_loop() done, defined at /opt/sml2mqtt/venv/lib/python3.9/site-packages/sml2mqtt/_signals.py:13> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0xb5c3c760>()]>>
[2021-10-20 13:10:00,073] [sml ] INFO | Starting V0.6
[2021-10-20 13:10:00,195] [sml.device.ttyUSB0 ] INFO | PORT_OPENED
[2021-10-20 13:10:01,039] [sml.device.ttyUSB0 ] INFO | OK
Thank you for reporting back!
I have another error every few hours which stops sml2mqtt from reporting any values. It does seem that the Python process does not exit and thus systemd not restarting the service:
[2022-01-25 04:50:45,423] [sml.device.ttyUSB0 ] ERROR | Traceback (most recent call last):
[2022-01-25 04:50:45,424] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/sml2mqtt/sml_device.py", line 90, in read
[2022-01-25 04:50:45,425] [sml.device.ttyUSB0 ] ERROR | for sml_obj in frame.get_obis():
[2022-01-25 04:50:45,425] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 112, in get_obis
[2022-01-25 04:50:45,426] [sml.device.ttyUSB0 ] ERROR | self._parse_msg(data)
[2022-01-25 04:50:45,426] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 101, in _parse_msg
[2022-01-25 04:50:45,427] [sml.device.ttyUSB0 ] ERROR | self._parse_msg(v)
[2022-01-25 04:50:45,427] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 99, in _parse_msg
[2022-01-25 04:50:45,428] [sml.device.ttyUSB0 ] ERROR | parent_obj[i] = v = self.get_value()
[2022-01-25 04:50:45,428] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 62, in get_value
[2022-01-25 04:50:45,429] [sml.device.ttyUSB0 ] ERROR | raise InvalidBufferPos(f'Pos bigger than buffer: {e_pos} > {self.buf_len}')
[2022-01-25 04:50:45,429] [sml.device.ttyUSB0 ] ERROR | smllib.sml_frame.InvalidBufferPos: Pos bigger than buffer: 941 > 219
[2022-01-25 04:50:45,430] [sml.device.ttyUSB0 ] INFO | ERROR
[2022-01-25 04:50:45,434] [sml.serial ] INFO | Port /dev/ttyUSB0 was closed
[2022-01-25 04:50:45,434] [sml.device.ttyUSB0 ] INFO | PORT_CLOSED
[2022-01-25 04:50:45,749] [asyncio ] ERROR | Task was destroyed but it is pending!
task: <Task pending name='Task-124577' coro=<stop_loop() done, defined at /opt/sml2mqtt/venv/lib/python3.8/site-packages/sml2mqtt/_signals.py:10> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x75b69550>()]>>
I just fixed an issue in the smllib but I have not yet ported it back to the sml2mqtt application. Would you mind sharing the frame (redact your personal information) just so I can make sure this is not another issue?
Nonetheless the application should exit properly ...
Will the frame be dumped with debug logging turned on or how can I get hold of the frame that causes the issue?
Yes - it should be right above the Traceback you posted
Hm, there is nothing in the log. Here is the log with some more context:
... snipped ...
[2022-01-25 00:28:03,543] [sml.mqtt ] ERROR | [code:4] The client is not currently connected.
[2022-01-25 00:28:04,545] [sml.mqtt ] ERROR | [code:4] The client is not currently connected.
[2022-01-25 00:28:05,019] [sml2mqtt ] INFO | Shutting down ...
[2022-01-25 00:28:06,727] [sml.device.ttyUSB0 ] INFO | PORT_OPENED
[2022-01-25 00:28:07,542] [sml.device.ttyUSB0 ] INFO | OK
[2022-01-25 04:50:45,423] [sml.device.ttyUSB0 ] ERROR | Traceback (most recent call last):
[2022-01-25 04:50:45,424] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/sml2mqtt/sml_device.py", line 90, in read
[2022-01-25 04:50:45,425] [sml.device.ttyUSB0 ] ERROR | for sml_obj in frame.get_obis():
[2022-01-25 04:50:45,425] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 112, in get_obis
[2022-01-25 04:50:45,426] [sml.device.ttyUSB0 ] ERROR | self._parse_msg(data)
[2022-01-25 04:50:45,426] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 101, in _parse_msg
[2022-01-25 04:50:45,427] [sml.device.ttyUSB0 ] ERROR | self._parse_msg(v)
[2022-01-25 04:50:45,427] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 99, in _parse_msg
[2022-01-25 04:50:45,428] [sml.device.ttyUSB0 ] ERROR | parent_obj[i] = v = self.get_value()
[2022-01-25 04:50:45,428] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 62, in get_value
[2022-01-25 04:50:45,429] [sml.device.ttyUSB0 ] ERROR | raise InvalidBufferPos(f'Pos bigger than buffer: {e_pos} > {self.buf_len}')
[2022-01-25 04:50:45,429] [sml.device.ttyUSB0 ] ERROR | smllib.sml_frame.InvalidBufferPos: Pos bigger than buffer: 941 > 219
[2022-01-25 04:50:45,430] [sml.device.ttyUSB0 ] INFO | ERROR
[2022-01-25 04:50:45,434] [sml.serial ] INFO | Port /dev/ttyUSB0 was closed
[2022-01-25 04:50:45,434] [sml.device.ttyUSB0 ] INFO | PORT_CLOSED
[2022-01-25 04:50:45,749] [asyncio ] ERROR | Task was destroyed but it is pending!
task: <Task pending name='Task-124577' coro=<stop_loop() done, defined at /opt/sml2mqtt/venv/lib/python3.8/site-packages/sml2mqtt/_signals.py:10> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x75b69550>()]>>
[2022-01-25 17:17:58,573] [sml.device.ttyUSB0 ] INFO | PORT_OPENED
[2022-01-25 17:17:59,047] [sml.device.ttyUSB0 ] INFO | OK
[2022-01-25 23:37:32,852] [sml.device.ttyUSB0 ] ERROR | Traceback (most recent call last):
[2022-01-25 23:37:32,852] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/sml2mqtt/sml_device.py", line 90, in read
[2022-01-25 23:37:32,853] [sml.device.ttyUSB0 ] ERROR | for sml_obj in frame.get_obis():
[2022-01-25 23:37:32,853] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 112, in get_obis
[2022-01-25 23:37:32,853] [sml.device.ttyUSB0 ] ERROR | self._parse_msg(data)
[2022-01-25 23:37:32,854] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 101, in _parse_msg
[2022-01-25 23:37:32,854] [sml.device.ttyUSB0 ] ERROR | self._parse_msg(v)
[2022-01-25 23:37:32,854] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 99, in _parse_msg
[2022-01-25 23:37:32,855] [sml.device.ttyUSB0 ] ERROR | parent_obj[i] = v = self.get_value()
[2022-01-25 23:37:32,855] [sml.device.ttyUSB0 ] ERROR | File "/opt/sml2mqtt/venv/lib/python3.8/site-packages/smllib/sml_frame.py", line 62, in get_value
[2022-01-25 23:37:32,855] [sml.device.ttyUSB0 ] ERROR | raise InvalidBufferPos(f'Pos bigger than buffer: {e_pos} > {self.buf_len}')
[2022-01-25 23:37:32,856] [sml.device.ttyUSB0 ] ERROR | smllib.sml_frame.InvalidBufferPos: Pos bigger than buffer: 941 > 219
[2022-01-25 23:37:32,856] [sml.device.ttyUSB0 ] INFO | ERROR
[2022-01-25 23:37:32,859] [sml.serial ] INFO | Port /dev/ttyUSB0 was closed
[2022-01-25 23:37:32,859] [sml.device.ttyUSB0 ] INFO | PORT_CLOSED
[2022-01-25 23:37:33,170] [asyncio ] ERROR | Task was destroyed but it is pending!
task: <Task pending name='Task-181350' coro=<stop_loop() done, defined at /opt/sml2mqtt/venv/lib/python3.8/site-packages/sml2mqtt/_signals.py:10> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x75ba57f0>()]>>
So the tool logs show PORT_OPENED & OK and then a few hours later the traceback gets dumped without any further information.
Wouldn't it be possible to just skip the current frame and continue with the next one instead of stopping the execution completely in case of a parsing error?
Wouldn't it be possible to just skip the current frame and continue with the next one instead of stopping the execution completely in case of a parsing error?
I've already fixed the issue in the underlying library but I have yet to port the changes to sml2mqtt. Maybe over the course of next week I'll find the time to do it.
Great. Thank you! The log somehow indicates that the port is opened again after it was closed but no data is read anymore. When I restart the service with "systemctl restart sml2mqtt" it works again. So I see 2 issues, one is the parsing error which raises an exception and the second one is that reopening the port does not work anymore. Unfortunately I have no idea why the serial port read does not return data anymore.
@mrumpf Do you still experience the issue?
@spacemanspiff2007: The issue is still present in my system. I have to restart sml2mqtt continuous
Which version are you running and can you post the logfile please?
Logfile is 104 MB :-D Most is like:
[2022-06-02 18:07:24,436] [sml.mqtt ] ERROR | Error while publishing to sml2mqtt//dev/ttyUSB0/0100100700ff: [code:4] The client is not currently connected. (MqttCodeError)
But I recogniced, that i am still on Version 1.0.1 - so I have to update and reverify the problem: [2022-06-02 08:34:37,316] [sml ] INFO | Starting V1.0.1
I updated and will monitor it with the new version: [2022-06-03 20:20:39,178] [sml ] INFO | Starting V1.1.0 [2022-06-03 20:20:39,292] [sml.ttyUSB0.status ] INFO | PORT_OPENED [2022-06-03 20:20:39,979] [sml.ttyUSB0.status ] INFO | OK
The Problem still exist in my setup (see attached logfile snippet):
[2022-06-08 01:33:26,962] [sml.mqtt ] ERROR | Error while publishing to sml2mqtt//dev/ttyUSB0/0100100700ff: [code:4] The client is not currently connected. (MqttCodeError) [2022-06-08 01:33:27,958] [sml.ttyUSB0 ] ERROR | Received Frame [2022-06-08 01:33:27,959] [sml.ttyUSB0 ] ERROR | -> b'7605065850a66200620072630101760107ffffffffffff05021d70370b0a014c475a0003403b4972620165021d7707016326de007605065850a762006200726307017707ffffffffffff0b0a014c475a0003403b49070100620affff72620165021d770775770701006032010101010101044c475a0177070100600100ff010101010b0a014c475a0003403b490177070100010800ff65001c010472620165021d7707621e52ff690000000003152c450177070100020800ff0172620165021d7707621e52ff6900000000000000000177070100100700ff0101621b52005900000000000000fb010101637264007605065850a862006200726302017101631c8c00' [2022-06-08 01:33:27,966] [sml.ttyUSB0 ] ERROR | Traceback (most recent call last): [2022-06-08 01:33:27,967] [sml.ttyUSB0 ] ERROR | File "/usr/lib/python3.9/site-packages/sml2mqtt/device/sml_device.py", line 119, in serial_data_read [2022-06-08 01:33:27,967] [sml.ttyUSB0 ] ERROR | await self.process_frame(frame) [2022-06-08 01:33:27,968] [sml.ttyUSB0 ] ERROR | File "/usr/lib/python3.9/site-packages/sml2mqtt/device/sml_device.py", line 151, in process_frame [2022-06-08 01:33:27,969] [sml.ttyUSB0 ] ERROR | for sml_obj in frame.get_obis(): [2022-06-08 01:33:27,970] [sml.ttyUSB0 ] ERROR | File "/usr/lib/python3.9/site-packages/smllib/sml_frame.py", line 124, in get_obis [2022-06-08 01:33:27,970] [sml.ttyUSB0 ] ERROR | ret.append(self.build_ctx[SmlListEntry].build(data, self.build_ctx)) [2022-06-08 01:33:27,971] [sml.ttyUSB0 ] ERROR | File "/usr/lib/python3.9/site-packages/smllib/builder/list_entry.py", line 14, in build [2022-06-08 01:33:27,972] [sml.ttyUSB0 ] ERROR | ret = super().build(obj, classes) # type: SmlListEntry [2022-06-08 01:33:27,972] [sml.ttyUSB0 ] ERROR | File "/usr/lib/python3.9/site-packages/smllib/builder/_builder.py", line 40, in build [2022-06-08 01:33:27,973] [sml.ttyUSB0 ] ERROR | raise WrongValueType(f'{value} ({type(value)}) != {field.type}') [2022-06-08 01:33:27,974] [sml.ttyUSB0 ] ERROR | smllib.errors.WrongValueType: 065850a7 (<class 'str'>) != (<class 'int'>, <class 'NoneType'>) [2022-06-08 01:33:27,975] [sml.ttyUSB0.status ] INFO | ERROR [2022-06-08 01:33:27,977] [sml.mqtt ] ERROR | Error while publishing to sml2mqtt//dev/ttyUSB0/status: [code:4] The client is not currently connected. (MqttCodeError) [2022-06-08 01:33:27,979] [sml.serial ] INFO | Port /dev/ttyUSB0 was closed [2022-06-08 01:33:27,980] [sml.ttyUSB0.status ] INFO | PORT_CLOSED [2022-06-08 01:33:27,983] [sml ] INFO | Shutting down ... [2022-06-08 01:33:27,984] [asyncio ] ERROR | Task exception was never retrieved future: <Task finished name='Task-409736' coro=<do_shutdown() done, defined at /usr/lib/python3.9/site-packages/sml2mqtt/shutdown.py:51> exception=MqttCodeError('Could not disconnect')> Traceback (most recent call last): File "/usr/lib/python3.9/site-packages/sml2mqtt/shutdown.py", line 61, in do_shutdown await sml2mqtt.mqtt.disconnect() File "/usr/lib/python3.9/site-packages/sml2mqtt/mqtt/mqtt.py", line 34, in disconnect await mqtt.disconnect() File "/usr/lib/python3.9/site-packages/asyncio_mqtt/client.py", line 240, in disconnect raise MqttCodeError(rc, "Could not disconnect") asyncio_mqtt.error.MqttCodeError: [code:4] The client is not currently connected.
Could you try again with 1.2.0? I added a fallback there.
Still up and running 👍
[2022-06-14 12:58:08,395] [sml ] INFO | Starting V1.2.0 [2022-06-14 12:58:08,508] [sml.ttyUSB0.status ] INFO | PORT_OPENED [2022-06-14 12:58:09,117] [sml.ttyUSB0.status ] INFO | OK [2022-06-14 21:24:01,621] [sml.ttyUSB0 ] INFO | get_obis failed - try parsing frame [2022-06-15 15:36:18,695] [sml.ttyUSB0 ] INFO | get_obis failed - try parsing frame [2022-06-15 19:55:39,955] [sml.ttyUSB0 ] INFO | get_obis failed - try parsing frame
As you can see in the log the fallback is working. If you experience any more issues feel free to open another issue.
I'm running sml2mqtt on a Raspi 2. This night, it crashed:
syslog doesn't contain anything interesting.