Errors resolving devices names with some commands?

[eljuanchete]

Hello, first of all let me say thank you for your fantastic evohome listener daemon. I have been using it last winter and everything was running smoothly. It has been a great help to monitor the system. When I saw your new gateway I wanted to test it. I have migrated settings and the gateway works, but when some commands are received I get some errors in the log for the commands SETPOINT_OVERRIDE, ZONE_HEAT_DEMAND, WINDOW_STATUS . The errors I get are:

2019-08-20 23:02:28 SETPOINT_OVERRIDE | 30:033798: ERROR - invalid length: --- RQ --- XX:XXXXXX YY:YYYYYY --:------ 2349 001 06 2019-08-20 23:02:28 ERROR | SETPOINT_OVERRIDE: IndexError('tuple index out of range',): --- RP --- YY:YYYYYY XX:XXXXXX --:------ 2349 007 0601F402FFFFFF

2019-08-20 22:57:52 ERROR | ZONE_HEAT_DEMAND: KeyError(252,): --- I --- YY:YYYYYY --:------ YY:YYYYYY 3150 002 FC00

2019-08-20 22:53:40 ERROR | WINDOW_STATUS: KeyError(6,): --- I --- XX:XXXXXX --:------ YY:YYYYYY 12B0 003 050000

I have masked the devices ID XX:XXXXXX is a TRV and YY:YYYYYY is the Gateway The corresponding log lines in evolistener.log are:

2019-08-20 23:02:28: --- RQ --- XX:XXXXXX YY:YYYYYY --:------ 0006 001 00 2019-08-20 23:02:28: SCHEDULE_SYNC --- RQ --- XX:XXXXXX YY:YYYYYY --:------ 0006 001 00 2019-08-20 23:02:28: --- RP --- YY:YYYYYY XX:XXXXXX --:------ 0006 004 0005071E 2019-08-20 23:02:28: SCHEDULE_SYNC --- RP --- YY:YYYYYY 30:033798 --:------ 0006 004 0005071E 2019-08-20 23:02:28: --- RQ --- XX:XXXXXX YY:YYYYYY --:------ 2349 001 06 2019-08-20 23:02:28: SETPOINT_OVERRIDE --- RQ --- XX:XXXXXX YY:YYYYYY --:------ 2349 001 06 2019-08-20 23:02:28: --- RP --- YY:YYYYYY XX:XXXXXX --:------ 2349 007 0601F402FFFFFF

2019-08-20 22:57:52 ERROR | ZONE_HEAT_DEMAND: KeyError(252,): --- I --- YY:YYYYYY --:------ YY:YYYYYY 3150 002 FC00

2019-08-20 22:53:40 ERROR | WINDOW_STATUS: KeyError(6,): --- I --- XX:XXXXXX --:------ YY:YYYYYY 12B0 003 050000

I think that these errors come from trying to resolve devices names, but did not make much progress as I am not an expert programmer. There are other errors in the log, but I think that they are due to other problems (commands not recognized, errors in RF messages, etc) Please, tell me if there is something else you need from my side to solve the errors. Regards

[smar000]

Hi

I have just pushed the current build I am using myself. This has had a number of bug fixes and updates, including support for multiple such gateways (so that they can be positioned at different locations for best reception etc).

I suggest trying this first. Certainly on my side, I am not seeing any of the errors you mention.

[eljuanchete]

That's perfect! Those errors are gone now! I am now seeing some other errors, just in case you want more information for them, because they seem harmless. These messages only happen with a zone with two TRVs. This zone is managed with the controller internal thermostat. Again, in this case ZZ:ZZZZZZZ is the zone and YY:YYYYYY is the gateway

2019-08-22 11:57:50 | | ERROR               | '252' on line 1069 [Command ZONE_HEAT_DEMAND, data: '---  I --- ZZ:ZZZZZZ --:------ ZZ:ZZZZZZ - 3150 002 FCC8', port: 1]

Next two appear when controller tries to make an RQ for SETPOINT_OVERRIDE or ZONE_INFO. I have been checking the code and it seems that responses have that payload length, but requests have a pyload length of 1

2019-08-22 11:53:06 | | SETPOINT_OVERRIDE   | Invalid payload length of 1 (should be 7 or 13). Raw msg: --- RQ --- YY:YYYYYY ZZ:ZZZZZZ --:------ 2349 001 00
2019-08-22 11:53:06 |1| SETPOINT_OVERRIDE   | RP| CTL Salon             -> GWAY Gateway          |  5.00°C @ Salon                [Zone 1 ]

