Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

All entities Unknown with Gateway status stuck on Problem #193

Closed
acseven opened this issue Jun 17, 2024 · 13 comments
Closed

All entities Unknown with Gateway status stuck on Problem #193

acseven opened this issue Jun 17, 2024 · 13 comments

Comments

@acseven
Copy link

acseven commented Jun 17, 2024

Describe the bug
Ramses CC entities status moves to unknown with SSM-D2 from indalo-tech. Gateway's status reads "Problem".

To Reproduce
Occurs randomly.

Please complete the following information:

  • ramses_cc: section from configuration.yaml
  • contemporaneous portion of the home-assistant.log

This is just a portion, it keeps going like this.

2024-06-16 20:55:41.335 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 22F2 006 0006480106E4 < PacketInvalid(RP --- 32:137185 18:003599 --:------ 22F2 006 0006480106E4 < Unexpected code for src (FAN) to Tx)
2024-06-16 20:55:44.372 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-16 20:55:50.448 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 2210 042 00FF00FFFFFF0000000000FFFFFFFFFF00FFFFFF0000000000FFFFFFFFFFFFFFFF000000000000000800 < PacketInvalid(RP --- 32:137185 18:003599 --:------ 2210 042 00FF00FFFFFF0000000000FFFFFFFFFF00FFFFFF0000000000FFFFFFFFFFFFFFFF000000000000000800 < Unexpected code for src (FAN) to Tx)
2024-06-16 20:55:53.432 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-16 20:55:56.465 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-16 20:55:59.487 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-16 20:56:02.524 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 313E 011 0000C44C8F0E003C800000 < PacketInvalid(RP --- 32:137185 18:003599 --:------ 313E 011 0000C44C8F0E003C800000 < Unexpected code for src (FAN) to Tx)
2024-06-16 20:56:05.537 WARNING (MainThread) [ramses_tx.message] RP --- 32:137185 18:003599 --:------ 3222 013 00000A00000000000000000000 < Payload doesn't match '^00[0-9A-F]{4,20}$': 00000A00000000000000000000
2024-06-16 21:25:41.365 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 22F2 006 0006520106FF < PacketInvalid(RP --- 32:137185 18:003599 --:------ 22F2 006 0006520106FF < Unexpected code for src (FAN) to Tx)
2024-06-16 21:25:44.387 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-16 21:25:50.456 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 2210 042 00FF00FFFFFF0000000000FFFFFFFFFF00FFFFFF0000000000FFFFFFFFFFFFFFFF000000000000000800 < PacketInvalid(RP --- 32:137185 18:003599 --:------ 2210 042 00FF00FFFFFF0000000000FFFFFFFFFF00FFFFFF0000000000FFFFFFFFFFFFFFFF000000000000000800 < Unexpected code for src (FAN) to Tx)
2024-06-16 21:25:53.463 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-16 21:25:56.490 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-16 21:25:59.507 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-16 21:26:02.534 WARNING (MainThread) [ramses_rf.dispatcher] RP --- 32:137185 18:003599 --:------ 313E 011 0000C44CAD0E003C800000 < PacketInvalid(RP --- 32:137185 18:003599 --:------ 313E 011 0000C44CAD0E003C800000 < Unexpected code for src (FAN) to Tx)
2024-06-16 21:26:05.562 WARNING (MainThread) [ramses_tx.message] RP --- 32:137185 18:003599 --:------ 3222 013 00000A00000000000000000000 < Payload doesn't match '^00[0-9A-F]{4,20}$': 00000A00000000000000000000
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
2024-06-16 21:55:52.845 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F4|RQ|32:137185, tx_count=1/4>: echo_timeout=4.0
2024-06-16 21:55:56.847 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F4|RQ|32:137185, tx_count=2/4>: echo_timeout=4.0
2024-06-16 21:56:00.849 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F4|RQ|32:137185, tx_count=3/4>: echo_timeout=4.0
2024-06-16 21:56:03.845 WARNING (MainThread) [ramses_rf.entity_base] 32:137185 (FAN): Failed to send discovery cmd: 22F4|RP|32:137185 within 15 secs: 
2024-06-16 21:56:04.850 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F4|RQ|32:137185, tx_count=4/4>: echo_timeout=4.0
2024-06-16 21:56:08.852 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F8|RQ|32:137185, tx_count=1/4>: echo_timeout=4.0
2024-06-16 21:56:12.854 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F8|RQ|32:137185, tx_count=2/4>: echo_timeout=4.0
2024-06-16 21:56:16.856 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F8|RQ|32:137185, tx_count=3/4>: echo_timeout=4.0
2024-06-16 21:56:18.845 WARNING (MainThread) [ramses_rf.entity_base] 32:137185 (FAN): Failed to send discovery cmd: 22F8|RP|32:137185 within 15 secs: 
2024-06-16 21:56:20.858 WARNING (MainThread) [ramses_tx.protocol_fsm] TOUT.. = <ProtocolContext state=WantEcho cmd_=22F8|RQ|32:137185, tx_count=4/4>: echo_timeout=4.0
  • contemporaneous portion of the packet.log - log tail:
