search

smar000 / evoGateway

Python script for listening in and responding to evohome heating control radio messages
46 stars 17 forks source link

'COMMAND SEND FAILED' when setting system mode #40

Closed BasKloet closed 2 years ago

BasKloet commented 2 years ago

First of all, thanks for this great program!

Now for the bug/question. If I try to set the system mode from using a mqtt command, it is received and gets processed correctly by the evoGateway script, but as far I I can determine it fails somewhere in the ramses_rf code:

2021-11-30 10:09:34,590 [719] MQTT message received: {"command": "set_system_mode", "system_mode": "auto", "until": null}
2021-11-30 10:09:35,634 [422] || HGI:262143         | CV                 | RQ | opentherm_msg    |  12  || {}
2021-11-30 10:09:36,684 [422] || HGI:262143         | CV                 | RQ | opentherm_msg    |  13  || {}
2021-11-30 10:09:37,726 [422] || HGI:262143         | CV                 | RQ | opentherm_msg    |  19  || {}
2021-11-30 10:09:38,978 [422] || HGI:262143         | CV                 | RQ | opentherm_msg    |  1A  || {}
2021-11-30 10:09:40,876 [422] || HGI:262143         | CV                 | RQ | opentherm_msg    |  1B  || {}
2021-11-30 10:09:41,928 [422] || HGI:262143         | CV                 | RQ | opentherm_msg    |  1C  || {}
2021-11-30 10:09:42,967 [422] || HGI:262143         | Controller         |  W | system_mode      |      || {'system_mode': 'auto', 'until': None}
2021-11-30 10:09:43,065 [422] || HGI:262143         | Controller         |  W | system_mode      |      || {'system_mode': 'auto', 'until': None}
2021-11-30 10:09:43,212 [422] || HGI:262143         | Controller         |  W | system_mode      |      || {'system_mode': 'auto', 'until': None}
2021-11-30 10:09:43,427 [550] COMMAND SEND FAILED for '{'command': 'set_system_mode', 'system_mode': 'auto', 'until': None}'
2021-11-30 10:10:02,739 [422] ||                    | CV                 |  I | opentherm_sync   |      || {'ticker': 25597}
2021-11-30 10:10:03,440 [422] || Controller         | HGI:262143         | RP | datetime         |      || {'datetime': '2021-11-30T10:10:12', 'is_dst': None, '_unknown_0': 'FC'}
2021-11-30 10:10:03,460 [422] || Controller         | HGI:262143         | RP | system_mode      | (02) || {'system_mode': 'eco_boost', 'until': None}

I stored debug logging as well, but it does not help me any further: events.debug.log

Can you give me some help on how to analyze this further? Or should I file this defect with ramses_rf?

smar000 commented 2 years ago

Can you try resending the command but including "ctl_id" with your actual controller ID as well in your json, e.g.:

{'command': 'set_system_mode', 'system_mode': 'auto', 'until': None, 'ctl_id': '01:123456'}

I have found that some commands require this to be explicitly stated whereas others don't. I will also have a look later this evening, if I get a bit of time.

BasKloet commented 2 years ago

If I add a ctl_id, I no longer get the FAILED message, but I also do not see a change in the mode either . I'll try to get more debug information later today.

smar000 commented 2 years ago

I've just uploaded a slightly updated version. Can you try this. From my brief testing, it appears to be setting the modes correctly (no need to specify the ctl_id anymore), as well as changing zone setpoints, hotwater etc.

BasKloet commented 2 years ago

My initial test was unsuccessful (same error), but I want to try if removing the Honeywell internet gateway from my network (since I want to get rid of that anyway) and re-running the python script in eavesdropping mode will help, since I also have a feeling that my devices.json file may have a problem. I'll give an update tomorrow.

Update: apparently my Honeywell wifi controller gives an error without this gateway present, and I think that's the reason that the eavesdropping did not see any zones. So I added it the gateway again and restarted the eavesdrop. I'll let it run through the night and do some more testing in the morning. Once I have everything working at some point in the future, I'll test if I can keep controlling everything with the gateway active but disconnected from the internet, since I would really like to be independent of an online third party.

BasKloet commented 2 years ago

I've updated both your code and for good measure also updated the ramses_rf dependency to the latest version (0.16.24). If I send the MQTT command and check the debug logging, I get the following:

2021-12-01 08:31:08,346 [720] MQTT message received: {"command": "set_system_mode", "system_mode": "eco_boost", "until": null}
2021-12-01 08:31:08,348 [888] MQTT message received: {"command": "set_system_mode", "system_mode": "eco_boost", "until": null}
2021-12-01 08:31:08,350 [975] Sending command:  W --- 18:000730 01:085159 --:------ 2E04 008 02FFFFFFFFFFFF00

When I check the mqtt topic 'evohome/evogateway/_zone_independent/command/#' (for a later call) I see the following:

{"command": "set_system_mode", "system_mode": "eco_boost", "until": null}
2021-12-01T08:46:46
Transmitted
2021-12-01T08:46:46
Failed
2021-12-01T08:47:12

So it seems that it somehow goes wrong in ramses_rf, do you know if there is any way to see more (debug) logging from ramses?

smar000 commented 2 years ago

So it seems that it somehow goes wrong in ramses_rf, do you know if there is any way to see more (debug) logging from ramses?

Just to be sure, I assume that the packet log shows the send command W --- 18:000730 01:085159 --:------ 2E04 008 02FFFFFFFFFFFF00 as well?

Failing that, you can try sending the command directly using the ramses cli and see if that works.

BasKloet commented 2 years ago

I'm not seeing any packets for 18:000730, I do see the above command, but for 18:262143.

2021-12-01T08:33:36.838296 000 W --- 18:262143 01:085159 --:------ 2E04 008 02FFFFFFFFFFFF00

This is my devices.json:

    "01:085159": {
        "alias": "Controller"
    },
    "10:062086": {
        "alias": "OTB:062086"
    },
    "18:000730": {
        "alias": "evoGateway"
    }

Unfortunately I cannot get the ramses cli to work:

python ./client.py execute /dev/ttyUSB-Evo --exec-cmd "W --- 18:000730 01:085159 --:------ 2E04 008 02FFFFFFFFFFFF00"
Usage: client.py execute [OPTIONS] SERIAL_PORT
Try 'client.py execute -h' for help.

Error: No such option: --exec-cmd
smar000 commented 2 years ago

I do see the above command, but for 18:262143

This is probably your nano cul. If I recall correctly, David (the author of ramses_rf) mentioned that the ID is no longer fixed to 18:000730, but is generated each time.

Unfortunately I cannot get the ramses cli to work

The argument is -x or --execute-cmd (you can see a list of the valid arguments in the client.py file).

BasKloet commented 2 years ago

This is probably your nano cul. If I recall correctly, David (the author of ramses_rf) mentioned that the ID is no longer fixed to 18:000730, but is generated each time.

Could this cause an issue with the fact that it's not in my devices.json, since it's not really possible to whitelist something that has no fixed ID? Or doesn't that matter since the nano cul is not really one of the Evo devices?

The argument is -x or --execute-cmd (you can see a list of the valid arguments in the client.py file).

