killall -HUP disconnects clients #657

kartom · 2017-12-22T07:42:31Z

The command killall -HUP which is used by i.e. the logrotate script in Ubuntu causes mosquitto to disconnect all clients, which leads to problems in some situations.

This problem seam to be realted to the reload of the configuration file and the content in the config.
I have not been able to figure out what is causing the problem but here is a mosquitto.con that makes mosquitto disconnect all clients everytime you send a killall -HUP mosquitto:

pid_file /var/run/mosquitto.pid

listener 1883

persistence true
persistence_location /var/lib/mosquitto/
persistence_file mosquitto.db

log_dest file /var/log/mosquitto/mosquitto.log
log_type all
connection_messages true
log_timestamp true

password_file /etc/mosquitto/passwd

The text was updated successfully, but these errors were encountered:

toast-uz · 2017-12-23T13:08:25Z

Could you show the version?

I reproduced this issue only on develop branch, while not on master v1.4.14. Maybe it's a bug on develop.

Result on develop branch:

$ cat test.conf 
log_type all
$ mosquitto -c test.conf &
[1] 3812
$ 1514034102: mosquitto version 1.4.90 (build date 2017-12-23 13:01:13+0000) starting
1514034102: Config loaded from test.conf.
1514034102: Opening ipv4 listen socket on port 1883.
1514034102: Opening ipv6 listen socket on port 1883.

(connected from another window)
$ 1514034117: New connection from ::1 on port 1883.
1514034117: New client connected from ::1 as mosqsub|3815-ip-172-31- (c1, k60).
1514034117: Sending CONNACK to mosqsub|3815-ip-172-31- (0, 0)
1514034117: Received SUBSCRIBE from mosqsub|3815-ip-172-31-
1514034117: 	# (QoS 0)
1514034117: mosqsub|3815-ip-172-31- 0 #
1514034117: Sending SUBACK to mosqsub|3815-ip-172-31-

$ ps -ef | grep mosquitto
centos    3812  2043  0 13:01 pts/0    00:00:00 mosquitto -c test.conf
centos    3815  2071  0 13:01 pts/1    00:00:00 mosquitto_sub -h localhost -t #
centos    3817  2043  0 13:02 pts/0    00:00:00 grep --color=auto mosquitto
$ sudo kill -s HUP 3812
$ 1514034159: Reloading config.
1514034159: Client mosqsub|3815-ip-172-31- disconnected.
1514034160: New connection from ::1 on port 1883.
1514034160: New client connected from ::1 as mosqsub|3815-ip-172-31- (c1, k60).
1514034160: Sending CONNACK to mosqsub|3815-ip-172-31- (0, 0)
1514034160: Received SUBSCRIBE from mosqsub|3815-ip-172-31-
1514034160: 	# (QoS 0)
1514034160: mosqsub|3815-ip-172-31- 0 #
1514034160: Sending SUBACK to mosqsub|3815-ip-172-31-

toast-uz · 2017-12-24T01:16:07Z

Found the first bad commit by using git bisect.

4afe1a150201989681ca37abeb345fc1a074f9e5 is the first bad commit
commit 4afe1a150201989681ca37abeb345fc1a074f9e5
Author: Roger A. Light <[email protected]>
Date:   Fri Oct 2 21:44:39 2015 +0100

    Swap plugin+built in order.

:040000 040000 de5cbf93ef93db1ee9314832f4ed48f69955288a 8e20d271bf77e20488afa26438852a56d5fa10e7 M	man
:040000 040000 b7667e8a6328474f4ec72476d1ff903bcdcb57c7 330497f6892900cde64d1562c7c519f2a9a40a7c M	src

toast-uz · 2017-12-24T01:24:11Z

I roughly checked the sources of the commit, but I'm not sure what is wrong. @ralight could you reconfirm it?

kartom · 2017-12-24T08:13:51Z

