[SRU] rabbitmq-server does not properly shutdown

Thank you for taking the time to report this bug and helping to make Ubuntu better. Please execute the following command only once, as it will automatically gather debugging information, in a terminal:
apport-collect 1784757

When reporting bugs in the future please use apport by using 'ubuntu-bug' and the name of the package affected. You can learn more about this functionality at https://wiki.ubuntu.com/ReportingBugs.

[Expired for rabbitmq-server (Ubuntu) because there has been no activity for 60 days.]

The rabbitmq-server-release GitHub repo has a systemd file which uses shutdown instead of stop:

https://github.com/rabbitmq/rabbitmq-server-release/blob/master/packaging/debs/Debian/debian/rabbitmq-server.service

Switching to this will shut down rabbitmq in the expected way, instead of having to wait ~90 seconds.

The attachment "rabbitmq-stop-shutdown.patch" seems to be a patch. If it isn't, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are a member of the ~ubuntu-reviewers, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issues please contact him.]

Thanks for the update Alex.
In general the package seems rather different than upstream in terms of systemd integration.
We will have to take a wider look at this than just this line.

I can confirm this issue on the latest versions of 18.04.2, somewhat nasty, really slows down reboots when RabbitMQ is installed. Here's reproduce steps to see the bug in action:

rabbitmq installed via "sudo apt install rabbitmq-server"

Stop the service: "sudo systemctl stop rabbitmq-server.service"

Then running "status", we can see the 90 second delay between the stop attempt at 10:31:06, and it giving up and killing the service at 10:32:36

$ sudo systemctl status rabbitmq-server.service
[sudo] password for nearlotech:
● rabbitmq-server.service - RabbitMQ Messaging Server
   Loaded: loaded (/lib/systemd/system/rabbitmq-server.service; enabled; vendor preset: enabled)
   Active: failed (Result: timeout) since Thu 2019-05-09 10:32:36 MDT; 1min 32s ago
  Process: 2409 ExecStop=/usr/sbin/rabbitmqctl stop (code=exited, status=0/SUCCESS)
  Process: 899 ExecStartPost=/usr/lib/rabbitmq/bin/rabbitmq-server-wait (code=exited, status=0/SUCCESS)
  Process: 898 ExecStart=/usr/sbin/rabbitmq-server (code=killed, signal=TERM)
 Main PID: 898 (code=killed, signal=TERM)

May 09 10:30:43 ubuntu1804vm systemd[1]: Starting RabbitMQ Messaging Server...
May 09 10:30:46 ubuntu1804vm rabbitmq[899]: Waiting for 'rabbit@ubuntu1804vm'
May 09 10:30:46 ubuntu1804vm rabbitmq[899]: pid is 978
May 09 10:30:50 ubuntu1804vm systemd[1]: Started RabbitMQ Messaging Server.
May 09 10:31:05 ubuntu1804vm systemd[1]: Stopping RabbitMQ Messaging Server...
May 09 10:31:06 ubuntu1804vm rabbitmq[2409]: Stopping and halting node 'rabbit@ubuntu1804vm'
May 09 10:32:36 ubuntu1804vm systemd[1]: rabbitmq-server.service: State 'stop-final-sigterm' timed out. Killing.
May 09 10:32:36 ubuntu1804vm systemd[1]: rabbitmq-server.service: Killing process 2706 (epmd) with signal SIGKILL.
May 09 10:32:36 ubuntu1804vm systemd[1]: rabbitmq-server.service: Failed with result 'timeout'.
May 09 10:32:36 ubuntu1804vm systemd[1]: Stopped RabbitMQ Messaging Server.

Hmm, the same took 1 second for me.

