Crashes when trying to daemonize

[SlowBro904]

This works:

(mypy) root@ubuntu:/mypy# export PYTHONPATH=/mypy; /usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf
redis initialized 127.0.0.1 6379

AUTH: user=admin, password matches = True
ACL: user=admin topic=mypy/d256cc9e/ping, matches = True

(mypy) root@ubuntu:/mypy# mosquitto_pub -t 'admin/d256cc9e/ping' -m 'ack' -u 'admin' -P 'password' -I 'd256cc9e' -h mqtt01 -p 8883 --cafile /mypy/certs/ca.crt
(mypy) root@ubuntu:/mypy#

(mypy) root@ubuntu:/mypy# mosquitto_sub -t 'admin/d256cc9e/ping' -u 'admin' -P 'password' -I 'd256cc9e' -h mqtt01 -p 8883 --cafile /mypy/certs/ca.crt

ack

However, running from /etc/init.d fails, and yes I did add the PYTHONPATH variable. NO log error messages, despite every log_type enabled in mosquitto.conf. And mosquitto works without the plugin.

I am on Ubuntu 17.10 and I downloaded the latest mosquitto_pyauth code from github last night. The make options were USE_CARES=1 PYTHON_VERSION=3.6. I am using the example redis_auth.py. Mosquitto version 1.4.12.

(mypy) root@ubuntu:/mypy# grep -C5 PYTHONPATH /etc/init.d/mosquitto
run_by_init() {
    ([ "$previous" ] && [ "$runlevel" ]) || [ "$runlevel" = S ]
}

export PATH="${PATH:+$PATH:}/usr/sbin:/sbin"
export PYTHONPATH="${PYTHONPATH}:/mypy"

case "$1" in
  start)
        if init_is_upstart; then
            exit 1
(mypy) root@ubuntu:/mypy# /etc/init.d/mosquitto restart
Restarting mosquitto (via systemctl): mosquitto.service.
(mypy) root@ubuntu:/mypy# ps -ef | grep -i mosq
root     12679 12669  0 02:26 pts/3    00:00:06 tail -f /var/log/mosquitto/mosquitto.log
root     28560 24666  1 10:13 pts/8    00:00:00 vi /etc/init.d/mosquitto
mosquit+ 28641     1  2 10:13 ?        00:00:00 /usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf
root     28646 24653  0 10:13 pts/7    00:00:00 grep --color=auto -i mosq
(mypy) root@ubuntu:/mypy# mv /etc/mosquitto/conf.d/pyauth.conf.disabled /etc/mosquitto/conf.d/pyauth.conf
(mypy) root@ubuntu:/mypy# /etc/init.d/mosquitto restart                                                Restarting mosquitto (via systemctl): mosquitto.service.
(mypy) root@ubuntu:/mypy# ps -ef | grep -i mosq                                                        root     12679 12669  0 02:27 pts/3    00:00:06 tail -f /var/log/mosquitto/mosquitto.log
root     28560 24666  0 10:13 pts/8    00:00:00 vi /etc/init.d/mosquitto
root     28687 24653  2 10:14 pts/7    00:00:00 grep --color=auto -i mosq
(mypy) root@ubuntu:/mypy# /etc/init.d/mosquitto restart
Restarting mosquitto (via systemctl): mosquitto.service.
(mypy) root@ubuntu:/mypy# ps -ef | grep -i mosq
root     28560 24666  0 10:13 pts/8    00:00:00 vi /etc/init.d/mosquitto
root     28693 12669  0 10:14 pts/3    00:00:00 tail -f /var/log/mosquitto/mosquitto.log
root     28735 24653  0 10:14 pts/7    00:00:00 grep --color=auto -i mosq
(mypy) root@ubuntu:/mypy# cat /etc/mosquitto/conf.d/pyauth.conf
auth_plugin /usr/lib/mosquitto_pyauth/auth_plugin_pyauth.so
auth_opt_pyauth_module redis_auth
(mypy) root@ubuntu:/mypy# tail /var/log/mosquitto/mosquitto.log
1524752004: New client connected from 10.0.2.2 as d256cc9e (c1, k60, u'admin').
1524752004: Sending CONNACK to d256cc9e (0, 0)
1524752004: Received PUBLISH from d256cc9e (d0, q1, r1, m601, 'admin/d256cc9e/user_op', ... (34 bytes))
1524752004: Sending PUBACK to d256cc9e (Mid: 601)
1524752046: Error in poll: Interrupted system call.
1524752046: mosquitto version 1.4.12 terminating
1524752047: mosquitto version 1.4.12 (build date Thu, 01 Mar 2018 09:24:46 -0500) starting
1524752047: Config loaded from /etc/mosquitto/mosquitto.conf.
1524752075: mosquitto version 1.4.12 (build date Thu, 01 Mar 2018 09:24:46 -0500) starting
1524752075: Config loaded from /etc/mosquitto/mosquitto.conf.
(mypy) root@ubuntu:/mypy# grep log /etc/mosquitto/mosquitto.conf
log_dest file /var/log/mosquitto/mosquitto.log
log_type all
log_type debug
log_type error
log_type warning
log_type notice
log_type information
log_type subscribe
log_type unsubscribe
log_type websockets
(mypy) root@ubuntu:/mypy#