I have reproduced it in the ppa versio for ubuntu (1.4.14) and the base version of Ubuntu 16.4 LTS (1.4.8). I seams that is has been disconnecting client every now an then all the time, but as i have been added more and more clients and extended the logging it happens every time for some clients. /Tomas Den 23 dec. 2017 14:08 skrev "toast-uz" <[email protected]>: Could you show the version? I reproduced this issue only on develop branch, while not on master v1.4.14. Maybe it's a bug on develop. Result on develop branch: $ cat test.conf log_type all $ mosquitto -c test.conf & [1] 3812 $ 1514034102: mosquitto version 1.4.90 (build date 2017-12-23 13:01:13+0000) starting 1514034102: Config loaded from test.conf. 1514034102: Opening ipv4 listen socket on port 1883. 1514034102: Opening ipv6 listen socket on port 1883. (connected from another window) $ 1514034117: New connection from ::1 on port 1883. 1514034117: New client connected from ::1 as mosqsub|3815-ip-172-31- (c1, k60). 1514034117: Sending CONNACK to mosqsub|3815-ip-172-31- (0, 0) 1514034117: Received SUBSCRIBE from mosqsub|3815-ip-172-31- 1514034117: # (QoS 0) 1514034117: mosqsub|3815-ip-172-31- 0 # 1514034117: Sending SUBACK to mosqsub|3815-ip-172-31- $ ps -ef | grep mosquitto centos 3812 2043 0 13:01 pts/0 00:00:00 mosquitto -c test.conf centos 3815 2071 0 13:01 pts/1 00:00:00 mosquitto_sub -h localhost -t # centos 3817 2043 0 13:02 pts/0 00:00:00 grep --color=auto mosquitto $ sudo kill -s HUP 3812 $ 1514034159: Reloading config. 1514034159: Client mosqsub|3815-ip-172-31- disconnected. 1514034160: New connection from ::1 on port 1883. 1514034160: New client connected from ::1 as mosqsub|3815-ip-172-31- (c1, k60). 1514034160: Sending CONNACK to mosqsub|3815-ip-172-31- (0, 0) 1514034160: Received SUBSCRIBE from mosqsub|3815-ip-172-31- 1514034160: # (QoS 0) 1514034160: mosqsub|3815-ip-172-31- 0 # 1514034160: Sending SUBACK to mosqsub|3815-ip-172-31- — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#657 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ALNLfNpykgBwyH1jsa7PXk1SwTwj2AXcks5tDPtNgaJpZM4RKvd1> .

toast-uz · 2017-12-24T08:44:59Z

Thank you for the information.
Seemed a little complicated. My symptom was under only one connected client and reproduced always.

ralight · 2017-12-24T10:25:16Z

I've not reproduced it under 1.4.14, but have done on develop. I haven't tried the actual binary from the 1.4.14 PPA though. @kartom, if you get chance could you try a self compiled version 1.4.14? I doubt I'll be able to look any further for the next few days.

keestux · 2017-12-31T17:46:16Z

I'm running mosquitto 1.4.14 from the PPA for Ubuntu xenial, and it shows the same behaviour. I have a sub client running all the time, and I see that it receives old retained messages when the server rotates the logs (mosquitto server gets a HUP signal).

Bug: #657

ralight · 2018-01-10T22:37:41Z

I've pushed a fix for the develop branch but still haven't reproduced it on 1.4.14.

wiebeytec · 2019-03-13T13:37:36Z

I have the same issue with 1.5.3 and 1.5.5. You don't really see it with mosquitto_sub because it's quiet about its reconnects, but because I run a custom written auth plugin, I can see the messages it creates:

1552483245: Login with '[email protected]' succeeded.
1552483245: New client connected from ::1 as mosqsub|4210-duivenkrac (c1, k60, u'[email protected]').
1552483245: [Client mosqsub|4210-duivenkrac, user: [email protected]]: subscribe - '$SYS/broker': aclallow.
1552483245: mosqsub|4210-duivenkrac 0 $SYS/broker/load/messages/received/1min

1552483279: Reloading config.

1552483279: Error: An auth_opt_ option exists in the config file without an auth_plugin.
1552483279: Error found at /root/mosquitto-test-server/mosquitto-nonssl.conf:23.
1552483279: Opening MySQL.
1552483280: 33235 records refreshed from DB table 'vwUserPasswords'
1552483281: 60672 users2sites records refreshed from DB
1552483281: 31077 records refreshed from DB table 'vwSitesMqttPasswordHash'
1552483281: MySQL opened.
1552483281: Login with '[email protected]' succeeded.
1552483287: [Client mosqsub|4210-duivenkrac, user: [email protected]]: subscribe - '$SYS/broker': aclallow.

You can see the last 'login succeeded' again, and you can see the client ID is the same.

This is the mosquitto config:

pid_file /tmp/mosquitto/mosquitto.pid

persistence true
persistence_location /tmp/mosquitto/

log_dest file /tmp/mosquitto/mosquitto.log
log_type error
log_type warning
log_type notice
log_type information
log_type subscribe
log_type unsubscribe

# Otherwise it seems we're doing heaps of ACL checks for clients that don't exist anymore
persistent_client_expiration 14d

allow_anonymous false

auth_plugin /root/mosquitto-test-server/libMosquittoAuth.so.1.0.0
auth_opt_db_host 127.0.0.1
auth_opt_db_port 3306
auth_opt_db_name removed
auth_opt_db_user mqttbridge
auth_opt_db_password removed
auth_opt_log_acl_checks true

listener 11883

Started with /opt/mosquitto-1.5.3/src/mosquitto -c /root/mosquitto-test-server/mosquitto-nonssl.conf.

This is a self-compiled binary.

