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.

Sign up for GitHub

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

Jump to bottom

ramses_cc.send_packet creates invalid address sets #164

Closed
Onl1ne1373 opened this issue Feb 9, 2024 · 8 comments
Closed

ramses_cc.send_packet creates invalid address sets #164

Onl1ne1373 opened this issue Feb 9, 2024 · 8 comments

Comments

@Onl1ne1373
Copy link

Onl1ne1373 commented Feb 9, 2024 •
edited
Loading

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
Copy link
Author

Onl1ne1373 commented Feb 9, 2024 •
edited
Loading

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
Copy link
Author

Onl1ne1373 commented Feb 9, 2024 •
edited
Loading

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
Copy link
Owner

zxdavb commented Feb 11, 2024

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
Copy link
Owner

zxdavb commented Feb 11, 2024 •
edited
Loading

Worse that that:

  • rather than wait to receive the invalid echo of the command you sent,
  • it should warn you that the command you are sending is potentially invalid

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

@zxdavb
Copy link
Owner

zxdavb commented Feb 11, 2024

See:

@zxdavb
Copy link
Owner

zxdavb commented Feb 11, 2024

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
Copy link
Author

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

@zxdavb
Copy link
Owner

zxdavb commented Feb 11, 2024

Full fix will be in 0.31.10 (and 0.41.10)

@zxdavb zxdavb closed this as completed Feb 11, 2024
@zxdavb zxdavb changed the title Missing packets in packet.log "RQ 01FF" send_packet service creates invalid address sets Mar 11, 2024
@zxdavb zxdavb changed the title send_packet service creates invalid address sets ramses_cc.send_packet creates invalid address sets Mar 11, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@zxdavb @Onl1ne1373