lrhorer
Posts: 54
Joined: Sun Feb 22, 2015 6:35 pm

systemd module not working

Thu Aug 01, 2019 1:22 pm

I am running a headless Raspberry Pi 2 as a simple relay controller. In order to work properly, I need certain directories and files to exist at boot time, so I created a simple BASH script and made it a systemd service. It isn't working, however. I can run the script after the system boots, and it works just fine, but the directories and their permissions are not set when the unit runs at boot. This causes some of the other services to fail. I have tried changing the dependencies, to no avail. Does anyone have any idea what is - or rather, isn't - going on here?

/lib/systemd/system/varlog.service:

[Unit]
Description=Create directories in /var/log
Requires=local-fs.target
After=local-fs.target

[Service]
Type=oneshot
ExecStart=/bin/bash /usr/local/sbin/varlog

[Install]
Alias=varlog



/usr/local/sbin/varlog:

/bin/mkdir -p /var/log/lightdm
/bin/mkdir -p /var/log/thermostat
/bin/mkdir -p /run/thermostat
/bin/chgrp -R thermostat /run/thermostat
/bin/chmod -f 777 /run/thermostat
/bin/chmod -f 777 /var/log/thermostat
/bin/chmod -f 664 /run/thermostat/*
/bin/chmod -f 664 /var/log/thermostat/*

User avatar
RaTTuS
Posts: 10532
Joined: Tue Nov 29, 2011 11:12 am
Location: North West UK
Contact: Twitter YouTube

Re: systemd module not working

Thu Aug 01, 2019 1:29 pm

your logic is backwards
make those other services depend on that on having run not the other way round
How To ask Questions :- http://www.catb.org/esr/faqs/smart-questions.html
WARNING - some parts of this post may be erroneous YMMV

1QC43qbL5FySu2Pi51vGqKqxy3UiJgukSX
Covfefe

lrhorer
Posts: 54
Joined: Sun Feb 22, 2015 6:35 pm

Re: systemd module not working

Thu Aug 01, 2019 2:49 pm

My logic is not backwards. They do depend upon it, and it runs, doesn't work which means they fail, which is exactly what I said in my post. Note I have made varlog dependent upon local-fs.target ( I tried other targets and services, as well), which creates the local file systems. Obviously, in order for varlog to create directories on the local file systems, those file systems must be mounted. The /run and /var/log directores are both tmpfs file systems. On another system with Apache2 installed, I made an almost identical varlog service a prerequisite for Apache2, and it works just fine, but this system isn't running a web server.

For reference, here are the other services I created.

tserver.service:
[Unit]
Description=Send data to network
After=varlog.service
Requires=varlog.service

[Service]
Type=simple
Restart=always
RestartSec=10
ExecStart=/usr/bin/python3 /usr/local/sbin/TServer.py

[Install]
Alias=tserver



tclient.service :
[Unit]
Description=Get data from Thermostat
After=varlog.service
Requires=varlog.service

[Service]
Type=simple
Restart=always
RestartSec=10
ExecStart=/usr/bin/python3 /usr/local/sbin/TClient.py

[Install]
Alias=tclient

bls
Posts: 406
Joined: Mon Oct 22, 2018 11:25 pm
Location: Seattle, WA
Contact: Twitter

Re: systemd module not working

Thu Aug 01, 2019 2:56 pm

What is the result of doing 'sudo systemctl start varlog'? What is in the system log (journalctl) when this system is started at boot time, and is it started at the point you expect it to be?

lrhorer
Posts: 54
Joined: Sun Feb 22, 2015 6:35 pm

Re: systemd module not working

Thu Aug 01, 2019 3:40 pm

As I said, it starts normally when I run it manually after boot:

HVAC-Relay1:~# systemctl status varlog.service
● varlog.service - Create directories in /var/log
Loaded: loaded (/lib/systemd/system/varlog.service; enabled; vendor preset: enabled)
Active: inactive (dead) since Thu 2019-08-01 10:20:43 CDT; 45s ago
Process: 269 ExecStart=/bin/bash /usr/local/sbin/varlog (code=exited, status=0/SUCCESS)
Main PID: 269 (code=exited, status=0/SUCCESS)

and no, it doesn't start when I expect. I made some progress by adding WantedBy=multi-user.target to the [Install] section of all three services. The one-shot service is now working. The two resident services still fail, but they restart. I still don't understand why they are failing, why they did not restart after failing until I added the WantedBy field, or why adding the WantedBy field allows the one-shot service to work.

Aug 1 10:20:54 HVAC-Relay1 systemd[1]: tserver.service: Service RestartSec=10s expired, scheduling restart.
Aug 1 10:20:54 HVAC-Relay1 systemd[1]: tserver.service: Scheduled restart job, restart counter is at 1.
Aug 1 10:20:54 HVAC-Relay1 systemd[1]: tclient.service: Service RestartSec=10s expired, scheduling restart.
Aug 1 10:20:54 HVAC-Relay1 systemd[1]: tclient.service: Scheduled restart job, restart counter is at 1.
Aug 1 10:20:54 HVAC-Relay1 systemd[1]: Stopped Get data from Thermostat.
Aug 1 10:20:54 HVAC-Relay1 systemd[1]: Started Get data from Thermostat.
Aug 1 10:20:54 HVAC-Relay1 systemd[1]: Stopped Send data to network.
Aug 1 10:20:54 HVAC-Relay1 systemd[1]: Started Send data to network.

Obviously, I would prefer these to work properly, although it's OK for the time being.

bls
Posts: 406
Joined: Mon Oct 22, 2018 11:25 pm
Location: Seattle, WA
Contact: Twitter

Re: systemd module not working

Thu Aug 01, 2019 4:06 pm

We’re happy to help here, but you haven’t provided the information that I requested: The console output from ‘sudo systemctl start varlog’, and the contents of the systemd journal (via ‘sudo journalctl’) from the attempt that systemd made to start the service. You didn’t provide either of these...

lrhorer
Posts: 54
Joined: Sun Feb 22, 2015 6:35 pm

Re: systemd module not working

Thu Aug 01, 2019 4:31 pm

Have you ever seen any output from a start command? I don't recall ever having done so:

HVAC-Relay1:~# systemctl start varlog
HVAC-Relay1:~# systemctl start tserver
HVAC-Relay1:~# systemctl start tclient

I posted the relevant entries in syslog. Journalctl doesn't really show anything different.

Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Reached target Sound Card.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started LSB: Switch to ondemand cpu governor (unless shift key is pressed).
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: varlog.service: Succeeded.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started Create directories in /var/log.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started Login Service.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started Avahi mDNS/DNS-SD Stack.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started WPA supplicant.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started Send data to network.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started Get data from Thermostat.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started dphys-swapfile - set up, mount/unmount, and delete a swap file.
Aug 01 11:19:03 HVAC-Relay1 systemd[1]: tserver.service: Main process exited, code=exited, status=1/FAILURE
Aug 01 11:19:03 HVAC-Relay1 systemd[1]: tserver.service: Failed with result 'exit-code'.
Aug 01 11:19:03 HVAC-Relay1 systemd[1]: tclient.service: Main process exited, code=exited, status=1/FAILURE
Aug 01 11:19:03 HVAC-Relay1 systemd[1]: tclient.service: Failed with result 'exit-code'.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started dhcpcd on all interfaces.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Reached target Network.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Starting OpenBSD Secure Shell server...
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Starting Permit User Sessions...
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Starting /etc/rc.local Compatibility...
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started /etc/rc.local Compatibility.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started Permit User Sessions.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started Serial Getty on ttyAMA0.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started Getty on tty1.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Reached target Login Prompts.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started OpenBSD Secure Shell server.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: tserver.service: Service RestartSec=10s expired, scheduling restart.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: tserver.service: Scheduled restart job, restart counter is at 1.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: Stopped Send data to network.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: Started Send data to network.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: tclient.service: Service RestartSec=10s expired, scheduling restart.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: tclient.service: Scheduled restart job, restart counter is at 1.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: Stopped Get data from Thermostat.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: Started Get data from Thermostat.

...

bls
Posts: 406
Joined: Mon Oct 22, 2018 11:25 pm
Location: Seattle, WA
Contact: Twitter

Re: systemd module not working

Thu Aug 01, 2019 5:25 pm

lrhorer wrote:
Thu Aug 01, 2019 4:31 pm
Have you ever seen any output from a start command? I don't recall ever having done so:

HVAC-Relay1:~# systemctl start varlog
HVAC-Relay1:~# systemctl start tserver
HVAC-Relay1:~# systemctl start tclient

I posted the relevant entries in syslog. Journalctl doesn't really show anything different.

Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Reached target Sound Card.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started LSB: Switch to ondemand cpu governor (unless shift key is pressed).
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: varlog.service: Succeeded.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started Create directories in /var/log.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started Login Service.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started Avahi mDNS/DNS-SD Stack.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started WPA supplicant.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started Send data to network.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started Get data from Thermostat.
Aug 01 11:19:02 HVAC-Relay1 systemd[1]: Started dphys-swapfile - set up, mount/unmount, and delete a swap file.
Aug 01 11:19:03 HVAC-Relay1 systemd[1]: tserver.service: Main process exited, code=exited, status=1/FAILURE
Aug 01 11:19:03 HVAC-Relay1 systemd[1]: tserver.service: Failed with result 'exit-code'.
Aug 01 11:19:03 HVAC-Relay1 systemd[1]: tclient.service: Main process exited, code=exited, status=1/FAILURE
Aug 01 11:19:03 HVAC-Relay1 systemd[1]: tclient.service: Failed with result 'exit-code'.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started dhcpcd on all interfaces.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Reached target Network.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Starting OpenBSD Secure Shell server...
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Starting Permit User Sessions...
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Starting /etc/rc.local Compatibility...
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started /etc/rc.local Compatibility.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started Permit User Sessions.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started Serial Getty on ttyAMA0.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started Getty on tty1.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Reached target Login Prompts.
Aug 01 11:19:07 HVAC-Relay1 systemd[1]: Started OpenBSD Secure Shell server.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: tserver.service: Service RestartSec=10s expired, scheduling restart.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: tserver.service: Scheduled restart job, restart counter is at 1.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: Stopped Send data to network.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: Started Send data to network.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: tclient.service: Service RestartSec=10s expired, scheduling restart.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: tclient.service: Scheduled restart job, restart counter is at 1.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: Stopped Get data from Thermostat.
Aug 01 11:19:13 HVAC-Relay1 systemd[1]: Started Get data from Thermostat.

...
Ack on the systemctl start, but just for completeness... One interesting thing in the journal. There is a "varlog.service: Succeeded." entry, and following that there is "Started Create directories in /var/log.". It's unclear whether these are simply out of order in the log, or the result of two separate starts of your varlog service.

Perhaps you could add

Code: Select all

echo "$(date) varlog started" >> /somewhere/somefile.log
to your /usr/local/sbin/varlog to suss that out. You could also do an 'ls -l' of each of the directories you expect to be there and output that to the same logfile. Also, for completeness/correctness, make sure that the /usr/local/sbin/varlog script exits with success (0).

If that doesn't give you enough info to track down the problem, try adding similar debug output (service starting and ls the directories) to a log to your other services (but you'll have to change them from directly running the python code to a script that does the debug output and then runs the python code).

Sorry that the answer wasn't completely obvious, but getting a closer-in view of what's going on should help a lot.

lrhorer
Posts: 54
Joined: Sun Feb 22, 2015 6:35 pm

Re: systemd module not working

Fri Aug 02, 2019 1:19 am

Thu 1 Aug 19:44:32 CDT 2019 varlog started
1564706673.4285336
Thu 1 Aug 19:44:33 CDT 2019 varlog finished
1564706673.6966412

tclient started 19:44:34 1564706674.128445
tclient started 19:44:44 1564706684.7160547
tclient enters loop 19:44:44 1564706684.7177026

tserver started 19:44:34 1564706674.0341847
tserver started 19:44:44 1564706684.3931649
tserver enters loop 19:44:44 1564706684.3957326

Clearly (once I added the WantedBy=multi-user.target entry to the service unit definition), varlog is running and exiting cleanly. It is also clear both tserver and tclient are running after varlog is complete, per the service unit definitions After=varlog.service, roughly 350 milliseconds after varlog completes. Both start at roughly the same time (within 90 milliseconds), and fail in much less than 1 second. Ten seconds later, again per the unit definitions, systemd restarts the two daemons, whereupon they both reach the entry points into their respective infinite loops in a few microseconds, and they never fail again.

"Ack on the systemctl start, but just for completeness..." Huh? Was that a typo? If not, I have no idea what you mean.

It is very likely the two Python servers are failing during the execution of the following code, which runs on both servers:

s = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
s.connect(("8.8.8.8", 80))
IP = s.getsockname()[0]
s.close

It opens a socket on the primary network interface in order to obtain the IP address of the interface, which is needed by both the client and the server. I tried a number of different things to get varlog to run after sockets are fully operational, to no avail. Here are the socket related entries in journalctl. Only the very last one seems to be at a point in time where the two Python services will not fail initially.

Aug 01 19:44:28 HVAC-Relay1 systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
Aug 01 19:44:28 HVAC-Relay1 systemd[1]: Listening on Journal Socket (/dev/log).
Aug 01 19:44:32 HVAC-Relay1 systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
Aug 01 19:44:32 HVAC-Relay1 systemd[1]: Listening on triggerhappy.socket.
Aug 01 19:44:32 HVAC-Relay1 systemd[1]: Listening on D-Bus System Message Bus Socket.
Aug 01 19:44:32 HVAC-Relay1 systemd[1]: Reached target Sockets.
Aug 01 19:44:32 HVAC-Relay1 thd[287]: Found socket passed from systemd
Aug 01 19:44:33 HVAC-Relay1 rsyslogd[276]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd. [v8.1901.0]
Aug 01 19:44:52 HVAC-Relay1 systemd[522]: Reached target Sockets.

bls
Posts: 406
Joined: Mon Oct 22, 2018 11:25 pm
Location: Seattle, WA
Contact: Twitter

Re: systemd module not working

Fri Aug 02, 2019 2:08 am

lrhorer wrote:
Fri Aug 02, 2019 1:19 am
"Ack on the systemctl start, but just for completeness..." Huh? Was that a typo? If not, I have no idea what you mean.

It is very likely the two Python servers are failing during the execution of the following code, which runs on both servers:

s = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
s.connect(("8.8.8.8", 80))
IP = s.getsockname()[0]
s.close

It opens a socket on the primary network interface in order to obtain the IP address of the interface, which is needed by both the client and the server. I tried a number of different things to get varlog to run after sockets are fully operational, to no avail. Here are the socket related entries in journalctl. Only the very last one seems to be at a point in time where the two Python services will not fail initially.
On the "Ack..." was simply agreeing with you that systemctl start rarely throws an error (but I've seen them...), and was just asking for it in the interest of completeness.

To make sure that the network is online before your Python services start, have you thought about using After=network-online.target? This is what the apt services use.

HTH

lrhorer
Posts: 54
Joined: Sun Feb 22, 2015 6:35 pm

Re: systemd module not working

Sat Aug 03, 2019 2:56 am

It still happens.

bls
Posts: 406
Joined: Mon Oct 22, 2018 11:25 pm
Location: Seattle, WA
Contact: Twitter

Re: systemd module not working

Sat Aug 03, 2019 3:28 am

Logs and other output would be very helpful...

jj_0
Posts: 109
Joined: Wed Jul 11, 2012 7:07 am

Re: systemd module not working

Sun Aug 04, 2019 8:10 am

I'm not sure if you are aware of it, but Systemd has a special facility for creating files and/or directories at boot: systemd-tmpfiles. This can be configured by placing a .conf file in the /etc/tmpfiles.d directory.
If you use that instead of your own unit it might work OK.

lrhorer
Posts: 54
Joined: Sun Feb 22, 2015 6:35 pm

Re: systemd module not working

Mon Aug 12, 2019 1:56 am

No, I did not know that, and I will try it, but that only solves the issue with varlog. The other services still start way too soon, no matter what I have tried. I have not been able to work on this the last few days and won't again until later in the week, because the system is down for hardware modifications.

Return to “Advanced users”