2024-06-16T20:41:23.639124 068  I 174 32:137185 --:------ 32:137185 31D9 017 000A020020202020202020202020202008
2024-06-16T20:46:23.361281 069  I --- 32:137185 --:------ 32:137185 31DA 030 00EF007FFFEFEF0886098C09940844F00200013236000000EF7FFF7FFF00
2024-06-16T20:55:36.078185 065 RQ --- 37:145236 32:137185 --:------ 31DA 001 00
2024-06-16T20:55:36.112315 069 RP --- 32:137185 37:145236 --:------ 31DA 030 00EF007FFFEFEF087B098B0991083DF00200013236000000EF7FFF7FFF00
2024-06-16T20:55:41.314240 000 RQ --- 18:003599 32:137185 --:------ 22F2 001 00
2024-06-16T20:55:41.335441 070 RP --- 32:137185 18:003599 --:------ 22F2 006 0006480106E4
2024-06-16T20:55:44.339256 000 RQ --- 18:003599 32:137185 --:------ 22F4 001 00
2024-06-16T20:55:44.372284 070 RP --- 32:137185 18:003599 --:------ 22F4 013 0060E400000000000000200000
2024-06-16T20:55:47.364475 000 RQ --- 18:003599 32:137185 --:------ 22F8 001 00
2024-06-16T20:55:50.393295 000 RQ --- 18:003599 32:137185 --:------ 2210 001 00
2024-06-16T20:55:50.447454 070 RP --- 32:137185 18:003599 --:------ 2210 042 00FF00FFFFFF0000000000FFFFFFFFFF00FFFFFF0000000000FFFFFFFFFFFFFFFF000000000000000800
2024-06-16T20:55:53.418649 000 RQ --- 18:003599 32:137185 --:------ 22E0 001 00
2024-06-16T20:55:53.432407 069 RP --- 32:137185 18:003599 --:------ 22E0 004 001AC800
2024-06-16T20:55:56.442486 000 RQ --- 18:003599 32:137185 --:------ 22E5 001 00
2024-06-16T20:55:56.464628 069 RP --- 32:137185 18:003599 --:------ 22E5 004 0034C800
2024-06-16T20:55:59.468807 000 RQ --- 18:003599 32:137185 --:------ 22E9 001 00
2024-06-16T20:55:59.486639 069 RP --- 32:137185 18:003599 --:------ 22E9 004 005CC800
2024-06-16T20:56:02.491808 000 RQ --- 18:003599 32:137185 --:------ 313E 001 00
2024-06-16T20:56:02.523698 070 RP --- 32:137185 18:003599 --:------ 313E 011 0000C44C8F0E003C800000
2024-06-16T20:56:05.515782 000 RQ --- 18:003599 32:137185 --:------ 3222 001 00
2024-06-16T20:56:05.536764 068 RP --- 32:137185 18:003599 --:------ 3222 013 00000A00000000000000000000
2024-06-16T20:56:22.768612 068  I 175 32:137185 --:------ 32:137185 31D9 017 000A020020202020202020202020202008
2024-06-16T20:56:22.872297 068  I --- 32:137185 --:------ 32:137185 31DA 030 00EF007FFFEFEF087F098B0991083EF00200013236000000EF7FFF7FFF00
2024-06-16T20:57:12.709653 069  I --- 32:137185 --:------ 32:137185 313F 009 007C9938D4100607E8
2024-06-16T21:06:22.198076 069  I --- 32:137185 --:------ 32:137185 31DA 030 00EF007FFFEFEF087E098A098F083AF00200013236000000EF7FFF7FFF00
2024-06-16T21:10:40.075292 066 RQ --- 37:145236 32:137185 --:------ 31DA 001 00
2024-06-16T21:10:40.107241 069 RP --- 32:137185 37:145236 --:------ 31DA 030 00EF007FFFEFEF08770986098D0833F00200013236000000EF7FFF7FFF00
2024-06-16T21:11:21.909487 069  I 176 32:137185 --:------ 32:137185 31D9 017 000A020020202020202020202020202008
2024-06-16T21:16:21.628706 069  I --- 32:137185 --:------ 32:137185 31DA 030 00EF007FFFEFEF08700986098B082BF00200013236000000EF7FFF7FFF00
2024-06-16T21:25:41.336238 000 RQ --- 18:003599 32:137185 --:------ 22F2 001 00
2024-06-16T21:25:41.365213 070 RP --- 32:137185 18:003599 --:------ 22F2 006 0006520106FF
2024-06-16T21:25:44.070143 068 RQ --- 37:145236 32:137185 --:------ 31DA 001 00
2024-06-16T21:25:44.104153 069 RP --- 32:137185 37:145236 --:------ 31DA 030 00EF007FFFEFEF08950988098A085CF00200013236000000EF7FFF7FFF00
2024-06-16T21:25:44.360262 000 RQ --- 18:003599 32:137185 --:------ 22F4 001 00
2024-06-16T21:25:44.387301 070 RP --- 32:137185 18:003599 --:------ 22F4 013 0060E400000000000000200000
2024-06-16T21:25:47.386299 000 RQ --- 18:003599 32:137185 --:------ 22F8 001 00
2024-06-16T21:25:50.414415 000 RQ --- 18:003599 32:137185 --:------ 2210 001 00
2024-06-16T21:25:50.456321 068 RP --- 32:137185 18:003599 --:------ 2210 042 00FF00FFFFFF0000000000FFFFFFFFFF00FFFFFF0000000000FFFFFFFFFFFFFFFF000000000000000800
2024-06-16T21:25:53.440427 000 RQ --- 18:003599 32:137185 --:------ 22E0 001 00
2024-06-16T21:25:53.462895 071 RP --- 32:137185 18:003599 --:------ 22E0 004 001AC800
2024-06-16T21:25:56.463635 000 RQ --- 18:003599 32:137185 --:------ 22E5 001 00
2024-06-16T21:25:56.489590 070 RP --- 32:137185 18:003599 --:------ 22E5 004 0034C800
2024-06-16T21:25:59.489620 000 RQ --- 18:003599 32:137185 --:------ 22E9 001 00
2024-06-16T21:25:59.506681 070 RP --- 32:137185 18:003599 --:------ 22E9 004 005CC800
2024-06-16T21:26:02.513636 000 RQ --- 18:003599 32:137185 --:------ 313E 001 00
2024-06-16T21:26:02.533718 068 RP --- 32:137185 18:003599 --:------ 313E 011 0000C44CAD0E003C800000
2024-06-16T21:26:05.537171 000 RQ --- 18:003599 32:137185 --:------ 3222 001 00
2024-06-16T21:26:05.561936 069 RP --- 32:137185 18:003599 --:------ 3222 013 00000A00000000000000000000
2024-06-16T21:26:21.071411 068  I 177 32:137185 --:------ 32:137185 31D9 017 000A020020202020202020202020202008
2024-06-16T21:26:21.164313 068  I --- 32:137185 --:------ 32:137185 31DA 030 00EF007FFFEFEF08950988098A085CF00200013236000000EF7FFF7FFF00
2024-06-16T21:27:11.018809 069  I --- 32:137185 --:------ 32:137185 313F 009 007C971AD5100607E8
2024-06-16T21:30:56.069841 066 RQ --- 37:145236 32:137185 --:------ 313F 001 00
2024-06-16T21:30:56.095473 068 RP --- 32:137185 37:145236 --:------ 313F 009 007C881ED5100607E8
2024-06-16T21:30:56.238364 066 RQ --- 37:145236 32:137185 --:------ 1470 001 00
2024-06-16T21:30:56.259316 070 RP --- 32:137185 37:145236 --:------ 1470 008 00920E60802A0108
2024-06-16T21:36:20.504021 069  I --- 32:137185 --:------ 32:137185 31DA 030 00EF007FFFEFEF088E098709880853F00200013236000000EF7FFF7FFF00
2024-06-16T21:40:48.069911 065 RQ --- 37:145236 32:137185 --:------ 31DA 001 00
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

