viessmann: cant parse datetime reply from heater

[ThomasCr]

Hi,

these days, after updating shNG incl. updating python3.8 to python3.9 I saw the following error in the log.

2022-11-12  10:51:43 ERROR    logics.viess_fixTime In der Logik ist ein Fehler aufgetreten:
   Logik 'viess_fixTime', Datei '/usr/lib/python3.9/_strptime.py', Zeile 349
   function _strptime(), Exception: time data '00' does not match format '%Y%m%d%W%H%M%S'

At first I thought it was my logic. @Morg42 pointed me to relevant code part: https://github.com/smarthomeNG/plugins/blob/develop/viessmann/__init__.py#L1228

#!/usr/bin/env python3
# viess_fixtime.py

from datetime import datetime

plug = sh.plugins.return_plugin('viessmann')

if plug is not None:

    sys_cur_time_dt = shtime.now()
    #sys_cur_time = sys_cur_time_dt.strftime('%Y%m%d%W%H%M%S')
    sys_cur_time = sys_cur_time_dt.strftime('%Y-%m-%d %H:%M:%S')
    logger.debug(f'sys_cur_time={sys_cur_time}')
    logger.debug(f'sys_cur_time_dt={sys_cur_time_dt}')

    viess_cur_time = plug.read_addr('088e')
    logger.debug(f"viess_cur_time={viess_cur_time}")

    viess_cur_time_dt = datetime.strptime(viess_cur_time, '%Y-%m-%dT%H:%M:%S')
    logger.debug(f"viess_cur_time_dt={viess_cur_time_dt}")

    timediff = shtime.time_diff(sys_cur_time_dt, viess_cur_time_dt, 'm')
#    if timediff <= -2 or timediff >= 2 or True:
    if timediff <= -2 or timediff >= 2:
        logger.warning(f'Update Viessmann Systemtime, Timediff: {timediff:.0f} Min.')
        logger.debug(f"sys_cur_time={sys_cur_time}")
        plug.write_addr('088e', sys_cur_time)
    else:
        logger.warning(f'Update Viessmann Systemtime not need, time in sync')
else:
    logger.error("can't get viessmann plugin")

But after I manually ran the values at the Python shell, I saw that the values were actually correct and also the call in _build_valuebytes_from_value for valuetype == 'datetime' to do the strftime is good.

