Can only send one command to Controller #23

eljuanchete · 2020-10-22T20:40:25Z

Hi,
using evohome-Listener v2.0.1 (python3 version) with evofw2. I tried evofw3 uart branch but could not get it to work.
I am trying to send a setpoint to 3 zones in a loop from Openhab but only the first setpoint is sent. All other two commands are ignored. I have tried to set a delay between the 3 commands, but without luck.
The first command is acknowledged

2020-10-22 22:21:45 |1/ - | COMMAND_OUT | SETPOINT_OVERRIDE ['Salon': 20 degC until 2020-10-22T23:55:00Z] Command SENT
2020-10-22 22:21:46 |1/ - | SETPOINT_OVERRIDE | W | GWAY EvoGateway -> CONTROLLER | 20.00°C @ Salon [Zone 1 ] - Until 2020-10-22 23:55:00
2020-10-22 22:21:46 |1/053| SETPOINT_OVERRIDE | I | CONTROLLER -> BROADCAST MESSAGE | 20.00°C @ Salon [Zone 1 ] - Until 2020-10-22 23:55:00
2020-10-22 22:21:46 |1/053| SETPOINT | I | CONTROLLER -> BROADCAST MESSAGE | 20.00°C @ Salon [Zone 1 ]
2020-10-22 22:21:46 |1/053| SETPOINT_OVERRIDE | I | CTL Salon -> GWAY EvoGateway | 20.00°C @ Salon [Zone 1 ] - Until 2020-10-22 23:55:00
2020-10-22 22:21:46 |1/ - | COMMAND_OUT | SETPOINT_OVERRIDE ['Salon': 20 degC until 2020-10-22T23:55:00Z] Command ACKNOWLEDGED

but no more commands are sent.

evolistener.log content is

2020-10-22 22:21:45 |-| MQTT_SUB {'command': 'setpoint_override', 'arguments': {'setpoint': 20, 'zone_id': 1, 'until': '2020-10-22T23:55:00Z'}}
2020-10-22 22:21:45 |1| COMMAND_OUT SETPOINT_OVERRIDE: Sending 'W --- 30:071715 01:088499 --:------ 2349 013 0007D004FFFFFF3717160A07E4'
2020-10-22 22:21:46 |1| SETPOINT_OVERRIDE --- W --- 30:071715 01:088499 --:------ 2349 013 0007D004FFFFFF3717160A07E4
2020-10-22 22:21:46 |1| SETPOINT_OVERRIDE --- 053 I --- 01:088499 --:------ 01:088499 2349 013 0007D004FFFFFF3717160A07E4
2020-10-22 22:21:46 |1| SETPOINT --- 053 I --- 01:088499 --:------ 01:088499 2309 003 0007D0
2020-10-22 22:21:46 |1| SETPOINT_OVERRIDE --- 053 I --- 01:088499 30:071715 --:------ 2349 013 0007D004FFFFFF3717160A07E4

After sending the command, the MQTT topics for cul_evo_gateway/sent_command are

sent_command = True
ack = False
command = setpoint_override {'setpoint': 20, 'zone_id': 1, 'until': '2020-10-22T23:55:00Z'}
evo_msg = W --- 30:071715 01:088499 --:------ 2349 013 0007D004FFFFFF3717160A07E4
failed = False
initial_sent_ts = 2020-10-22T20:18:37Z
last_retry_ts = 2020-10-15T08:36:08Z
org_instruction = {"command": "setpoint_override", "arguments": {"setpoint": 20, "zone_id": 1, "until": "2020-10-22T23:55:00Z"}}
retries = 0

and evohome-Listener seems to stop sending MQTT messages anymore. It seems as if the ACK is ACKNOWLEDGED but not recognized so no more commands are processed?
I have taken a look at the code but my coding skills are not very good and could not make progress. I think that the problem is in line 1774

if last_sent_command and msg.source == last_sent_command.destination and msg.destination == THIS_GATEWAY_ID:

but I have not been able to find the exact problem.

Do not hesitate to contact for any tests you need.
Best regards

smar000 · 2020-10-23T06:56:45Z

That's odd. I am regularly sending messages from openHAB (infact, I send a batch of 4 or 5 messages in one go every 5 minutes to get various openTherm data).

Are your 3 messages showing up in your mqtt broker, and then showing up in the evolistener logs? i.e. are you sure the messages have got through?

eljuanchete · 2020-10-23T12:07:36Z

Yes, the three messages are being sent via MQTT.
Also, although I get "Command ACKNOWLEDGED" events in events.log the MQTT topic ack is always False and the timestamp of this topic in MQTT is the same of the first MQTT message, as well as the timestamp of all the other topics under cul_evo_gateway/sent_command
So, it seems that sequence is:
1.- First MQTT message sent
2.- MQTT message subscription processed vi evohome-Listener
3.- MQTT message sent to the controller "Command SENT"
4.- All topics are updated in /sent_command with ack=False, failed=False and retries=0
5.- ACK received from controller "Command ACKNOWLEDGED"
6.- Second MQTT message sent
7.- Third MQTT message sent