root@b:~# systemctl status rabbitmq-server
● rabbitmq-server.service - RabbitMQ Messaging Server
   Loaded: loaded (/lib/systemd/system/rabbitmq-server.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Fri 2019-05-10 07:16:00 UTC; 5s ago
  Process: 6004 ExecStop=/usr/sbin/rabbitmqctl stop (code=exited, status=0/SUCCESS)
  Process: 5348 ExecStart=/usr/sbin/rabbitmq-server (code=killed, signal=TERM)
 Main PID: 5348 (code=killed, signal=TERM)

May 10 07:15:40 b systemd[1]: Starting RabbitMQ Messaging Server...
May 10 07:15:41 b rabbitmq[5349]: Waiting for rabbit@b
May 10 07:15:41 b rabbitmq[5349]: pid is 5365
May 10 07:15:43 b systemd[1]: Started RabbitMQ Messaging Server.
May 10 07:15:43 b systemd[1]: rabbitmq-server.service: Failed to reset devices.list: Operation not permitted
May 10 07:15:59 b systemd[1]: Stopping RabbitMQ Messaging Server...
May 10 07:15:59 b rabbitmq[6004]: Stopping and halting node rabbit@b
May 10 07:16:00 b systemd[1]: Stopped RabbitMQ Messaging Server.

Do you have any config changes or ongoing messages running while this shutdown happens that might explain and lead us to the root cause?

The stop action is just:
  $ /usr/sbin/rabbitmqctl stop

You might change the loglevel [1] and then in a second console attach to the log to see what is going on in that time?

[1]: https://www.rabbitmq.com/logging.html

Like Christian, I also am seeing only a 1 second stop. I tried a few different things but couldn't reproduce the delay.

I poked through /usr/lib/rabbitmq/lib/rabbitmq_server-3.6.10/sbin/rabbitmq-server, but it's unclear what the technical difference is between 'stop' and 'shutdown'. Some comments in the code suggest that under some circumstances a wait might be triggered - if you instrument that code perhaps you can identify if it is hitting that wait, and if so why.

Without knowing more, just switching to using 'shutdown' feels like a kludge/workaround, and probably not what we should deploy as a fix to this. Instead, some additional investigation needs done to figure out why it is delaying, or at least more specific reproduction steps so others can do that sleuthing.

So, as I don't think there's anything more we can do on this end, I'm going to drop the server-next tag for the time being. Feel free to re-add it if you think there's enough info for us to take another stab at it though.

I'm not sure why I did not mention originally, sorry for that, but there is a chance that what makes it reproducible is starting the daemon inside the lxd/lxc

For those who don't use lxd - the commands would be (I don't have access to linuxes or my infrastructure at the moment, so might be a bit incorrect):

lxc launch ubuntu:bionic
lxc exec <container name> bash

inside container:
apt update
apt install rabbitmq-server
systemct restart rabbitmq-server

Fixes in Debian packaging which also address the problem:

- https://salsa.debian.org/openstack-team/third-party/rabbitmq-server/commit/9764f7e6ffeaa99325b8e5ff41e80b1c4b2894d3
- https://salsa.debian.org/openstack-team/third-party/rabbitmq-server/commit/c5b99f5c4811f460b73c8c8505a98fa55dcd752b

If I start the server with just `service rabbitmq-server start`, my process tree looks like:

rabbitmq 11316 0.0 0.1 4628 800 ? Ss 14:59 0:00 /bin/sh /usr/sbin/rabbitmq-server
rabbitmq 11337 0.0 0.3 4628 1792 ? S 14:59 0:00 /bin/sh /usr/lib/rabbitmq/bin/rabbitmq-server
rabbitmq 11633 8.8 12.4 2165876 61504 ? Sl 14:59 0:02 /usr/lib/erlang/erts-9.2/bin/beam.smp -W w -A 64 -P 1048576 -t 5000000 -stbt db -zdbbl 32000 -K true -B i -- -root /usr/lib/erlang -progname erl -- -home /var/lib/rabbitmq -- -pa /usr/lib/rabbitmq/lib/rabbitmq_server-3.6.10/ebin -noshell -noinput -s rabbit boot -sname rabbit@golestandt -boot start_sasl -kernel inet_default_connect_options [{nodelay,true}] -sasl errlog_type error -sasl sasl_error_logger false -rabbit error_logger {file,"/<email address hidden>"} -rabbit sasl_error_logger {file,"/<email address hidden>"} -rabbit enabled_plugins_file "/etc/rabbitmq/enabled_plugins" -rabbit plugins_dir "/usr/lib/rabbitmq/plugins:/usr/lib/rabbitmq/lib/rabbitmq_server-3.6.10/plugins" -rabbit plugins_expand_dir "/var/lib/rabbitmq/mnesia/rabbit@golestandt-plugins-expand" -os_mon start_cpu_sup false -os_mon start_disksup false -os_mon start_memsup false -mnesia dir "/var/lib/rabbitmq/mnesia/rabbit@golestandt" -kernel inet_dist_listen_min 25672 -kernel inet_dist_listen_max 25672
rabbitmq 11745 0.1 0.1 4520 728 ? Ss 14:59 0:00 erl_child_setup 65536
rabbitmq 11809 0.0 0.2 8264 1072 ? Ss 14:59 0:00 inet_gethost 4
rabbitmq 11810 0.0 0.3 10384 1660 ? S 14:59 0:00 inet_gethost 4
rabbitmq 11504 0.0 0.0 26852 204 ? S 14:59 0:00 /usr/lib/erlang/erts-9.2/bin/epmd -daemon

