MQTT connection lost (timeout) and never reconnect when bus is lost for a moment

[mdelpire]

Hi,

Thanks a lot for the work to make ebus available to the outside world. I'm running ebusd on docker and communicate with an adapter v3 over Wifi. I'm mainly using MQTT to query the bus (one query / second). I noticed that sometimes, I'm using the connection with the MQTT broker and unfortunately this one won't be reconnected afterwards without the restart of the container. This connection happens when the bus is lost for a moment. In the log below, we see for instance that the bus was lost for a reason or another for about 10 seconds. I don't know why I have the strange device status at the end. If we look at the log of the MQTT broker at the same time (yime is not synchronized so timestamps is not exactly the same) we see a timeout for the client ebusd and this one is nerver reconnected.

Is there something I can do to avoid this in the future?

Thanks a lot,

Maxime

ebusd log

2021-03-26 12:11:49.048 [update notice] received update-write bai SetMode QQ=10: auto;0.0;60.0;-;1;0;1;0;0;0, 2021-03-26 12:11:53.266 [update notice] received read bai Status01 QQ=10: 28.0;28.0;13.500;55.0;52.0;off, 2021-03-26 12:11:55.366 [update notice] received read bai DateTime QQ=10: sync;13:12:18;-.-.-;13.500, 2021-03-26 12:11:59.539 [update notice] received update-write bai SetMode QQ=10: auto;0.0;60.0;-;1;0;1;0;0;0 2021-03-26 12:12:01.063 [bus notice] arbitration won in invalid state skip, 2021-03-26 12:12:11.053 [bus error] send message part 0: ERR: no signal, 2021-03-26 12:12:02.895 [bus notice] arbitration won in invalid state skip, 2021-03-26 12:12:06.220 [bus error] send to 08: ERR: SYN received, retry, 2021-03-26 12:12:11.052 [bus error] send message part 0: ERR: no signal, 2021-03-26 12:12:11.052 [bus error] send to 08: ERR: no signal, give up, 2021-03-26 12:12:11.052 [mqtt error] read bai PartloadHcKW: ERR: no signal, 2021-03-26 12:12:11.052 [mqtt error] read bai WPPostrunTime: ERR: no signal, 2021-03-26 12:12:11.052 [mqtt error] read bai BlockTimeHcMax: ERR: no signal, 2021-03-26 12:12:11.052 [mqtt error] read bai HwcTemp: ERR: no signal, 2021-03-26 12:12:11.052 [mqtt error] read bai StorageTemp: ERR: no signal, 2021-03-26 12:12:11.053 [mqtt error] read bai FlowTempDesired: ERR: no signal, 2021-03-26 12:12:11.053 [bus error] send to 08: ERR: no signal, give up, 2021-03-26 12:12:11.053 [mqtt error] read bai HwcTempDesired: ERR: no signal, 2021-03-26 12:12:11.053 [mqtt error] read bai StorageTempDesired: ERR: no signal, 2021-03-26 12:12:11.053 [mqtt error] read bai ACRoomthermostat: ERR: no signal, 2021-03-26 12:12:11.053 [mqtt error] read bai ExtFlowTempDesiredMin: ERR: no signal, 2021-03-26 12:12:11.053 [mqtt error] read bai WP: ERR: no signal, 2021-03-26 12:12:11.053 [bus error] signal lost, 2021-03-26 12:12:11.613 [bus error] send to 08: ERR: no signal, give up, 2021-03-26 12:12:11.613 [bus error] send message part 0: ERR: no signal, 2021-03-26 12:12:11.613 [mqtt error] read bai extWP: ERR: no signal, 2021-03-26 12:12:12.735 [bus error] send to 08: ERR: no signal, give up, 2021-03-26 12:12:12.735 [bus error] send message part 0: ERR: no signal, 2021-03-26 12:12:12.735 [mqtt error] read bai Storageloadpump: ERR: no signal, 2021-03-26 12:12:13.575 [bus error] send to 08: ERR: no signal, give up, 2021-03-26 12:12:13.575 [bus error] send message part 0: ERR: no signal, 2021-03-26 12:12:13.575 [mqtt error] read bai CirPump: ERR: no signal, 2021-03-26 12:12:14.696 [bus error] send to 08: ERR: no signal, give up, 2021-03-26 12:12:14.696 [bus error] send message part 0: ERR: no signal, 2021-03-26 12:12:14.696 [mqtt error] read bai WPPWMPower: ERR: no signal, 2021-03-26 12:12:15.818 [bus error] send to 08: ERR: no signal, give up, 2021-03-26 12:12:15.818 [bus error] send message part 0: ERR: no signal, 2021-03-26 12:12:15.818 [mqtt error] read bai DCRoomthermostat: ERR: no signal, 2021-03-26 12:12:16.252 [bus error] device status: unexpected available enhanced following byte 1, 2021-03-26 12:12:16.263 [bus notice] signal acquired, 2021-03-26 12:12:16.436 [bus error] device status: unexpected available enhanced byte 2, 2021-03-26 12:12:16.455 [bus error] device status: unexpected available enhanced byte 2, 2021-03-26 12:12:16.548 [bus error] device status: unexpected available enhanced byte 2, 2021-03-26 12:12:16.905 [update notice] received read bai Status01 QQ=10: 28.0;28.0;13.500;55.0;52.0;off, 2021-03-26 12:12:17.000 [bus notice] max. symbols per second: 120, 2021-03-26 12:12:17.022 [update notice] received update-read broadcast vdatetime QQ=10: 13:12:18;26.03.2021, 2021-03-26 12:12:18.442 [update notice] received update-write bai SetMode QQ=10: auto;0.0;60.0;-;1;0;1;0;0;0,

MQTT log

