search

volkszaehler / mbmd

ModBus Measurement Daemon - simple reading of data from ModBus meters and grid inverters
BSD 3-Clause "New" or "Revised" License
229 stars 81 forks source link

Automatic startup with systemd doesn't work with MQTT enabled and slow WiFi connections #269

Closed MartinJ-de closed 2 years ago

MartinJ-de commented 2 years ago

The provided systemd unit does not work if mbmd is configured with MQTT and the system used needs some time to establish a network connection via WiFi. Systemd will try to start mbmd fairly early and this fails because the connection to the mqtt-broker fails without running WiFi-connection. After a few tries systemd disables the service.

My workaround was a startup-file like this:

!/usr/bin/bash

sleep 60 && mbmd [...]

This enables the system to establish a working WiFi-connection and mbmd starts successfull. There should be a better way to do this.

andig commented 2 years ago

You could make the service wait for the network target,

MartinJ-de commented 2 years ago

Like this?

[Unit] Description=mbmd After=network.target [Service] ExecStart= /usr/local/bin/mbmd run -r 15s Restart=always [Install] WantedBy=multi-user.target

That unit file didn't work:

Jun 27 20:40:41 pi-hauptverteilung mbmd[416]: 2022/06/27 20:40:41 mbmd 0.13 (fa6b574) Jun 27 20:40:41 pi-hauptverteilung mbmd[416]: 2022/06/27 20:40:41 config: using /etc/mbmd.yaml Jun 27 20:40:41 pi-hauptverteilung mbmd[416]: 2022/06/27 20:40:41 config: creating RTU connection for /dev/ttyS0 (9600baud, 8N1) Jun 27 20:40:41 pi-hauptverteilung mbmd[416]: 2022/06/27 20:40:41 config: declared device SDM:21.0 Jun 27 20:40:41 pi-hauptverteilung mbmd[416]: 2022/06/27 20:40:41 config: declared device SDM:22.0 Jun 27 20:40:41 pi-hauptverteilung mbmd[416]: 2022/06/27 20:40:41 config: declared device SDM:23.0 Jun 27 20:40:41 pi-hauptverteilung mbmd[416]: 2022/06/27 20:40:41 config: declared device SDM:10.0 Jun 27 20:40:41 pi-hauptverteilung mbmd[416]: 2022/06/27 20:40:41 httpd: starting api at x.x.x.x:8080 Jun 27 20:40:41 pi-hauptverteilung mbmd[416]: 2022/06/27 20:40:41 mqtt: connecting mbmd at [tcp://y.y.y.y:1883] Jun 27 20:40:41 pi-hauptverteilung mbmd[416]: 2022/06/27 20:40:41 mqtt: error connecting: Network Error : dial tcp y.y.y.y:1883: connect: network is unreachable Jun 27 20:40:42 pi-hauptverteilung systemd[1]: mbmd.service: Main process exited, code=exited, status=1/FAILURE Jun 27 20:40:42 pi-hauptverteilung systemd[1]: mbmd.service: Failed with result 'exit-code'. Jun 27 20:40:42 pi-hauptverteilung systemd[1]: mbmd.service: Scheduled restart job, restart counter is at 5. Jun 27 20:40:42 pi-hauptverteilung systemd[1]: Stopped mbmd. Jun 27 20:40:42 pi-hauptverteilung systemd[1]: Started mbmd. Jun 27 20:40:42 pi-hauptverteilung mbmd[428]: 2022/06/27 20:40:42 mbmd 0.13 (fa6b574) Jun 27 20:40:42 pi-hauptverteilung mbmd[428]: 2022/06/27 20:40:42 config: using /etc/mbmd.yaml Jun 27 20:40:42 pi-hauptverteilung mbmd[428]: 2022/06/27 20:40:42 config: creating RTU connection for /dev/ttyS0 (9600baud, 8N1) Jun 27 20:40:42 pi-hauptverteilung mbmd[428]: 2022/06/27 20:40:42 config: declared device SDM:21.0 Jun 27 20:40:42 pi-hauptverteilung mbmd[428]: 2022/06/27 20:40:42 config: declared device SDM:22.0 Jun 27 20:40:42 pi-hauptverteilung mbmd[428]: 2022/06/27 20:40:42 config: declared device SDM:23.0 Jun 27 20:40:42 pi-hauptverteilung mbmd[428]: 2022/06/27 20:40:42 config: declared device SDM:10.0 Jun 27 20:40:42 pi-hauptverteilung mbmd[428]: 2022/06/27 20:40:42 httpd: starting api at x.x.x.x:8080 Jun 27 20:40:42 pi-hauptverteilung mbmd[428]: 2022/06/27 20:40:42 mqtt: connecting mbmd at [tcp://y.y.y.y:1883] Jun 27 20:40:42 pi-hauptverteilung mbmd[428]: 2022/06/27 20:40:42 mqtt: error connecting: Network Error : dial tcp y.y.y.y:1883: connect: network is unreachable Jun 27 20:40:42 pi-hauptverteilung systemd[1]: mbmd.service: Main process exited, code=exited, status=1/FAILURE Jun 27 20:40:42 pi-hauptverteilung systemd[1]: mbmd.service: Failed with result 'exit-code'. Jun 27 20:40:42 pi-hauptverteilung systemd[1]: mbmd.service: Scheduled restart job, restart counter is at 6. Jun 27 20:40:42 pi-hauptverteilung systemd[1]: Stopped mbmd. Jun 27 20:40:42 pi-hauptverteilung systemd[1]: mbmd.service: Start request repeated too quickly. Jun 27 20:40:42 pi-hauptverteilung systemd[1]: mbmd.service: Failed with result 'exit-code'. Jun 27 20:40:42 pi-hauptverteilung systemd[1]: Failed to start mbmd.

After that, WiFi came up.

andig commented 2 years ago

Add

Wants=network-online.target

PR for readme welcome ;)