2019-08-22 11:59:33 | | ZONE_INFO           | Invalid payload length of 1 (should be mod 6). Raw msg: --- RQ --- YY:YYYYYY ZZ:ZZZZZZ --:------ 000A 001 01
2019-08-22 11:59:33 |1| ZONE_INFO           | RP| CTL Salon             -> GWAY Gateway          | Temp. range: 5.0°C to 35.0°C @ Dormitorio           [Zone 2 ] (Flags: 16)

This one is a request from gateway to controller to check controller mode

2019-08-22 11:50:43 | | CONTROLLER_MODE     | Invalid payload length of 1 (should be 8). Raw msg: --- RQ --- YY:YYYYYY ZZ:ZZZZZZ --:------ 2E04 001 FF
2019-08-22 11:50:43 |1| CONTROLLER_MODE     | RP| CTL Salon             -> GWAY Gateway          | Heating Off mode  - PERMANENT

If you prefer me to open another issue or consider that these messages can be ignored you can close the issue. Thank you very much again!

[smar000]

You can ignore the RQ related errors. Those are simply because the code doesn't (yet) silently ignore the 'RQ' messages being sent out.

The Zone_Heat_Demand one is odd though, as I don't see that on mine, even on zones with multiple TRVs (I have a number of such zones). The error unfortunately does not give us the full stack trace, and so no real indication of where it is occurring.

Maybe try commenting out the try on line 1067 and then the except lines 1071 to 1073 and see if that gives you a more meaningful stack trace.

[eljuanchete]

I have made tests commenting the lines. The errors I got are:

2019-08-25 15:10:48 | | zone_id 252; zone_name BDR Boiler Relay; topic Relays/BDR Boiler Relay; demand 200| 
2019-08-25 15:10:48 | | ERROR               | '252' on line 1077 [Command ZONE_HEAT_DEMAND, data: '---  I --- 01:088499 --:------ 01:088499 3150 002 FCC8', port: 1]
Traceback (most recent call last):
  File "/opt/evogateway/evohome-Listener/evogateway.py", line 1069, in process_received_message
    COMMANDS[msg.command](msg)
  File "/opt/evogateway/evohome-Listener/evogateway.py", line 716, in zone_heat_demand
    display_data_row(msg, "{:6.1f}%".format(demand_percentage), zone_id)
  File "/opt/evogateway/evohome-Listener/evogateway.py", line 244, in display_data_row
    if ref_zone >-1 and zones[ref_zone]:
KeyError: 252

I have been checking further and don´t know if it can be related to something in my setup that may be different to yours. I have an RF controller and a separate Ethernet-RF gateway (my evohome is the non-wireless version). The controller manages temperature for one zone (Salon) with 2 TRVs. All other zones have just one TRV. In the RQ not recognized both the source and the destination are the controller (device 01:ZZZZZZ), which is also the thermostat for the one zone with 2 TRVs, so it seems that the packet is a request from the controller to the zone master thermostat to check for heat demand, right? All other ZONE_HEAT_DEMAND requests work fine. I set some debug in zone_heat_demand callback and when it is called variables have these values: zone_id 252; zone_name BDR Boiler Relay; topic Relays/BDR Boiler Relay; demand 200 However I have no zone 252 in my devices.json Nor do I have a Boiler Relay device. The boiler relay is device is 13:RRRRRR with zone number 5. Is this enough for you or do you need anything else?

[smar000]

That error is due to a minor bug in the row data display function. I've uploaded a quick fix (untested). Give this a try and see if it resolves the issue for you.

WRT the RQ not recognised, I'm not sure what you mean. Your previous error log entries on the RQ messages are entirely due to the code not being updated to ignore these requests (as those parts of the code were from the previous 'listener' only period). From what I can tell, when source/destination are the same, these are broadcast messages.

Also BTW, zone 252 is an internal to evohome zone ID for BDR relays (I think the boiler/heat relay), and possibly for some type of broadcast messages - though I'm not entirely sure on the specifics of both these. This is just what I've picked up from watching the messages on my system etc.

[eljuanchete]

Have just given a try for a couple hours and didn´t detect those errors again. Regarding the not recognized RQ I just tried to give you information that could help you troubleshoot it. Everything is working fine now. If you need/want anything else from me to test just let me know. Otherwise you can close the issue. Thank you very much again for your hard work with this.

[smar000]

Great to hear. BTW, which firmware did you use on the arduino to get the "sending" working?

[eljuanchete]

Only tried the fifo branch you recommended directly. I made no test with any other firmware. I only made some checks sending commands and still have not performed deeper tests. I plan to do it in the next weeks and rewrite some Openhab code to bypass the current binding and try to make it a completely "offline" system. Lately the connection to Evohome servers is very little reliable and downtimes are several hours long.

