Describe the bug Ramses CC entities status moves to unknown with

<a class="user-mention notranslate" data-hovercard-type="user" data-hovercard-url="/us

<a class="user-mention notranslate" data-hovercard-type="user" data-hover

I did say: The HRU has chosen not to respond to the <co

<a class="user-mention notranslate" data-hovercard-type="user" data-hovercard-url="/us

All entities Unknown with Gateway status stuck on Problem,about zxdavb/ramses_cc

Comments (13)

zxdavb commented on August 28, 2024 1

[Edit] My working thesis is that the root cause of this issue at the hardware layer.

Two distinct problems are described in the issue.

TL;DR: In this case, both can be safely ignored (assuming no hardware problems with your dongle).

The Gateway status frequently reports a Problem of short duration.

This issue occurs with systems that have HVAC, and no CH/DHW.

HVAC systems are not as chatty as CH/DHW, and that lack of RF traffic lead ramses_rf to belive that the gateway (the USB dongle) has stopped Rx packets.

TODO: I need to adjust the timings for this.

Gateway status permanently stuck on Problem ~~Failure to send discovery command~~:

2024-06-16 21:55:41.838 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F2|RQ|32:137185, tx_count=1/4>: echo_timeout=0.5
2024-06-16 21:55:42.840 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F2|RQ|32:137185, tx_count=2/4>: echo_timeout=1.0
2024-06-16 21:55:44.841 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F2|RQ|32:137185, tx_count=3/4>: echo_timeout=2.0
2024-06-16 21:55:48.843 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F2|RQ|32:137185, tx_count=4/4>: echo_timeout=4.0
2024-06-16 21:55:48.844 WARNING (MainThread) [ramses_rf.entity_base] 32:137185 (FAN): Failed to send discovery cmd: 22F2|RP|32:137185: <ProtocolContext state=WantEcho cmd_=22F2|RQ|32:137185, tx_count=4/4>: Exceeded maximum retries

~~The HRU has chosen not to respond to the RQ|22F2, and ramses_rf won't take no for an answer, and is not being polite about it.~~

from ramses_cc.

zxdavb commented on August 28, 2024

@acseven can you ping me a 72 hour packet log please, so I can check what I just wrote is true.

I would also like to know that make / model of your kit.

from ramses_cc.

acseven commented on August 28, 2024

@acseven can you ping me a 72 hour packet log please, so I can check what I just wrote is true.

@zxdavb Hi, sure I've attached a log which includes the excerpt in the OP.

packet.log

I would also like to know that make / model of your kit.

Which kit do you mean?

HRU is a Siber DF EVO 2 with a Siber DFEVOCTRL08 remote control
The RF receiver is from indalo tech, SSM-D2 Rev B

Regarding your comments, I don't know if I understood your reasoning correctly, but I'm not referring to sparse intervals of RF packets being transferred or not; I mean that it stops altogether and the only way to communicate is by pulling the USB stick and re-attaching it:

from ramses_cc.

acseven commented on August 28, 2024

Happened again, stopped at ~08:11:05 and I pulled the USB dongle and manually reloaded the integration at ~22:21:57:

2024-06-22T05:24:39.430089 000 RQ --- 18:003599 32:137185 --:------ 3222 001 00
2024-06-22T06:57:32.114489 000 RQ --- 18:003599 32:137185 --:------ 3222 001 00
2024-06-22T06:57:32.320591 000 RQ --- 18:003599 32:137185 --:------ 3222 001 00
2024-06-22T07:05:21.000139 000 RQ --- 18:003599 32:137185 --:------ 22F8 001 00
2024-06-22T07:58:03.659164 000 RQ --- 18:003599 32:137185 --:------ 22F8 001 00
2024-06-22T08:11:05.846266 000 RQ --- 18:003599 32:137185 --:------ 22F8 001 00
2024-06-22T08:11:05.846837 000 RQ --- 18:003599 32:137185 --:------ 2210 001 00
2024-06-22T22:21:57.323258 # ramses_tx 0.31.23
2024-06-22T22:21:57.382678 000  I --- 18:003599 63:262142 --:------ 7FFF 016 0010019041D3CA5076302E33312E3233
2024-06-22T22:21:57.414656 000  I --- 18:003599 63:262142 --:------ 7FFF 016 0010019041D3CA5076302E33312E3233
2024-06-22T22:22:12.569059 000 RQ --- 18:003599 32:137185 --:------ 22E9 001 00
2024-06-22T22:22:12.594097 068 RP --- 32:137185 18:003599 --:------ 22E9 004 005CC800
2024-06-22T22:22:15.591187 000 RQ --- 18:003599 32:137185 --:------ 22F1 001 00
2024-06-22T22:22:15.613152 000 RQ --- 18:003599 32:137185 --:------ 2210 001 00