Additional context
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?

Sidenote: an odd sensor is the "filter remaining" sensor, which comes back as soon as the gateway also comes back:

image

A few seconds after reloading:

image

Please advise if this seems more likely to be the dongle than something about the integration.

@zxdavb
Copy link
Owner

zxdavb commented Jun 21, 2024

[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).

  1. 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.

  1. 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.

@zxdavb
Copy link
Owner

zxdavb commented Jun 21, 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.

@acseven
Copy link
Author

acseven commented Jun 21, 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:

image

@acseven
Copy link
Author

acseven commented Jun 22, 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'

@zxdavb
Copy link
Owner

zxdavb commented Jun 22, 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.

@zxdavb
Copy link
Owner

zxdavb commented Jun 22, 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.

@zxdavb
Copy link
Owner

zxdavb commented Jun 22, 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?)

@zxdavb zxdavb changed the title Ramses CC times out with no apparent interaction System unresponsive with Gateway status stuck on Problem Jun 23, 2024
@zxdavb zxdavb changed the title System unresponsive with Gateway status stuck on Problem All entities Unknown with Gateway status stuck on Problem Jun 23, 2024
@zxdavb
Copy link
Owner

zxdavb commented Jun 23, 2024

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

@zxdavb zxdavb closed this as completed Jun 23, 2024
@acseven
Copy link
Author

acseven commented Jun 23, 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:

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

@ghoti57
Copy link

ghoti57 commented Jun 24, 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.

@zxdavb
Copy link
Owner

zxdavb commented Jun 24, 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.

@zxdavb
Copy link
Owner

zxdavb commented Jun 24, 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

@acseven
Copy link
Author

acseven commented Jun 24, 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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants