systemd configuration does not work

[MDo3]

I did the mqttwarn setup on a Raspberry Pi. When I run it manually everything works but i have a problem with systemd.

Steps I took:

useradd --create-home --shell /bin/bash mqttwarn
cp etc/mqttwarn.default /etc/default/mqttwarn
cp etc/mqttwarn.service /usr/lib/systemd/system/
cp etc/mqttwarn.logrotate /etc/logrotate.d/mqttwarn
mkdir /var/log/mqttwarn
chown mqttwarn:mqttwarn /var/log/mqttwarn

cd /usr/lib/systemd/system 
sudo nano mqttwarn.service

#
#   useradd --create-home --shell /bin/bash mqttwarn
#   cp etc/mqttwarn.default /etc/default/mqttwarn
#   cp etc/mqttwarn.service /usr/lib/systemd/system/
#   cp etc/mqttwarn.logrotate /etc/logrotate.d/mqttwarn
#   mkdir /var/log/mqttwarn
#   chown mqttwarn:mqttwarn /var/log/mqttwarn
#   systemctl enable mqttwarn
#
# Configuration
# -------------
# The configuration file is located at /etc/mqttwarn/mqttwarn.ini,
# but the default setting can be changed by amending the
# MQTTWARNINI environment variable defined in /etc/default/mqttwarn.
#
# Setup example configuration::
#
#   mkdir /etc/mqttwarn
#   cp mqttwarn.ini.sample /etc/mqttwarn/mqttwarn.ini
#
# Start
# -----
# ::
#
#   systemctl start mqttwarn
#

[Unit]
Description=mqttwarn pluggable mqtt notification service
Documentation=https://github.com/jpmens/mqttwarn
After=network.target

[Service]
Type=simple
User=mqttwarn
Group=mqttwarn
LimitNOFILE=65536
Environment='STDOUT=/var/log/mqttwarn/mqttwarn.log'
Environment='STDERR=/var/log/mqttwarn/mqttwarn.log'
EnvironmentFile=/etc/default/mqttwarn
PassEnvironment=MQTTWARNINI
ExecStart=/bin/sh -c 'exec /usr/local/bin/mqttwarn ${MQTTWARN_OPTIONS} >>${STDOUT} 2>>${STDERR}'
KillMode=control-group
Restart=on-failure

[Install]
WantedBy=multi-user.target
Alias=mqttwarn.service

systemctl enable mqttwarn
sudo systemctl start mqttwarn
sudo systemctl status mqttwarn.service