2024-06-22 22:13:01.019 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22E5|RQ|32:137185, tx_count=3/4>: echo_timeout=4.0
2024-06-22 22:13:03.007 WARNING (MainThread) [ramses_rf.entity_base] 32:137185 (FAN): Failed to send discovery cmd: 22E5|RP|32:137185 within 15 secs: 
2024-06-22 22:13:05.020 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22E5|RQ|32:137185, tx_count=4/4>: echo_timeout=4.0
2024-06-22 22:13:10.011 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22E9|RQ|32:137185, tx_count=1/4>: echo_timeout=4.0
2024-06-22 22:13:14.014 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22E9|RQ|32:137185, tx_count=2/4>: echo_timeout=4.0
2024-06-22 22:13:18.016 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22E9|RQ|32:137185, tx_count=3/4>: echo_timeout=4.0
2024-06-22 22:13:21.009 WARNING (MainThread) [ramses_rf.entity_base] 32:137185 (FAN): Failed to send discovery cmd: 22E9|RP|32:137185 within 15 secs: 
2024-06-22 22:13:22.017 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22E9|RQ|32:137185, tx_count=4/4>: echo_timeout=4.0
2024-06-22 22:21:57.301 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/ramses_rf/gateway.py", line 204, in stop
    await super().stop()
  File "/usr/local/lib/python3.12/site-packages/ramses_tx/gateway.py", line 230, in stop
    await self._protocol.wait_for_connection_lost()
  File "/usr/local/lib/python3.12/site-packages/ramses_tx/protocol.py", line 167, in wait_for_connection_lost
    return await asyncio.wait_for(self._wait_connection_lost, timeout)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/asyncio/tasks.py", line 520, in wait_for
    return await fut
           ^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/ramses_tx/transport.py", line 920, in _read_ready
    data: bytes = self.serial.read(self._max_read_size)
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/serial/serialposix.py", line 595, in read
    raise SerialException(
serial.serialutil.SerialException: device reports readiness to read but returned no data (device disconnected or multiple access on port?)
2024-06-22 22:21:57.322 WARNING (MainThread) [homeassistant.util.loop] Detected blocking call to open inside the event loop by custom integration 'ramses_cc' at custom_components/ramses_cc/broker.py, line 175: return Gateway( (offender: /usr/local/lib/python3.12/logging/__init__.py, line 1263: return open_func(self.baseFilename, self.mode,), please create a bug report at https://github.com/zxdavb/ramses_cc/issues
Traceback (most recent call last):
  File "<frozen runpy>", line 198, in _run_module_as_main
  File "<frozen runpy>", line 88, in _run_code
  File "/usr/src/homeassistant/homeassistant/__main__.py", line 223, in <module>
    sys.exit(main())
  File "/usr/src/homeassistant/homeassistant/__main__.py", line 209, in main
    exit_code = runner.run(runtime_conf)
  File "/usr/src/homeassistant/homeassistant/runner.py", line 190, in run
    return loop.run_until_complete(setup_and_run_hass(runtime_config))
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 672, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 639, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1988, in _run_once
    handle._run()
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.12/site-packages/aiohttp/web_protocol.py", line 452, in _handle_request
    resp = await request_handler(request)
  File "/usr/local/lib/python3.12/site-packages/aiohttp/web_app.py", line 543, in _handle
    resp = await handler(request)
  File "/usr/local/lib/python3.12/site-packages/aiohttp/web_middlewares.py", line 114, in impl
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 92, in security_filter_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/forwarded.py", line 210, in forwarded_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 26, in request_context_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 85, in ban_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 242, in auth_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/headers.py", line 32, in headers_middleware
    response = await handler(request)
  File "/usr/src/homeassistant/homeassistant/helpers/http.py", line 73, in handle
    result = await handler(request, **request.match_info)
  File "/usr/src/homeassistant/homeassistant/components/config/config_entries.py", line 120, in post
    await hass.config_entries.async_reload(entry_id)
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 1897, in async_reload
    return await self.async_setup(entry_id, _lock=False)
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 1821, in async_setup
    await entry.async_setup(self.hass)
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 594, in async_setup
    result = await component.async_setup_entry(hass, self)
  File "/config/custom_components/ramses_cc/__init__.py", line 89, in async_setup_entry
    await broker.async_setup()
  File "/config/custom_components/ramses_cc/broker.py", line 126, in async_setup
    self.client = self._create_client(merged_schema)
  File "/config/custom_components/ramses_cc/broker.py", line 175, in _create_client
    return Gateway(

2024-06-22 22:21:57.442 WARNING (MainThread) [homeassistant.components.climate] Entity climate.32:137185 (<class 'custom_components.ramses_cc.climate.RamsesHvac'>) implements HVACMode(s): auto, off and therefore implicitly supports the turn_on/turn_off methods without setting the proper ClimateEntityFeature. Please create a bug report at https://github.com/zxdavb/ramses_cc/issues
2024-06-22 22:22:12.594 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 22E9 004 005CC800 < PacketInvalid(RP --- 32:137185 18:003599 --:------ 22E9 004 005CC800 < Unexpected code for src (FAN) to Tx)
2024-06-22 22:22:15.672 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 22E0 004 001AC800 < PacketInvalid(RP --- 32:137185 18:003599 --:------ 22E0 004 001AC800 < Unexpected code for src (FAN) to Tx)
2024-06-22 22:22:15.721 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 22E5 004 0034C800 < PacketInvalid(RP --- 32:137185 18:003599 --:------ 22E5 004 0034C800 < Unexpected code for src (FAN) to Tx)
2024-06-22 22:22:15.763 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 22F2 006 0005D501065A < PacketInvalid(RP --- 32:137185 18:003599 --:------ 22F2 006 0005D501065A < Unexpected code for src (FAN) to Tx)
2024-06-22 22:22:15.818 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 22F4 013 0060E400000000000000200000 < PacketInvalid(RP --- 32:137185 18:003599 --:------ 22F4 013 0060E400000000000000200000 < Unexpected code for src (FAN) to Tx)
2024-06-22 22:22:27.556 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 3222 003 006000 < PacketInvalid(RP --- 32:137185 18:003599 --:------ 3222 003 006000 < Unexpected code for src (FAN) to Tx)
2024-06-22 22:26:39.995 WARNING (MainThread) [bluetooth_auto_recovery.recover] Could not cycle the Bluetooth adapter hci0 [64:49:7D:E5:26:A7]: [Errno 110] Operation timed out
2024-06-22 22:26:44.996 WARNING (MainThread) [bluetooth_auto_recovery.recover] Could not reset the power state of the Bluetooth adapter hci0 [64:49:7D:E5:26:A7] due to timeout after 5 seconds
2024-06-22 22:28:57.451 ERROR (MainThread) [homeassistant.helpers.event] Error while dispatching event for climate.32_137185 to <Job track state_changed event ['climate.32_137185'] HassJobType.Callback <bound method HomeAccessory.async_update_event_state_callback of <accessory display_name='UVR' services=['AccessoryInformation', 'Thermostat', 'Fanv2']>>>
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 335, in _async_dispatch_entity_id_event
    hass.async_run_hass_job(job, event)
  File "/usr/src/homeassistant/homeassistant/core.py", line 936, in async_run_hass_job
    hassjob.target(*args)
  File "/usr/src/homeassistant/homeassistant/components/homekit/accessories.py", line 511, in async_update_event_state_callback
    self.async_update_state_callback(new_state)
  File "/usr/src/homeassistant/homeassistant/components/homekit/accessories.py", line 535, in async_update_state_callback
    self.async_update_state(new_state)
  File "/usr/src/homeassistant/homeassistant/components/homekit/type_thermostats.py", line 627, in async_update_state
    homekit_hvac_action = HC_HASS_TO_HOMEKIT_ACTION[hvac_action]
                          ~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^
KeyError: 'speed 1, low'

from ramses_cc.

zxdavb commented on August 28, 2024

Regarding your comments, I don't know if I understood your reasoning correctly, but I'm not referring to sparse intervals of RF packets being transferred or not; I mean that it stops altogether and the only way to communicate is by pulling the USB stick and re-attaching it:

After I re-read your first post, I wasn't sure if I had understood - that's why I asked for the log.

The scattered intervals of problems are of no concern, but the longer period is not right.

From your packet log (I have inserted the blank line):

2024-06-16T21:40:48.244682 073 RP --- 32:137185 37:145236 --:------ 31DA 030 00EF007FFFEFEF088F09870988084FF00200013236000000EF7FFF7FFF00
2024-06-16T21:41:20.215710 070  I 178 32:137185 --:------ 32:137185 31D9 017 000A020020202020202020202020202008
2024-06-16T21:46:19.947506 069  I --- 32:137185 --:------ 32:137185 31DA 030 00EF007FFFEFEF088A09850986084BF00200013236000000EF7FFF7FFF00

2024-06-17T10:09:36.400153 # ramses_tx 0.31.20
2024-06-17T10:09:36.458874 000  I --- 18:003599 63:262142 --:------ 7FFF 016 001001902575821876302E33312E3230
2024-06-17T10:09:51.630157 000 RQ --- 18:003599 32:137185 --:------ 22E9 001 00
2024-06-17T10:09:51.652199 070 RP --- 32:137185 18:003599 --:------ 22E9 004 005CC800
2024-06-17T10:09:54.652308 000 RQ --- 18:003599 32:137185 --:------ 22F1 001 00

You have a problem from just after 2024-06-16T21:46:19 until 2024-06-17T10:09:36, when it appears the integration was restarted or reloaded.

I would say that this is caused at the hardware layer.

This is the same:

2024-06-22T05:24:39.430089 000 RQ --- 18:003599 32:137185 --:------ 3222 001 00
2024-06-22T06:57:32.114489 000 RQ --- 18:003599 32:137185 --:------ 3222 001 00
2024-06-22T06:57:32.320591 000 RQ --- 18:003599 32:137185 --:------ 3222 001 00
2024-06-22T07:05:21.000139 000 RQ --- 18:003599 32:137185 --:------ 22F8 001 00
2024-06-22T07:58:03.659164 000 RQ --- 18:003599 32:137185 --:------ 22F8 001 00
2024-06-22T08:11:05.846266 000 RQ --- 18:003599 32:137185 --:------ 22F8 001 00
2024-06-22T08:11:05.846837 000 RQ --- 18:003599 32:137185 --:------ 2210 001 00

2024-06-22T22:21:57.323258 # ramses_tx 0.31.23
2024-06-22T22:21:57.382678 000  I --- 18:003599 63:262142 --:------ 7FFF 016 0010019041D3CA5076302E33312E3233
2024-06-22T22:21:57.414656 000  I --- 18:003599 63:262142 --:------ 7FFF 016 0010019041D3CA5076302E33312E3233
2024-06-22T22:22:12.569059 000 RQ --- 18:003599 32:137185 --:------ 22E9 001 00
2024-06-22T22:22:12.594097 068 RP --- 32:137185 18:003599 --:------ 22E9 004 005CC800

But note the 3 Tx of the RQ|3222 & RQ|22F8 before it dies - I'd like to see that packet log, going back a few hours.

from ramses_cc.

zxdavb commented on August 28, 2024

I did say:

The HRU has chosen not to respond to the RQ|22F2, and...

This is incorrect:

2024-06-21T20:56:08.748366 000 RQ --- 18:003599 32:137185 --:------ 3222 001 00
2024-06-21T20:56:08.770268 066 RP --- 32:137185 18:003599 --:------ 3222 013 00000A00000000000000000000
2024-06-21T21:01:46.298314 000 RQ --- 18:003599 32:137185 --:------ 3222 001 00
2024-06-21T21:01:46.318351 066 RP --- 32:137185 18:003599 --:------ 3222 003 006000

So (when it fails) the dongle is Tx (or not, you are seeing an echo, not a Tx), and it is not getting a corresponding Rx when you would expect it to.

It's the lack of the Rx that is the problem.

from ramses_cc.

zxdavb commented on August 28, 2024

The issue is sorted by disconnecting the USB SSM-D2 dongle from indalo-tech, reconnecting it and reloading the integration: the gateway is detected as OK straight away and the fan takes a few seconds to get status from all available entities. This has happened a few times now since I got the integration to work with my HRU. I think disconnecting the USB dongle has always been necessary to get it back running, but I'll confirm this whenever it happens again.

One question: some integrations have a automatic reloading feature, could this be implemented here?

I could code up a USB reset, and a reload - it wouldn't be a high priority.

I would start by treating it as a hardware problem. Check connections/ports/etc - then maybe speak to pete.

2024-06-22 22:21:57.301 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
...
  File "/usr/local/lib/python3.12/site-packages/serial/serialposix.py", line 595, in read
    raise SerialException(
serial.serialutil.SerialException: device reports readiness to read but returned no data (device disconnected or multiple access on port?)

from ramses_cc.

zxdavb commented on August 28, 2024

I am closing this issue - do re-open it, if there is evidence that it is not hardware related.

from ramses_cc.

acseven commented on August 28, 2024

Thank you for the input. I think I've ruled out the HA host hardware from being the culprit.

I've tested the dongle connected to a Windows PC while shared using USP over IP directly to Home Assistant with:

In Home Assistant OS, with this addon: https://github.com/irakhlin/hassio-usbip-mounter
In a Windows 11 PC with https://github.com/dorssel/usbipd-win

It ends up just the same way as if directly connected to the host machine; so I guess it's likely the dongle.

from ramses_cc.

ghoti57 commented on August 28, 2024

@zxdavb does ramses_rf restart itself if the USB dongle is unplugged and reinserted?
I don't see that behaviour on my system.
Can ramses_rf restart itself under any circumstances.

In the logs above the echos show that there is no loss of communication between the host and dongle.

from ramses_cc.

zxdavb commented on August 28, 2024

does ramses_rf restart itself if the USB dongle is unplugged and reinserted?
Can ramses_rf restart itself under any circumstances.

No & No.

I am not sure how to effect this - periodic USB reset?

HA has a 'reload' feature, that is exposed in HA & can be used with automation: see #181 - this is all effected in HA & ramses_cc, via a new instance of ramses_rf.

In the logs above the echos show that there is no loss of communication between the host and dongle.

Yes. So I have run out of ideas.

No-one else is reporting this behaviour, that I am aware of.

from ramses_cc.

zxdavb commented on August 28, 2024

FYI, I would be reluctant to implement a USB restart feature:

never needed one before - most people managing without
implementing it would be masking the underlying issue

from ramses_cc.

acseven commented on August 28, 2024

HA has a 'reload' feature,

I wasn’t aware of this, it should suffice for the intended purpose. In any case, only part of the issue I’m experiencing is addressed by that.

from ramses_cc.

All entities Unknown with Gateway status stuck on Problem about ramses_cc HOT 13 CLOSED

Comments (13)

Related Issues (20)

Recommend Projects

React

Vue.js

Typescript

TensorFlow

Django

Laravel

D3

Recommend Topics

javascript

web

server

Machine learning

Visualization

Game

Recommend Org

Facebook

Microsoft

Google

Alibaba

D3

Tencent