search

zxdavb / ramses_cc

HA integration for CH/DHW and HVAC systems that use the RAMSES II RF protocol
GNU General Public License v3.0
78 stars 17 forks source link

`ramses_cc.send_packet` creates invalid address sets #164

Closed Onl1ne1373 closed 8 months ago

Onl1ne1373 commented 8 months ago

I have a problem that I do not receive the following packets in the packet.log and not in ramses_cc_message event, but they are received by the HGI80.

045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020

This log is from the serial port with the tail -f command, so it does receive the packet. But it is not in the packet.log and I cannot find a error in the Home Assistant log.

Background info: A normal RQ 01FF from a Spider thermostat is directed to the gateway address starting with 18:. I have 6 thermostats and 2 send the message to the gateway, the others don't. I don't know why, but it is not really important, I know they do react to the RP anyway. I do receive the messages directed to the gateway.

A log with multiple RQ 01FF messages, all message without 18:010547 are ignored:

045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
072 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
073 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
072 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
054 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020
055 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020
054 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020
065 RQ --- 21:051294 21:051294 --:------ 01FF 026 008028282AD0008000243028320000C10280800280FF80040020
066 RQ --- 21:051294 21:051294 --:------ 01FF 026 008028282AD0008000243028320000C10280800280FF80040020
065 RQ --- 21:051294 21:051294 --:------ 01FF 026 008028282AD0008000243028320000C10280800280FF80040020
092 RQ --- 21:033619 21:033619 --:------ 01FF 026 008028282AD0008000243028320000C10280800280FF80040020
092 RQ --- 21:033619 21:033619 --:------ 01FF 026 008028282AD0008000243028320000C10280800280FF80040020
045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
073 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
073 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
074 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
053 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020
054 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020
053 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020

Running 0.41.7, problem is also in previous versions.

Could you have a look why ramses is ignoring these messages?

Onl1ne1373 commented 8 months ago

I added fake timestamps and tried "client.py parse" on

Onl1ne1373@DebianRamses:~/src/ramses_rf$ cat usb-01ff.log 
2024-02-05T18:38:45.319438 045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
2024-02-05T18:38:45.319438 045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
2024-02-05T18:38:45.319438 045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
2024-02-05T18:38:45.319438 072 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 073 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 072 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 054 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 055 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 054 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 065 RQ --- 21:051294 21:051294 --:------ 01FF 026 008028282AD0008000243028320000C10280800280FF80040020
2024-02-05T18:38:45.319438 066 RQ --- 21:051294 21:051294 --:------ 01FF 026 008028282AD0008000243028320000C10280800280FF80040020
2024-02-05T18:38:45.319438 065 RQ --- 21:051294 21:051294 --:------ 01FF 026 008028282AD0008000243028320000C10280800280FF80040020
2024-02-05T18:38:45.319438 092 RQ --- 21:033619 21:033619 --:------ 01FF 026 008028282AD0008000243028320000C10280800280FF80040020
2024-02-05T18:38:45.319438 092 RQ --- 21:033619 21:033619 --:------ 01FF 026 008028282AD0008000243028320000C10280800280FF80040020
2024-02-05T18:38:45.319438 045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
2024-02-05T18:38:45.319438 045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
2024-02-05T18:38:45.319438 045 RQ --- 21:041873 18:010547 --:------ 01FF 026 00802A2A2CD0008000243028320000440280800280FF800400A4
2024-02-05T18:38:45.319438 073 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 073 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 074 RQ --- 21:033620 18:010547 --:------ 01FF 026 0080292729D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 053 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 054 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020
2024-02-05T18:38:45.319438 053 RQ --- 21:033394 21:033394 --:------ 01FF 026 008029282AD0008000143C28320000C10280800280FF80040020

And the result also did not show the packages and not error messages:

Onl1ne1373@DebianRamses:~/src/ramses_rf$ cat usb-01ff.log | python3 client.py parse

client.py: Starting ramses_rf...
18:45:14.958 Best practice is exactly one gateway (HGI) in the known_list: []
18:45:14.958 It is strongly recommended to provide a known_list, and use it as a whitelist (device_id filter), configure: enforce_known_list = True