Oddly, if I copy the init script into my current working directory, it works. So I don't see what's different about using the init script in /etc/init.d. Maybe some environment variable? Something about the interaction between systemd and this plugin?

(mypy) root@ubuntu:/mypy# ./mosquitto.init.d.sh start
 * Starting network daemon: mosquitto
   ...done.
(mypy) root@ubuntu:/mypy# ps -ef | grep -i mosq
root     28693 12669  0 10:32 pts/3    00:00:00 tail -f /var/log/mosquitto/mosquitto.log
root     28802 28771  0 10:46 pts/4    00:00:01 mosquitto_sub -t admin/d256cc9e/ping -u admin -P password -I d256cc9e -h mqtt01 -p 8883 --cafile /mypy/certs/ca.crt
root     29142 28785  1 11:00 pts/5    00:00:00 vim mosquitto.init.d.sh
mosquit+ 29180     1 32 11:01 ?        00:00:00 /usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf
root     29183 24666  2 11:01 pts/8    00:00:00 grep --color=auto -i mosq
(mypy) root@ubuntu:/mypy#

[mbachry]

Odd. I'll have some time to look into it at weekend.

Could you check journal logs in the meantime? When it fails to start via systemctl, check output in systemctl status mosquitto, journalctl -xe and/or journalctl -u mosquitto. Also it's worth checking if there's an actual crash: look for log entries with "segfault at" or "general protection ip" in dmesg. Thanks!

[SlowBro904]

No gold. Can you think of any other diagnostics to run?

(mypy) root@ubuntu:/mypy# systemctl status mosquitto
● mosquitto.service - LSB: mosquitto MQTT v3.1 message broker
   Loaded: loaded (/etc/init.d/mosquitto; generated; vendor preset: enabled)
   Active: active (exited) since Thu 2018-04-26 12:03:40 EDT; 1min 43s ago
     Docs: man:systemd-sysv-generator(8)
  Process: 30019 ExecStop=/etc/init.d/mosquitto stop (code=exited, status=0/SUCCESS)
  Process: 30031 ExecStart=/etc/init.d/mosquitto start (code=exited, status=0/SUCCESS)
      CPU: 998ms