So, it seems that between step 5 and 6 at least I am missing ack=True

In case it helps, I have also tried setting different THIS_GATEWAY_ID values in evogateway.cfg as I have seen several different IDs in different posts/issues, and in all cases it seems as if the first message is sent and acknowledged but not the other messages. I have configured a sleep of up to 2 seconds between commands too

Any other idea to continue debugging?

smar000 · 2020-10-23T21:35:54Z

Changing the THIS_GATEWAY_ID should not make any difference, as you are receiving messages back (as confirmed by the acknowledgement of your message).

I genuinely have no idea as to why your repeat commands are not working. It has been working fine for me for 2 years+.

Are you 100% sure that your command messages are getting through to the listener? Each time a command message is sent, it will print this in your window, and save to the file (do a search for COMMAND_OUT in the log). Are you seeing 3 such messages in your log?

Finally, what do you have in your config file for COMMAND_RESEND_TIMEOUT_SECS and COMMAND_RESEND_ATTEMPTS?

eljuanchete · 2020-10-24T10:33:42Z

Yes, 100% sure.
I kept debugging and think I have now found the error. The log file only contains the events, but the docker container log where evohome-listener is running shows an exception when the first MQTT command is processed. That's why it does not continue and no more MQTT messages are sent. I changed all my setup to docker some months ago but did not try to send commands as heating was off in spring/summer.

So, it seems as if there is a problem decoding JSON {"command":"setpoint_override", "arguments" : {"setpoint": 16.0, "zone_id" : 1}}

2020-10-24 00:35:19 |1/ - | COMMAND_OUT | SETPOINT_OVERRIDE ['Salon': 16.0 deg C] Command SENT
Exception in thread Thread-1:
Traceback (most recent call last):
File "/usr/local/lib/python3.6/threading.py", line 916, in _bootstrap_inner
self.run()
File "/usr/local/lib/python3.6/threading.py", line 864, in run
self._target(*self._args, **self._kwargs)
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 3452, in _thread_main
self.loop_forever(retry_first_connection=True)
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 1779, in loop_forever
rc = self.loop(timeout, max_packets)
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 1181, in loop
rc = self.loop_read(max_packets)
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 1572, in loop_read
rc = self._packet_read()
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 2310, in _packet_read
rc = self._packet_handle()
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 2936, in _packet_handle
return self._handle_publish()
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 3216, in _handle_publish
self._handle_on_message(message)
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 3444, in _handle_on_message
self.on_message(self, self._userdata, message)
File "/opt/evogateway/evogateway.py", line 487, in mqtt_on_message
json_data = json.loads(str(msg.payload, "utf-8"))
File "/usr/local/lib/python3.6/json/init.py", line 354, in loads
return _default_decoder.decode(s)
File "/usr/local/lib/python3.6/json/decoder.py", line 339, in decode
obj, end = self.raw_decode(s, idx=_w(s, 0).end())
File "/usr/local/lib/python3.6/json/decoder.py", line 357, in raw_decode
raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
2020-10-24 00:35:19 |1/ - | SETPOINT_OVERRIDE | W | GWAY EvoGateway -> CONTROLLER | 16.00°C @ Salon [Zone 1 ]
2020-10-24 00:35:19 |1/052| SETPOINT_OVERRIDE | I | CONTROLLER -> BROADCAST MESSAGE | 16.00°C @ Salon [Zone 1 ]
2020-10-24 00:35:19 |1/052| SETPOINT | I | CONTROLLER -> BROADCAST MESSAGE | 16.00°C @ Salon [Zone 1 ]
2020-10-24 00:35:19 |1/052| SETPOINT_OVERRIDE | I | CTL Salon -> GWAY EvoGateway | 16.00°C @ Salon [Zone 1 ]
2020-10-24 00:35:19 |1/ - | COMMAND_OUT | SETPOINT_OVERRIDE ['Salon': 16.0 deg C] Command ACKNOWLEDGED

Python version is 3.6.8 and Dockerfile is