(smarthome) smarthome@heizung:/opt/smarthome$ python3
Python 3.9.15 (main, Oct 12 2022, 19:14:24)
[GCC 9.4.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import time
>>> from datetime import datetime
>>> import dateutil.parser
>>> sys_cur_time_dt = datetime.now()
>>> sys_cur_time = sys_cur_time_dt.strftime('%Y-%m-%d %H:%M:%S')
>>> print(sys_cur_time)
2022-11-12 10:33:24
>>> value=sys_cur_time
>>> print (dateutil.parser.isoparse(value))
2022-11-12 10:33:24
>>> print (dateutil.parser.isoparse(value).strftime('%Y%m%d%w%H%M%S'))
202211126103324

So I was wondering, where the heck this happends... After missing a good old Stacktrace I was digging around to find how to add it. Which led to the following simple solution.

thomas@heizung:/opt/smarthome$ git diff /opt/smarthome/lib/scheduler.py 
diff --git a/lib/scheduler.py b/lib/scheduler.py
index 6055779b..0eba9860 100644
--- a/lib/scheduler.py
+++ b/lib/scheduler.py
@@ -743,7 +743,7 @@ class Scheduler(threading.Thread):
                 logic_method = 'Hauptroutine der Logik'
             else:
                 logic_method = 'function ' + tb[2] + '()'
-            logger.error(f"In der Logik ist ein Fehler aufgetreten:\n   Logik '{logic.name}', Datei '{tb[0]}', Zeile {tb[1]}\n   {logic_method}, Exception: {e}")
+            logger.error(f"In der Logik ist ein Fehler aufgetreten:\n   Logik '{logic.name}', Datei '{tb[0]}', Zeile {tb[1]}\n   {logic_method}, Exception: {e}", exc_info=True)
             #logger.exception(f"In der Logik ist ein Fehler aufgetreten:\n   Logik '{logic.name}', Datei '{tb[0]}', Zeile {tb[1]}\n   {logic_method}, Exception: '{e}'\n ")

         return

Now my log entry looked like this:

2022-11-12  11:08:11 ERROR    logics.viess_fixTime In der Logik ist ein Fehler aufgetreten:
   Logik 'viess_fixTime', Datei '/usr/lib/python3.9/_strptime.py', Zeile 349
   function _strptime(), Exception: time data '00' does not match format '%Y%m%d%W%H%M%S'
Traceback (most recent call last):
  File "/opt/smarthome/lib/scheduler.py", line 724, in _execute_logic_task
    exec(logic._bytecode, logic_globals)
  File "/opt/smarthome/logics/viess_fixtime.py", line 26, in <module>
    plug.write_addr('088e', sys_cur_time)
  File "/opt/smarthome/plugins/viessmann/__init__.py", line 488, in write_addr
    return self._parse_response(response_packet, commandname)
  File "/opt/smarthome/plugins/viessmann/__init__.py", line 1446, in _parse_response
    value = datetime.strptime(rawdatabytes.hex(), '%Y%m%d%W%H%M%S').isoformat()
  File "/usr/lib/python3.9/_strptime.py", line 568, in _strptime_datetime
    tt, fraction, gmtoff_fraction = _strptime(data_string, format)
  File "/usr/lib/python3.9/_strptime.py", line 349, in _strptime
    raise ValueError("time data %r does not match format %r" %
ValueError: time data '00' does not match format '%Y%m%d%W%H%M%S'

So the error is at the processing of the reply. Maybe we need first to replace the leading 0 from the weekday?

Oh, and my unit is a V200KW2 which uses KW protocol.

[ThomasCr]

okay, after all I add a debug log from the plugin.

2022-11-12  12:24:37 WARNING  plugins.viessmann   parsed datestring for given value 2022-11-12 12:24:32 as: 202211126122432
2022-11-12  12:24:37 WARNING  plugins.viessmann   modded datestring after insert weekday: 2022111206122432
2022-11-12  12:24:37 DEBUG    plugins.viessmann   Created value bytes for type datetime as bytes: b' "\x11\x12\x06\x12$2'
2022-11-12  12:24:37 DEBUG    plugins.viessmann   Payload length is: 8 bytes
2022-11-12  12:24:37 DEBUG    plugins.viessmann   Created command Systemtime to be sent as hexstring: 01f4088e082022111206122432 and as bytes: bytearray(b'\x01\xf4\x08\x8e\x08 "\x11\x12\x06\x12$2') with value 2022-11-12 12:24:32 (transf
ormed to value byte 2022111206122432)
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Starting sync loop - attempt 2/5
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Got sync. Commencing command send
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Successfully sent packet: 01f7210808
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Trying to receive 8 bytes of the response
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Received 8 bytes chunk of response as hexstring 20233b48737888b0 and as bytes b' #;Hsx\x88\xb0'
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Response decoded to: commandcode: 2108, responsedatacode: 1, valuebytecount: 8, responsetypecode: 1
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Starting sync loop - attempt 1/5
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Rawdatabytes formatted: 20233b48737888b0 and unformatted: bytearray(b' #;Hsx\x88\xb0')
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Matched command Timer_Warmwasser_Di and read transformed timer [{'An': '04:00', 'Aus': '04:30'}, {'An': '07:30', 'Aus': '09:00'}, {'An': '14:30', 'Aus': '15:00'}, {'An': '17:00', 'Aus': 
'22:00'}] and byte length 8
2022-11-12  12:24:39 DEBUG    plugins.viessmann   process_response_timer: 2108
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Viessmann timer dict: {'Timer_Warmwasser': {'Timer_Warmwasser_Mo': [{'An': '04:00', 'Aus': '04:30'}, {'An': '07:30', 'Aus': '09:00'}, {'An': '14:30', 'Aus': '15:00'}, {'An': '17:00', 'Au
s': '22:00'}], 'Timer_Warmwasser_Di': [{'An': '04:00', 'Aus': '04:30'}, {'An': '07:30', 'Aus': '09:00'}, {'An': '14:30', 'Aus': '15:00'}, {'An': '17:00', 'Aus': '22:00'}]}}
2022-11-12  12:24:39 DEBUG    plugins.viessmann   send_timer_commands Timer_Warmwasser_Mi
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Got a new read job: Command Timer_Warmwasser_Mi
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Build read packet for command Timer_Warmwasser_Mi
2022-11-12  12:24:39 DEBUG    plugins.viessmann   Created command Timer_Warmwasser_Mi to be sent as hexstring: 01f7211008 and as bytes: bytearray(b'\x01\xf7!\x10\x08')
2022-11-12  12:24:41 DEBUG    plugins.viessmann   Starting sync loop - attempt 2/5
2022-11-12  12:24:41 DEBUG    plugins.viessmann   Got sync. Commencing command send
2022-11-12  12:24:41 DEBUG    plugins.viessmann   Successfully sent packet: 01f4088e082022111206122432
2022-11-12  12:24:41 DEBUG    plugins.viessmann   Trying to receive 1 bytes of the response
2022-11-12  12:24:41 DEBUG    plugins.viessmann   Received 1 bytes chunk of response as hexstring 00 and as bytes b'\x00'
2022-11-12  12:24:41 DEBUG    plugins.viessmann   Response decoded to: commandcode: 088e, responsedatacode: 1, valuebytecount: 1, responsetypecode: 1
2022-11-12  12:24:41 DEBUG    plugins.viessmann   Starting sync loop - attempt 1/5
2022-11-12  12:24:41 DEBUG    plugins.viessmann   Rawdatabytes formatted: 00 and unformatted: bytearray(b'\x00')
2022-11-12  12:24:41 ERROR    logics.viess_fixTime In der Logik ist ein Fehler aufgetreten:
   Logik 'viess_fixTime', Datei '/usr/lib/python3.9/_strptime.py', Zeile 349
   function _strptime(), Exception: time data '00' does not match format '%Y%m%d%W%H%M%S'
Traceback (most recent call last):
  File "/opt/smarthome/lib/scheduler.py", line 724, in _execute_logic_task
    exec(logic._bytecode, logic_globals)
  File "/opt/smarthome/logics/viess_fixtime.py", line 26, in <module>
    plug.write_addr('088e', sys_cur_time)
  File "/opt/smarthome/plugins/viessmann/__init__.py", line 488, in write_addr
    return self._parse_response(response_packet, commandname)
  File "/opt/smarthome/plugins/viessmann/__init__.py", line 1446, in _parse_response
    value = datetime.strptime(rawdatabytes.hex(), '%Y%m%d%W%H%M%S').isoformat()
  File "/usr/lib/python3.9/_strptime.py", line 568, in _strptime_datetime
    tt, fraction, gmtoff_fraction = _strptime(data_string, format)
  File "/usr/lib/python3.9/_strptime.py", line 349, in _strptime
    raise ValueError("time data %r does not match format %r" %
ValueError: time data '00' does not match format '%Y%m%d%W%H%M%S'
2022-11-12  12:24:43 DEBUG    plugins.viessmann   Starting sync loop - attempt 2/5
2022-11-12  12:24:43 DEBUG    plugins.viessmann   Got sync. Commencing command send
2022-11-12  12:24:43 DEBUG    plugins.viessmann   Successfully sent packet: 01f7211008

[ThomasCr]

if i read the vcontrol documentation correctly, the return value 00 simply means ok So why the plugin try to parse the response to datetime.

[Morg42]

The interpretation of 0x00 as "OK" seems plausible with the KW2 protocol.

Unfortunately, I can not test these formats myself as my device doesn't seem to have the timer functions.

Maybe @sisamiwe can help with the date/time-functions, afair he implemented these...?

Update: ich bekomme bei meiner Anlage 088e mit 8 Bytes ausgelesen, im Hex-Format liefert das Plugin ae0bae0b8f012f01. Daraus kann ich weder einen (durch strptime) parsebaren String noch eine vernünftige Datums-/Zeitangabe extrahieren.

Noch ein Nachtrag: dein Log ist irgendwie durcheinander - da werden mehrere Command gelesen, aber die Debug-Ausgaben davon, welches Kommando zusammengesetzt wird und welches gesendet und welches ggf. empfangen wird, sind ziemlich über kreuz.

Kannst du ggf. mal alle Scheduler bzw. cyclic Items deaktivieren und - manuell? - einmal 088e (Systemtime) und einman 2110 (Timer Mi) lesen? Idealerweise ist dann der gesamte Sende-/Lesevorgang jeder Adresse für sich zusammenhängend...

[Morg42]

proposed fix in develop, please test it on KW protocol

[Morg42]

@ThomasCr hast du Zeit gehabt mal zu prüfen, ob es jetzt geht?

[Morg42]

Solange es kein negatives Feedback gibt, schließe ich das. Sollte aus meiner Sicht erledigt sein.