search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
73.93k stars 30.99k forks source link

OTGW unable to connect #75781

Closed johansmitsnl closed 2 years ago

johansmitsnl commented 2 years ago

The problem

Since the update to 2022.7.x I'm not able to connect with my serial connected OTGW.

What version of Home Assistant Core has the issue?

2022.7.7

What was the last working version of Home Assistant Core?

2022.6.7

What type of installation are you running?

Home Assistant Container

Integration causing the issue

OTGW

Link to integration documentation on our website

https://www.home-assistant.io/integrations/opentherm_gw/

Diagnostics information

2022-07-26 18:45:00 ERROR (MainThread) [homeassistant.util.logging] Exception in receive_report when dispatching 'opentherm_gw_1_update': ({'outside_temp': None},)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/sensor.py", line 132, in receive_report
    value = status[self._source].get(self._var)
KeyError: 'boiler'

2022-07-26 18:45:00 ERROR (MainThread) [homeassistant.util.logging] Exception in receive_report when dispatching 'opentherm_gw_1_update': ({'outside_temp': None},)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/sensor.py", line 132, in receive_report
    value = status[self._source].get(self._var)
KeyError: 'boiler'

2022-07-26 18:45:00 ERROR (MainThread) [homeassistant.util.logging] Exception in receive_report when dispatching 'opentherm_gw_1_update': ({'outside_temp': None},)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/sensor.py", line 132, in receive_report
    value = status[self._source].get(self._var)
KeyError: 'thermostat'

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

75663 and #75285 did not fix the issue. But since there where already issues filed I did not report or checked my logs.

probot-home-assistant[bot] commented 2 years ago

Hey there @mvn23, mind taking a look at this issue as it has been labeled with an integration (opentherm_gw) you are listed as a code owner for? Thanks! (message by CodeOwnersMention)

opentherm_gw documentation opentherm_gw source (message by IssueLinks)

mvn23 commented 2 years ago

Thank you for the report. Are there any errors while HA is starting or when you reload the integration?

Fietspomp86 commented 2 years ago

I'm having same issue, I've updated Home Assistant to 7.7

Removed integration when updating to the first 7x versions. Now added again, with settings socket://192.168.x.x:23

This is my log:

homeassistant | 2022-07-27 17:29:25 ERROR (MainThread) [aiohttp.server] Error handling request homeassistant | Traceback (most recent call last): homeassistant | File "/usr/local/lib/python3.10/site-packages/aiohttp/web_protocol.py", line 435, in _handle_request homeassistant | resp = await request_handler(request) homeassistant | File "/usr/local/lib/python3.10/site-packages/aiohttp/web_app.py", line 504, in _handle homeassistant | resp = await handler(request) homeassistant | File "/usr/local/lib/python3.10/site-packages/aiohttp/web_middlewares.py", line 117, in impl homeassistant | return await handler(request) homeassistant | File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 60, in security_filter_middleware homeassistant | return await handler(request) homeassistant | File "/usr/src/homeassistant/homeassistant/components/http/forwarded.py", line 222, in forwarded_middleware homeassistant | return await handler(request) homeassistant | File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 28, in request_context_middleware homeassistant | return await handler(request) homeassistant | File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 79, in ban_middleware homeassistant | return await handler(request) homeassistant | File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 236, in auth_middleware homeassistant | return await handler(request) homeassistant | File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 136, in handle homeassistant | result = await result homeassistant | File "/usr/src/homeassistant/homeassistant/components/config/config_entries.py", line 177, in post homeassistant | return await super().post(request, flow_id) homeassistant | File "/usr/src/homeassistant/homeassistant/components/http/data_validator.py", line 62, in wrapper homeassistant | result = await method(view, request, *args, **kwargs) homeassistant | File "/usr/src/homeassistant/homeassistant/helpers/data_entry_flow.py", line 109, in post homeassistant | result = await self._flow_mgr.async_configure(flow_id, data) homeassistant | File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 277, in async_configure homeassistant | result = await self._async_handle_step( homeassistant | File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 359, in _async_handle_step homeassistant | result: FlowResult = await getattr(flow, method)(user_input) homeassistant | File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/config_flow.py", line 68, in async_step_init homeassistant | res = await asyncio.wait_for(test_connection(), timeout=10) homeassistant | File "/usr/local/lib/python3.10/asyncio/tasks.py", line 456, in wait_for homeassistant | return fut.result() homeassistant | File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/config_flow.py", line 65, in test_connection homeassistant | return status[gw_vars.OTGW].get(gw_vars.OTGW_ABOUT) homeassistant | TypeError: 'bool' object is not subscriptable

mvn23 commented 2 years ago

@Fietspomp86 you're affected by #75589 This issue may be a duplicate of that one, but I'm awaiting feedback from @johansmitsnl to confirm that.

johansmitsnl commented 2 years ago

@mvn23 here is the relevant output of the start:

s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service legacy-cont-init: starting
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service legacy-services: starting
services-up: info: copying legacy longrun home-assistant (no readiness notification)
s6-rc: info: service legacy-services successfully started
2022-07-26 18:43:29 ERROR (MainThread) [pyotgw.connection] The serial device on /dev/ttyUSB1 is not responding. Will keep trying.
2022-07-26 18:43:29 ERROR (MainThread) [pyotgw.protocol] Disconnected: None
2022-07-26 18:43:31 WARNING (MainThread) [aioesphomeapi.reconnect_logic] Can't connect to ESPHome API for zwembad @ 10.253.126.55: Error connecting to ('10.253.126.55', 6053): [Errno 113] Connect call failed ('10.253.126.55', 6053)
2022-07-26 18:43:38 ERROR (SyncWorker_5) [homeassistant.components.dhcp] Cannot watch for dhcp packets: [Errno 1] Operation not permitted
2022-07-26 18:43:39 ERROR (MainThread) [pyotgw.protocol] Disconnected: None
2022-07-26 18:43:52 ERROR (MainThread) [pyotgw.protocol] Disconnected: None
2022-07-26 18:44:08 ERROR (MainThread) [pyotgw.protocol] Disconnected: None
2022-07-26 18:44:30 ERROR (MainThread) [pyotgw.protocol] Disconnected: None
2022-07-26 18:44:54 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2022-07-26 18:45:00 ERROR (MainThread) [homeassistant.util.logging] Exception in receive_report when dispatching 'opentherm_gw_1_update': ({'outside_temp': None},)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/sensor.py", line 132, in receive_report
    value = status[self._source].get(self._var)
KeyError: 'boiler'

2022-07-26 18:45:00 ERROR (MainThread) [homeassistant.util.logging] Exception in receive_report when dispatching 'opentherm_gw_1_update': ({'outside_temp': None},)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/sensor.py", line 132, in receive_report
    value = status[self._source].get(self._var)
KeyError: 'boiler'
mvn23 commented 2 years ago

Thank you for the log.

This is a duplicate of #75589

Note that any fix for that bug will not fix the fact that your gateway is not responding. That is out of our control and may be a hardware issue.

Bekkie commented 2 years ago

@mvn23 I have the errors as described by @Fietspomp86, did also the same (remove 7x version, now installing again). I used this string as "Path or URL" : "socket://192.xx.xx.xxx:20108", please note: The OpenTherm monitor application is able to connect and in the previous HA releases all did worked fine.

Is also got this errors in my log, Logger: pyotgw.pyotgw Source: /usr/local/lib/python3.10/site-packages/pyotgw/pyotgw.py:812 First occurred: 22:12:20 (3 occurrences) Last logged: 22:12:26

Timed out waiting for command: PR, value: A. Timed out waiting for command: PR, value: B. Timed out waiting for command: PR, value: C.

ewf75 commented 2 years ago

I have the same errors as @Bekkie, only the timed out waiting for command are slightly different: Timed out waiting for command: PR, value: A. Timed out waiting for command: PR, value: I. Timed out waiting for command: PR, value: S.

The otmonitor application can connect to the gateway and also the problem started since HA release 2022.7.x.

mvdnes commented 2 years ago

After the upgrade to 2022.7.6, I noticed a similar problem. Turns out, my OTGW hardware was able to send data, but did not receive anything. When connecting otmonitor, I would get all the events and data, but could not set anything via the PS command, or others.

@mvn23 Could it be that in the fix for 2022.7.6, otgw has changed it behaviour? That it would previously still display data, but now requires a response to the PS command? During my debugging of this issue, I did receive the same errors that @Fietspomp86 mentioned, which prompted me to open issue #75589.

I don't know exactly how, but by resetting the device a couple of times and by connecting it to debug it, my OTGW started to accept input again. So unfortunately I can't help on how to fix the actual cause of the problem.

mvn23 commented 2 years ago

You might be on to something here. Since 2022.7.6 we use pyotgw 2.0.x instead of 1.1. It is a major rewrite of the library and I just reviewed the changes to the connection logic. It does indeed require two-way communication now to report success on a connection attempt, whereas in 1.1 this was not the case.

@johansmitsnl @Bekkie @ewf75 can you check whether or not commands work for you in otmonitor?

ewf75 commented 2 years ago

@mvn23 I did several commands via otmonitor these are the results: 20:34:40.578970 Command: PR=A 20:34:40.652240 PR: A=OpenTherm Gateway 4.3

20:36:44.424855 Command: PR=S 20:36:44.486339 PR: S=16.00

20:37:21.530833 Command: PR=B 20:37:21.641215 PR: B=14:30 07-01-2021

20:37:54.317994 Command: PR=C 20:37:54.396651 PR: C=4 MHz

johansmitsnl commented 2 years ago

@mvn23 van you give me some pointers on how to debug?

mvn23 commented 2 years ago

You can add something like this to configuration.yaml to enable relevant debug logging:

logger:
  default: warning
  logs:
    homeassistant.components.opentherm_gw: debug
    pyotgw: debug

This will log sent and received traffic among other things. Just don't forget to remove it again after you're done because it generates quite a lot of messages.

johansmitsnl commented 2 years ago

@mvn23 here is the output:

s6-rc: info: service legacy-services successfully started
2022-07-30 16:51:56 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Woonkamer (1845)' for apple_tv integration not ready yet: Not found at 10.253.126.75, waiting for discovery; Retrying in background
2022-07-30 16:51:59 DEBUG (MainThread) [pyotgw.status] Starting reporting routine
2022-07-30 16:51:59 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 1: BC074F94B
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 2: AF0181711
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 3: T80190000
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 4: B401923E6
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 3
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 5: T10010A00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 4
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 6: BD0010A00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 5
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 7: T80000200
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 6
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 8: B40000200
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 7
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 9: T00110000
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 8
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 10: BC0110000
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 9
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 11: T00090000
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 10
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 12: R00770000
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 11
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 13: BC077466B
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 12
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 14: AC0090000
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 13
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 15: T00110000
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 14
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 16: BC0110000
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 15
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 74 F9 4B
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 19 00 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 19 23 E6
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 01 01 0A 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 05 01 0A 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 00 02 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 00 02 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 11 00 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 11 00 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 09 00 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 77 00 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 77 46 6B
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: A 04 09 00 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 11 00 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 11 00 00
2022-07-30 16:52:06 DEBUG (MainThread) [homeassistant.components.opentherm_gw.binary_sensor] Added OpenTherm Gateway binary sensor Boiler Flame Huiskamer (Boiler)
2022-07-30 16:52:06 DEBUG (MainThread) [homeassistant.components.opentherm_gw.sensor] Added OpenTherm Gateway sensor Relative Modulation Level Huiskamer (Boiler)
2022-07-30 16:52:06 DEBUG (MainThread) [homeassistant.components.opentherm_gw.sensor] Added OpenTherm Gateway sensor Central Heating Water Pressure Huiskamer (Boiler)
2022-07-30 16:52:06 DEBUG (MainThread) [homeassistant.components.opentherm_gw.sensor] Added OpenTherm Gateway sensor Room Temperature Huiskamer (Thermostat)
2022-07-30 16:52:06 DEBUG (MainThread) [homeassistant.components.opentherm_gw.sensor] Added OpenTherm Gateway sensor Central Heating Water Temperature Huiskamer (Boiler)
2022-07-30 16:52:06 DEBUG (MainThread) [homeassistant.components.opentherm_gw.sensor] Added OpenTherm Gateway sensor Outside Temperature Huiskamer (Thermostat)
2022-07-30 16:52:06 DEBUG (MainThread) [homeassistant.components.opentherm_gw.sensor] Added OpenTherm Gateway sensor Return Water Temperature Huiskamer (Boiler)
2022-07-30 16:52:06 DEBUG (MainThread) [homeassistant.components.opentherm_gw.sensor] Added OpenTherm Gateway sensor Return Water Temperature Huiskamer (Thermostat)
2022-07-30 16:52:06 DEBUG (MainThread) [homeassistant.components.opentherm_gw.sensor] Added OpenTherm Gateway sensor Total Burner Starts Huiskamer (Boiler)
2022-07-30 16:52:06 DEBUG (MainThread) [homeassistant.components.opentherm_gw.sensor] Added OpenTherm Gateway sensor Total Burner Hours Huiskamer (Boiler)
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 17: T80190000
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.protocol] Received line 18: B401923E6
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 19 00 00
2022-07-30 16:52:06 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 19 23 E6
2022-07-30 16:52:06 ERROR (MainThread) [pyotgw.connection] The serial device on /dev/open-therm is not responding. Will keep trying.
2022-07-30 16:52:07 DEBUG (MainThread) [homeassistant.components.opentherm_gw.climate] Added OpenTherm Gateway climate device Huiskamer
2022-07-30 16:52:07 ERROR (MainThread) [pyotgw.protocol] Disconnected: None
2022-07-30 16:52:12 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-07-30 16:52:12 DEBUG (MainThread) [pyotgw.protocol] Received line 1: T80190000
2022-07-30 16:52:12 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:12 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 19 00 00
2022-07-30 16:52:12 DEBUG (MainThread) [pyotgw.protocol] Received line 2: BC0192419
2022-07-30 16:52:12 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:12 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 19 24 19
2022-07-30 16:52:13 DEBUG (MainThread) [pyotgw.protocol] Received line 3: T10010A00
2022-07-30 16:52:13 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:13 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 01 01 0A 00
2022-07-30 16:52:13 DEBUG (MainThread) [pyotgw.protocol] Received line 4: BD0010A00
2022-07-30 16:52:13 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:13 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 05 01 0A 00
2022-07-30 16:52:14 DEBUG (MainThread) [pyotgw.protocol] Received line 5: T80000200
2022-07-30 16:52:14 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:14 DEBUG (MainThread) [pyotgw.protocol] Received line 6: B40000200
2022-07-30 16:52:14 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-07-30 16:52:14 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 00 02 00
2022-07-30 16:52:14 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 00 02 00
2022-07-30 16:52:15 DEBUG (MainThread) [pyotgw.protocol] Received line 7: T00110000
2022-07-30 16:52:15 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:15 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 11 00 00
2022-07-30 16:52:15 DEBUG (MainThread) [pyotgw.protocol] Received line 8: BC0110000
2022-07-30 16:52:15 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:15 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 11 00 00
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.protocol] Received line 9: T00090000
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 09 00 00
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.protocol] Received line 10: R00740000
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 74 00 00
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.protocol] Received line 11: BC074F94B
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 74 F9 4B
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.protocol] Received line 12: AC0090000
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:16 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: A 04 09 00 00
2022-07-30 16:52:17 DEBUG (MainThread) [pyotgw.protocol] Received line 13: T1002010D
2022-07-30 16:52:17 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-07-30 16:52:17 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 01 02 01 0D
2022-07-30 16:52:17 ERROR (MainThread) [pyotgw.protocol] Disconnected: None
mvn23 commented 2 years ago

