MQTT sending commands stops working after mosquitto restart

[m-reuter]

After my server running mosquitto reboots for software updates the raspberry running pyHPSU isn't able to send commands (for instance rotex/command/heat_slope) anymore. Reading values keeps working. After restarting the hpsu service sending commands works again. Nothing is mentioned in the logfile (LOG_LEVEL_STRING = WARNING).

Originally posted by @svde in #50 (comment)

[segaura]

@svde help me understand: are you talking of MQTT Daemon mode which stops working sometimes, while MQTT output plugin is still publishing values.
Do you confirm you are using code from segaura master branch latest commit as I guess looking at your fork?
Can you test with log level = DEBUG? (by the way, what is LOG_LEVEL_STRING?)
Are you using systemd or equivalent to start/restart the pyHPSU service?

[svde]

Do you confirm you are using code from segaura master branch latest commit as I guess looking at your fork?
Correct. I've only modified the install.sh file so it doesn't overwrite the service files.

Can you test with log level = DEBUG? (by the way, what is LOG_LEVEL_STRING?)
A (failed) attempt to set the log level via the configuration file. I've now added

Are you using systemd or equivalent to start/restart the pyHPSU service?
Yes, systemd.

As a workaround I had a cronjob which restarts the hpsu service at 03:00. I disabled this cronjob yesterday.

This morning I monitored the rotex/# topic:

$ mosquitto_sub -v -t "rotex/#"
rotex/t_hs 25.30
rotex/t_hs_set 0.00
rotex/t_ext 5.50
rotex/t_dhw 47.80
rotex/t_return 24.60
rotex/flow_rate 0
rotex/t_hc 34.70
rotex/t_hc_set 27.70
rotex/ta2 5.50
rotex/hyst_hp 7.00
rotex/command/t_room1_setpoint 19.50

I'd now expect to see the value immediately repeated in "rotex/t_room1_setpoint", but that doesn't happen.

rotex/t_hs 25.30
rotex/t_hs_set 0.00
rotex/water_pressure 1.309
rotex/t_ext 5.50
rotex/t_dhw 47.80
rotex/t_dhw_set 48.00
rotex/t_return 23.20
rotex/flow_rate 0
rotex/t_hc 34.60
rotex/t_hc_set 27.70
rotex/ta2 5.50
rotex/t_room1_setpoint 20.00

Same here.

rotex/heat_slope 0.5
rotex/t_dhw_setpoint1 48.00
rotex/hyst_hp 7.00
rotex/command/heat_slope 0.8

and here.

rotex/t_hs 25.30
rotex/t_hs_set 0.00
rotex/t_ext 5.50

After restarting the hpsu service and sending a command, it's echoed back immediately, as I expect.

rotex/command/t_dhw_setpoint1 48.00
rotex/t_dhw_setpoint1 48.00

2022-03-02 08:00:33,645 - DEBUG - mqtt output plugin data published, mid: 10
2022-03-02 08:00:59,938 - DEBUG - complete topic: rotex/command/t_dhw_setpoint1
2022-03-02 08:00:59,941 - DEBUG - command topic: t_dhw_setpoint1
2022-03-02 08:00:59,943 - DEBUG - value: 48.00
2022-03-02 08:00:59,944 - INFO - setup HPSU to accept commands
2022-03-02 08:00:59,947 - INFO - HPSU ['t_dhw_setpoint1:48.00'], loading command traslations file: /etc/pyHPSU/commands_hpsu_EN.csv
2022-03-02 08:00:59,970 - INFO - HPSU ['t_dhw_setpoint1:48.00'], loading command details file: /etc/pyHPSU/commands_hpsu.json
2022-03-02 08:01:00,032 - INFO - send command to hpsu: t_dhw_setpoint1:48.00
2022-03-02 08:01:00,037 - DEBUG - CanPI, t_dhw_setpoint1 sent: Timestamp: 0.000000 ID: 0680 S DLC: 7 32 00 fa 00 13 01 e0
2022-03-02 08:01:00,039 - INFO - send same command in read mode to hpsu: t_dhw_setpoint1:48.00
2022-03-02 08:01:00,044 - DEBUG - CanPI, t_dhw_setpoint1 sent: Timestamp: 0.000000 ID: 0190 S DLC: 7 31 00 13 00 00 00 00
2022-03-02 08:01:00,083 - DEBUG - CanPI t_dhw_setpoint1, got: 32 10 13 01 E0 00 00
2022-03-02 08:01:33,074 - INFO - HPSU ['flow_rate', 'hyst_hp', 't_hc', 't_hc_set', 't_hs', 't_hs_set', 't_ext', 't_dhw', 't_return', 'ta2'], loading command traslations file: /etc/pyHPSU/commands_hpsu_EN.csv
2022-03-02 08:01:33,095 - INFO - HPSU ['flow_rate', 'hyst_hp', 't_hc', 't_hc_set', 't_hs', 't_hs_set', 't_ext', 't_dhw', 't_return', 'ta2'], loading command details file: /etc/pyHPSU/commands_hpsu.json

It's easy to reproduce. Turn off the mosquitto service, wait 30 seconds, then turn it back on again. pyhpsu may fail to read the values once. But for the next one it sets up a new instance and is able to read again. This doesn't happen for the process which is subscribed to command topic.

[segaura]

Cool, thank you.
The MQTT-publishing-things are done by MQTT output plugin and a new MQTT client is created for each "burst" of parameters to be red from HPSU, so maybe if there are connection problems they are "forgotten" a few seconds later.
The MQTT-command-thing is done by MQTT Daemon which keeps re-using the same MQTT connection over and over, so what you describe is feasible.

I confirm the same behaviour happens on my setup, where mosquitto is 2.0.something and is running on a container.

I will investigate on this and report here. Obviously if anyone has suggestions on how to improve the code, they are welcome.

[arizzi]

Silly workaround right now: exit the program when we detect an issue with MQTT server (then the service will keep try respawing until the mqtt server is back)

           hpsu_plugin = module.export(hpsu=n_hpsu, logger=logger, config_file=options.conf_file)
            try:
                hpsu_plugin.pushValues(vars=arrResponse)
            except:
                logger.error("It seems we disconnected, exit")
                os._exit(2)

[svde]

Perhaps this is a way to do it: michaelarnauts/aiocomfoconnect@383cb94