However, doing `service epmd start` before that gives:

epmd 12226 0.0 0.3 26852 1728 ? Ss 15:01 0:00 /usr/bin/epmd -systemd
rabbitmq 12263 0.0 0.1 4628 816 ? Ss 15:01 0:00 /bin/sh /usr/sbin/rabbitmq-server
rabbitmq 12287 0.0 0.3 4628 1736 ? S 15:01 0:00 /bin/sh /usr/lib/rabbitmq/bin/rabbitmq-server
rabbitmq 12582 25.5 13.2 2171584 65160 ? Sl 15:01 0:02 /usr/lib/erlang/erts-9.2/bin/beam.smp -W w -A 64 -P 1048576 -t 5000000 -stbt db -zdbbl 32000 -K true -B i -- -root /usr/lib/erlang -progname erl -- -home /var/lib/rabbitmq -- -pa /usr/lib/rabbitmq/lib/rabbitmq_server-3.6.10/ebin -noshell -noinput -s rabbit boot -sname rabbit@golestandt -boot start_sasl -kernel inet_default_connect_options [{nodelay,true}] -sasl errlog_type error -sasl sasl_error_logger false -rabbit error_logger {file,"/<email address hidden>"} -rabbit sasl_error_logger {file,"/<email address hidden>"} -rabbit enabled_plugins_file "/etc/rabbitmq/enabled_plugins" -rabbit plugins_dir "/usr/lib/rabbitmq/plugins:/usr/lib/rab...

Alex, thanks for looking up the Debian upstream situation, this is looking a lot more actionable so am re-adding it to server-next.

Sounds like if we just picked the two changes to the service file from the debian commits, those would solve the problem? If so, that should be straightforward to SRU.

I'm still not able to reproduce the error.

If you can provide an exact set of steps to run in an lxc container it'd help a lot. Here's what I've got so far:

```
$ lxc launch ubuntu:bionic bionic-lp-1784757
Creating bionic-lp-1784757
Starting bionic-lp-1784757
trent:~/ubuntu/RabbitmqServer/sru.1784757$ lxc exec bionic-lp-1784757 -- bash
root@bionic-lp-1784757:~# apt update
Hit:1 http://archive.ubuntu.com/ubuntu bionic InRelease
(...)
root@bionic-lp-1784757:~# ps aux | grep ^rabbit
rabbitmq 1390 0.0 0.0 4628 868 ? Ss 01:30 0:00 /bin/sh /usr/sbin/rabbitmq-server
rabbitmq 1403 0.0 0.0 4628 1844 ? S 01:30 0:00 /bin/sh /usr/lib/rabbitmq/bin/rabbitmq-server
rabbitmq 1553 0.0 0.0 26852 204 ? S 01:30 0:00 /usr/lib/erlang/erts-9.2/bin/epmd -daemon
rabbitmq 1684 0.0 0.1 4291312 62276 ? Sl 01:30 0:02 /usr/lib/erlang/erts-9.2/bin/beam.smp -W w -A 96 -P 1048576 (...)
rabbitmq 1834 0.0 0.0 4520 804 ? Ss 01:30 0:00 erl_child_setup 65536
rabbitmq 1913 0.0 0.0 8264 1128 ? Ss 01:30 0:00 inet_gethost 4
rabbitmq 1914 0.0 0.0 14616 1888 ? S 01:30 0:00 inet_gethost 4
root@bionic-lp-1784757:~# sudo time --format %E systemctl stop rabbitmq-server.service
0:00.88
```