client.py: Starting engine...
18:38:45.319 ||  21:041873 |  18:010547 | RQ | message_01ff     |      || {'temperature': 21.0, 'setpoint_bounds': (21.0, 22.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
18:38:45.319 ||  21:041873 |  18:010547 | RQ | message_01ff     |      || {'temperature': 21.0, 'setpoint_bounds': (21.0, 22.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
18:38:45.319 ||  21:041873 |  18:010547 | RQ | message_01ff     |      || {'temperature': 21.0, 'setpoint_bounds': (21.0, 22.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
18:38:45.319 ||  21:033620 |  18:010547 | RQ | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (19.5, 20.5), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
18:38:45.319 ||  21:033620 |  18:010547 | RQ | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (19.5, 20.5), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
18:38:45.319 ||  21:033620 |  18:010547 | RQ | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (19.5, 20.5), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
18:38:45.319 ||  21:041873 |  18:010547 | RQ | message_01ff     |      || {'temperature': 21.0, 'setpoint_bounds': (21.0, 22.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
18:38:45.319 ||  21:041873 |  18:010547 | RQ | message_01ff     |      || {'temperature': 21.0, 'setpoint_bounds': (21.0, 22.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
18:38:45.319 ||  21:041873 |  18:010547 | RQ | message_01ff     |      || {'temperature': 21.0, 'setpoint_bounds': (21.0, 22.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
18:38:45.319 ||  21:033620 |  18:010547 | RQ | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (19.5, 20.5), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
18:38:45.319 ||  21:033620 |  18:010547 | RQ | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (19.5, 20.5), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
18:38:45.319 ||  21:033620 |  18:010547 | RQ | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (19.5, 20.5), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}

client.py: Engine stopped: ended without error (e.g. EOF)
 - finished ramses_rf.

So it is not ramses_cc related, but something in the parser.

Onl1ne1373 commented 8 months ago

It also happens with a W 22C9:

045  W --- 21:033618 21:033618 --:------ 22C9 006 00073A07D001

It is not visible in the packet.log, only on serial direct. So it seems it has something to do with the addressing.

15 minutes later.... There was indeed something wrong with the addressing. This was caused by a binding error, giving the wrong address in the reply. But while debugging the problem it would have been nice to have a packet.log to see the problem.

zxdavb commented 8 months ago

There was indeed something wrong with the addressing. This was caused by a binding error, giving the wrong address in the reply.

One of those cases, where things are obvious in retrospect:

RQ --- 21:033618 18:010547 --:------ 01FF 026 0080292428D00...  # addr set is valid
RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D00...  # addr set is invalid
RQ --- 21:033618 --:------ 21:033618 01FF 026 0080292428D00...  # addr set *should be* invalid
 I --- 21:033618 --:------ 21:033618 01FF 026 0080292428D00...  # addr set is valid

But while debugging the problem it would have been nice to have a packet.log to see the problem.

I agree. You shoudl have gotten an error message: Bad frame: invalid address set

I often deprecate some logging to reduce log spam. In this case, I believe I went too far. I will put it back. For the four packets above, we have:

22:39:02.001 ||  21:033618 |  18:010547 | RQ | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (18.0, 20.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
22:39:02.003 ||  21:033618 |            | RQ | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (18.0, 20.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
22:39:02.004 ||  21:033618 |            |  I | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (18.0, 20.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}

... but I will make it do this:

22:39:02.001 ||  21:033618 |  18:010547 | RQ | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (18.0, 20.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
11:43:25.698 045 RQ --- 21:033618 21:033618 --:------ 01FF 026 0080292428D0008000143C28320000C10280800280FF80040020  # addr set is invalid
 < PacketInvalid(Bad frame: invalid address set)
22:39:02.003 ||  21:033618 |            | RQ | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (18.0, 20.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
22:39:02.004 ||  21:033618 |            |  I | message_01ff     |      || {'temperature': 20.5, 'setpoint_bounds': (18.0, 20.0), 'time_planning': False, 'temp_adjusted': False, '_flags_10': 'D0'}
zxdavb commented 8 months ago

Worse that that:

If I can do the above, then maybe I can remove the PacketInvalid(... warnings sometime in future

zxdavb commented 8 months ago

See:

zxdavb commented 8 months ago

So:


ramses_tx.command:command.py:259 RQ --- 04:240790 --:------ 04:240790 1060 003 006401             < Command potentially invalid: wrong verb or dst addr should not be src
ramses_tx.command:command.py:259 RP --- 04:240790 --:------ 04:240790 1060 003 006401             < Command potentially invalid: wrong verb or dst addr should not be src
ramses_tx.command:command.py:259  W --- 04:240790 --:------ 04:240790 1060 003 006401             < Command potentially invalid: wrong verb or dst addr should not be src
ramses_tx.command:command.py:259 RQ --- --:------ --:------ 12:106131 313F 009 00380128CF110A07E5 < Command potentially invalid: wrong verb or dst addr should be present
ramses_tx.command:command.py:259 RP --- --:------ --:------ 12:106131 313F 009 00380128CF110A07E5 < Command potentially invalid: wrong verb or dst addr should be present
ramses_tx.command:command.py:259  W --- --:------ --:------ 12:106131 313F 009 00380128CF110A07E5 < Command potentially invalid: wrong verb or dst addr should be present
ramses_tx.command:command.py:259 RQ --- 21:033618 --:------ 21:033618 01FF 026 0080292428D0008... < Command potentially invalid: wrong verb or dst addr should not be src
Onl1ne1373 commented 8 months ago

Thanks for taking your time to enhance the logging! Those warnings look good.

zxdavb commented 8 months ago

Full fix will be in 0.31.10 (and 0.41.10)