Thanks, I'll try that call tomorrow. I found the client.py somewhat hard to read because there wasn't really a fixed list of arguments, but arguments that were added in lots of places throughout the file (and I was a bit rushed and didn't have the time to fully try to comprehend the file).

BasKloet commented 2 years ago

Update: I found the problem with the client, I was using the 'execute' command, while I should be using the 'monitor' command.

python3.8 client.py monitor /dev/ttyUSB-Evo -x 'W --- 18:000730 01:085159 --:------ 2E04 008 02FFFFFFFFFFFF00'

09:34:27.648 Execute: Command is invalid: '{'debug_mode': 0, 'reduce_processing': 0, 'long_dates': None, 'eavesdrop': None, 'client_state': None, 'hide_summary': False, 'show_summary': None, 'exec_cmd': 'W --- 18:000730 01:085159 --:------ 2E04 008 02FFFFFFFFFFFF00', 'exec_scr': None, 'poll_devices': None}'

I feel like the syntax should be something like: RQ 01:145038 1F09 00, but I'm not sure how to get there from what I've got.

smar000 commented 2 years ago

I just tried setting the mode to "auto" on mine, and see the following in the packet log:

2021-12-02T08:49:36.158359 000  W --- 18:136712 01:139901 --:------ 2E04 008 00FFFFFFFFFFFF00
2021-12-02T08:49:36.177942 055  I --- 01:139901 18:136712 --:------ 2E04 008 00FFFFFFFFFFFF00

Given this, I am guessing your syntax would be something like:

python ./client.py monitor /dev/ttyUSB-Evo -x "W 01:085159 2E04 02FFFFFFFFFFFF00"

Are other commands working for you? What about a simple date/time request?

BasKloet commented 2 years ago 
python3.8 ./client.py monitor /dev/ttyUSB-Evo -x "W 01:085159 2E04 02FFFFFFFFFFFF00" 

client.py: Starting ramses_rf...
10:09:44.981 It is strongly recommended to provide a known_list, and use it as a whitelist (device_id filter), configure: enforce_known_list = True
10:09:44.990 Not using any device filter: using a known_list (as a whitelist) is strongly recommended)
10:09:45.669 Creating a Device: 18:262143 (<class 'ramses_rf.devices.HgiGateway'>)
10:09:45.667 || HGI:262143 | NUL:262142 |  I | puzzle_packet    |      || {'datetime': '2021-12-02T10:09:44.991', 'engine': 'v0.16.24', 'parser': 'v0.16.24'}
10:09:45.707 || HGI:262143 | CTL:085159 |  W | system_mode      | (02) || {'system_mode': 'eco_boost', 'until': None}
10:09:45.809 || HGI:262143 | CTL:085159 |  W | system_mode      | (02) || {'system_mode': 'eco_boost', 'until': None}
10:09:46.209 || HGI:262143 | CTL:085159 |  W | system_mode      | (02) || {'system_mode': 'eco_boost', 'until': None}
10:09:47.811 || HGI:262143 | CTL:085159 |  W | system_mode      | (02) || {'system_mode': 'eco_boost', 'until': None}
10:09:49.781 PktProtocolQos.send_data(sent=2E04| W|01:085159): boff=3, want=2E04| I|01:085159, tout=2021-12-02T10:09:49.776: QoS: IS_EXPIRED (giving up) (3/3)
10:09:50.135 Creating a Device: 30:151978 (<class 'ramses_rf.devices.Device'>)
10:09:50.132 || RFG:151978 | OTB:062086 | RQ | opentherm_msg    |  05  || {'msg_id': 5, 'msg_type': 'Read-Data', 'msg_name': 'fault_flags', 'description': 'Fault flags & OEM fault code'}
10:09:50.217 || HGI:262143 | RFG:151978 | RQ | device_info      |      || {}
10:09:50.466 Creating a Device: 10:062086 (<class 'ramses_rf.devices.OtbGateway'>)
10:09:50.464 || OTB:062086 | RFG:151978 | RP | opentherm_msg    |  05  || {'msg_id': 5, 'msg_type': 'Read-Ack', 'msg_name': 'fault_flags', 'value_hb': [0, 0, 0, 0, 0, 0, 0, 0], 'value_lb': 255, 'description': 'Fault flags & OEM faul
10:09:50.631 || RFG:151978 | OTB:062086 | RQ | opentherm_msg    |  11  || {'msg_id': 17, 'msg_type': 'Read-Data', 'msg_name': 'RelativeModulationLevel', 'description': 'Relative modulation level'}
10:09:51.001 || OTB:062086 | RFG:151978 | RP | opentherm_msg    |  11  || {'msg_id': 17, 'msg_type': 'Read-Ack', 'msg_name': 'RelativeModulationLevel', 'value': 0.0, 'description': 'Relative modulation level'}
10:09:51.130 || RFG:151978 | OTB:062086 | RQ | opentherm_msg    |  12  || {'msg_id': 18, 'msg_type': 'Read-Data', 'msg_name': 'CHWaterPressure', 'description': 'Central heating water pressure (bar)'}
10:09:51.542 || OTB:062086 | RFG:151978 | RP | opentherm_msg    |  12  || {'msg_id': 18, 'msg_type': 'Read-Ack', 'msg_name': 'CHWaterPressure', 'value': 1.8, 'description': 'Central heating water pressure (bar)'}
10:09:51.731 || RFG:151978 | OTB:062086 | RQ | opentherm_msg    |  13  || {'msg_id': 19, 'msg_type': 'Read-Data', 'msg_name': 'DHWFlowRate', 'description': 'DHW flow rate (litres/minute)'}
10:09:52.222 || HGI:262143 | RFG:151978 | RQ | device_info      |      || {}
10:09:52.624 || OTB:062086 | RFG:151978 | RP | opentherm_msg    |  19  || {'msg_id': 25, 'msg_type': 'Read-Ack', 'msg_name': 'BoilerWaterTemperature', 'value': 50.0, 'description': 'Boiler water temperature'}
10:09:52.731 || RFG:151978 | OTB:062086 | RQ | opentherm_msg    |  1A  || {'msg_id': 26, 'msg_type': 'Read-Data', 'msg_name': 'DHWTemperature', 'description': 'DHW temperature'}
10:09:53.163 || OTB:062086 | RFG:151978 | RP | opentherm_msg    |  1A  || {'msg_id': 26, 'msg_type': 'Read-Ack', 'msg_name': 'DHWTemperature', 'value': 42.0, 'description': 'DHW temperature'}
10:09:53.340 || RFG:151978 | OTB:062086 | RQ | opentherm_msg    |  1C  || {'msg_id': 28, 'msg_type': 'Read-Data', 'msg_name': 'ReturnWaterTemperature', 'description': 'Return water temperature'}
10:09:53.539 || RFG:151978 | CTL:085159 | RQ | system_fault     |  00  || {}
10:09:53.575 Creating a Device: 01:085159 (<class 'ramses_rf.devices.Controller'>)
10:09:53.568 || CTL:085159 | RFG:151978 | RP | system_fault     |  00  || {'log_idx': '00', 'log_entry': ['21-11-30T22:55:52', 'restore', 'comms_fault', 'remote_gateway', '00', '30:151978', 'B0', '0000', 'FFFF7000']}
10:09:53.703 || OTB:062086 | RFG:151978 | RP | opentherm_msg    |  1C  || {'msg_id': 28, 'msg_type': 'Read-Ack', 'msg_name': 'ReturnWaterTemperature', 'value': 49.5, 'description': 'Return water temperature'}
10:09:53.841 || RFG:151978 | OTB:062086 | RQ | opentherm_msg    |  73  || {'msg_id': 115, 'msg_type': 'Read-Data', 'msg_name': 'OEMDiagnosticCode', 'description': 'OEM diagnostic code'}
10:09:53.938 || RFG:151978 | OTB:062086 | RQ | boiler_setpoint  |      || {}
10:09:53.963 || OTB:062086 | RFG:151978 | RP | boiler_setpoint  |      || {'setpoint': 44.0}
10:09:54.224 || HGI:262143 | RFG:151978 | RQ | device_info      |      || {}
10:09:54.241 || OTB:062086 | RFG:151978 | RP | opentherm_msg    |  73  || {'msg_id': 115, 'msg_type': 'Unknown-DataId', 'msg_name': 'OEMDiagnosticCode', 'description': 'OEM diagnostic code'}
10:09:56.199 PktProtocolQos.send_data(sent=10E0|RQ|30:151978): boff=3, want=10E0|RP|30:151978, tout=2021-12-02T10:09:56.196: QoS: IS_EXPIRED (giving up) (2/2)
10:09:56.230 || HGI:262143 | CTL:085159 | RQ | zone_devices     | 000D || {}
10:09:58.230 || HGI:262143 | CTL:085159 | RQ | zone_devices     | 000D || {}
10:10:00.233 || HGI:262143 | CTL:085159 | RQ | zone_devices     | 000D || {}
10:10:02.209 PktProtocolQos.send_data(sent=000C|RQ|01:085159|000D): boff=3, want=000C|RP|01:085159|000D, tout=2021-12-02T10:10:02.204: QoS: IS_EXPIRED (giving up) (2/2)
10:10:02.239 || HGI:262143 | CTL:085159 | RQ | system_zones     | 0008 || {}
10:10:04.241 || HGI:262143 | CTL:085159 | RQ | system_zones     | 0008 || {}
10:10:05.738 ||            | OTB:062086 |  I | opentherm_sync   |      || {'ticker': 31307}
10:10:06.249 || HGI:262143 | CTL:085159 | RQ | system_zones     | 0008 || {}
10:10:08.225 PktProtocolQos.send_data(sent=0005|RQ|01:085159|0008): boff=3, want=0005|RP|01:085159|0008, tout=2021-12-02T10:10:08.220: QoS: IS_EXPIRED (giving up) (2/2)
10:10:08.255 || HGI:262143 | CTL:085159 | RQ | system_zones     | 0009 || {}
10:10:10.255 || HGI:262143 | CTL:085159 | RQ | system_zones     | 0009 || {}
10:10:12.257 || HGI:262143 | CTL:085159 | RQ | system_zones     | 0009 || {}
10:10:14.234 PktProtocolQos.send_data(sent=0005|RQ|01:085159|0009): boff=3, want=0005|RP|01:085159|0009, tout=2021-12-02T10:10:14.229: QoS: IS_EXPIRED (giving up) (2/2)
10:10:14.265 || HGI:262143 | CTL:085159 | RQ | system_zones     | 000A || {}
10:10:16.266 || HGI:262143 | CTL:085159 | RQ | system_zones     | 000A || {}
10:10:17.238 || CTL:085159 |            |  I | heat_demand      |  FC  || {'domain_id': 'FC', 'heat_demand': 0.0}
10:10:18.269 || HGI:262143 | CTL:085159 | RQ | system_zones     | 000A || {}
10:10:20.245 PktProtocolQos.send_data(sent=0005|RQ|01:085159|000A): boff=3, want=0005|RP|01:085159|000A, tout=2021-12-02T10:10:20.241: QoS: IS_EXPIRED (giving up) (2/2)
10:10:20.276 || HGI:262143 | CTL:085159 | RQ | system_zones     | 000B || {}
10:10:22.281 || HGI:262143 | CTL:085159 | RQ | system_zones     | 000B || {}
10:10:24.285 RQ --- 18:000030 01:085159 --:------ 0005 002 000B < There appears to be more than one HGI80-compatible device (active gateway: 18:262143), this is unsupported
10:10:24.286 Blocking packets with device_id: 18:000030 (is foreign gateway), configure the known_list/block_list as required

Sending the command works now, but does not seem to have any effect

smar000 commented 2 years ago

It does not look as if you are getting a response back from your controller. I suggest trying sending something simple like 313F (get system datetime) and make sure that you get a response back. If you don't, then not sure what else to suggest. Maybe worth asking on the ramses repo?

BasKloet commented 2 years ago

For now I'm going to leave this as is for a bit, I've got too many other things to do right now and I can still fall back on setting the state through the Evohome api. I'll open an issue with ramses once I have a bit more time, since the problem seems to be in the interaction between ramses and my local devices.

Just a note, I'm still very happy with what I've achieved using your library. All my thermostat devices in Domoticz are now updated from mqtt messages, instead of having to poll the Evohome api every 5 minutes and getting random authorization errors multiple times per day. Besides that I also have access to a ton of Opentherm data from my system now, which I can use to analyze my current setup and the changes I plan to make in the future. So thank you for both the library and all the help you've provided on this issue.

smar000 commented 2 years ago

You are most welcome!