I've also experimented with having epmd started or stopped, in various order with the start/stop of rabbitmq-server, but it always takes only a second or two to start or stop. Debian's changes suggest that the bug is some interrelationship with epmd, but it's unclear from the patch what exactly that is.

Are there any config settings, architecture specificness, or other considerations that need taken into account?

# I run into this problem reliably in Bionic following this process, (as of 7/19/2019, this process caused the bug to manifest)

# Clean install ubuntu server 18.04.2 (using traditional installer media, not live media)
# (installing into a gen2 Hyper-V VM running on Windows 10 1903)

# after install and first reboot, patch it up all the way:

sudo apt update
sudo apt full-upgrade

sudo shutdown -r now

sudo apt install -y apt-transport-https locales software-properties-common curl

# setup repo for nodejs version 8.x:
curl -sL https://deb.nodesource.com/setup_8.x | sudo -E bash -

sudo apt install -y fonts-noto nodejs git supervisor nginx ssl-cert postgresql adduser redis-server rabbitmq-server libstdc++6 libxml2 libboost-regex-dev zlib1g fonts-dejavu fonts-liberation ttf-mscorefonts-installer fonts-crosextra-carlito fonts-takao-gothic fonts-opensymbol libxss1 libcairo2 xvfb libxtst6 libgconf2-4 libasound2

sudo shutdown -r now

# on this reboot after Rabitmq-server has been installed (along with all that other junk) then the bug manifests reliably in bionic.

# my method to fix the problem in Bionic for now is simple, borrowing from the upstream Debian patch:

sudo nano /lib/systemd/system/rabbitmq-server.service

# make the [Unit] definition look like this:
[Unit]
Description=RabbitMQ Messaging Server
After=network.target epmd@0.0.0.0.socket
Wants=network.target epmd@0.0.0.0.socket

# then reload and reboot, no more delay at Rabbitmq
sudo systemctl daemon-reload
sudo systemctl restart rabbitmq-server.service

sudo shutdown -r now

# forgot to include the shutdown changes, so here's a full procedure to fix this in Bionic:

sudo nano /lib/systemd/system/rabbitmq-server.service

# fixup the [Unit] entry to look like this:
[Unit]
Description=RabbitMQ Messaging Server
After=network.target epmd@0.0.0.0.socket
Wants=network.target epmd@0.0.0.0.socket

# change just the ExecStop under [Service] to use "shutdown" instead of "stop":
ExecStop=/usr/sbin/rabbitmqctl shutdown

# reload and reboot:
sudo systemctl stop rabbitmq-server.service
sudo systemctl daemon-reload
sudo systemctl restart rabbitmq-server.service
sudo shutdown -r now

I'm looking at this bug now.

I was able to reproduce this bug when using a bionic VM. I didn't have to go through all the steps from comment #13, but I also noticed that the bug doesn't manifest all the time; sometimes, a "systemct restart rabbitmq-server" will take just 1 or 2 seconds. However, I was able to reproduce the issue in one out of every two attempts. I'm preparing the fix now.