Apr 26 12:03:39 ubuntu systemd[1]: Starting LSB: mosquitto MQTT v3.1 message broker...
Apr 26 12:03:40 ubuntu mosquitto[30031]:  * Starting network daemon: mosquitto
Apr 26 12:03:40 ubuntu mosquitto[30031]:    ...done.
Apr 26 12:03:40 ubuntu systemd[1]: Started LSB: mosquitto MQTT v3.1 message broker.
(mypy) root@ubuntu:/mypy# journalctl -xe | tail -40
Apr 26 11:51:55 ubuntu systemd-networkd[406]: enp0s3: Configured
Apr 26 12:01:18 ubuntu kernel: e1000: enp0s3 NIC Link is Down
Apr 26 12:01:18 ubuntu systemd-networkd[406]: enp0s3: Lost carrier
Apr 26 12:01:18 ubuntu systemd-networkd[406]: enp0s3: DHCP lease lost
Apr 26 12:01:18 ubuntu systemd-timesyncd[401]: No network connectivity, watching for changes.
Apr 26 12:01:22 ubuntu kernel: e1000: enp0s3 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
Apr 26 12:01:22 ubuntu systemd-networkd[406]: enp0s3: Gained carrier
Apr 26 12:01:22 ubuntu systemd-networkd[406]: enp0s3: DHCPv4 address 10.0.2.15/24 via 10.0.2.2
Apr 26 12:01:22 ubuntu systemd-networkd[406]: enp0s3: Configured
Apr 26 12:03:15 ubuntu systemd[1]: Reloading.
Apr 26 12:03:39 ubuntu systemd[1]: Stopping LSB: mosquitto MQTT v3.1 message broker...
-- Subject: Unit mosquitto.service has begun shutting down
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
--
-- Unit mosquitto.service has begun shutting down.
Apr 26 12:03:39 ubuntu mosquitto[30019]:  * Stopping network daemon: mosquitto
Apr 26 12:03:39 ubuntu mosquitto[30019]:    ...done.
Apr 26 12:03:39 ubuntu systemd[1]: Stopped LSB: mosquitto MQTT v3.1 message broker.
-- Subject: Unit mosquitto.service has finished shutting down
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
--
-- Unit mosquitto.service has finished shutting down.
Apr 26 12:03:39 ubuntu systemd[1]: Starting LSB: mosquitto MQTT v3.1 message broker...
-- Subject: Unit mosquitto.service has begun start-up
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
--
-- Unit mosquitto.service has begun starting up.
Apr 26 12:03:40 ubuntu mosquitto[30031]:  * Starting network daemon: mosquitto
Apr 26 12:03:40 ubuntu mosquitto[30031]:    ...done.
Apr 26 12:03:40 ubuntu systemd[1]: Started LSB: mosquitto MQTT v3.1 message broker.
-- Subject: Unit mosquitto.service has finished start-up
-- Defined-By: systemd
-- Support: http://www.ubuntu.com/support
--
-- Unit mosquitto.service has finished starting up.
--
-- The start-up result is done.
(mypy) root@ubuntu:/mypy# journalctl -u mosquitto | tail
Apr 26 11:19:16 ubuntu mosquitto[29463]:    ...done.
Apr 26 11:19:16 ubuntu systemd[1]: Started LSB: mosquitto MQTT v3.1 message broker.
Apr 26 12:03:39 ubuntu systemd[1]: Stopping LSB: mosquitto MQTT v3.1 message broker...
Apr 26 12:03:39 ubuntu mosquitto[30019]:  * Stopping network daemon: mosquitto
Apr 26 12:03:39 ubuntu mosquitto[30019]:    ...done.
Apr 26 12:03:39 ubuntu systemd[1]: Stopped LSB: mosquitto MQTT v3.1 message broker.
Apr 26 12:03:39 ubuntu systemd[1]: Starting LSB: mosquitto MQTT v3.1 message broker...
Apr 26 12:03:40 ubuntu mosquitto[30031]:  * Starting network daemon: mosquitto
Apr 26 12:03:40 ubuntu mosquitto[30031]:    ...done.
Apr 26 12:03:40 ubuntu systemd[1]: Started LSB: mosquitto MQTT v3.1 message broker.
(mypy) root@ubuntu:/mypy# dmesg |grep -i segfault
(mypy) root@ubuntu:/mypy# dmesg |grep -i "general protection ip"
(mypy) root@ubuntu:/mypy# ps -ef | grep -i mosq
root     28802 28771  0 14:50 pts/4    00:00:05 mosquitto_sub -t admin/d256cc9e/ping -u admin -P password -I d256cc9e -h mqtt01 -p 8883 --cafile /mypy/certs/ca.crt
root     30008 12669  0 15:48 pts/3    00:00:00 tail -f /var/log/mosquitto/mosquitto.log
root     30149 29908  0 15:55 pts/1    00:00:00 grep --color=auto -i mosq
(mypy) root@ubuntu:/mypy#

[SlowBro904]

Were you able to check this? I don't know what else to look for, but it could be a problem on my end.