Looks like you're having the same issue @mvdnes described in https://github.com/home-assistant/core/issues/75781#issuecomment-1198453880 The connection to the gateway gets established and you are receiving the OpenTherm protocol messages, but you never get any response to the command that is sent. This leads me to believe that the command gets lost somewhere between Home Assistant and your OpenTherm Gateway. You can try to connect to the gateway using a terminal (screen should work) and issue some commands from there (e.g. PR=A) to see if that gives you any response.

Fietspomp86 commented 2 years ago

Hey, just tried latest Home Assistant RC, which includes pyotgw 2.0.2

Issue is still there, when trying to connect:

homeassistant       | 2022-08-02 17:02:06.304 DEBUG (MainThread) [pyotgw.status] Starting reporting routine
homeassistant       | 2022-08-02 17:02:06.308 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
homeassistant       | 2022-08-02 17:02:06.496 DEBUG (MainThread) [pyotgw.protocol] Received line 1: T00110000
homeassistant       | 2022-08-02 17:02:06.496 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
homeassistant       | 2022-08-02 17:02:06.496 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 11 00 00
homeassistant       | 2022-08-02 17:02:06.635 DEBUG (MainThread) [pyotgw.protocol] Received line 2: BC0110000
homeassistant       | 2022-08-02 17:02:06.635 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
homeassistant       | 2022-08-02 17:02:06.636 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 11 00 00
homeassistant       | 2022-08-02 17:02:07.503 DEBUG (MainThread) [pyotgw.protocol] Received line 3: T00720000
homeassistant       | 2022-08-02 17:02:07.503 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
homeassistant       | 2022-08-02 17:02:07.503 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 72 00 00
homeassistant       | 2022-08-02 17:02:07.622 DEBUG (MainThread) [pyotgw.protocol] Received line 4: BF0720000
homeassistant       | 2022-08-02 17:02:08.511 DEBUG (MainThread) [pyotgw.protocol] Received line 5: T80000200
homeassistant       | 2022-08-02 17:02:08.512 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
homeassistant       | 2022-08-02 17:02:08.512 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 00 02 00
homeassistant       | 2022-08-02 17:02:08.631 DEBUG (MainThread) [pyotgw.protocol] Received line 6: B40000200
homeassistant       | 2022-08-02 17:02:08.631 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
homeassistant       | 2022-08-02 17:02:08.631 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 00 02 00
homeassistant       | 2022-08-02 17:02:09.519 DEBUG (MainThread) [pyotgw.protocol] Received line 7: T80190000
homeassistant       | 2022-08-02 17:02:09.519 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
homeassistant       | 2022-08-02 17:02:09.520 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 19 00 00
homeassistant       | 2022-08-02 17:02:09.638 DEBUG (MainThread) [pyotgw.protocol] Received line 8: BC0192600
homeassistant       | 2022-08-02 17:02:09.639 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
homeassistant       | 2022-08-02 17:02:09.639 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 19 26 00
homeassistant       | 2022-08-02 17:02:10.527 DEBUG (MainThread) [pyotgw.protocol] Received line 9: T80730000
homeassistant       | 2022-08-02 17:02:10.527 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
homeassistant       | 2022-08-02 17:02:10.528 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 73 00 00
homeassistant       | 2022-08-02 17:02:10.646 DEBUG (MainThread) [pyotgw.protocol] Received line 10: B70730000
homeassistant       | 2022-08-02 17:02:11.309 ERROR (MainThread) [pyotgw.connection] The serial device on socket://192.168.2.61:23 is not responding. Will keep trying.
homeassistant       | 2022-08-02 17:02:11.311 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback SerialTransport._call_connection_lost(None)
homeassistant       | Traceback (most recent call last):
homeassistant       |   File "/usr/local/lib/python3.10/asyncio/events.py", line 80, in _run
homeassistant       |     self._context.run(self._callback, *self._args)
homeassistant       |   File "/usr/local/lib/python3.10/site-packages/serial_asyncio/__init__.py", line 417, in _call_connection_lost
homeassistant       |     self._serial.close()
homeassistant       |   File "/usr/local/lib/python3.10/site-packages/serial/urlhandler/protocol_socket.py", line 104, in close
homeassistant       |     time.sleep(0.3)
homeassistant       |   File "/usr/src/homeassistant/homeassistant/util/async_.py", line 180, in protected_loop_func
homeassistant       |     check_loop(func, strict=strict)
homeassistant       |   File "/usr/src/homeassistant/homeassistant/util/async_.py", line 141, in check_loop
homeassistant       |     raise RuntimeError(
homeassistant       | RuntimeError: Detected blocking call to sleep inside the event loop. Use `await hass.async_add_executor_job()`; This is causing stability issues. Please report issue

Using otmonitor.exe , is working just fine. This program also has an option to work as a relay-server, but this is causing same output as above.

My OTGW is running firmware 5.2, don't know if this is important to know?

If you need any more information, let me know!

mvn23 commented 2 years ago

Your case seems the same as with @mvdnes and @johansmitsnl above in that there is no response to the command that is sent. Can you get a response to any command when using otmonitor?

Fietspomp86 commented 2 years ago

Your case seems the same as with @mvdnes and @johansmitsnl above in that there is no response to the command that is sent. Can you get a response to any command when using otmonitor?

No, but my OTGW is linked by a ESP8266 using ESP-link and in monitor mode. I purely use it to monitor my boiler as I control it with my Toon thermostat. Maybe this is the culprit?

mvn23 commented 2 years ago

If you're not getting responses to any commands from other sources as well then it's not a bug in Home Assistant or the library. I don't plan on 'fixing' the integration or the library to work with broken hardware. Debugging why you don't get a response is another issue which is out of the scope of this bug report, but I would start by replacing the ESP with a USB-TTL cable to see if that works.

johansmitsnl commented 2 years ago

@mvn23 when I screen to the device I get a lot off feedback from the device. When I send (I think) it does not seem to do anything else. Before the upgrade it was working fine and no changes to the hardware, so no broken hardware from my side.

mvn23 commented 2 years ago

If the gateway is not responding to commands even when you send them through otmonitor or screen there's definitely something wrong with it. We can't do anything in Home Assistant to fix that. It may have seemed to work fine before as it is still sending out data and previous versions did not rely on commands to connect and initialize, but then you probably just never noticed that the commands didn't work (i.e. it seems not to receive data).

johansmitsnl commented 2 years ago

@mvn23 but I was able to change the temperature of the thermostat, so sending was possible. Will recheck.

Fietspomp86 commented 2 years ago

If the gateway is not responding to commands even when you send them through otmonitor or screen there's definitely something wrong with it. We can't do anything in Home Assistant to fix that. It may have seemed to work fine before as it is still sending out data and previous versions did not rely on commands to connect and initialize, but then you probably just never noticed that the commands didn't work (i.e. it seems not to receive data).

I think you're spot on. Also with OTmonitor I can see values and since I never send commands I didn't know that didn't work. Anyway, removed OTGW and checked by connecting to my laptop directly using USB - TTL, working fine. So flashed latest firmware and re-installed back onto boiler, now it's working! Perhaps it just needed a good reboot, but now I commands also work.

So in my experience with latest pyotgw and RC home assistant it works again :-). Thanks for the hard work!

mvn23 commented 2 years ago

@mvn23 I did several commands via otmonitor these are the results: 20:34:40.578970 Command: PR=A 20:34:40.652240 PR: A=OpenTherm Gateway 4.3

20:36:44.424855 Command: PR=S 20:36:44.486339 PR: S=16.00

20:37:21.530833 Command: PR=B 20:37:21.641215 PR: B=14:30 07-01-2021

20:37:54.317994 Command: PR=C 20:37:54.396651 PR: C=4 MHz

Apologies, I missed this one before. You do seem to get responses from the gateway. Are you still experiencing issues? If so, could you post a debug log?

khenderick commented 2 years ago

Since there is some suspicion on faulty hardware, I also have the same issue since 2022.7.7, so I don't think it's hardware related. I have a direct connection to USB.

I'll try to gather some debug logs as soon as possible. Awaiting those, I also confirmed the hardware is responding when connecting to my laptop using;

10:09:15.557309 Command: PR=A
10:09:15.592710 PR: A=OpenTherm Gateway 5.2
10:09:25.747487 Command: PR=B
10:09:25.777709 PR: B=12:02 28-12-2021
10:09:32.870622 Command: PR=C
10:09:32.889495 PR: C=4 MHz

Got a few interesting snippets from the debug logs:

...
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value I
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Received line 7: P I=00
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Submitting line 7 to CommandProcessor
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: P I=00
2022-08-03 11:33:41 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P I=00
2022-08-03 11:33:41 WARNING (MainThread) [pyotgw.commandprocessor] Command PR failed with P I=00, retrying...
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Received line 8: PR: I=0
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Submitting line 8 to CommandProcessor
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: I=0
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value L
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Received line 9: PR: L=FXOMPC
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Submitting line 9 to CommandProcessor
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: L=FXOMPC
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value M
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Received line 10: PR: M=G
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Submitting line 10 to CommandProcessor
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: M=G
...
...
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 1
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Received line 19: PS: 1
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Submitting line 19 to CommandProcessor
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 1
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Received line 20: 000000/00000000,0.00,00000001/00000001,0.00,0.00,100.00,0/0,0.00,0.00,1.20,0.00,0.00,0.00,39.00,0.00,0.00,38.50,0.00,0,60/38,45/20,0.00,0.00,00000000/00000000,0,0,0,0,0,0,0,0,0,0
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Submitting line 20 to CommandProcessor
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:33:41 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/__init__.py", line 430, in connect_and_subscribe
    self.status = await self.gateway.connect(self.device_path)
  File "/usr/local/lib/python3.10/site-packages/pyotgw/pyotgw.py", line 51, in connect
    await self.get_status()
  File "/usr/local/lib/python3.10/site-packages/pyotgw/pyotgw.py", line 272, in get_status
    v.DATA_MASTER_CH_ENABLED: int(master_status[7]),