(I don't know why it's saying I don't have auth_plugin, because I do, and it works).

ralight · 2019-09-17T18:09:48Z

For some people this could be due to the logrotate script on Debian incorrectly calling "killall mosquitto", which would kill any tasks with mosquitto in the name, not just the mosquitto broker. This is being fixed now.

For completely self compiled and installed binaries that won't be the cause.

wiebeytec · 2019-09-18T07:10:42Z

I'm confused. Why would this be the cause? I only have Mosquitto running as broker on the server, nothing else by that name.

ralight · 2019-09-18T07:30:26Z

That's why I said "for some people". If you had clients running on the same machine as the broker, with "mosquitto" in their name, then they would be unexpectedly sent a HUP.

daenney · 2020-01-18T15:22:44Z

I'm getting this too. I just upgraded to 1.6.8 b/c of #1459 and though the error related to that one is gone, a HUP still kills all client connections.

I run from the Docker container, as a systemd service:

[Unit]
Description=Mosquitto
After=docker.service
Requires=docker.service

[Service]
ExecStartPre=-/usr/bin/docker rm mosquitto
ExecStart=-/usr/bin/docker run \
                           --name mosquitto \
                           --read-only \
                           -p 127.0.0.1:1883:1883 \
                           -p 127.0.0.1:9001:9001 \
                           --expose 1883 \
                           --expose 9001 \
                           -v mosquitto_data:/mosquitto/data:rw \
                           -v /etc/docker/config/mosquitto:/mosquitto/config:ro \
                           eclipse-mosquitto:1.6.8
ExecReload=/usr/bin/docker kill -s HUP mosquitto
ExecStop=-/usr/bin/docker stop mosquitto

[Install]
WantedBy=multi-user.target

$ systemctl reload mosquitto

$ journalctl -u mosquitto
[..]
Jan 18 16:12:07 endor systemd[1]: Reloading Mosquitto.
Jan 18 16:12:08 endor docker[17116]: mosquitto
Jan 18 16:12:08 endor systemd[1]: Reloaded Mosquitto.
Jan 18 16:12:08 endor docker[16612]: Reloading config.
Jan 18 16:12:08 endor docker[16612]: Loading config file /mosquitto/config/conf.d/plain.conf
Jan 18 16:12:08 endor docker[16612]: Loading config file /mosquitto/config/conf.d/websockets.conf
Jan 18 16:12:08 endor docker[16612]: Client fargton-53511d5f-212a-408a-babb-2cc418264223 disconnected.
Jan 18 16:12:08 endor docker[16612]: Client fargton-209725c9-28be-439a-8c72-b6cf84c15885 disconnected.
Jan 18 16:12:08 endor docker[16612]: Client dammsugare-829468be-e469-485a-bd35-00c6ebc2fbfa disconnected.
Jan 18 16:12:08 endor docker[16612]: Client rodljus-3891e934-fff8-4ce6-925a-531425dbf10e disconnected.
[..]

ralight · 2020-12-22T23:42:57Z

I think this has been fixed. The issue is around files not being accessible after root privileges have been dropped.

PierreF added Component: mosquitto-broker Status: Blocked Another issue needs to be resolved first labels Jan 5, 2018

ralight added a commit that referenced this issue Jan 10, 2018

Fix HUP disconnecting clients incorrectly.

b4c72e8

Bug: #657

brocaar mentioned this issue May 13, 2019

Denied PUBLISH after killall -HUP #1277

Closed

twegener-embertec mentioned this issue Sep 5, 2019

killall -HUP disconnects clients when using use_identity_as_username true #1402

Closed

ralight closed this as completed Dec 23, 2020

github-actions bot locked as resolved and limited conversation to collaborators Aug 11, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

killall -HUP disconnects clients #657

killall -HUP disconnects clients #657

kartom commented Dec 22, 2017 •

edited

toast-uz commented Dec 23, 2017

toast-uz commented Dec 24, 2017

toast-uz commented Dec 24, 2017

kartom commented Dec 24, 2017 via email

toast-uz commented Dec 24, 2017

ralight commented Dec 24, 2017

keestux commented Dec 31, 2017

ralight commented Jan 10, 2018

wiebeytec commented Mar 13, 2019 •

edited

ralight commented Sep 17, 2019

wiebeytec commented Sep 18, 2019

ralight commented Sep 18, 2019

daenney commented Jan 18, 2020

ralight commented Dec 22, 2020

killall -HUP disconnects clients #657

killall -HUP disconnects clients #657

Comments

kartom commented Dec 22, 2017 • edited

toast-uz commented Dec 23, 2017

toast-uz commented Dec 24, 2017

toast-uz commented Dec 24, 2017

kartom commented Dec 24, 2017 via email

toast-uz commented Dec 24, 2017

ralight commented Dec 24, 2017

keestux commented Dec 31, 2017

ralight commented Jan 10, 2018

wiebeytec commented Mar 13, 2019 • edited

ralight commented Sep 17, 2019

wiebeytec commented Sep 18, 2019

ralight commented Sep 18, 2019

daenney commented Jan 18, 2020

ralight commented Dec 22, 2020

kartom commented Dec 22, 2017 •

edited

wiebeytec commented Mar 13, 2019 •

edited