Service not starting after boot, but service running fine when started manually

[eikowagenknecht]

Hi there, I'm running this on a raspberry pi 3b, latest raspbian.

I can start mbusd via command line:
pi@pi-modbus:~ $ sudo mbusd -c /etc/mbusd/mbusd-ttyUSB0.conf
I can also start as a service:
pi@pi-modbus:~ $ sudo systemctl start [email protected]
It runs just fine like that (log below for service start):

pi@pi-modbus:~ $ sudo journalctl -u [email protected] -f -n 10
-- Logs begin at Thu 2019-02-14 11:11:59 CET. --
May 14 16:00:41 pi-modbus systemd[1]: Started Modbus TCP to Modbus RTU (RS-232/485) gateway..
May 14 16:00:41 pi-modbus mbusd[15393]: 14 May 2020 16:00:41 mbusd-0.4.1 started...
May 14 16:00:43 pi-modbus mbusd[15393]: 14 May 2020 16:00:43 conn_open(): accepting connection from 192.168.40.32
May 14 16:00:53 pi-modbus mbusd[15393]: 14 May 2020 16:00:53 conn_close(): closing connection from 192.168.40.32
May 14 16:00:53 pi-modbus mbusd[15393]: 14 May 2020 16:00:53 conn_open(): accepting connection from 192.168.40.32
May 14 16:01:03 pi-modbus mbusd[15393]: 14 May 2020 16:01:03 conn_close(): closing connection from 192.168.40.32
May 14 16:01:03 pi-modbus mbusd[15393]: 14 May 2020 16:01:03 conn_open(): accepting connection from 192.168.40.32
May 14 16:01:13 pi-modbus mbusd[15393]: 14 May 2020 16:01:13 conn_close(): closing connection from 192.168.40.32
May 14 16:01:13 pi-modbus mbusd[15393]: 14 May 2020 16:01:13 conn_open(): accepting connection from 192.168.40.32
May 14 16:01:23 pi-modbus mbusd[15393]: 14 May 2020 16:01:23 conn_close(): closing connection from 192.168.40.32
May 14 16:01:23 pi-modbus mbusd[15393]: 14 May 2020 16:01:23 conn_open(): accepting connection from 192.168.40.32
May 14 16:01:33 pi-modbus mbusd[15393]: 14 May 2020 16:01:33 conn_close(): closing connection from 192.168.40.32
May 14 16:01:33 pi-modbus mbusd[15393]: 14 May 2020 16:01:33 conn_open(): accepting connection from 192.168.40.32

But when I enable the service:

pi@pi-modbus:~ $ sudo systemctl enable [email protected]
Created symlink /etc/systemd/system/multi-user.target.wants/[email protected] → /lib/systemd/system/[email protected].

And reboot the raspberry:
pi@pi-modbus:~ $ sudo reboot
I only get a "Failed to start ..." message in the logs:

pi@pi-modbus:~ $ sudo journalctl -u [email protected] -f -n 500
-- Logs begin at Thu 2020-05-14 16:02:10 CEST. --
May 14 16:02:13 pi-modbus systemd[1]: Started Modbus TCP to Modbus RTU (RS-232/485) gateway..
May 14 16:02:13 pi-modbus mbusd[298]: 14 May 2020 16:02:13 mbusd-0.4.1 started...
May 14 16:02:13 pi-modbus mbusd[298]: 14 May 2020 16:02:13 sock_create_server(): unable to bind() socket (Cannot assign requested address)
May 14 16:02:13 pi-modbus mbusd[298]: 14 May 2020 16:02:13 conn_init(): can't create listen socket (Cannot assign requested address)
May 14 16:02:13 pi-modbus mbusd[298]: 14 May 2020 16:02:13 conn_init() failed, exiting...
May 14 16:02:14 pi-modbus systemd[1]: [email protected]: Main process exited, code=exited, status=99/n/a
May 14 16:02:14 pi-modbus systemd[1]: [email protected]: Failed with result 'exit-code'.
May 14 16:02:15 pi-modbus systemd[1]: [email protected]: Service RestartSec=1s expired, scheduling restart.
May 14 16:02:15 pi-modbus systemd[1]: [email protected]: Scheduled restart job, restart counter is at 1.
May 14 16:02:15 pi-modbus systemd[1]: Stopped Modbus TCP to Modbus RTU (RS-232/485) gateway..
May 14 16:02:15 pi-modbus systemd[1]: Started Modbus TCP to Modbus RTU (RS-232/485) gateway..
May 14 16:02:15 pi-modbus mbusd[412]: 14 May 2020 16:02:15 mbusd-0.4.1 started...
May 14 16:02:15 pi-modbus mbusd[412]: 14 May 2020 16:02:15 sock_create_server(): unable to bind() socket (Cannot assign requested address)
May 14 16:02:15 pi-modbus mbusd[412]: 14 May 2020 16:02:15 conn_init(): can't create listen socket (Cannot assign requested address)
May 14 16:02:15 pi-modbus mbusd[412]: 14 May 2020 16:02:15 conn_init() failed, exiting...
May 14 16:02:15 pi-modbus systemd[1]: [email protected]: Main process exited, code=exited, status=99/n/a
May 14 16:02:15 pi-modbus systemd[1]: [email protected]: Failed with result 'exit-code'.
May 14 16:02:16 pi-modbus systemd[1]: [email protected]: Service RestartSec=1s expired, scheduling restart.
May 14 16:02:16 pi-modbus systemd[1]: [email protected]: Scheduled restart job, restart counter is at 2.
May 14 16:02:16 pi-modbus systemd[1]: Stopped Modbus TCP to Modbus RTU (RS-232/485) gateway..
May 14 16:02:16 pi-modbus systemd[1]: Started Modbus TCP to Modbus RTU (RS-232/485) gateway..
May 14 16:02:16 pi-modbus mbusd[414]: 14 May 2020 16:02:16 mbusd-0.4.1 started...
May 14 16:02:16 pi-modbus mbusd[414]: 14 May 2020 16:02:16 sock_create_server(): unable to bind() socket (Cannot assign requested address)
May 14 16:02:16 pi-modbus mbusd[414]: 14 May 2020 16:02:16 conn_init(): can't create listen socket (Cannot assign requested address)
May 14 16:02:16 pi-modbus mbusd[414]: 14 May 2020 16:02:16 conn_init() failed, exiting...
May 14 16:02:16 pi-modbus systemd[1]: [email protected]: Main process exited, code=exited, status=99/n/a
May 14 16:02:16 pi-modbus systemd[1]: [email protected]: Failed with result 'exit-code'.
May 14 16:02:17 pi-modbus systemd[1]: [email protected]: Service RestartSec=1s expired, scheduling restart.
May 14 16:02:17 pi-modbus systemd[1]: [email protected]: Scheduled restart job, restart counter is at 3.
May 14 16:02:17 pi-modbus systemd[1]: Stopped Modbus TCP to Modbus RTU (RS-232/485) gateway..
May 14 16:02:17 pi-modbus systemd[1]: Started Modbus TCP to Modbus RTU (RS-232/485) gateway..
May 14 16:02:17 pi-modbus mbusd[464]: 14 May 2020 16:02:17 mbusd-0.4.1 started...
May 14 16:02:17 pi-modbus mbusd[464]: 14 May 2020 16:02:17 sock_create_server(): unable to bind() socket (Cannot assign requested address)
May 14 16:02:17 pi-modbus mbusd[464]: 14 May 2020 16:02:17 conn_init(): can't create listen socket (Cannot assign requested address)
May 14 16:02:17 pi-modbus mbusd[464]: 14 May 2020 16:02:17 conn_init() failed, exiting...
May 14 16:02:17 pi-modbus systemd[1]: [email protected]: Main process exited, code=exited, status=99/n/a
May 14 16:02:17 pi-modbus systemd[1]: [email protected]: Failed with result 'exit-code'.
May 14 16:02:19 pi-modbus systemd[1]: [email protected]: Service RestartSec=1s expired, scheduling restart.
May 14 16:02:19 pi-modbus systemd[1]: [email protected]: Scheduled restart job, restart counter is at 4.
May 14 16:02:19 pi-modbus systemd[1]: Stopped Modbus TCP to Modbus RTU (RS-232/485) gateway..
May 14 16:02:19 pi-modbus systemd[1]: Started Modbus TCP to Modbus RTU (RS-232/485) gateway..
May 14 16:02:19 pi-modbus mbusd[475]: 14 May 2020 16:02:19 mbusd-0.4.1 started...
May 14 16:02:19 pi-modbus mbusd[475]: 14 May 2020 16:02:19 sock_create_server(): unable to bind() socket (Cannot assign requested address)
May 14 16:02:19 pi-modbus mbusd[475]: 14 May 2020 16:02:19 conn_init(): can't create listen socket (Cannot assign requested address)
May 14 16:02:19 pi-modbus mbusd[475]: 14 May 2020 16:02:19 conn_init() failed, exiting...
May 14 16:02:19 pi-modbus systemd[1]: [email protected]: Main process exited, code=exited, status=99/n/a
May 14 16:02:19 pi-modbus systemd[1]: [email protected]: Failed with result 'exit-code'.
May 14 16:02:20 pi-modbus systemd[1]: [email protected]: Service RestartSec=1s expired, scheduling restart.
May 14 16:02:20 pi-modbus systemd[1]: [email protected]: Scheduled restart job, restart counter is at 5.
May 14 16:02:20 pi-modbus systemd[1]: Stopped Modbus TCP to Modbus RTU (RS-232/485) gateway..
May 14 16:02:20 pi-modbus systemd[1]: [email protected]: Start request repeated too quickly.
May 14 16:02:20 pi-modbus systemd[1]: [email protected]: Failed with result 'exit-code'.
May 14 16:02:20 pi-modbus systemd[1]: Failed to start Modbus TCP to Modbus RTU (RS-232/485) gateway..

Waiting does not help, but restarting fixes it:
pi@pi-modbus:~ $ sudo systemctl restart [email protected]

Since I do not want to have to do this after every reboot I'm asking:

How can I fix this? I am no linux expert but have never seen this with other services (like openhab, homebridge etc..).

[eikowagenknecht]

After some research (mainly https://www.freedesktop.org/wiki/Software/systemd/NetworkTarget/), I changed the service file /lib/systemd/system/[email protected] to include a reference to network-online.target as "After" and "Wants":

[Unit]
Description=Modbus TCP to Modbus RTU (RS-232/485) gateway.
After=network-online.target
Wants=network-online.target
Requires=network.target

[Service]
ExecStart=/usr/bin/mbusd -d -v2 -L - -c /etc/mbusd/mbusd-%i.conf -p /dev/%i
Restart=on-failure
RestartSec=1
StandardOutput=journal
StandardError=journal

[Install]
WantedBy=multi-user.target

That seems to have fixed it and makes sense to me because mbusd cannot bind to the correct address until the network is up and running.

Maybe it would make sense to include this in the generated service file or make the program more robust to changing network conditions (like the link above suggests)?

[3cky]

Thank you! I'll update the service file with these changes.

[3cky]

Probably related to #56.