pi@raspberrypi:/usr/lib/systemd/system $ systemctl enable mqttwarn
==== AUTHENTICATING FOR org.freedesktop.systemd1.manage-unit-files ===
Authentication is required to manage system service or unit files.
Authenticating as:  (pi)
Password: 
==== AUTHENTICATION COMPLETE ===
==== AUTHENTICATING FOR org.freedesktop.systemd1.reload-daemon ===
Authentication is required to reload the systemd state.
Authenticating as: (pi)
Password: 
==== AUTHENTICATION COMPLETE ===
pi@raspberrypi:/usr/lib/systemd/system $ sudo systemctl start mqttwarn
pi@raspberrypi:/usr/lib/systemd/system $ sudo systemctl status mqttwarn.service
● mqttwarn.service - mqttwarn pluggable mqtt notification service
     Loaded: loaded (/lib/systemd/system/mqttwarn.service; enabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Sun 2022-05-22 22:01:36 CEST; 4s ago
       Docs: https://github.com/jpmens/mqttwarn
    Process: 5677 ExecStart=/bin/sh -c exec /usr/local/bin/mqttwarn ${MQTTWARN_OPTIONS} >>${STDOUT} 2>>${STDERR} (code=exited, sta>
   Main PID: 5677 (code=exited, status=126)
        CPU: 29ms

May 22 22:01:36 raspberrypi systemd[1]: mqttwarn.service: Scheduled restart job, restart counter is at 5.
May 22 22:01:36 raspberrypi systemd[1]: Stopped mqttwarn pluggable mqtt notification service.
May 22 22:01:36 raspberrypi systemd[1]: mqttwarn.service: Start request repeated too quickly.
May 22 22:01:36 raspberrypi systemd[1]: mqttwarn.service: Failed with result 'exit-code'.
May 22 22:01:36 raspberrypi systemd[1]: Failed to start mqttwarn pluggable mqtt notification service.

As you can see, an error appears and the service does not start. Does anyone know where the problem is?

[amotl]

Hi,

it looks like you are using sudo everywhere, but not with systemctl enable mqttwarn, no? What happens if you also use it there?

With kind regards,
Andreas.

[amotl]

Hi again,

did you also provision the mqttwarn.ini configuration file?

https://github.com/jpmens/mqttwarn/blob/33a298312562bbc7c2b2723f5c8aa1a8ffcc5720/etc/mqttwarn.service#L23-L32

With kind regards,
Andreas.

[MDo3]

If I enable without sudo it simply doesn't ask for a password before enabling the service.

I have the mqttwarn.ini file in:
/etc/mqttwarn/mqttwarn.ini

But I think this is not a problem, as as you can see when I run the application it starts up manually.

pi@raspberrypi:~ $ sudo systemctl enable mqttwarn
pi@raspberrypi:~ $ sudo systemctl start mqttwarn
pi@raspberrypi:~ $ sudo systemctl status mqttwarn.service
● mqttwarn.service - mqttwarn pluggable mqtt notification service
     Loaded: loaded (/lib/systemd/system/mqttwarn.service; enabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Sun 2022-05-22 22:55:17 CEST; 8s ago
       Docs: https://github.com/jpmens/mqttwarn
    Process: 5998 ExecStart=/bin/sh -c exec /usr/local/bin/mqttwarn ${MQTTWARN_OPTIONS} >>${STDOUT} 2>>${STDERR} (code=exited, sta>
   Main PID: 5998 (code=exited, status=126)
        CPU: 29ms

May 22 22:55:16 raspberrypi systemd[1]: mqttwarn.service: Scheduled restart job, restart counter is at 5.
May 22 22:55:17 raspberrypi systemd[1]: Stopped mqttwarn pluggable mqtt notification service.
May 22 22:55:17 raspberrypi systemd[1]: mqttwarn.service: Start request repeated too quickly.
May 22 22:55:17 raspberrypi systemd[1]: mqttwarn.service: Failed with result 'exit-code'.
May 22 22:55:17 raspberrypi systemd[1]: Failed to start mqttwarn pluggable mqtt notification service.

pi@raspberrypi:~ $ mqttwarn
2022-05-22 22:57:02,972 INFO     [mqttwarn.commands         ] Starting mqttwarn
2022-05-22 22:57:02,977 INFO     [mqttwarn.commands         ] Log level is DEBUG
2022-05-22 22:57:02,983 DEBUG    [mqttwarn.core             ] Trying to load built-in service "file" from "file"
2022-05-22 22:57:02,999 DEBUG    [mqttwarn.core             ] Trying to load service "file" from file "/home/pi/.local/lib/python3.9/site-packages/mqttwarn/services/file.py"
2022-05-22 22:57:03,011 INFO     [mqttwarn.core             ] Successfully loaded service "file"
2022-05-22 22:57:03,016 DEBUG    [mqttwarn.core             ] Trying to load built-in service "log" from "log"
2022-05-22 22:57:03,022 DEBUG    [mqttwarn.core             ] Trying to load service "log" from file "/home/pi/.local/lib/python3.9/site-packages/mqttwarn/services/log.py"
2022-05-22 22:57:03,032 INFO     [mqttwarn.core             ] Successfully loaded service "log"
2022-05-22 22:57:03,037 DEBUG    [mqttwarn.core             ] Trying to load built-in service "ifttt" from "ifttt"
2022-05-22 22:57:03,043 DEBUG    [mqttwarn.core             ] Trying to load service "ifttt" from file "/home/pi/.local/lib/python3.9/site-packages/mqttwarn/services/ifttt.py"
2022-05-22 22:57:03,052 INFO     [mqttwarn.core             ] Successfully loaded service "ifttt"
2022-05-22 22:57:03,056 DEBUG    [mqttwarn.core             ] Attempting connection to MQTT broker localhost:1883...
2022-05-22 22:57:03,060 DEBUG    [mqttwarn.core             ] Setting LWT to clients/mqttwarn...
2022-05-22 22:57:03,080 INFO     [mqttwarn.core             ] Starting 1 worker threads
2022-05-22 22:57:03,089 DEBUG    [mqttwarn.core             ] Job queue has 0 items to process
2022-05-22 22:57:03,092 DEBUG    [mqttwarn.core             ] Connected to MQTT broker, subscribing to topics...
2022-05-22 22:57:03,098 DEBUG    [mqttwarn.core             ] Cleansession==False; previous subscriptions for clientid mqttwarn remain active on broker
2022-05-22 22:57:03,103 DEBUG    [mqttwarn.core             ] Subscribing to tele/tasmota_D6376C/LWT (qos=0)
2022-05-22 22:57:03,115 DEBUG    [mqttwarn.core             ] Message received on tele/tasmota_D6376C/LWT: Online
2022-05-22 22:57:03,120 DEBUG    [mqttwarn.core             ] Section [status] matches message on tele/tasmota_D6376C/LWT. Processing...
2022-05-22 22:57:03,125 DEBUG    [mqttwarn.core             ] Cannot decode JSON object, payload=Online: Expecting value: line 1 column 1 (char 0)
2022-05-22 22:57:03,133 DEBUG    [mqttwarn.core             ] Message on tele/tasmota_D6376C/LWT going to ifttt:notify
2022-05-22 22:57:03,137 DEBUG    [mqttwarn.core             ] New `ifttt:notify' job: tele/tasmota_D6376C/LWT
2022-05-22 22:57:03,142 DEBUG    [mqttwarn.core             ] Processor #0 is handling: `ifttt' for notify
2022-05-22 22:57:03,148 INFO     [mqttwarn.core             ] Invoking service plugin for `ifttt'
2022-05-22 22:57:03,155 DEBUG    [mqttwarn.services.ifttt   ] *** MODULE=/home/pi/.local/lib/python3.9/site-packages/mqttwarn/services/ifttt.py: service=ifttt, target=notify
2022-05-22 22:57:03,159 DEBUG    [mqttwarn.services.ifttt   ] Sending ifttt event
2022-05-22 22:57:03,230 DEBUG    [urllib3.connectionpool    ] Starting new HTTPS connection (1): maker.ifttt.com:443
2022-05-22 22:57:03,830 DEBUG    [urllib3.connectionpool    ] https://maker.ifttt.com:443 "POST /trigger/Esp32/with/key/b4BnnKTDYjaIxxxxxxxx HTTP/1.1" 200 45
2022-05-22 22:57:03,866 DEBUG    [mqttwarn.services.ifttt   ] Successfully sent ifttt event
2022-05-22 22:57:03,875 DEBUG    [mqttwarn.core             ] Job queue has 0 items to process
^C2022-05-22 22:57:24,398 DEBUG    [mqttwarn.core             ] Disconnecting from MQTT broker...
2022-05-22 22:57:24,409 INFO     [mqttwarn.core             ] Clean disconnection from broker
2022-05-22 22:57:24,416 INFO     [mqttwarn.core             ] Waiting for queue to drain
2022-05-22 22:57:24,420 DEBUG    [mqttwarn.core             ] Exiting on signal 2
pi@raspberrypi:~ $  which mqttwarn
/home/pi/.local/bin/mqttwarn
pi@raspberrypi:~ $ 

Is it possible that the error is in the "ExecStart =" configuration?

[amotl]

Hi again,

(code=exited, status=126)

The GNU Bash manual tells us that:

If a command is not found, the child process created to execute it returns a status of 127. If a command is found but is not executable, the return status is 126.

-- https://www.gnu.org/software/bash/manual/html_node/Exit-Status.html

Maybe this bit helps?

If I enable without sudo it simply doesn't ask for a password before enabling the service.

Yeah, but then it would be invoked as user pi, no? All the service setup and installation commands should actually be invoked as root user. So, regardless of any other misconfigurations I cannot see currently, you might want to switch over to the root user using sudo su - in order to invoke all commands, specifically the systemctl ones.

With kind regards,
Andreas.

[MDo3]

I tried to activate the service by switching to the root user but the effect is the same:

pi@raspberrypi:~ $ sudo su
root@raspberrypi:/home/pi# sudo systemctl enable mqttwarn
root@raspberrypi:/home/pi# sudo systemctl start mqttwarn
root@raspberrypi:/home/pi# sudo systemctl status mqttwarn.service
● mqttwarn.service - mqttwarn pluggable mqtt notification service
     Loaded: loaded (/lib/systemd/system/mqttwarn.service; enabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Mon 2022-05-23 00:48:46 CEST; 9s ago
       Docs: https://github.com/jpmens/mqttwarn
    Process: 1111 ExecStart=/bin/sh -c exec /usr/local/bin/mqttwarn ${MQTTWARN_OPTIONS} >>${STDOUT} 2>>${STDERR} (code=exited, status=126)
   Main PID: 1111 (code=exited, status=126)
        CPU: 29ms

May 23 00:48:46 raspberrypi systemd[1]: mqttwarn.service: Scheduled restart job, restart counter is at 5.
May 23 00:48:46 raspberrypi systemd[1]: Stopped mqttwarn pluggable mqtt notification service.
May 23 00:48:46 raspberrypi systemd[1]: mqttwarn.service: Start request repeated too quickly.
May 23 00:48:46 raspberrypi systemd[1]: mqttwarn.service: Failed with result 'exit-code'.
May 23 00:48:46 raspberrypi systemd[1]: Failed to start mqttwarn pluggable mqtt notification service.
root@raspberrypi:/home/pi# systemctl enable mqttwarn
root@raspberrypi:/home/pi# systemctl start mqttwarn
root@raspberrypi:/home/pi# systemctl status mqttwarn.service
● mqttwarn.service - mqttwarn pluggable mqtt notification service
     Loaded: loaded (/lib/systemd/system/mqttwarn.service; enabled; vendor preset: enabled)
     Active: failed (Result: exit-code) since Mon 2022-05-23 00:50:59 CEST; 10s ago
       Docs: https://github.com/jpmens/mqttwarn
    Process: 1141 ExecStart=/bin/sh -c exec /usr/local/bin/mqttwarn ${MQTTWARN_OPTIONS} >>${STDOUT} 2>>${STDERR} (code=exited, status=126)
   Main PID: 1141 (code=exited, status=126)
        CPU: 29ms

I also tried to modify mqttwarn.service by changing user and group to "pi", then the error code changes to (code = exited, status = 2)

[Service]
Type=simple
User=pi
Group=pi
LimitNOFILE=65536

I also noticed strange behavior with the export MQTTWARN INI = command Changing the file location works but only until you restart. When I restart my device and then try to start mqttwarn manually I get an error.

Last login: Mon May 23 01:21:43 2022 from 192.168.0.100
pi@raspberrypi:~ $ mqttwarn
Traceback (most recent call last):
  File "/home/pi/.local/bin/mqttwarn", line 8, in <module>
    sys.exit(run())
  File "/home/pi/.local/lib/python3.9/site-packages/mqttwarn/commands.py", line 93, in run
    run_mqttwarn()
  File "/home/pi/.local/lib/python3.9/site-packages/mqttwarn/commands.py", line 132, in run_mqttwarn
    config = load_configuration(name=scriptname)
  File "/home/pi/.local/lib/python3.9/site-packages/mqttwarn/configuration.py", line 189, in load_configuration
    raise FileNotFoundError('Configuration file "{}" does not exist'.format(configfile))
FileNotFoundError: Configuration file "mqttwarn.ini" does not exist
pi@raspberrypi:~ $ export MQTTWARNINI=/etc/mqttwarn/mqttwarn.ini
pi@raspberrypi:~ $ mqttwarn
2022-05-23 01:26:13,530 INFO     [mqttwarn.commands         ] Starting mqttwarn
2022-05-23 01:26:13,534 INFO     [mqttwarn.commands         ] Log level is DEBUG
2022-05-23 01:26:13,541 DEBUG    [mqttwarn.core             ] Trying to load built-in service "file" from "file"
2022-05-23 01:26:13,556 DEBUG    [mqttwarn.core             ] Trying to load service "file" from file "/home/pi/.local/lib/python3.9/site-packages/mqttwarn/services/file.py"
2022-05-23 01:26:13,566 INFO     [mqttwarn.core             ] Successfully loaded service "file"
2022-05-23 01:26:13,571 DEBUG    [mqttwarn.core             ] Trying to load built-in service "log" from "log"
2022-05-23 01:26:13,577 DEBUG    [mqttwarn.core             ] Trying to load service "log" from file "/home/pi/.local/lib/python3.9/site-packages/mqttwarn/services/log.py"
2022-05-23 01:26:13,586 INFO     [mqttwarn.core             ] Successfully loaded service "log"
2022-05-23 01:26:13,591 DEBUG    [mqttwarn.core             ] Trying to load built-in service "ifttt" from "ifttt"
2022-05-23 01:26:13,597 DEBUG    [mqttwarn.core             ] Trying to load service "ifttt" from file "/home/pi/.local/lib/python3.9/site-packages/mqttwarn/services/ifttt.py"
2022-05-23 01:26:13,606 INFO     [mqttwarn.core             ] Successfully loaded service "ifttt"
2022-05-23 01:26:13,610 DEBUG    [mqttwarn.core             ] Attempting connection to MQTT broker localhost:1883...
2022-05-23 01:26:13,614 DEBUG    [mqttwarn.core             ] Setting LWT to clients/mqttwarn...
2022-05-23 01:26:13,645 INFO     [mqttwarn.core             ] Starting 1 worker threads
2022-05-23 01:26:13,655 DEBUG    [mqttwarn.core             ] Job queue has 0 items to process
2022-05-23 01:26:13,662 DEBUG    [mqttwarn.core             ] Connected to MQTT broker, subscribing to topics...
2022-05-23 01:26:13,677 DEBUG    [mqttwarn.core             ] Cleansession==False; previous subscriptions for clientid mqttwarn remain active on broker
2022-05-23 01:26:13,683 DEBUG    [mqttwarn.core             ] Subscribing to tele/tasmota_D6376C/LWT (qos=0)
2022-05-23 01:26:13,705 DEBUG    [mqttwarn.core             ] Message received on tele/tasmota_D6376C/LWT: Online
2022-05-23 01:26:13,710 DEBUG    [mqttwarn.core             ] Section [status] matches message on tele/tasmota_D6376C/LWT. Processing...
2022-05-23 01:26:13,717 DEBUG    [mqttwarn.core             ] Cannot decode JSON object, payload=Online: Expecting value: line 1 column 1 (char 0)
2022-05-23 01:26:13,736 DEBUG    [mqttwarn.core             ] Message on tele/tasmota_D6376C/LWT going to ifttt:notify
2022-05-23 01:26:13,740 DEBUG    [mqttwarn.core             ] New `ifttt:notify' job: tele/tasmota_D6376C/LWT
2022-05-23 01:26:13,748 DEBUG    [mqttwarn.core             ] Processor #0 is handling: `ifttt' for notify
2022-05-23 01:26:13,761 INFO     [mqttwarn.core             ] Invoking service plugin for `ifttt'
2022-05-23 01:26:13,768 DEBUG    [mqttwarn.services.ifttt   ] *** MODULE=/home/pi/.local/lib/python3.9/site-packages/mqttwarn/services/ifttt.py: service=ifttt, target=notify
2022-05-23 01:26:13,773 DEBUG    [mqttwarn.services.ifttt   ] Sending ifttt event
2022-05-23 01:26:13,844 DEBUG    [urllib3.connectionpool    ] Starting new HTTPS connection (1): maker.ifttt.com:443
2022-05-23 01:26:14,392 DEBUG    [urllib3.connectionpool    ] https://maker.ifttt.com:443 "POST /trigger/Esp32/with/key/b4BnnKTDYxxxxxxxx HTTP/1.1" 200 45
2022-05-23 01:26:14,429 DEBUG    [mqttwarn.services.ifttt   ] Successfully sent ifttt event
2022-05-23 01:26:14,439 DEBUG    [mqttwarn.core             ] Job queue has 0 items to process
^C2022-05-23 01:26:19,790 DEBUG    [mqttwarn.core             ] Disconnecting from MQTT broker...
2022-05-23 01:26:19,799 INFO     [mqttwarn.core             ] Clean disconnection from broker
2022-05-23 01:26:19,804 INFO     [mqttwarn.core             ] Waiting for queue to drain
2022-05-23 01:26:19,809 DEBUG    [mqttwarn.core             ] Exiting on signal 2

After trying to start the service, the contents of mqttwarn.log looks like this:

/bin/sh: 1: exec: /usr/local/bin/mqttwarn: Permission denied
/bin/sh: 1: exec: /usr/local/bin/mqttwarn: Permission denied
/bin/sh: 1: exec: /usr/local/bin/mqttwarn: Permission denied
/bin/sh: 1: exec: /usr/local/bin/mqttwarn: Permission denied
/bin/sh: 1: exec: /usr/local/bin/mqttwarn: Permission denied

I will just add that I previously added the homebridge service to the systemctl by of the following guide and there we managed to start the service without any problem.

https://pysselilivet.blogspot.com/2017/01/homebridge-autostart-with-systemd.html

I think there must be a mistake somewhere in this manual.

https://github.com/jpmens/mqttwarn/blob/main/etc/mqttwarn.service

[amotl]

I also noticed strange behavior with the export MQTTWARNINI= command. Changing the file location works but only until you restart. When I restart my device and then try to start mqttwarn manually I get an error.

That is intended. The effect of the export command, typed interactively into your terminal, will only be valid within your current session. That is suitable to start programs interactively. For running programs as daemons, environment variables have to be supplied by other means, for example through a systemd unit definition.

After trying to start the service, the contents of mqttwarn.log looks like this:
/bin/sh: 1: exec: /usr/local/bin/mqttwarn: Permission denied

Indeed, that's a very good trace. You may be able to fix the problem by adjusting the file permissions, like:

sudo chmod +rx /usr/local/bin/mqttwarn
sudo systemctl restart mqttwarn

[MDo3]

Thanks for trying to help. I did as you told me, but the log still says about a permissions problem

.

[jpmens]

Those errors indicate that the permissions on the file are wrong; try a chmod 755 /usr/local/bin/mqttwarn

[MDo3]

Those errors indicate that the permissions on the file are wrong; try a chmod 755 /usr/local/bin/mqttwarn`

Despite changing permissions, it shows 777 all the time. Of course, I refreshed the FTP directory view. As you can see, the modification date of this file is 5/18/2022

[jpmens]

We're seeing commands entered on the shell and some FTP popups; I cannot help you this way. Please stick to working with the command line as I've no idea what your FTP thing is actually showing you.

[amotl]

Hi again,

I also think manipulating the filesystem through FTP or such might be the reason for the hiccups you are observing. Can you try a clean install, using a terminal / the command line only?

With kind regards,
Andreas.