IndexError: string index out of range
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Received line 21: PS: 0
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Submitting line 21 to CommandProcessor
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:33:42 DEBUG (MainThread) [pyotgw.protocol] Received line 22: R80190000
2022-08-03 11:33:42 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-03 11:33:42 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 19 00 00
2022-08-03 11:33:42 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
...

Here I did a powercycle of the OTGW hardware itself (while keeping it connected to my HA node):

...
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-03 11:35:47 ERROR (MainThread) [pyotgw.protocol] Disconnected: None
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: R8000000
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: R8310000
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: BC011000
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: Thermostat connected
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.protocol] Received line 9498: 
C00100
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.protocol] Submitting line 9498 to CommandProcessor
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 5
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.protocol] Received line 1: sconnected
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: sconnected
2022-08-03 11:35:47 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: sconnected
2022-08-03 11:35:47 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with sconnected, retrying...
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.protocol] Received line 2: S 0
PS: 0
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: S 0
PS: 0
2022-08-03 11:35:47 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: S 0
PS: 0
2022-08-03 11:35:47 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with S 0
PS: 0, retrying...
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.protocol] Received line 3: PS: 0
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-03 11:35:47 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/serial/by-id/usb-Prolific_Technology_Inc._USB-Serial_Controller-if00-port0
2022-08-03 11:35:48 DEBUG (MainThread) [pyotgw.protocol] Received line 4: R00000000
2022-08-03 11:35:48 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-03 11:35:48 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 00 00 00
2022-08-03 11:35:48 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:35:48 DEBUG (MainThread) [pyotgw.protocol] Received line 5: BC0000000
2022-08-03 11:35:48 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-03 11:35:48 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 00 00 00
2022-08-03 11:35:48 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:35:49 DEBUG (MainThread) [pyotgw.protocol] Received line 6: R80190000
2022-08-03 11:35:49 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-03 11:35:49 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 19 00 00
2022-08-03 11:35:49 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:35:49 DEBUG (MainThread) [pyotgw.protocol] Received line 7: B40192680
2022-08-03 11:35:49 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-03 11:35:49 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 19 26 80
2022-08-03 11:35:49 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
...

After a while, I also got

...
2022-08-03 11:38:59 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-03 11:38:59 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 01 01 00 00
2022-08-03 11:38:59 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:38:59 DEBUG (MainThread) [pyotgw.protocol] Received line 378: BD0010000
2022-08-03 11:38:59 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-03 11:38:59 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 05 01 00 00
2022-08-03 11:38:59 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:39:00 DEBUG (MainThread) [pyotgw.commandprocessor] Serial transport closed, not sending command SW
2022-08-03 11:39:00 DEBUG (MainThread) [pyotgw.commandprocessor] Serial transport closed, not sending command CS
2022-08-03 11:39:00 ERROR (MainThread) [homeassistant.util.logging] Exception in receive_report when dispatching 'opentherm_gw_otgw_update': ({'dhw_setpoint': None, 'control_setpoint': None},)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/binary_sensor.py", line 130, in receive_report
    state = status[self._source].get(self._var)
KeyError: 'boiler'

2022-08-03 11:39:00 ERROR (MainThread) [homeassistant.util.logging] Exception in receive_report when dispatching 'opentherm_gw_otgw_update': ({'dhw_setpoint': None, 'control_setpoint': None},)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/binary_sensor.py", line 130, in receive_report
    state = status[self._source].get(self._var)
KeyError: 'boiler'

2022-08-03 11:39:00 ERROR (MainThread) [homeassistant.util.logging] Exception in receive_report when dispatching 'opentherm_gw_otgw_update': ({'dhw_setpoint': None, 'control_setpoint': None},)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/binary_sensor.py", line 130, in receive_report
    state = status[self._source].get(self._var)
KeyError: 'boiler'

...this KeyError is repeating dozens of times, and then just continue in the below repeating behavior...

2022-08-03 11:39:00 DEBUG (MainThread) [pyotgw.protocol] Received line 379: R80380000
2022-08-03 11:39:00 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-03 11:39:00 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 38 00 00
2022-08-03 11:39:00 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-03 11:39:00 DEBUG (MainThread) [pyotgw.protocol] Received line 380: B4038FFFF
2022-08-03 11:39:00 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message que
...
mvn23 commented 2 years ago

Thank you for the logs. Unfortunately there do seem to be some issues with your gateway.

2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value I 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Received line 7: P I=00 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Submitting line 7 to CommandProcessor 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: P I=00 2022-08-03 11:33:41 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P I=00 2022-08-03 11:33:41 WARNING (MainThread) [pyotgw.commandprocessor] Command PR failed with P I=00, retrying... 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset! 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Received line 8: PR: I=0 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Submitting line 8 to CommandProcessor 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: I=0

To take the first thing I noticed from the first log, we expect to see PR: I=00 as a response to the command PR=I (PR with value I). In your log, we see that you first receive P I=00 and afterwards PR: I=0. In both cases, some characters are missing.

2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 1 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset! 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Received line 20: 000000/00000000,0.00,00000001/00000001,0.00,0.00,100.00,0/0,0.00,0.00,1.20,0.00,0.00,0.00,39.00,0.00,0.00,38.50,0.00,0,60/38,45/20,0.00,0.00,00000000/00000000,0,0,0,0,0,0,0,0,0,0 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.protocol] Submitting line 20 to CommandProcessor 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1 2022-08-03 11:33:41 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset! 2022-08-03 11:33:41 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/init.py", line 430, in connect_and_subscribe self.status = await self.gateway.connect(self.device_path) File "/usr/local/lib/python3.10/site-packages/pyotgw/pyotgw.py", line 51, in connect await self.get_status() File "/usr/local/lib/python3.10/site-packages/pyotgw/pyotgw.py", line 272, in get_status v.DATA_MASTER_CH_ENABLED: int(master_status[7]), IndexError: string index out of range

Line 20 should start with a series of 8 bits (0 or 1), you only have 6. This is causing the IndexError

I won't go into the warnings you got during the power cycle, as this may have been caused by the powercycle itself, although sconnected looks a lot like Disconnected with some characters missing.

The last snippet you posted is interesting and may hint at an issue with the library. I will investigate that.

khenderick commented 2 years ago

Allright, thanks for the feedback. Wrt the PR: I=0, I have the feeling that there might be a bit of logs missing before that I didn't copy. I'll keep monitoring the logs a bit, they might reveal new things.

What is the firmware your library supports? I noticed a user above reporting 4.3 while I have 5.2. And it seems that 5.4 is already available. https://otgw.tclcode.com/changelog.html

mvn23 commented 2 years ago

It was initially written for and tested against 4.3. When 5.0 came out it was updated for that and should work with 5.4 and 6.1 as well. I'm running 5.1 at the moment without any problems.

khenderick commented 2 years ago

Ok, thanks. I'm going do a bit more trial-and-error with the firmware then. @mvn23 do you have still a hex file for 5.1? I can't download that one anymore.

From the changelogs; 5.2 introduced the requirement to set the CS every minute which impacted my automations as I now need an automation who writes these values every minute. It seems 5.3 also mentions some fixes related to the watchdog, so I might be missing these.

Wrt the messed up PR: I=0 I noticed that in that particular case a few Watchdog timer reset! was logged around that time. It might be possible that characters are missed because of that.

Later on, I got

...
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value I
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.protocol] Received line 7: PR: I=00
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.protocol] Submitting line 7 to CommandProcessor
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: I=00
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
...

Which indicate that this command - usually - works. I have the feeling that this Watchdog timer reset! introduces a lot of side effects.

Another thing that I noticed in the logs that might be interesting is when I reloaded the integration, it seems to clear leftover messages from the command queue. However, there were a lot of them (~ 50-100 ish). Could this be a issue where some bug (either in the library or in the firmware) causes these commands to build up?

mvn23 commented 2 years ago

From the changelogs; 5.2 introduced the requirement to set the CS every minute which impacted my automations as I now need an automation who writes these values every minute. It seems 5.3 also mentions some fixes related to the watchdog, so I might be missing these.

I may add support for this in a future version. In the mean time, you can indeed use a timer in Home Assistant to send the commands.

Wrt the messed up PR: I=0 I noticed that in that particular case a few Watchdog timer reset! was logged around that time. It might be possible that characters are missed because of that.

Later on, I got

...
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value I
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.protocol] Received line 7: PR: I=00
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.protocol] Submitting line 7 to CommandProcessor
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: I=00
2022-08-03 13:04:32 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
...

Which indicate that this command - usually - works. I have the feeling that this Watchdog timer reset! introduces a lot of side effects.

That's the internal watchdog in pyotgw monitoring the serial connection for inactivity. A timer reset indicates that there was activity on the connection and the inactivity timer is starting again. It is expected behavior and does not affect communication with the gateway.

Another thing that I noticed in the logs that might be interesting is when I reloaded the integration, it seems to clear leftover messages from the command queue. However, there were a lot of them (~ 50-100 ish). Could this be a issue where some bug (either in the library or in the firmware) causes these commands to build up?

It is likely related to the missing characters. Any message that does not look like an OpenTherm protocol message (i.e. does not match r"^(T|B|R|A|E)([0-9A-F]{8})$") is assumed to be a response to a command and gets submitted to the command queue. Before sending a command, we clear the queue to make sure there are no leftover messages from previous failed commands. If you are receiving incomplete protocol messages, they will end up in that queue as well. I may consider to also clear the queue periodically in a future version to avoid such buildup as there are some other messages that end up there as well.

khenderick commented 2 years ago

I may add support for this in a future version. In the mean time, you can indeed use a timer in Home Assistant to send the commands.

Yeah, I can perfectly handle this with automations, no worries :slightly_smiling_face:

That's the internal watchdog in pyotgw monitoring the serial connection for inactivity. A timer reset indicates that there was activity on the connection and the inactivity timer is starting again. It is expected behavior and does not affect communication with the gateway.

Ah, good to know.

It is likely related to the missing characters. Any message that does not look like an OpenTherm protocol message (i.e. does not match r"^(T|B|R|A|E)([0-9A-F]{8})$") is assumed to be a response to a command and gets submitted to the command queue. Before sending a command, we clear the queue to make sure there are no leftover messages from previous failed commands. If you are receiving incomplete protocol messages, they will end up in that queue as well. I may consider to also clear the queue periodically in a future version to avoid such buildup as there are some other messages that end up there as well.

Odd, there indeed seems to be quite some messages that look like they should match the regex, if not for missing characters;

...
2022-08-03 13:32:00 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: Thermostat connected
2022-08-03 13:32:00 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: OpenTherm Gateway 5.4
2022-08-03 13:32:00 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: hrmostat disconnected
2022-08-03 13:32:00 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: BC010000
2022-08-03 13:32:00 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: R8190000
2022-08-03 13:32:00 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: BC0000000^MR00120000
2022-08-03 13:32:00 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: B401C3B80
...
khenderick commented 2 years ago

Seems all is resolved in 2022.8.0.

It looks like the changes in the (re)connect logic solved the missing characters as I don't see any issue at this moment. The key errors are also gone.

Sorry I kinda wasted your time on debugging this issue as it was already resolved. I'm grateful for this integration.

johansmitsnl commented 2 years ago

@mvn23

I have checked the cables and all looks good. With the new HA update 2022.08.0 I get this log:

2022-08-04 09:19:17.301 DEBUG (MainThread) [pyotgw.status] Starting reporting routine
2022-08-04 09:19:17.331 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 09:19:17.413 DEBUG (MainThread) [pyotgw.protocol] Received line 1: SE
2022-08-04 09:19:17.414 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 09:19:17.416 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 09:19:17.450 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: SE
2022-08-04 09:19:18.014 DEBUG (MainThread) [pyotgw.protocol] Received line 2: T80000200
2022-08-04 09:19:18.014 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 09:19:18.015 DEBUG (MainThread) [pyotgw.protocol] Received line 3: B40000200
2022-08-04 09:19:18.015 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-08-04 09:19:18.032 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 00 02 00
2022-08-04 09:19:18.033 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 00 02 00
2022-08-04 09:19:18.090 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Huiskamer for opentherm_gw
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 357, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/__init__.py", line 115, in async_setup_entry
    await asyncio.wait_for(
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for
    return fut.result()
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/__init__.py", line 441, in connect_and_subscribe
    self.status = await self.gateway.connect(self.device_path)
  File "/usr/local/lib/python3.10/site-packages/pyotgw/pyotgw.py", line 47, in connect
    if not await self.connection.connect(port, timeout):
  File "/usr/local/lib/python3.10/site-packages/pyotgw/connection.py", line 57, in connect
    transport, protocol = await self._connecting_task
  File "/usr/local/lib/python3.10/site-packages/pyotgw/connection.py", line 124, in _attempt_connect
    await asyncio.wait_for(
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for
    return fut.result()
  File "/usr/local/lib/python3.10/site-packages/pyotgw/protocol.py", line 134, in init_and_wait_for_activity
    await self.command_processor.issue_cmd(v.OTGW_CMD_SUMMARY, 0, retry=0)
  File "/usr/local/lib/python3.10/site-packages/pyotgw/commandprocessor.py", line 92, in issue_cmd
    ret = await process(msg)
  File "/usr/local/lib/python3.10/site-packages/pyotgw/commandprocessor.py", line 57, in process
    raise v.OTGW_ERRS[msg]
SyntaxError: Syntax Error: The command contained an unexpected character or was incomplete.
2022-08-04 09:19:18.179 WARNING (MainThread) [homeassistant.config_entries] Config entry 'shellyplug-s-A33CF3' for shelly integration not ready yet: Timeout during device setup; Retrying in background
2022-08-04 09:19:18.920 DEBUG (MainThread) [pyotgw.protocol] Received line 4: T00110000
2022-08-04 09:19:18.921 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 09:19:18.923 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 11 00 00
2022-08-04 09:19:18.997 DEBUG (MainThread) [pyotgw.protocol] Received line 5: BC0110000
2022-08-04 09:19:18.998 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 09:19:19.000 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 11 00 00
2022-08-04 09:19:19.900 DEBUG (MainThread) [pyotgw.protocol] Received line 6: T00090000
2022-08-04 09:19:19.901 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 09:19:19.903 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 09 00 00
2022-08-04 09:19:19.922 DEBUG (MainThread) [pyotgw.protocol] Received line 7: R00770000
2022-08-04 09:19:19.923 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 09:19:19.923 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 77 00 00
2022-08-04 09:19:19.994 DEBUG (MainThread) [pyotgw.protocol] Received line 8: BC0774675
2022-08-04 09:19:19.994 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 09:19:19.995 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 77 46 75
2022-08-04 09:19:20.026 DEBUG (MainThread) [pyotgw.protocol] Received line 9: AC0090000
2022-08-04 09:19:20.027 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 09:19:20.027 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: A 04 09 00 00
2022-08-04 09:19:20.899 DEBUG (MainThread) [pyotgw.protocol] Received line 10: T900E6400
2022-08-04 09:19:20.900 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 09:19:20.902 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 01 0E 64 00
2022-08-04 09:19:20.985 DEBUG (MainThread) [pyotgw.protocol] Received line 11: B500E6400
2022-08-04 09:19:20.986 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 09:19:20.987 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 05 0E 64 00
mvn23 commented 2 years ago

Do you get the same response every time you (re)load the integration? The error is caused by the gateway responding to a PS=0 command with SE (see here for more info) so something is causing the gateway to not receive the command properly. Is anything else connected to the gateway at the same time?

johansmitsnl commented 2 years ago

No nothing special connected to the gateway, just the boiler and thermostat.

When I restart I get this (sorry for the big log but it shows various messages that might be relevant):

2022-08-04 15:29:59.724 DEBUG (MainThread) [pyotgw.status] Starting reporting routine
2022-08-04 15:29:59.754 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:29:59.834 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS: 0
2022-08-04 15:29:59.835 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:29:59.836 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:29:59.854 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-04 15:29:59.893 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:29:59.926 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value A
2022-08-04 15:29:59.926 DEBUG (MainThread) [pyotgw.protocol] Received line 2: T10010A00
2022-08-04 15:29:59.927 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:29:59.951 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 01 01 0A 00
2022-08-04 15:29:59.976 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:01.512 DEBUG (MainThread) [pyotgw.protocol] Received line 3: PR: A=OpenTherm Gateway 4.2.5
2022-08-04 15:30:01.512 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:01.512 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:01.513 DEBUG (MainThread) [pyotgw.protocol] Received line 4: BD0010A00
2022-08-04 15:30:01.513 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:01.513 DEBUG (MainThread) [pyotgw.protocol] Received line 5: T80000200
2022-08-04 15:30:01.513 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-08-04 15:30:01.513 DEBUG (MainThread) [pyotgw.protocol] Received line 6: B40000200
2022-08-04 15:30:01.513 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 3
2022-08-04 15:30:01.550 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: A=OpenTherm Gateway 4.2.5
2022-08-04 15:30:01.551 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 05 01 0A 00
2022-08-04 15:30:01.551 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 00 02 00
2022-08-04 15:30:01.552 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 00 02 00
2022-08-04 15:30:01.568 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:01.619 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value B
2022-08-04 15:30:01.631 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:01.669 DEBUG (MainThread) [pyotgw.protocol] Received line 7: PR: B=17:59 20-10-2015
2022-08-04 15:30:01.669 DEBUG (MainThread) [pyotgw.protocol] Submitting line 7 to CommandProcessor
2022-08-04 15:30:01.669 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:08.914 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:08.914 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: B=17:59 20-10-2015
2022-08-04 15:30:08.933 DEBUG (MainThread) [pyotgw.protocol] Received line 8: T00110000
2022-08-04 15:30:08.934 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:08.934 DEBUG (MainThread) [pyotgw.protocol] Received line 9: BC0110000
2022-08-04 15:30:08.934 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-08-04 15:30:08.934 DEBUG (MainThread) [pyotgw.protocol] Received line 10: T00090000
2022-08-04 15:30:08.934 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 3
2022-08-04 15:30:08.935 DEBUG (MainThread) [pyotgw.protocol] Received line 11: R00770000
2022-08-04 15:30:08.935 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 4
2022-08-04 15:30:08.935 DEBUG (MainThread) [pyotgw.protocol] Received line 12: BC0774675
2022-08-04 15:30:08.935 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 5
2022-08-04 15:30:08.935 DEBUG (MainThread) [pyotgw.protocol] Received line 13: AC0090000
2022-08-04 15:30:08.935 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 6
2022-08-04 15:30:08.935 DEBUG (MainThread) [pyotgw.protocol] Received line 14: T00030000
2022-08-04 15:30:08.936 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 7
2022-08-04 15:30:08.936 DEBUG (MainThread) [pyotgw.protocol] Received line 15: B40030083
2022-08-04 15:30:08.936 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 8
2022-08-04 15:30:08.936 DEBUG (MainThread) [pyotgw.protocol] Received line 16: T80190000
2022-08-04 15:30:08.936 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 9
2022-08-04 15:30:08.936 DEBUG (MainThread) [pyotgw.protocol] Received line 17: BC0192480
2022-08-04 15:30:08.936 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 10
2022-08-04 15:30:08.936 DEBUG (MainThread) [pyotgw.protocol] Received line 18: T10010A00
2022-08-04 15:30:08.937 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 11
2022-08-04 15:30:08.937 DEBUG (MainThread) [pyotgw.protocol] Received line 19: BD0010A00
2022-08-04 15:30:08.937 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 12
2022-08-04 15:30:08.937 DEBUG (MainThread) [pyotgw.protocol] Received line 20: T80000200
2022-08-04 15:30:08.937 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 13
2022-08-04 15:30:08.937 DEBUG (MainThread) [pyotgw.protocol] Received line 21: B40000200
2022-08-04 15:30:08.938 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 14
2022-08-04 15:30:08.938 DEBUG (MainThread) [pyotgw.protocol] Received line 22: T00110000
2022-08-04 15:30:08.938 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 15
2022-08-04 15:30:08.938 DEBUG (MainThread) [pyotgw.protocol] Received line 23: BC0110000
2022-08-04 15:30:08.938 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 16
2022-08-04 15:30:08.938 DEBUG (MainThread) [pyotgw.protocol] Received line 24: T00090000
2022-08-04 15:30:08.938 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 17
2022-08-04 15:30:08.938 DEBUG (MainThread) [pyotgw.protocol] Received line 25: R00780000
2022-08-04 15:30:08.939 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 18
2022-08-04 15:30:08.942 DEBUG (MainThread) [pyotgw.protocol] Received line 26: BC078711E
2022-08-04 15:30:08.942 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 19
2022-08-04 15:30:08.942 DEBUG (MainThread) [pyotgw.protocol] Received line 27: AC0090000
2022-08-04 15:30:08.942 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 20
2022-08-04 15:30:09.086 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 11 00 00
2022-08-04 15:30:09.086 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 11 00 00
2022-08-04 15:30:09.087 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 09 00 00
2022-08-04 15:30:09.087 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 77 00 00
2022-08-04 15:30:09.087 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 77 46 75
2022-08-04 15:30:09.088 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: A 04 09 00 00
2022-08-04 15:30:09.088 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 03 00 00
2022-08-04 15:30:09.088 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 03 00 83
2022-08-04 15:30:09.088 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 19 00 00
2022-08-04 15:30:09.088 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 19 24 80
2022-08-04 15:30:09.089 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 01 01 0A 00
2022-08-04 15:30:09.089 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 05 01 0A 00
2022-08-04 15:30:09.090 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 00 02 00
2022-08-04 15:30:09.090 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 00 02 00
2022-08-04 15:30:09.091 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 11 00 00
2022-08-04 15:30:09.091 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 11 00 00
2022-08-04 15:30:09.091 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 09 00 00
2022-08-04 15:30:09.091 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 78 00 00
2022-08-04 15:30:09.091 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 78 71 1E
2022-08-04 15:30:09.093 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: A 04 09 00 00
2022-08-04 15:30:09.135 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:09.355 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value C
2022-08-04 15:30:09.909 DEBUG (MainThread) [pyotgw.protocol] Received line 28: T00050000
2022-08-04 15:30:09.910 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:09.910 DEBUG (MainThread) [pyotgw.protocol] Received line 29: R00740000
2022-08-04 15:30:09.910 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-08-04 15:30:09.910 DEBUG (MainThread) [pyotgw.protocol] Received line 30: BC074F955
2022-08-04 15:30:09.910 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 3
2022-08-04 15:30:09.911 DEBUG (MainThread) [pyotgw.protocol] Received line 31: AF0050000
2022-08-04 15:30:09.942 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 05 00 00
2022-08-04 15:30:09.943 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 74 00 00
2022-08-04 15:30:09.943 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 74 F9 55
2022-08-04 15:30:09.953 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:09.990 DEBUG (MainThread) [pyotgw.protocol] Received line 32: PR: C=4 MHz
2022-08-04 15:30:09.991 DEBUG (MainThread) [pyotgw.protocol] Submitting line 32 to CommandProcessor
2022-08-04 15:30:09.991 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:10.293 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:10.415 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Huiskamer' for opentherm_gw integration not ready yet: Could not connect to gateway at /dev/open-therm: ; Retrying in background
2022-08-04 15:30:10.418 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:10.779 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:10.919 DEBUG (MainThread) [pyotgw.protocol] Received line 33: T80190000
2022-08-04 15:30:10.919 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:10.919 DEBUG (MainThread) [pyotgw.protocol] Received line 34: BC0192480
2022-08-04 15:30:10.919 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-08-04 15:30:10.934 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 19 00 00
2022-08-04 15:30:10.934 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 19 24 80
2022-08-04 15:30:10.944 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:10.995 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:11.056 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:11.113 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:11.473 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:11.571 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:11.644 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:11.669 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:11.705 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:11.969 DEBUG (MainThread) [pyotgw.protocol] Received line 35: T10010A00
2022-08-04 15:30:11.969 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:11.969 DEBUG (MainThread) [pyotgw.protocol] Received line 36: BD0010A00
2022-08-04 15:30:11.969 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-08-04 15:30:11.973 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 01 01 0A 00
2022-08-04 15:30:11.973 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 05 01 0A 00
2022-08-04 15:30:11.974 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:11.992 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.006 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.007 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.031 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.033 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.034 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.034 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.037 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.037 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.038 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.038 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.038 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.039 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.039 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.039 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.040 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.211 DEBUG (MainThread) [pyotgw.status] Starting reporting routine
2022-08-04 15:30:12.291 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:12.311 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS: 0
2022-08-04 15:30:12.312 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:12.312 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.330 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-04 15:30:12.336 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:12.337 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value A
2022-08-04 15:30:12.381 DEBUG (MainThread) [pyotgw.protocol] Received line 2: PR: A=OpenTherm Gatay 4.2.5
2022-08-04 15:30:12.382 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:12.382 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.382 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: A=OpenTherm Gatay 4.2.5
2022-08-04 15:30:12.383 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.394 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value B
2022-08-04 15:30:12.450 DEBUG (MainThread) [pyotgw.protocol] Received line 3: PR: B=17:59 20-10-2015
2022-08-04 15:30:12.451 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:12.451 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.451 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: B=17:59 20-10-2015
2022-08-04 15:30:12.456 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.457 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value C
2022-08-04 15:30:12.479 DEBUG (MainThread) [pyotgw.protocol] Received line 4: PR: C=4 MHz
2022-08-04 15:30:12.479 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:30:12.480 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.480 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: C=4 MHz
2022-08-04 15:30:12.482 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.483 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value W
2022-08-04 15:30:12.506 DEBUG (MainThread) [pyotgw.protocol] Received line 5: PR: W=A
2022-08-04 15:30:12.506 DEBUG (MainThread) [pyotgw.protocol] Submitting line 5 to CommandProcessor
2022-08-04 15:30:12.507 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.510 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: W=A
2022-08-04 15:30:12.520 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.527 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value G
2022-08-04 15:30:12.555 DEBUG (MainThread) [pyotgw.protocol] Received line 6: PR: G=00
2022-08-04 15:30:12.555 DEBUG (MainThread) [pyotgw.protocol] Submitting line 6 to CommandProcessor
2022-08-04 15:30:12.556 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.557 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: G=00
2022-08-04 15:30:12.569 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.571 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value I
2022-08-04 15:30:12.639 DEBUG (MainThread) [pyotgw.protocol] Received line 7: PR: I=10
2022-08-04 15:30:12.639 DEBUG (MainThread) [pyotgw.protocol] Submitting line 7 to CommandProcessor
2022-08-04 15:30:12.639 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.646 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: I=10
2022-08-04 15:30:12.650 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.651 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value L
2022-08-04 15:30:12.673 DEBUG (MainThread) [pyotgw.protocol] Received line 8: PR: L=FXOMPC
2022-08-04 15:30:12.673 DEBUG (MainThread) [pyotgw.protocol] Submitting line 8 to CommandProcessor
2022-08-04 15:30:12.673 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.674 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: L=FXOMPC
2022-08-04 15:30:12.677 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.679 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value M
2022-08-04 15:30:12.696 DEBUG (MainThread) [pyotgw.protocol] Received line 9: PR: M=G
2022-08-04 15:30:12.696 DEBUG (MainThread) [pyotgw.protocol] Submitting line 9 to CommandProcessor
2022-08-04 15:30:12.697 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.697 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: M=G
2022-08-04 15:30:12.699 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.699 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value Q
2022-08-04 15:30:12.717 DEBUG (MainThread) [pyotgw.protocol] Received line 37: ew
2022-08-04 15:30:12.718 DEBUG (MainThread) [pyotgw.protocol] Submitting line 37 to CommandProcessor
2022-08-04 15:30:12.718 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:30:12.719 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.779 DEBUG (MainThread) [pyotgw.protocol] Received line 10: PR: Q=ST8000020
2022-08-04 15:30:12.779 DEBUG (MainThread) [pyotgw.protocol] Submitting line 10 to CommandProcessor
2022-08-04 15:30:12.779 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.780 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: Q=ST8000020
2022-08-04 15:30:12.781 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.782 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value S
2022-08-04 15:30:12.806 DEBUG (MainThread) [pyotgw.protocol] Received line 11: PR: S=17.00
2022-08-04 15:30:12.807 DEBUG (MainThread) [pyotgw.protocol] Submitting line 11 to CommandProcessor
2022-08-04 15:30:12.807 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.812 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: S=17.00
2022-08-04 15:30:12.813 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.814 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value O
2022-08-04 15:30:12.833 DEBUG (MainThread) [pyotgw.protocol] Received line 12: P:O=N
2022-08-04 15:30:12.834 DEBUG (MainThread) [pyotgw.protocol] Submitting line 12 to CommandProcessor
2022-08-04 15:30:12.834 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.845 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: P:O=N
2022-08-04 15:30:12.849 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P:O=N
2022-08-04 15:30:12.866 WARNING (MainThread) [pyotgw.commandprocessor] Command PR failed with P:O=N, retrying...
2022-08-04 15:30:12.882 DEBUG (MainThread) [pyotgw.protocol] Received line 13: B40000200
2022-08-04 15:30:12.883 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:12.884 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.885 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 00 02 00
2022-08-04 15:30:12.886 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.902 DEBUG (MainThread) [pyotgw.protocol] Received line 14: PR: O=N
2022-08-04 15:30:12.902 DEBUG (MainThread) [pyotgw.protocol] Submitting line 14 to CommandProcessor
2022-08-04 15:30:12.903 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.904 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: O=N
2022-08-04 15:30:12.906 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.907 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value P
2022-08-04 15:30:12.934 DEBUG (MainThread) [pyotgw.protocol] Received line 15: PR: P=Low power
2022-08-04 15:30:12.935 DEBUG (MainThread) [pyotgw.protocol] Submitting line 15 to CommandProcessor
2022-08-04 15:30:12.935 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.943 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: P=Low power
2022-08-04 15:30:12.945 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.945 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value R
2022-08-04 15:30:12.961 DEBUG (MainThread) [pyotgw.protocol] Received line 16: PR: R=D
2022-08-04 15:30:12.962 DEBUG (MainThread) [pyotgw.protocol] Submitting line 16 to CommandProcessor
2022-08-04 15:30:12.963 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:12.963 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: R=D
2022-08-04 15:30:12.966 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:12.967 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value T
2022-08-04 15:30:13.046 DEBUG (MainThread) [pyotgw.protocol] Received line 17: PR: T=11
2022-08-04 15:30:13.046 DEBUG (MainThread) [pyotgw.protocol] Submitting line 17 to CommandProcessor
2022-08-04 15:30:13.047 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:13.049 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: T=11
2022-08-04 15:30:13.083 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:13.084 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PR with value V
2022-08-04 15:30:13.128 DEBUG (MainThread) [pyotgw.protocol] Received line 18: PR: V=3
2022-08-04 15:30:13.138 DEBUG (MainThread) [pyotgw.protocol] Submitting line 18 to CommandProcessor
2022-08-04 15:30:13.138 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:13.145 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PR: PR: V=3
2022-08-04 15:30:13.164 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:13.175 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 1
2022-08-04 15:30:13.190 DEBUG (MainThread) [pyotgw.protocol] Received line 19: PS: 1
2022-08-04 15:30:13.191 DEBUG (MainThread) [pyotgw.protocol] Submitting line 19 to CommandProcessor
2022-08-04 15:30:13.191 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:13.192 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 1
2022-08-04 15:30:13.195 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:13.350 DEBUG (MainThread) [pyotgw.protocol] Received line 20: 000010000,00000000/00000000,100.0,15.036.50,0.00,0.0,0.00,0/0,0/0,0.00,0.00,63829,0,0,18037,28958,0,0,0
2022-08-04 15:30:13.350 DEBUG (MainThread) [pyotgw.protocol] Submitting line 20 to CommandProcessor
2022-08-04 15:30:13.351 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:13.527 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:13.540 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:13.541 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Huiskamer for opentherm_gw
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 357, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/__init__.py", line 115, in async_setup_entry
    await asyncio.wait_for(
  File "/usr/local/lib/python3.10/asyncio/tasks.py", line 445, in wait_for
    return fut.result()
  File "/usr/src/homeassistant/homeassistant/components/opentherm_gw/__init__.py", line 441, in connect_and_subscribe
    self.status = await self.gateway.connect(self.device_path)
  File "/usr/local/lib/python3.10/site-packages/pyotgw/pyotgw.py", line 51, in connect
    await self.get_status()
  File "/usr/local/lib/python3.10/site-packages/pyotgw/pyotgw.py", line 336, in get_status
    slave_status = device_status[1]
IndexError: list index out of range
2022-08-04 15:30:13.783 DEBUG (MainThread) [pyotgw.protocol] Received line 21: PS: 0
T00110000
2022-08-04 15:30:13.783 DEBUG (MainThread) [pyotgw.protocol] Submitting line 21 to CommandProcessor
2022-08-04 15:30:13.793 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:13.799 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
T00110000
2022-08-04 15:30:13.823 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:13.861 DEBUG (MainThread) [pyotgw.protocol] Received line 22: BC0110000
2022-08-04 15:30:13.862 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:13.863 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 11 00 00
2022-08-04 15:30:13.867 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:14.530 WARNING (MainThread) [aioesphomeapi.reconnect_logic] Can't connect to ESPHome API for zwembad @ 10.253.126.55: Error connecting to ('10.253.126.55', 6053): [Errno 113] Connect call failed ('10.253.126.55', 6053)
2022-08-04 15:30:14.767 DEBUG (MainThread) [pyotgw.protocol] Received line 23: T00090000
2022-08-04 15:30:14.768 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:14.783 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 09 00 00
2022-08-04 15:30:14.784 DEBUG (MainThread) [pyotgw.protocol] Received line 24: R070000
2022-08-04 15:30:14.784 DEBUG (MainThread) [pyotgw.protocol] Submitting line 24 to CommandProcessor
2022-08-04 15:30:14.785 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:14.824 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:14.834 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:14.860 DEBUG (MainThread) [pyotgw.protocol] Received line 25: BC0774675
2022-08-04 15:30:14.861 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:14.863 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 77 46 75
2022-08-04 15:30:14.884 DEBUG (MainThread) [pyotgw.protocol] Received line 26: AC009000
2022-08-04 15:30:14.885 DEBUG (MainThread) [pyotgw.protocol] Submitting line 26 to CommandProcessor
2022-08-04 15:30:14.885 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:30:14.888 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:14.889 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:15.725 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:15.726 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:15.727 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:15.728 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: PR: C=4 MHz
2022-08-04 15:30:15.741 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: ew
2022-08-04 15:30:15.817 DEBUG (MainThread) [pyotgw.protocol] Received line 27: T900E6400
2022-08-04 15:30:15.818 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:15.864 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 01 0E 64 00
2022-08-04 15:30:15.887 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:15.889 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:15.910 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS: 0
2022-08-04 15:30:15.911 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:15.912 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:15.912 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-04 15:30:15.914 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:17.602 DEBUG (MainThread) [pyotgw.protocol] Received line 2: T80190000
2022-08-04 15:30:17.603 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:17.604 DEBUG (MainThread) [pyotgw.protocol] Received line 3: BC0192480
2022-08-04 15:30:17.604 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-08-04 15:30:17.649 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 19 00 00
2022-08-04 15:30:17.650 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 19 24 80
2022-08-04 15:30:17.791 DEBUG (MainThread) [pyotgw.protocol] Received line 4: T10010A00
2022-08-04 15:30:17.792 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:17.838 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:17.841 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 01 01 0A 00
2022-08-04 15:30:17.852 DEBUG (MainThread) [pyotgw.protocol] Received line 5: BD0010A00
2022-08-04 15:30:17.853 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:17.868 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 05 01 0A 00
2022-08-04 15:30:17.870 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:17.873 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:17.881 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:18.757 DEBUG (MainThread) [pyotgw.protocol] Received line 6: T80000200
2022-08-04 15:30:18.758 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:18.759 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 00 02 00
2022-08-04 15:30:18.762 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:18.830 DEBUG (MainThread) [pyotgw.protocol] Received line 28: 000200
2022-08-04 15:30:18.831 DEBUG (MainThread) [pyotgw.protocol] Submitting line 28 to CommandProcessor
2022-08-04 15:30:18.832 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 3
2022-08-04 15:30:18.885 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:19.758 DEBUG (MainThread) [pyotgw.protocol] Received line 7: B40T00110000
2022-08-04 15:30:19.759 DEBUG (MainThread) [pyotgw.protocol] Submitting line 7 to CommandProcessor
2022-08-04 15:30:19.760 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:19.761 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:20.732 DEBUG (MainThread) [pyotgw.protocol] Received line 8: BC0110000
T00090000
2022-08-04 15:30:20.733 DEBUG (MainThread) [pyotgw.protocol] Submitting line 8 to CommandProcessor
2022-08-04 15:30:20.734 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:30:20.735 DEBUG (MainThread) [pyotgw.protocol] Received line 9: R00780000
2022-08-04 15:30:20.735 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:20.737 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 78 00 00
2022-08-04 15:30:20.738 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:20.739 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
8711E08-04 15:30:20.811 DEBUG (MainThread) [pyotgw.protocol] Received line 29: 
2022-08-04 15:30:20.812 DEBUG (MainThread) [pyotgw.protocol] Submitting line 29 to CommandProcessor
2022-08-04 15:30:20.812 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 4
2022-08-04 15:30:20.817 DEBUG (MainThread) [pyotgw.protocol] Received line 10: BC070000
2022-08-04 15:30:20.818 DEBUG (MainThread) [pyotgw.protocol] Submitting line 10 to CommandProcessor
2022-08-04 15:30:20.818 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 3
2022-08-04 15:30:20.820 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:20.821 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:21.714 DEBUG (MainThread) [pyotgw.protocol] Received line 11: T10100F00
2022-08-04 15:30:21.715 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:21.716 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 01 10 0F 00
2022-08-04 15:30:21.719 DEBUG (MainThread) [pyotgw.protocol] Received line 12: R007400
2022-08-04 15:30:21.720 DEBUG (MainThread) [pyotgw.protocol] Submitting line 12 to CommandProcessor
2022-08-04 15:30:21.720 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 4
2022-08-04 15:30:21.721 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:21.723 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:21.801 DEBUG (MainThread) [pyotgw.protocol] Received line 13: BC074F955
2022-08-04 15:30:21.802 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:21.804 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 74 F9 55
2022-08-04 15:30:21.809 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:21.810 DEBUG (MainThread) [pyotgw.protocol] Received line 14: AD00F00
2022-08-04 15:30:21.811 DEBUG (MainThread) [pyotgw.protocol] Submitting line 14 to CommandProcessor
2022-08-04 15:30:21.811 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 5
2022-08-04 15:30:21.820 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:22.706 DEBUG (MainThread) [pyotgw.protocol] Received line 30: AC0090010000
2022-08-04 15:30:22.707 DEBUG (MainThread) [pyotgw.protocol] Submitting line 30 to CommandProcessor
2022-08-04 15:30:22.708 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 5
2022-08-04 15:30:22.711 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:22.802 DEBUG (MainThread) [pyotgw.protocol] Received line 31: 2480
2022-08-04 15:30:22.803 DEBUG (MainThread) [pyotgw.protocol] Submitting line 31 to CommandProcessor
2022-08-04 15:30:22.804 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 6
2022-08-04 15:30:22.805 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:23.495 ERROR (SyncWorker_3) [homeassistant.components.dhcp] Cannot watch for dhcp packets: [Errno 1] Operation not permitted
2022-08-04 15:30:23.691 DEBUG (MainThread) [pyotgw.protocol] Received line 15: T80190BC019T00100
2022-08-04 15:30:23.692 DEBUG (MainThread) [pyotgw.protocol] Submitting line 15 to CommandProcessor
2022-08-04 15:30:23.692 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 6
2022-08-04 15:30:23.697 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:23.780 DEBUG (MainThread) [pyotgw.protocol] Received line 16: BD0000
2022-08-04 15:30:23.780 DEBUG (MainThread) [pyotgw.protocol] Submitting line 16 to CommandProcessor
2022-08-04 15:30:23.781 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 7
2022-08-04 15:30:23.782 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:24.682 DEBUG (MainThread) [pyotgw.protocol] Received line 17: T8000200
2022-08-04 15:30:24.683 DEBUG (MainThread) [pyotgw.protocol] Submitting line 17 to CommandProcessor
2022-08-04 15:30:24.683 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 8
2022-08-04 15:30:24.687 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:25.675 DEBUG (MainThread) [pyotgw.protocol] Received line 18: B4000200
T0110000
2022-08-04 15:30:25.676 DEBUG (MainThread) [pyotgw.protocol] Submitting line 18 to CommandProcessor
2022-08-04 15:30:25.676 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 9
2022-08-04 15:30:25.679 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:25.763 DEBUG (MainThread) [pyotgw.protocol] Received line 19: BC01000
2022-08-04 15:30:25.763 DEBUG (MainThread) [pyotgw.protocol] Submitting line 19 to CommandProcessor
2022-08-04 15:30:25.764 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 10
2022-08-04 15:30:25.767 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:25.808 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:25.808 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:25.809 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:25.813 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: R070000
2022-08-04 15:30:25.813 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: AC009000
2022-08-04 15:30:25.813 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 000200
8711E08-04 15:30:25.814 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 
2022-08-04 15:30:25.814 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: AC0090010000
2022-08-04 15:30:25.814 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 2480
2022-08-04 15:30:25.832 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:25.848 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS: 0
2022-08-04 15:30:25.849 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:25.850 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:25.850 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-04 15:30:25.852 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:26.755 DEBUG (MainThread) [pyotgw.protocol] Received line 2: T0900
B0765
2022-08-04 15:30:26.756 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:26.756 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:26.758 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:26.766 DEBUG (MainThread) [pyotgw.protocol] Received line 3: 009000
2022-08-04 15:30:26.767 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:26.768 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:30:26.769 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:27.658 DEBUG (MainThread) [pyotgw.protocol] Received line 4: T108187
2022-08-04 15:30:27.658 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:30:27.659 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 3
2022-08-04 15:30:27.661 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:27.669 DEBUG (MainThread) [pyotgw.protocol] Received line 5: 078000
2022-08-04 15:30:27.670 DEBUG (MainThread) [pyotgw.protocol] Submitting line 5 to CommandProcessor
2022-08-04 15:30:27.671 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 4
2022-08-04 15:30:27.672 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:28.770 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:28.771 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:28.772 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:28.774 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: B40T00110000
2022-08-04 15:30:28.774 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: BC0110000
T00090000
2022-08-04 15:30:28.775 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: BC070000
2022-08-04 15:30:28.775 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: R007400
2022-08-04 15:30:28.775 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: AD00F00
2022-08-04 15:30:28.776 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T80190BC019T00100
2022-08-04 15:30:28.776 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: BD0000
2022-08-04 15:30:28.777 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T8000200
2022-08-04 15:30:28.777 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: B4000200
T0110000
2022-08-04 15:30:28.778 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: BC01000
2022-08-04 15:30:28.790 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:28.804 DEBUG (MainThread) [pyotgw.protocol] Received line 6: B081E
BC01280
2022-08-04 15:30:28.805 DEBUG (MainThread) [pyotgw.protocol] Submitting line 6 to CommandProcessor
2022-08-04 15:30:28.806 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 5
2022-08-04 15:30:28.807 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
T1010A0-04 15:30:29.729 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS: 0
B010A00
2022-08-04 15:30:29.730 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:29.731 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
T1010A0-04 15:30:29.732 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
B010A00
2022-08-04 15:30:29.737 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:30.632 DEBUG (MainThread) [pyotgw.protocol] Received line 2: T80000
2022-08-04 15:30:30.633 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:30.633 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:30.635 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:30.721 DEBUG (MainThread) [pyotgw.protocol] Received line 3: B400020
2022-08-04 15:30:30.721 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:30.722 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:30:30.723 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:31.809 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:31.809 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:31.810 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:31.812 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T0900
B0765
2022-08-04 15:30:31.812 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 009000
2022-08-04 15:30:31.813 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T108187
2022-08-04 15:30:31.813 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 078000
2022-08-04 15:30:31.814 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: B081E
BC01280
2022-08-04 15:30:31.824 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:31.838 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS: 0
2022-08-04 15:30:31.839 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:31.840 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:31.841 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-04 15:30:31.845 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:32.615 DEBUG (MainThread) [pyotgw.protocol] Received line 2: T0090000
2022-08-04 15:30:32.616 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:32.617 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:32.625 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:32.626 DEBUG (MainThread) [pyotgw.protocol] Received line 3: 0740000
2022-08-04 15:30:32.627 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:32.628 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:30:32.629 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:32.705 DEBUG (MainThread) [pyotgw.protocol] Received line 4: BC04F95
2022-08-04 15:30:32.706 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:30:32.706 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 3
2022-08-04 15:30:32.713 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:32.717 DEBUG (MainThread) [pyotgw.protocol] Received line 5: 009000
2022-08-04 15:30:32.718 DEBUG (MainThread) [pyotgw.protocol] Submitting line 5 to CommandProcessor
2022-08-04 15:30:32.719 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 4
2022-08-04 15:30:32.720 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:33.696 DEBUG (MainThread) [pyotgw.protocol] Received line 6: T0100
B01000
2022-08-04 15:30:33.697 DEBUG (MainThread) [pyotgw.protocol] Submitting line 6 to CommandProcessor
2022-08-04 15:30:33.697 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 5
2022-08-04 15:30:33.703 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:33.725 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:33.726 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:33.727 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:33.728 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T80000
2022-08-04 15:30:33.729 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: B400020
2022-08-04 15:30:33.743 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
T090008-04 15:30:34.688 DEBUG (MainThread) [pyotgw.protocol] Received line 1: P: 
B0940
2022-08-04 15:30:34.688 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:34.689 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
T090008-04 15:30:34.691 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P: 
B0940
T090008-04 15:30:34.692 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P: 
B0940
T090008-04 15:30:34.703 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P: 
B0940, retrying...
2022-08-04 15:30:36.580 DEBUG (MainThread) [pyotgw.protocol] Received line 2: P:0
T10010A00
BD0010A0
T0000200
2022-08-04 15:30:36.581 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:36.581 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:36.582 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P:0
T10010A00
BD0010A0
T0000200
2022-08-04 15:30:36.583 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P:0
T10010A00
BD0010A0
T0000200
2022-08-04 15:30:36.593 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P:0
T10010A00
BD0010A0
T0000200, retrying...
2022-08-04 15:30:36.612 DEBUG (MainThread) [pyotgw.protocol] Received line 3: PS: 0
2022-08-04 15:30:36.613 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:36.613 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:36.614 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-04 15:30:36.617 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:36.669 DEBUG (MainThread) [pyotgw.protocol] Received line 4: B40000200
2022-08-04 15:30:36.670 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:36.671 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 00 02 00
2022-08-04 15:30:36.673 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:36.706 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:36.707 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:36.708 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:36.709 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T0090000
2022-08-04 15:30:36.710 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 0740000
2022-08-04 15:30:36.710 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: BC04F95
2022-08-04 15:30:36.711 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 009000
2022-08-04 15:30:36.711 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T0100
B01000
2022-08-04 15:30:36.722 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:36.736 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS: 
2022-08-04 15:30:36.737 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:36.738 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:36.739 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 
2022-08-04 15:30:36.746 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:37.572 DEBUG (MainThread) [pyotgw.protocol] Received line 2: T010000
2022-08-04 15:30:37.572 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:37.573 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:37.579 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:38.575 DEBUG (MainThread) [pyotgw.protocol] Received line 3: B01000
T0900
07000
2022-08-04 15:30:38.575 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:38.576 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:30:38.577 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:39.644 DEBUG (MainThread) [pyotgw.protocol] Received line 4: B07465
T021D
BD0201D
2022-08-04 15:30:39.645 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:30:39.645 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 3
2022-08-04 15:30:39.647 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:39.676 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:39.676 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:39.677 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:39.688 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
T090000-04 15:30:40.547 DEBUG (MainThread) [pyotgw.protocol] Received line 1: P: 0
2022-08-04 15:30:40.548 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:40.549 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
T090000-04 15:30:40.551 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P: 0
T090000-04 15:30:40.551 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P: 0
T090000, retrying...556 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P: 0
2022-08-04 15:30:40.580 DEBUG (MainThread) [pyotgw.protocol] Received line 2: P:0
2022-08-04 15:30:40.581 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:40.581 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:40.583 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P:0
2022-08-04 15:30:40.584 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P:0
2022-08-04 15:30:40.590 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P:0, retrying...
2022-08-04 15:30:40.636 DEBUG (MainThread) [pyotgw.protocol] Received line 3: PS:0
B0192480
2022-08-04 15:30:40.637 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:40.637 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:40.639 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS:0
B0192480
2022-08-04 15:30:40.641 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
B010A00-04 15:30:41.629 DEBUG (MainThread) [pyotgw.protocol] Received line 4: T100100
2022-08-04 15:30:41.630 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:30:41.630 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:41.633 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:42.532 DEBUG (MainThread) [pyotgw.protocol] Received line 5: T8000020
2022-08-04 15:30:42.533 DEBUG (MainThread) [pyotgw.protocol] Submitting line 5 to CommandProcessor
2022-08-04 15:30:42.534 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:30:42.535 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:42.650 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:42.650 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:42.651 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:42.653 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T010000
2022-08-04 15:30:42.653 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: B01000
T0900
07000
2022-08-04 15:30:42.654 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: B07465
T021D
BD0201D
2022-08-04 15:30:42.712 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:42.737 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS: 0
2022-08-04 15:30:42.738 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:42.739 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:42.740 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-04 15:30:42.741 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:43.525 DEBUG (MainThread) [pyotgw.protocol] Received line 2: T00110000
2022-08-04 15:30:43.526 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:43.527 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 11 00 00
2022-08-04 15:30:43.528 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:43.613 DEBUG (MainThread) [pyotgw.protocol] Received line 3: BC0110000
2022-08-04 15:30:43.614 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:43.615 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 11 00 00
2022-08-04 15:30:43.617 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:44.516 DEBUG (MainThread) [pyotgw.protocol] Received line 4: T090000
2022-08-04 15:30:44.516 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:30:44.517 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:44.519 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:45.506 DEBUG (MainThread) [pyotgw.protocol] Received line 5: 070000
B081E
T00030000
2022-08-04 15:30:45.507 DEBUG (MainThread) [pyotgw.protocol] Submitting line 5 to CommandProcessor
2022-08-04 15:30:45.508 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:30:45.511 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:45.538 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:45.538 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:45.539 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
B010A00-04 15:30:45.541 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T100100
2022-08-04 15:30:45.541 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T8000020
2022-08-04 15:30:45.556 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:45.596 DEBUG (MainThread) [pyotgw.protocol] Received line 1: P:0
B03083
2022-08-04 15:30:45.597 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:45.597 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:45.599 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P:0
B03083
2022-08-04 15:30:45.600 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P:0
B03083
2022-08-04 15:30:45.606 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P:0
B03083, retrying...
2022-08-04 15:30:46.498 DEBUG (MainThread) [pyotgw.protocol] Received line 2: P:0
T809000
2022-08-04 15:30:46.499 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:46.499 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:46.500 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P:0
T809000
2022-08-04 15:30:46.501 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P:0
T809000
2022-08-04 15:30:46.512 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P:0
T809000, retrying...
2022-08-04 15:30:46.532 DEBUG (MainThread) [pyotgw.protocol] Received line 3: PS 0
2022-08-04 15:30:46.533 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:46.533 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:46.534 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS 0
2022-08-04 15:30:46.535 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: PS 0
2022-08-04 15:30:46.546 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with PS 0, retrying...
2022-08-04 15:30:46.587 DEBUG (MainThread) [pyotgw.protocol] Received line 4: PS:0
BC092480
2022-08-04 15:30:46.588 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:30:46.588 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:46.589 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS:0
BC092480
2022-08-04 15:30:46.590 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:48.481 DEBUG (MainThread) [pyotgw.protocol] Received line 5: T1001A00
BD010A0
T80000200
2022-08-04 15:30:48.482 DEBUG (MainThread) [pyotgw.protocol] Submitting line 5 to CommandProcessor
2022-08-04 15:30:48.483 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:48.484 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:48.513 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:48.514 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:48.514 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:48.516 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T090000
2022-08-04 15:30:48.516 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 070000
B081E
T00030000
2022-08-04 15:30:48.530 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:48.544 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS:0
2022-08-04 15:30:48.545 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:48.546 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:48.550 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS:0
2022-08-04 15:30:48.551 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:49.473 DEBUG (MainThread) [pyotgw.protocol] Received line 2: B0020
T0110000
2022-08-04 15:30:49.473 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:49.474 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:49.480 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:50.465 DEBUG (MainThread) [pyotgw.protocol] Received line 3: BC0110000
T090000
2022-08-04 15:30:50.466 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:50.466 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:30:50.473 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:50.477 DEBUG (MainThread) [pyotgw.protocol] Received line 4: 0740000
2022-08-04 15:30:50.478 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:30:50.479 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 3
2022-08-04 15:30:50.482 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:50.554 DEBUG (MainThread) [pyotgw.protocol] Received line 5: BC074F955
2022-08-04 15:30:50.555 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:50.558 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 74 F9 55
2022-08-04 15:30:50.563 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:51.468 DEBUG (MainThread) [pyotgw.protocol] Received line 6: 0090000
R00770000
2022-08-04 15:30:51.468 DEBUG (MainThread) [pyotgw.protocol] Submitting line 6 to CommandProcessor
2022-08-04 15:30:51.469 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 4
2022-08-04 15:30:51.470 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:51.486 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:51.487 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:51.487 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:51.494 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T1001A00
BD010A0
T80000200
2022-08-04 15:30:51.503 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:51.518 DEBUG (MainThread) [pyotgw.protocol] Received line 1: P: 0
2022-08-04 15:30:51.519 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:51.519 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:51.525 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P: 0
2022-08-04 15:30:51.526 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P: 0
2022-08-04 15:30:51.532 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P: 0, retrying...
2022-08-04 15:30:51.564 DEBUG (MainThread) [pyotgw.protocol] Received line 2: BC0774675
PS 000
2022-08-04 15:30:51.565 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:51.565 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:51.566 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: BC0774675
PS 000
2022-08-04 15:30:51.567 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: BC0774675
PS 000
2022-08-04 15:30:51.577 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with BC0774675
PS , retrying...
2022-08-04 15:30:51.597 DEBUG (MainThread) [pyotgw.protocol] Received line 3: PS: 0
2022-08-04 15:30:51.597 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:51.598 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:51.602 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-04 15:30:51.603 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:52.448 DEBUG (MainThread) [pyotgw.protocol] Received line 4: T09000
2022-08-04 15:30:52.449 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:30:52.450 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:52.454 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:54.473 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:54.474 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:54.474 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:54.476 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: B0020
T0110000
2022-08-04 15:30:54.476 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: BC0110000
T090000
2022-08-04 15:30:54.477 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 0740000
2022-08-04 15:30:54.477 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 0090000
R00770000
2022-08-04 15:30:54.492 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:54.521 DEBUG (MainThread) [pyotgw.protocol] Received line 1: P:0
B4000200
2022-08-04 15:30:54.522 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:54.522 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:54.523 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P:0
B4000200
2022-08-04 15:30:54.524 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P:0
B4000200
2022-08-04 15:30:54.534 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P:0
B4000200, retrying...
2022-08-04 15:30:54.554 DEBUG (MainThread) [pyotgw.protocol] Received line 2: PS: 0
2022-08-04 15:30:54.555 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:54.555 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:54.560 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-04 15:30:54.561 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:55.457 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:55.457 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:55.458 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:55.459 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T09000
2022-08-04 15:30:55.471 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:56.428 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS: 0
B01000
R08000
2022-08-04 15:30:56.429 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:56.429 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:56.430 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
B01000
R08000
2022-08-04 15:30:56.433 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:57.563 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:57.564 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:57.565 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:57.576 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:57.592 DEBUG (MainThread) [pyotgw.protocol] Received line 1: P:0
2022-08-04 15:30:57.593 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:57.593 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:57.594 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P:0
2022-08-04 15:30:57.595 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P:0
2022-08-04 15:30:57.605 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P:0, retrying...
2022-08-04 15:30:58.401 DEBUG (MainThread) [pyotgw.protocol] Received line 2: P:0
T0190000
2022-08-04 15:30:58.402 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:30:58.403 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:58.404 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P:0
T0190000
2022-08-04 15:30:58.404 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P:0
T0190000
2022-08-04 15:30:58.415 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P:0
T0190000, retrying...
2022-08-04 15:30:58.434 DEBUG (MainThread) [pyotgw.protocol] Received line 3: P: 0
2022-08-04 15:30:58.435 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:30:58.435 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:58.436 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P: 0
2022-08-04 15:30:58.437 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P: 0
2022-08-04 15:30:58.447 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P: 0, retrying...
2022-08-04 15:30:58.466 DEBUG (MainThread) [pyotgw.protocol] Received line 4: P: 0
2022-08-04 15:30:58.467 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:30:58.468 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:58.473 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P: 0
2022-08-04 15:30:58.474 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P: 0
2022-08-04 15:30:58.480 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P: 0, retrying...
2022-08-04 15:30:58.490 DEBUG (MainThread) [pyotgw.protocol] Received line 5: BC019240
2022-08-04 15:30:58.491 DEBUG (MainThread) [pyotgw.protocol] Submitting line 5 to CommandProcessor
2022-08-04 15:30:58.492 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:58.492 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: BC019240
2022-08-04 15:30:58.493 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: BC019240
2022-08-04 15:30:58.501 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with BC019240, retrying...
2022-08-04 15:30:58.509 DEBUG (MainThread) [pyotgw.protocol] Received line 6: PS: 0
2022-08-04 15:30:58.510 DEBUG (MainThread) [pyotgw.protocol] Submitting line 6 to CommandProcessor
2022-08-04 15:30:58.510 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:58.512 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-04 15:30:58.516 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:30:58.525 DEBUG (MainThread) [pyotgw.protocol] Received line 7: PS:0
2022-08-04 15:30:58.526 DEBUG (MainThread) [pyotgw.protocol] Submitting line 7 to CommandProcessor
2022-08-04 15:30:58.526 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:58.527 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:59.393 DEBUG (MainThread) [pyotgw.protocol] Received line 8: T1010A00
2022-08-04 15:30:59.394 DEBUG (MainThread) [pyotgw.protocol] Submitting line 8 to CommandProcessor
2022-08-04 15:30:59.394 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:30:59.397 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:30:59.436 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:30:59.436 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:30:59.437 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:30:59.448 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:30:59.464 DEBUG (MainThread) [pyotgw.protocol] Received line 1: P:0
2022-08-04 15:30:59.465 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:30:59.466 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:30:59.468 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P:0
2022-08-04 15:30:59.468 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P:0
2022-08-04 15:30:59.478 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P:0, retrying...
2022-08-04 15:30:59.484 DEBUG (MainThread) [pyotgw.protocol] Received line 2: BD0010A00
2022-08-04 15:30:59.485 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:30:59.486 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 05 01 0A 00
2022-08-04 15:31:02.378 DEBUG (MainThread) [pyotgw.protocol] Received line 3: P: 0
T00200
B00200
T0100
B0100
T090000
007400
2022-08-04 15:31:02.378 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:31:02.379 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:31:02.380 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P: 0
T00200
B00200
T0100
B0100
T090000
007400
2022-08-04 15:31:02.380 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P: 0
T00200
B00200
T0100
B0100
T090000
007400
2022-08-04 15:31:02.391 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P: 0
T00200
B00200
T0100
B0100
T090000
007400, retrying...
2022-08-04 15:31:02.399 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:31:02.399 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:31:02.400 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:31:02.402 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: PS:0
2022-08-04 15:31:02.402 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T1010A00
2022-08-04 15:31:02.415 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:31:02.456 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS: 0
B04F955
2022-08-04 15:31:02.457 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:31:02.458 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:31:02.459 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
B04F955
2022-08-04 15:31:02.466 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:31:02.470 DEBUG (MainThread) [pyotgw.protocol] Received line 2: 090000
2022-08-04 15:31:02.471 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:31:02.472 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:31:02.473 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:03.448 DEBUG (MainThread) [pyotgw.protocol] Received line 3: T000F0
BC0774675
2022-08-04 15:31:03.449 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:31:03.450 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:31:03.451 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:03.460 DEBUG (MainThread) [pyotgw.protocol] Received line 4: 000F00
2022-08-04 15:31:03.460 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:31:03.461 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 3
2022-08-04 15:31:03.462 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:04.449 ERROR (MainThread) [pyotgw.connection] The serial device on /dev/open-therm is not responding. Will keep trying.
2022-08-04 15:31:05.342 DEBUG (MainThread) [pyotgw.protocol] Received line 5: T0900
B0940
T10010A00
2022-08-04 15:31:05.343 DEBUG (MainThread) [pyotgw.protocol] Submitting line 5 to CommandProcessor
2022-08-04 15:31:05.343 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 4
2022-08-04 15:31:05.345 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:05.431 DEBUG (MainThread) [pyotgw.protocol] Received line 6: BD0010A00
2022-08-04 15:31:05.432 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:31:05.433 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 05 01 0A 00
2022-08-04 15:31:05.435 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:06.333 DEBUG (MainThread) [pyotgw.protocol] Received line 7: T80000200
2022-08-04 15:31:06.334 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:31:06.335 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 00 02 00
2022-08-04 15:31:06.338 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:06.422 DEBUG (MainThread) [pyotgw.protocol] Received line 8: B40000200
2022-08-04 15:31:06.423 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:31:06.424 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 00 02 00
2022-08-04 15:31:06.427 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:07.334 DEBUG (MainThread) [pyotgw.protocol] Received line 9: T00110000
2022-08-04 15:31:07.335 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:31:07.336 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 11 00 00
2022-08-04 15:31:07.337 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:07.413 DEBUG (MainThread) [pyotgw.protocol] Received line 10: BC0110000
2022-08-04 15:31:07.414 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:31:07.415 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 11 00 00
2022-08-04 15:31:07.418 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:08.331 DEBUG (MainThread) [pyotgw.protocol] Received line 11: T00090000
2022-08-04 15:31:08.332 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:31:08.333 DEBUG (MainThread) [pyotgw.protocol] Received line 12: R00780000
2022-08-04 15:31:08.333 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-08-04 15:31:08.334 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 00 09 00 00
2022-08-04 15:31:08.335 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 78 00 00
2022-08-04 15:31:08.336 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:08.339 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:08.404 DEBUG (MainThread) [pyotgw.protocol] Received line 13: BC078711E
2022-08-04 15:31:08.405 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:31:08.406 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 78 71 1E
2022-08-04 15:31:08.410 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:08.417 DEBUG (MainThread) [pyotgw.protocol] Received line 14: AC0090000
2022-08-04 15:31:08.418 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:31:08.419 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: A 04 09 00 00
2022-08-04 15:31:08.420 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:09.329 DEBUG (MainThread) [pyotgw.protocol] Received line 15: T101818C7
2022-08-04 15:31:09.330 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:31:09.330 DEBUG (MainThread) [pyotgw.protocol] Received line 16: R00740000
2022-08-04 15:31:09.331 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 2
2022-08-04 15:31:09.332 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: T 01 18 18 C7
2022-08-04 15:31:09.334 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: R 00 74 00 00
2022-08-04 15:31:09.336 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:09.337 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:09.398 DEBUG (MainThread) [pyotgw.protocol] Received line 17: BC074F955
2022-08-04 15:31:09.398 DEBUG (MainThread) [pyotgw.messageprocessor] Added line to message queue. Queue size: 1
2022-08-04 15:31:09.399 DEBUG (MainThread) [pyotgw.messageprocessor] Processing: B 04 74 F9 55
2022-08-04 15:31:09.403 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:09.409 DEBUG (MainThread) [pyotgw.protocol] Received line 18: A701818C7
2022-08-04 15:31:09.411 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:09.463 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:31:10.405 DEBUG (MainThread) [pyotgw.protocol] Received line 1: P:0
BC0192480
2022-08-04 15:31:10.406 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:31:10.406 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:31:10.407 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P:0
BC0192480
2022-08-04 15:31:10.408 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P:0
BC0192480
2022-08-04 15:31:10.417 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P:0
BC0192480, retrying...
2022-08-04 15:31:11.290 DEBUG (MainThread) [pyotgw.protocol] Received line 2: P:0
T010A00
2022-08-04 15:31:11.291 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:31:11.291 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:31:11.294 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P:0
T010A00
2022-08-04 15:31:11.294 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P:0
T010A00
2022-08-04 15:31:11.299 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P:0
T010A00, retrying...
2022-08-04 15:31:11.348 DEBUG (MainThread) [pyotgw.protocol] Received line 3: P: 0
2022-08-04 15:31:11.349 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:31:11.350 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:31:11.352 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: P: 0
2022-08-04 15:31:11.352 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: P: 0
2022-08-04 15:31:11.359 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with P: 0, retrying...
PS: 008-04 15:31:11.386 DEBUG (MainThread) [pyotgw.protocol] Received line 4: B00100
2022-08-04 15:31:11.387 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:31:11.387 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
PS: 008-04 15:31:11.389 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: B00100
PS: 008-04 15:31:11.390 WARNING (MainThread) [pyotgw.commandprocessor] Unknown message in command queue: B00100
PS: 0, retrying...1.396 WARNING (MainThread) [pyotgw.commandprocessor] Command PS failed with B00100
2022-08-04 15:31:11.419 DEBUG (MainThread) [pyotgw.protocol] Received line 5: PS: 
2022-08-04 15:31:11.420 DEBUG (MainThread) [pyotgw.protocol] Submitting line 5 to CommandProcessor
2022-08-04 15:31:11.420 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:31:11.421 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 
2022-08-04 15:31:11.423 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
2022-08-04 15:31:12.281 DEBUG (MainThread) [pyotgw.protocol] Received line 6: T00200
2022-08-04 15:31:12.282 DEBUG (MainThread) [pyotgw.protocol] Submitting line 6 to CommandProcessor
2022-08-04 15:31:12.283 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:31:12.284 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:12.376 DEBUG (MainThread) [pyotgw.protocol] Received line 7: B4000200
2022-08-04 15:31:12.377 DEBUG (MainThread) [pyotgw.protocol] Submitting line 7 to CommandProcessor
2022-08-04 15:31:12.378 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:31:12.379 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:12.418 DEBUG (MainThread) [pyotgw.connection] Watchdog triggered!
2022-08-04 15:31:12.419 DEBUG (MainThread) [pyotgw.connection] Canceling Watchdog task.
2022-08-04 15:31:12.420 DEBUG (MainThread) [pyotgw.connection] Scheduling reconnect...
2022-08-04 15:31:12.421 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 090000
2022-08-04 15:31:12.422 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T000F0
BC0774675
2022-08-04 15:31:12.422 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: 000F00
2022-08-04 15:31:12.423 DEBUG (MainThread) [pyotgw.commandprocessor] Clearing leftover message from command queue: T0900
B0940
T10010A00
2022-08-04 15:31:12.461 DEBUG (MainThread) [pyotgw.commandprocessor] Sending command: PS with value 0
2022-08-04 15:31:12.476 DEBUG (MainThread) [pyotgw.protocol] Received line 1: PS: 0
2022-08-04 15:31:12.477 DEBUG (MainThread) [pyotgw.protocol] Submitting line 1 to CommandProcessor
2022-08-04 15:31:12.477 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:31:12.478 DEBUG (MainThread) [pyotgw.commandprocessor] Got possible response for command PS: PS: 0
2022-08-04 15:31:12.480 DEBUG (MainThread) [pyotgw.connection] Connected to serial device on /dev/open-therm
B010000-04 15:31:13.361 DEBUG (MainThread) [pyotgw.protocol] Received line 2: T01000
2022-08-04 15:31:13.362 DEBUG (MainThread) [pyotgw.protocol] Submitting line 2 to CommandProcessor
2022-08-04 15:31:13.362 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 1
2022-08-04 15:31:13.364 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:14.276 DEBUG (MainThread) [pyotgw.protocol] Received line 3: T0000
R0700
2022-08-04 15:31:14.277 DEBUG (MainThread) [pyotgw.protocol] Submitting line 3 to CommandProcessor
2022-08-04 15:31:14.278 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 2
2022-08-04 15:31:14.280 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:14.354 DEBUG (MainThread) [pyotgw.protocol] Received line 4: B077465
2022-08-04 15:31:14.355 DEBUG (MainThread) [pyotgw.protocol] Submitting line 4 to CommandProcessor
2022-08-04 15:31:14.356 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 3
2022-08-04 15:31:14.357 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
2022-08-04 15:31:14.366 DEBUG (MainThread) [pyotgw.protocol] Received line 5: 090000
2022-08-04 15:31:14.367 DEBUG (MainThread) [pyotgw.protocol] Submitting line 5 to CommandProcessor
2022-08-04 15:31:14.367 DEBUG (MainThread) [pyotgw.commandprocessor] Response submitted. Queue size: 4
2022-08-04 15:31:14.369 DEBUG (MainThread) [pyotgw.connection] Watchdog timer reset!
mvn23 commented 2 years ago

In the beginning between 15:30:01.669 and 15:30:08.914 something seems to tie up Home Assistant startup for quite some time. This triggers the config entry not ready warning at 15:30:10.415 as initialization does not complete within 10 seconds (maybe we should increase this timeout). However, it does recover from this on the second attempt.

For the rest of the log, I see a lot of mangled messages similar to what @khenderick had earlier on. Both OpenTherm protocol messages and command responses seem to be affected. You'll have to get that sorted out before we can look at a possible software issue.

johansmitsnl commented 2 years ago

I can confirm that the hardware responds correctly on with HA turned off connecting with screen.

Here the output of the commands:

mvn23 commented 2 years ago

Ok, but a sample size of 3 commands is not really a reliable way to determine proper functionality. We're seeing in the logs that the data is not received properly. This means that things go awry anywhere between the serial interface of the gateway sending the data and pyotgw processing it.

There are only about 15 lines of code dealing with the received data in pyotgw before the messages are being logged. These lines seem to work fine, even in your logs most messages have no issues. Therefore, I am inclined to suspect another part in the chain causing problems.

The fact that startup seems to block for about 7 seconds may be something worth investigating. Which hardware are you using to run Home Assistant? Does it show high CPU usage when running Home Assistant? Was Home Assistant running (with the integration disabled) when you tested the commands? What happens when you leave screen open for a while to just see the protocol messages?

johansmitsnl commented 2 years ago

It runs on a celeron CPU but the disk I/O is not very fast (although it is a ssd), the load is low almost idle (load average: 0.03, 0.07, 0.08). The HA instance has quite some integrations. The startup time is always like this. Since I have nothing to compare it seems like normal.

When I have screen open I get the protocol messages normally. Here some of them:

BD0010A00
T80000200
B40000200
T00110000
BC0110000
T00090000
R00770000
BC0774675
AC0090000
T901818E1
R00780000
BC078711E
AF01818E1
T80190000
BC01923CC
T10010A00
BD0010A00
T80000200
B40000200
T00110000
BC0110000
T00090000
mvn23 commented 2 years ago

I may have found the problem, but I'm not able to reproduce the mangled messages on my networked setup. Can you try adding the following line to homeassistant/components/opentherm_gw/__init__.py?

--- a/homeassistant/components/opentherm_gw/__init__.py
+++ b/homeassistant/components/opentherm_gw/__init__.py
@@ -117,6 +117,7 @@ async def async_setup_entry(hass: HomeAssistant, config_entry: ConfigEntry) -> b
             timeout=CONNECTION_TIMEOUT,
         )
     except (asyncio.TimeoutError, ConnectionError, SerialException) as ex:
+        await gateway.cleanup()
         raise ConfigEntryNotReady(
             f"Could not connect to gateway at {gateway.device_path}: {ex}"
         ) from ex
johansmitsnl commented 2 years ago

@mvn23 this patch works for me.

ewf75 commented 2 years ago

@mvn23 first I updated the firmware to 5.4 and updated to HA 2022.8.1. I could make a connection after two times. But then the connection was lost and the room setting temperature wasn't updated.

After using the correct SSH addon I could find the file and updated to code as described above. Now the room setting temperature is updated in HA when I changed it on the thermostat. :-)

Now is one thing not working, what I use, that's setting the outside temperature. Calling the service from HA gives a green button for success, but nothing is showed on the thermostat (the outside temperature was shown till HA 2022.6.7). There is no log entry ... so I have yet no more information about that. But it must probably reported in another bug if I have more info.

johansmitsnl commented 2 years ago

@balloob I have not seen this fix in the latest releases. Can you tell when this fix will be included?

paulvt commented 2 years ago

Also, I had to update the firmware of the Opentherm Gateway from 4.2 to 5.4 to make this all work. This might be worth a mention somewhere!

With the old firmware, I got:

Aug 23 09:31:42 void docker-compose[316023]: home-assistant_1  | 2022-08-23 09:31:42.946 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Thermostat for opentherm_gw
...
Aug 23 09:31:42 void docker-compose[316023]: home-assistant_1  |   File "/usr/local/lib/python3.10/site-packages/pyotgw/pyotgw.py", line 217, in get_reports
Aug 23 09:31:42 void docker-compose[316023]: home-assistant_1  |     v.OTGW_LED_F: led_funcs[5],
Aug 23 09:31:42 void docker-compose[316023]: home-assistant_1  | IndexError: string index out of range
mvn23 commented 2 years ago

Also, I had to update the firmware of the Opentherm Gateway from 4.2 to 5.4 to make this all work. This might be worth a mention somewhere!

With the old firmware, I got:

Aug 23 09:31:42 void docker-compose[316023]: home-assistant_1  | 2022-08-23 09:31:42.946 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Thermostat for opentherm_gw
...
Aug 23 09:31:42 void docker-compose[316023]: home-assistant_1  |   File "/usr/local/lib/python3.10/site-packages/pyotgw/pyotgw.py", line 217, in get_reports
Aug 23 09:31:42 void docker-compose[316023]: home-assistant_1  |     v.OTGW_LED_F: led_funcs[5],
Aug 23 09:31:42 void docker-compose[316023]: home-assistant_1  | IndexError: string index out of range

It should be compatible with older firmware versions as well and AFAIK nothing changed regarding the LEDs between v4 and v5. Please open a new issue if you're experiencing problems like this.

paulvt commented 2 years ago

I only upgraded the firmware and upgraded HA from 2022.6 to 2022.8 again after having this fail last time and now all is fine. I am not really feeling like breaking things again by downgrading the firmware on the OTGW. I don't have enough time to investigate all kinds of breakage due to combinations of integration and firmware version, I'm afraid.