FROM python:3.6.8
RUN mkdir /opt/evogateway
WORKDIR /opt/evogateway
RUN pip install --upgrade pip
RUN pip install pyserial
RUN pip install paho-mqtt
RUN pip install enum34
COPY ./data/* /opt/evogateway/
CMD [ "python", "/opt/evogateway/evogateway.py" ]

I changed the container to use UTF-8 and made a test to check python is using UTF8

root@905cf87e0d8b:/opt/evogateway# python
Python 3.6.8 (default, Jun 11 2019, 01:16:11)
[GCC 6.3.0 20170516] on linux
Type "help", "copyright", "credits" or "license" for more information.

print(chr(0x5555))
啕

So it seems that this is fine. Then uncommented debug lines print(msg.payload) and print(json_data) in lines 483 and 488 and see

b'{"command":"setpoint_override", "arguments" : {"setpoint": 16.0, "zone_id" : 1}}'
{'command': 'setpoint_override', 'arguments': {'setpoint': 16.0, 'zone_id': 1}}
2020-10-24 12:29:59 |1/ - | COMMAND_OUT | SETPOINT_OVERRIDE ['Salon': 16.0 deg C] Command SENT
b''
Exception in thread Thread-1:
Traceback (most recent call last):
File "/usr/local/lib/python3.6/threading.py", line 916, in _bootstrap_inner
self.run()
File "/usr/local/lib/python3.6/threading.py", line 864, in run
self._target(*self._args, **self._kwargs)
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 3452, in _thread_main
self.loop_forever(retry_first_connection=True)
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 1779, in loop_forever
rc = self.loop(timeout, max_packets)
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 1181, in loop
rc = self.loop_read(max_packets)
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 1572, in loop_read
rc = self._packet_read()
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 2310, in _packet_read
rc = self._packet_handle()
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 2936, in _packet_handle
return self._handle_publish()
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 3216, in _handle_publish
self._handle_on_message(message)
File "/usr/local/lib/python3.6/site-packages/paho/mqtt/client.py", line 3444, in _handle_on_message
self.on_message(self, self._userdata, message)
File "/opt/evogateway/evogateway.py", line 487, in mqtt_on_message
json_data = json.loads(msg.payload.decode("utf-8"))
File "/usr/local/lib/python3.6/json/init.py", line 354, in loads
return _default_decoder.decode(s)
File "/usr/local/lib/python3.6/json/decoder.py", line 339, in decode
obj, end = self.raw_decode(s, idx=_w(s, 0).end())
File "/usr/local/lib/python3.6/json/decoder.py", line 357, in raw_decode
raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
2020-10-24 12:29:59 |1/ - | SETPOINT_OVERRIDE | W | GWAY EvoGateway -> CONTROLLER | 16.00°C @ Salon [Zone 1 ]
2020-10-24 12:29:59 |1/051| SETPOINT_OVERRIDE | I | CONTROLLER -> BROADCAST MESSAGE | 16.00°C @ Salon [Zone 1 ]
2020-10-24 12:29:59 |1/051| SETPOINT | I | CONTROLLER -> BROADCAST MESSAGE | 16.00°C @ Salon [Zone 1 ]
2020-10-24 12:29:59 |1/051| SETPOINT_OVERRIDE | I | CTL Salon -> GWAY EvoGateway | 16.00°C @ Salon [Zone 1 ]
2020-10-24 12:29:59 |1/ - | COMMAND_OUT | SETPOINT_OVERRIDE ['Salon': 16.0 deg C] Command ACKNOWLEDGED

Then I tried to make some changes in the json.loads line but, to be honest, I don't know very well what I am doing. Do you have any idea on what might be wrong related to this UTF8 coding?

smar000 · 2020-10-25T16:08:46Z

Ah ok, you didn't mention before that you were running in a docker (shouldn't make a difference if done in exactly the same way, but introduces another potential source of problems). I had a quick look at your log above and the respective code, but nothing jumps out. It may be worth trying it out without the docker environment and see if that shows anything further.

Sorry, but unfortunately I don't really have the time to spend much further on this.

eljuanchete · 2020-10-26T14:18:17Z

Yes, I understand this does not seem related to the script but to the environment where it is running.
I have made a quick change to avoid the exception in case an invalid JSON is sent.

The changes proposed are just to catch the exception. This is working fine in my environment.
Maybe this can incorporated in evohome-Listener? What do you think?

At beginning of script

from json.decoder import JSONDecodeError

Line 487

  try:
    json_data = json.loads(msg.payload.decode())
    #print(json_data)
    log("{: <18} {}".format("MQTT_SUB", json_data))

    if SYS_CONFIG_COMMAND in json_data:
      if json_data[SYS_CONFIG_COMMAND] in RESET_COM_PORTS:
        new_command = get_reset_serialports_command()
        new_command.instruction = json.dumps(json_data)
      elif json_data[SYS_CONFIG_COMMAND] == CANCEL_SEND_COMMANDS:
        send_queue = []
        last_sent_command = None
        display_and_log(SYSTEM_MSG_TAG, "Cancelled all queued outbound commands")
        return
      else:
        display_and_log(SYSTEM_MSG_TAG, "System configuration command '{}' not recognised".format(json_data[SYS_CONFIG_COMMAND]))
        return
    else:
      new_command = get_command_from_mqtt_json(json_data)

    send_queue.append(new_command)
  except JSONDecodeError as e:
    return

smar000 · 2020-10-29T22:20:26Z

Thanks. I'll consider it next time I'm looking at the code, but in general I don't like silently dropping errors. Better to understand the cause of the problem and then try to address that if possible (admittedly not always easy!).

#23) Add exception handling for JSON Decode Error

dhuizinga · 2021-09-06T19:57:14Z

I apologize in advance for what is likely inappropriate use of this commenting-on-a-closed-issue to gain some specific knowledge on the topic of using this script with docker, but can I ask whether the the end the docker approach below is now functional, @eljuanchete ?

Python version is 3.6.8 and Dockerfile is

FROM python:3.6.8
RUN mkdir /opt/evogateway
WORKDIR /opt/evogateway
RUN pip install --upgrade pip
RUN pip install pyserial
RUN pip install paho-mqtt
RUN pip install enum34
COPY ./data/* /opt/evogateway/
CMD [ "python", "/opt/evogateway/evogateway.py" ]

And while on the subject, it looks as if the dockerfile above uses the script already present on the host. Is there an idiot-proof way of including even the retrieval of the (latest) script from this repository in above dockerfile?

Again, apologies if inappropriate, kindly tell me what would be the appropriate way to discuss such topics :)

eljuanchete · 2021-09-07T18:49:24Z

Hello, this is (IIRC) the docker file I used (more or less like yours except you are not installing ramsesrf (take into count that a new release of ramses_rf with breaking changes has just been released so maybe you should use the previous one)) FROM python:3 RUN mkdir /opt/evogateway WORKDIR /opt/evogateway RUN pip install pyserial RUN pip install paho-mqtt RUN pip install enum34 RUN pip install colorama RUN pip install ramses_rf COPY ./data/* /opt/evogateway/ CMD [ "python", "/opt/evogateway/evogateway.py" ] I did not configure an automated download and perform manual upgrades I seem to recall that I had problems while setting up the latest version due to the changes in config files, but can’t remember what was the problem and how I solved it. I just can tell that once I got it working it has been running smoothly since then Sorry I cannot be of much help here Best regards

…

El 6 sept 2021, a las 21:57, dhuizinga ***@***.***> escribió: I apologize in advance for what is likely inappropriate use of this commenting-on-a-closed-issue to gain some specific knowledge on the topic of using this script with docker, but can I ask whether the the end the docker approach below is now functional, @eljuanchete <https://github.com/eljuanchete> ? Python version is 3.6.8 and Dockerfile is FROM python:3.6.8 RUN mkdir /opt/evogateway WORKDIR /opt/evogateway RUN pip install --upgrade pip RUN pip install pyserial RUN pip install paho-mqtt RUN pip install enum34 COPY ./data/* /opt/evogateway/ CMD [ "python", "/opt/evogateway/evogateway.py" ] And while on the subject, it looks as if the dockerfile above uses the script already present on the host. Is there an idiot-proof way of including even the retrieval of the (latest) script from this repository in above dockerfile? Again, apologies if inappropriate, kindly tell me what would be the appropriate way to discuss such topics :) — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#23 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AGM5I4C6ZGMXXLTG6ZRT3C3UAUMKNANCNFSM4S3WO6EQ>. Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

smar000 closed this as completed Oct 29, 2020

PRoomberg mentioned this issue Dec 31, 2020

Add exception handling for JSON Decode Error #27

Merged

smar000 added a commit that referenced this issue Jan 1, 2021

Merge pull request #27 from PRoomberg/Fix-for-JSCON-decode-error-(issue-

ebb315e

#23) Add exception handling for JSON Decode Error

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Can only send one command to Controller #23

Can only send one command to Controller #23

eljuanchete commented Oct 22, 2020

smar000 commented Oct 23, 2020

eljuanchete commented Oct 23, 2020

smar000 commented Oct 23, 2020

eljuanchete commented Oct 24, 2020

smar000 commented Oct 25, 2020

eljuanchete commented Oct 26, 2020

smar000 commented Oct 29, 2020

dhuizinga commented Sep 6, 2021

eljuanchete commented Sep 7, 2021 via email

Can only send one command to Controller #23

Can only send one command to Controller #23

Comments

eljuanchete commented Oct 22, 2020

smar000 commented Oct 23, 2020

eljuanchete commented Oct 23, 2020

smar000 commented Oct 23, 2020

eljuanchete commented Oct 24, 2020

smar000 commented Oct 25, 2020

eljuanchete commented Oct 26, 2020

smar000 commented Oct 29, 2020

dhuizinga commented Sep 6, 2021

eljuanchete commented Sep 7, 2021 via email