adding @nicolasbock and @mruffell for their awareness, as rabbitmq-server is in x/b/f-proposed for bug 1874075 currently; hopefully that bug can be verified this week so it can be released at the 7-day aging period next monday, to clear the way for this one (normally i'd suggest just re-uploading with the fixes for this to release them together, but bug 1874075 has been going for a while so it should probably go out asap)

On Tuesday, July 07 2020, Dan Streetman wrote:

> adding @nicolasbock and @mruffell for their awareness, as rabbitmq-
> server is in x/b/f-proposed for bug 1874075 currently; hopefully that
> bug can be verified this week so it can be released at the 7-day aging
> period next monday, to clear the way for this one (normally i'd suggest
> just re-uploading with the fixes for this to release them together, but
> bug 1874075 has been going for a while so it should probably go out
> asap)

Thanks, Dan.

I have the fix ready for this bug, by the way. If you're interested,
you can take a look at it here:

  https://code.launchpad.net/~sergiodj/ubuntu/+source/rabbitmq-server/+git/rabbitmq-server/+ref/bug1784757-fix-server-restart-hang

I'll wait until the package enters -update before I resume the SRU
process.

Cheers,

--
Sergio
GPG key ID: E92F D0B3 6B14 F1F4 D8E0 EB2F 106D A1C8 C3CB BF14

Hello Ivan, or anyone else affected,

Accepted rabbitmq-server into bionic-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/rabbitmq-server/3.6.10-1ubuntu0.4 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, what testing has been performed on the package and change the tag from verification-needed-bionic to verification-done-bionic. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-bionic. In either case, without details of your testing we will not be able to proceed.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance for helping!

N.B. The updated package will be released to -updates after the bug(s) fixed by this package have been verified and the package has been in -proposed for a minimum of 7 days.

The fix for this bug has been awaiting testing feedback in the -proposed repository for bionic for more than 90 days. Please test this fix and update the bug appropriately with the results. In the event that the fix for this bug is still not verified 15 days from now, the package will be removed from the -proposed repository.

First, verifying that the current package fails:

root@bug1784757-rabbitmq-server:~# apt policy rabbitmq-server
rabbitmq-server:
  Installed: 3.6.10-1ubuntu0.3
  Candidate: 3.6.10-1ubuntu0.3
  Version table:
 *** 3.6.10-1ubuntu0.3 500
        500 http://archive.ubuntu.com/ubuntu bionic-updates/main amd64 Packages
        100 /var/lib/dpkg/status
     3.6.10-1 500
        500 http://archive.ubuntu.com/ubuntu bionic/main amd64 Packages
root@bug1784757-rabbitmq-server:~# time systemctl restart rabbitmq-server.service

real 1m33.535s
user 0m0.005s
sys 0m0.007s

Now, installing rabbitmq-server from -proposed, and verifying that the bug is fixed:

root@bug1784757-rabbitmq-server:~# apt policy rabbitmq-server
rabbitmq-server:
  Installed: 3.6.10-1ubuntu0.4
  Candidate: 3.6.10-1ubuntu0.4
  Version table:
 *** 3.6.10-1ubuntu0.4 500
        500 http://archive.ubuntu.com/ubuntu bionic-proposed/main amd64 Packages
        100 /var/lib/dpkg/status
     3.6.10-1ubuntu0.3 500
        500 http://archive.ubuntu.com/ubuntu bionic-updates/main amd64 Packages
     3.6.10-1 500
        500 http://archive.ubuntu.com/ubuntu bionic/main amd64 Packages
root@bug1784757-rabbitmq-server:~# for i in $(seq 10); do time systemctl restart rabbitmq-server.service ; done

real 0m2.980s
user 0m0.006s
sys 0m0.004s

real 0m3.010s
user 0m0.004s
sys 0m0.000s

real 0m4.907s
user 0m0.004s
sys 0m0.000s

real 0m3.012s
user 0m0.002s
sys 0m0.002s

real 0m2.899s
user 0m0.004s
sys 0m0.000s

real 0m2.975s
user 0m0.004s
sys 0m0.000s

real 0m3.036s
user 0m0.002s
sys 0m0.003s

real 0m3.013s
user 0m0.004s
sys 0m0.000s

real 0m3.003s
user 0m0.004s
sys 0m0.000s

real 0m3.040s
user 0m0.004s
sys 0m0.000s

Therefore, I'm marking this bug as verified.

This bug was fixed in the package rabbitmq-server - 3.6.10-1ubuntu0.4

---------------
rabbitmq-server (3.6.10-1ubuntu0.4) bionic; urgency=medium

  * Improve systemd service file in order to avoid a 90-second hang
    when restarting rabbitmq-server. (LP: #1784757) (Closes #902136)
    - d/rabbitmq-server.service: Make sure the service starts after
      epmd. Use "Type=notify" for the service.
    - d/control: Depend on socat, which is needed for the communication
      between rabbitmq-server and systemd when "Type=notify" is used.

 -- Sergio Durigan Junior <email address hidden> Tue, 07 Jul 2020 10:26:18 -0400

The verification of the Stable Release Update for rabbitmq-server has completed successfully and the package is now being released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.