[smar000]

I found that that on my systems, only the fifo branch worked for sending commands (the master branch just ignored them), and hence was wondering.

FYI, on my openHAB, I have a switch to choose whether to use offline or online, in case the offline system is down for any reason, with normal operation being offline.

[eljuanchete]

I didn't think of using a switch for offline vs online use. It is a very clever option so that all automations can work whether any system is down. I'll give a look into this. Anyway, your gateway has been running in the last 10 months perfectly without even the need for restart/reboots on a Raspberry Pi 2B. Thanks again

[Gamelauncher]

After months of lurking I received my c1101 today and setup everything, I would like to give a big shout out for the work you've done!

Not wanting to hi-jack this thread, though since I ran into a similar issue I thought I'd post in here:

2019-08-27 23:49:03 |1| ZONE_TEMPERATURE    | I | CONTROLLER            -> BROADCAST MESSAGE     | 27.88°C @ Controller           [Zone 0 ] 
2019-08-27 23:50:48 |1| WINDOW_STATUS       | I | TRV Livingroom        -> CONTROLLER            |  CLOSED                        [Zone 1 ] 
2019-08-27 23:50:48 | | ERROR               | '1' on line 1069 [Command WINDOW_STATUS, data: '---  I --- 04:232201 --:------ 01:132956 12B0 003 000000', port: 1]
Traceback (most recent call last):
  File "evogateway.py", line 1069, in process_received_message
    COMMANDS[msg.command](msg)
  File "evogateway.py", line 649, in window_status
    mqtt_publish("{}/{}".format(zones[zone_id], msg.source_name),"window_status",status)
KeyError: 1
2019-08-27 23:51:31 |1| ZONE_HEAT_DEMAND    | I | TRV Bedroom           -> CONTROLLER            |    0.0% @ Bedroom              [Zone 2 ] 

From time to time the above error floats by and not sure what causes it ...

2019-08-27 21:50:37 | |                     | -----------------------------------------------------------
2019-08-27 21:50:37 | |                     | Devices loaded from 'devices.json' file:
2019-08-27 21:50:37 | |                     |    01:132956 - Controller             - Zone 0   [Master]
2019-08-27 21:50:37 | |                     |    04:232191 - Bedroom                - Zone 2   [Master]
2019-08-27 21:50:37 | |                     |    04:232195 - Office                 - Zone 3   [Master]
2019-08-27 21:50:37 | |                     |    04:232201 - Livingroom             - Zone 1  
2019-08-27 21:50:37 | |                     |    13:000432 - Heating                - Zone 252
2019-08-27 21:50:37 | |                     |    30:071715 - EvoGateway             - Zone 240 [Master]
2019-08-27 21:50:37 | |                     | -----------------------------------------------------------

Controller is an evohome wireless and is the master for zone 1.

Any idea's?

[smar000]

Can you check your devices.json file and make sure that you don't have a zone 0. Controller should be zone 1. Valid zones numbers are 1 to 12 inclusive for 'normal' zones (ignoring the 240/252 etc, which are internal).

See if that helps.

[smar000]

I didn't think of using a switch for offline vs online use. It is a very clever option so that all automations can work whether any system is down.

The latest update (just pushed a few minutes ago) also has automatic retries for failed sends. Given the nature of the evohome radio protocol, send commands do sometimes fail without warning. This build also updates a corresponding MQTT topic with send status, number of retries and permanent failure flag etc. I now have my openHAB using this failure flag to automatically resend the same command via the online version in the event of a failure from the offline version, i.e. my system default is to use offline, and if this repeatedly fails for whatever reason, try the online version.

Anyway, your gateway has been running in the last 10 months perfectly without even the need for restart/reboots on a Raspberry Pi 2B.

Great to hear!

[eljuanchete]

The latest update (just pushed a few minutes ago) also has automatic retries for failed sends. Given the nature of the evohome radio protocol, send commands do sometimes fail without warning. This build also updates a corresponding MQTT topic with send status, number of retries and permanent failure flag etc. I now have my openHAB using this failure flag to automatically resend the same command via the online version in the event of a failure from the offline version, i.e. my system default is to use offline, and if this repeatedly fails for whatever reason, try the online version.

That's great. Last year I used it mainly for monitoring purposes and getting used to Evohome setup. This year I plan on start making some automations and this will be the best way and for sure the most reliable. Thanks again

[smar000]

@Gamelauncher - did you manage to get the errors resolved? If not, I suggest opening a new issue as your errors do not seem to be related to the original issue reported in this thread.

I will accordingly close this one for now.