MartinJ-de commented 2 years ago

Nope, still too early. I added the line above and replaced my start-script (with the sleep) with a direct mbmd-call.

Here wpa_supplicant had just started (this will take several seconds till network is up), mbmd gets started (and fails later, after several restarts):

Jun 28 17:54:17 pi-hauptverteilung dhcpcd[365]: wlan0: starting wpa_supplicant Jun 28 17:54:17 pi-hauptverteilung systemd[1]: systemd-machine-id-commit.service: Main process exited, code=killed, status=15/TERM Jun 28 17:54:17 pi-hauptverteilung systemd[1]: systemd-machine-id-commit.service: Failed with result 'timeout'. Jun 28 17:54:18 pi-hauptverteilung systemd[1]: Failed to start Commit a transient machine-id on disk. Jun 28 17:54:18 pi-hauptverteilung dhcpcd-run-hooks[387]: wlan0: starting wpa_supplicant Jun 28 17:54:18 pi-hauptverteilung mbmd[333]: 2022/06/28 17:54:18 config: creating RTU connection for /dev/ttyS0 (9600

andig commented 2 years ago

Doesn‘t that sound like a distro problem? Apparently your network isn‘t up although thats requested. Or the remote service ist not up yet?

MartinJ-de commented 2 years ago

This is a standard Debian 11 "Bullseye" - Lite installation, 2022-04-04-raspios-bullseye-armhf-lite.img with the latest patches on a Pi Zero W Rev. 1.1. Only mbmd installed. The remote mqtt broker is up 24/365, I'm using it for Lorawan and severals other services.

RichieB2B commented 2 years ago

I just had the same issue, fixed it by adding this to the mbmd.service file:

After=network-online.target

Wants just make the service start at the same time, After actually waits for it to be completed.

MartinJ-de commented 2 years ago

Unfortunately, this doesn't work in my environment (Raspberry Pi Zero W Rev 1.1 with Debian Lite (Bullseye), latest patch version.

This is my (new) mbmd.service

([Unit] Description=mbmd After=syslog.target After=network-online.target

[Service] ExecStart=/usr/local/bin/mbmd run -a /dev/ttyS0 -c /etc/mbmd.yaml --mqtt-homie "" -r 10s

ExecStart=/root/start_mbmd.sh

Restart=always

[Install] WantedBy=multi-user.target

In /var/log/daemon.log:

Jul 13 08:28:15 pi-hauptverteilung mbmd[261]: 2022/07/13 08:28:15 mbmd 0.13 (fa6b574) Jul 13 08:28:15 pi-hauptverteilung systemd[1]: Starting WPA supplicant... [...] Jul 13 08:28:21 pi-hauptverteilung systemd[1]: mbmd.service: Start request repeated too quickly. Jul 13 08:28:21 pi-hauptverteilung systemd[1]: mbmd.service: Failed with result 'exit-code'. Jul 13 08:28:21 pi-hauptverteilung systemd[1]: Failed to start mbmd. [...] Jul 13 08:28:31 pi-hauptverteilung dhcpcd[262]: wlan0: leased x.x.x.7 for 86400 seconds Jul 13 08:28:31 pi-hauptverteilung avahi-daemon[249]: Joining mDNS multicast group on interface wlan0.IPv4 with address x.x.x.7. Jul 13 08:28:31 pi-hauptverteilung dhcpcd[262]: wlan0: adding route to x.x.x.0/24 Jul 13 08:28:31 pi-hauptverteilung dhcpcd[262]: wlan0: adding default route via x.x.x.1

mbmd should start after this event...

RichieB2B commented 2 years ago

@MartinJ-de I have the same OS and it works for me. Did you do a systemctl daemon-reload ? With After=network-online.target mbmd should not start until after Reached target Network is Online.

Jul 13 00:36:24 keittio dhcpcd[530]: wlan0: leased 192.168.10.118 for 86400 seconds
Jul 13 00:36:24 keittio dhcpcd[530]: wlan0: adding route to 192.168.10.0/24
Jul 13 00:36:24 keittio dhcpcd[530]: wlan0: adding default route via 192.168.10.1
Jul 13 00:36:24 keittio systemd[1]: Stopping Network Time Synchronization...
Jul 13 00:36:24 keittio systemd[1]: systemd-timesyncd.service: Succeeded.
Jul 13 00:36:24 keittio systemd[1]: Stopped Network Time Synchronization.
Jul 13 00:36:24 keittio systemd[1]: Starting Network Time Synchronization...
Jul 13 00:36:25 keittio systemd[1]: Started Network Time Synchronization.
Jul 13 00:36:25 keittio dhcpcd[530]: forked to background, child pid 1739
Jul 13 00:36:25 keittio systemd[1]: Started DHCP Client Daemon.
Jul 13 00:36:25 keittio systemd[1]: Reached target Network is Online.
Jul 13 00:36:25 keittio systemd[1]: Started mbmd.

If you keep having problems try delaying the restart of mbmd by adding this to the [Service] section:

RestartSec=30