2021-03-26T12:13:43.375399090Z 1616760823: Client ebusd_21.2_1 has exceeded timeout, disconnecting.

[mdelpire]

Update with log in debug mode, bus signal was shortly lost and MQTT has been disconnected on the broker side

2021-03-29 06:48:13.155 [bus debug] send/receive symbol latency 9 ms, 2021-03-29 06:48:13.929 [mqtt debug] received topic ebusd/bai/CirPump/get with data 1, 2021-03-29 06:48:13.929 [mqtt info] received get topic for bai CirPump, 2021-03-29 06:48:13.929 [bus info] send message: 3108b509030d7b00, 2021-03-29 06:48:13.972 [bus debug] start request 31, 2021-03-29 06:48:13.972 [bus debug] arbitration start with 31, 2021-03-29 06:48:14.438 [bus notice] arbitration won in invalid state skip, 2021-03-29 06:48:14.439 [bus debug] ERR: read timeout during skip, switching to ready, 2021-03-29 06:48:14.483 [bus debug] ERR: SYN received during receive command, switching to ready 2021-03-29 06:48:14.498 [bus debug] start request 31, 2021-03-29 06:48:14.498 [bus debug] arbitration start with 31, 2021-03-29 06:48:14.563 [main debug] performing regular tasks, 2021-03-29 06:48:16.040 [mqtt error] read bai CirPump: ERR: no signal, 2021-03-29 06:48:16.040 [mqtt debug] publish ebusd/bai/SetMode auto;64.0;60.0;-;0;0;1;0;0;0, 2021-03-29 06:48:16.040 [mqtt debug] publish ebusd/bai/DateTime valid;08:48:12;29.03.2021;6.875, 2021-03-29 06:48:16.040 [mqtt debug] publish ebusd/bai/Status02 auto;60;64.0;80;60.0, 2021-03-29 06:48:16.040 [mqtt debug] publish ebusd/bai/ACRoomthermostat on, 2021-03-29 06:48:16.040 [mqtt debug] publish ebusd/bai/extWP on, 2021-03-29 06:48:16.040 [mqtt debug] publish ebusd/bai/WP on, 2021-03-29 06:48:16.040 [mqtt debug] publish ebusd/bai/ExtFlowTempDesiredMin 64.00, 2021-03-29 06:48:16.040 [mqtt debug] publish ebusd/bai/Storageloadpump 0, 2021-03-29 06:48:16.040 [mqtt debug] received topic ebusd/bai/WPPWMPower/get with data 1, 2021-03-29 06:48:16.040 [mqtt info] received get topic for bai WPPWMPower, 2021-03-29 06:48:16.040 [bus info] send message: 3108b509030d7300, 2021-03-29 06:48:16.040 [bus error] send to 08: ERR: no signal, give up, 2021-03-29 06:48:16.040 [bus error] send message part 0: ERR: no signal, 2021-03-29 06:48:16.040 [mqtt error] read bai WPPWMPower: ERR: no signal, 2021-03-29 06:48:16.040 [mqtt debug] received topic ebusd/bai/DCRoomthermostat/get with data 1, 2021-03-29 06:48:16.040 [mqtt info] received get topic for bai DCRoomthermostat, 2021-03-29 06:48:16.040 [bus info] send message: 3108b509030d0e00, 2021-03-29 06:48:16.040 [mqtt error] read bai DCRoomthermostat: ERR: no signal, 2021-03-29 06:48:16.040 [bus debug] ERR: read timeout during skip, switching to no signal, 2021-03-29 06:48:16.040 [bus error] signal lost, 2021-03-29 06:48:16.475 [bus debug] ERR: SYN received during no signal, switching to ready, 2021-03-29 06:48:16.475 [bus notice] signal acquired, 2021-03-29 06:48:16.489 [bus error] device status: unexpected available enhanced byte 2, 2021-03-29 06:48:16.930 [mqtt debug] received topic ebusd/bai/HwcDemand/get with data 1, 2021-03-29 06:48:16.930 [mqtt info] received get topic for bai HwcDemand, 2021-03-29 06:48:16.930 [bus info] send message: 3108b509030d5800, 2021-03-29 06:48:19.154 [update info] received MS cmd: 1008b5110101 / 097e68e006847e0100ff, 2021-03-29 06:48:19.155 [update notice] received read bai Status01 QQ=10: 63.0;52.0;6.875;66.0;63.0;on, 2021-03-29 06:48:21.188 [update info] received BC cmd: 10feb5160301e006, 2021-03-29 06:48:21.188 [update notice] received update-read broadcast outsidetemp QQ=10: 6.875

[john30]

please increase the disconnect timeout on the broker and check if the behaviour is the same

[mdelpire]

Hi, Thanks for your response. I checked the configuration file of my broker but I don't see any disconnect timeout in the configuration file of Mosquitto. However the keep alive can be defined at the client side which is hardcoded to 60 for ebusd if I am not wrong.

Is there another way to inscrease a disconnect timeout? Also is it normal that when the MQTT disconnects it never tries to reconnect?

Thanks

[gebenh]

I had a similar issue but I don't know whether its directly related but the behavior and log messages were similar to this issue report. Nevertheless, maybe it helps analyzing the issue: My Problem: I didn't receive updated values on the MQTT from the polling of ebusd after few hours of running ebusd. Therefore, I thought that it is an mqtt issue, but then I realized that I still receive the ebusd/global/# messages.

After increasing the --latency parameter from 20 to 100 for ebusd and restarting the ebus adapter 3 (wifi version) it is stable since 5 days on my side. Regards,

[Trilis29]

I have the same problem, if I have my mqtt server restarted ebusd does not try to reconnect... any solution yet?

[john30]

I can't reproduce this with the current code base. could you please clone this repo, compile and check if the behaviour persists?

[john30]

closed due to inactivity