rabbitmq-server logrotate issue

[Jean-Luc D.]

[Problem]
=========

The postrotate script (`/etc/init.d/rabbitmq-server rotate-logs`) also invokes a log rotation, which conflicts with logrotate itself.
It was working as expected on Xenial, but it became a problem on Focal and RabbitMQ 3.8 (see the tests below).

After a few weeks running, it becomes a mess (some logs are not compressed, duplicate filenames like .log.2 and .log.2.gz).

Depending on the disk space available, it can became an issue and it might be critical in production environments.

[Test Plan]
===========

Tested with Vagrant (VirtualBox) and a fresh install on each run.

Clock syncing needs to be disabled with:

    v.customize ["setextradata", :id, "VBoxInternal/Devices/VMMDev/0/Config/GetHostTimeDisabled", "1"]

Test #1, current config (not expected, double log rotation)

    vagrant@ubuntu-focal:~$ cat /etc/logrotate.d/rabbitmq-server
    /var/log/rabbitmq/*.log {
            weekly
            missingok
            rotate 20
            compress
            delaycompress
            notifempty
            sharedscripts
            postrotate
                /etc/init.d/rabbitmq-server rotate-logs > /dev/null
            endscript
    }
    vagrant@ubuntu-focal:~$ date ; ls -l /var/log/rabbitmq/
    Thu Mar 25 18:25:49 UTC 2021
    total 32
    drwxr-x--- 2 rabbitmq rabbitmq 4096 Mar 25 18:25 log
    -rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:25 <email address hidden>
    -rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:25 rabbit@ubuntu-focal_upgrade.log
    -rw-r----- 1 rabbitmq rabbitmq 61 Mar 25 18:25 startup_err
    -rw-r----- 1 rabbitmq rabbitmq 573 Mar 25 18:25 startup_log
    vagrant@ubuntu-focal:~$ sudo date --utc 04032358
    Sat Apr 3 23:58:00 UTC 2021
    vagrant@ubuntu-focal:~$ sleep 180 ; date ; ls -l /var/log/rabbitmq/
    Sun Apr 4 00:01:18 UTC 2021
    total 48
    drwxr-x--- 2 rabbitmq rabbitmq 4096 Mar 25 18:25 log
    -rw-r----- 1 rabbitmq rabbitmq 82 Apr 4 00:00 <email address hidden>
    -rw-r----- 1 rabbitmq rabbitmq 66 Apr 4 00:00 <email address hidden>
    -rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:25 <email address hidden>
    -rw-r----- 1 rabbitmq rabbitmq 82 Apr 4 00:00 rabbit@ubuntu-focal_upgrade.log
    -rw-r----- 1 rabbitmq rabbitmq 66 Apr 4 00:00 rabbit@ubuntu-focal_upgrade.log.0
    -rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:25 rabbit@ubuntu-focal_upgrade.log.2
    -rw-r----- 1 rabbitmq rabbitmq 61 Mar 25 18:25 startup_err
    -rw-r----- 1 rabbitmq rabbitmq 573 Mar 25 18:25 startup_log

    vagrant@ubuntu-focal:~$ sudo tail /<email address hidden>
    2021-03-25 18:25:37.453 [info] <0.267.0> Setting up a table for per-vhost connection counting on this node: 'tracked_connection_per_vhost_on_node_rabbit@ubuntu-focal'
    2021-03-25 18:25:37.454 [info] <0.267.0> Running boot step routing_ready defined by app rabbit
    2021-03-25 18:25:37.454 [info] <0.267.0> Running boot step pre_flight defined by app rabbit
    2021-03-25 18:25:37.454 [info] <0.267.0> Running boot step notify_cluster defined by app rabbit
    2021-03-25 18:25:37.454 [info] <0.267.0> Running boot step networking defined by app rabbit
    2021-03-25 18:25:37.457 [info] <0.597.0> started TCP listener on [::]:5672
    2021-03-25 18:25:37.460 [info] <0.267.0> Running boot step cluster_name defined by app rabbit
    2021-03-25 18:25:37.460 [info] <0.267.0> Running boot step direct_client defined by app rabbit
    2021-03-25 18:25:37.554 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 50
    2021-03-25 18:25:38.045 [info] <0.8.0> Server startup complete; 0 plugins started.

    vagrant@ubuntu-focal:~$ sudo cat /<email address hidden>
    2021-04-04 00:00:03.036 [info] <0.748.0> Log file rotation forced

    vagrant@ubuntu-focal:~$ sudo cat /<email address hidden>
    2021-04-04 00:00:03.036 [info] <0.748.0> Log file re-opened after forced rotation

Test #2, no postrotate script (expected, single log rotation)

    vagrant@ubuntu-focal:~$ cat /etc/logrotate.d/rabbitmq-server
    /var/log/rabbitmq/*.log {
            weekly
            missingok
            rotate 20
            compress
            delaycompress
            notifempty
    }
    vagrant@ubuntu-focal:~$ date ; ls -l /var/log/rabbitmq/
    Thu Mar 25 18:37:39 UTC 2021
    total 32
    drwxr-x--- 2 rabbitmq rabbitmq 4096 Mar 25 18:37 log
    -rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:37 <email address hidden>
    -rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:37 rabbit@ubuntu-focal_upgrade.log
    -rw-r----- 1 rabbitmq rabbitmq 61 Mar 25 18:37 startup_err
    -rw-r----- 1 rabbitmq rabbitmq 573 Mar 25 18:37 startup_log
    vagrant@ubuntu-focal:~$ sudo date --utc 04032358
    Sat Apr 3 23:58:00 UTC 2021
    vagrant@ubuntu-focal:~$ sleep 180 ; date ; ls -l /var/log/rabbitmq/
    Sun Apr 4 00:01:05 UTC 2021
    total 32
    drwxr-x--- 2 rabbitmq rabbitmq 4096 Mar 25 18:37 log
    -rw-r----- 1 rabbitmq rabbitmq 0 Apr 4 00:00 <email address hidden>
    -rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:37 <email address hidden>
    -rw-r----- 1 rabbitmq rabbitmq 0 Apr 4 00:00 rabbit@ubuntu-focal_upgrade.log
    -rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:37 rabbit@ubuntu-focal_upgrade.log.1
    -rw-r----- 1 rabbitmq rabbitmq 61 Mar 25 18:37 startup_err
    -rw-r----- 1 rabbitmq rabbitmq 573 Mar 25 18:37 startup_log

    vagrant@ubuntu-focal:~$ sudo tail /<email address hidden>
    2021-03-25 18:37:06.863 [info] <0.267.0> Setting up a table for per-vhost connection counting on this node: 'tracked_connection_per_vhost_on_node_rabbit@ubuntu-focal'
    2021-03-25 18:37:06.864 [info] <0.267.0> Running boot step routing_ready defined by app rabbit
    2021-03-25 18:37:06.864 [info] <0.267.0> Running boot step pre_flight defined by app rabbit
    2021-03-25 18:37:06.864 [info] <0.267.0> Running boot step notify_cluster defined by app rabbit
    2021-03-25 18:37:06.864 [info] <0.267.0> Running boot step networking defined by app rabbit
    2021-03-25 18:37:06.868 [info] <0.597.0> started TCP listener on [::]:5672
    2021-03-25 18:37:06.869 [info] <0.267.0> Running boot step cluster_name defined by app rabbit
    2021-03-25 18:37:06.869 [info] <0.267.0> Running boot step direct_client defined by app rabbit
    2021-03-25 18:37:06.956 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 50
    2021-03-25 18:37:07.529 [info] <0.8.0> Server startup complete; 0 plugins started.

    # <email address hidden> is empty

Test #3, flooding logs to confirm the server catches the log rotation

    # Similar to test #2, but running `while true; do date; sudo rabbitmqctl set_log_level debug; sleep 0.2; sudo rabbitmqctl set_log_level info; sleep 0.2; done` in the background

    vagrant@ubuntu-focal:/var/log/rabbitmq$ sudo tail <email address hidden>
    2021-04-03 23:59:57.544 [notice] <0.146.0> Changed loghwm of /var/log/rabbitmq/rabbit@ubuntu-focal_upgrade.log to 5000
    2021-04-03 23:59:57.544 [notice] <0.146.0> Changed loglevel of /var/log/rabbitmq/rabbit@ubuntu-focal_upgrade.log to debug
    2021-04-03 23:59:58.795 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 50
    2021-04-03 23:59:58.795 [notice] <0.104.0> Changed loglevel of /<email address hidden> to info
    2021-04-03 23:59:58.796 [notice] <0.146.0> Changed loghwm of /var/log/rabbitmq/rabbit@ubuntu-focal_upgrade.log to 50
    2021-04-03 23:59:58.796 [notice] <0.146.0> Changed loglevel of /var/log/rabbitmq/rabbit@ubuntu-focal_upgrade.log to info
    2021-04-04 00:00:00.119 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 5000
    2021-04-04 00:00:00.120 [notice] <0.104.0> Changed loglevel of /<email address hidden> to debug
    2021-04-04 00:00:00.121 [notice] <0.146.0> Changed loghwm of /var/log/rabbitmq/rabbit@ubuntu-focal_upgrade.log to 5000
    2021-04-04 00:00:00.121 [notice] <0.146.0> Changed loglevel of /var/log/rabbitmq/rabbit@ubuntu-focal_upgrade.log to debug

    vagrant@ubuntu-focal:/var/log/rabbitmq$ sudo head <email address hidden>
    2021-04-04 00:00:01.317 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 50
    2021-04-04 00:00:01.320 [notice] <0.104.0> Changed loglevel of /<email address hidden> to info
    2021-04-04 00:00:01.321 [notice] <0.146.0> Changed loghwm of /var/log/rabbitmq/rabbit@ubuntu-focal_upgrade.log to 50
    2021-04-04 00:00:01.322 [notice] <0.146.0> Changed loglevel of /var/log/rabbitmq/rabbit@ubuntu-focal_upgrade.log to info
    2021-04-04 00:00:02.938 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 5000
    2021-04-04 00:00:02.939 [notice] <0.104.0> Changed loglevel of /<email address hidden> to debug
    2021-04-04 00:00:02.939 [notice] <0.146.0> Changed loghwm of /var/log/rabbitmq/rabbit@ubuntu-focal_upgrade.log to 5000
    2021-04-04 00:00:02.940 [notice] <0.146.0> Changed loglevel of /var/log/rabbitmq/rabbit@ubuntu-focal_upgrade.log to debug
    2021-04-04 00:00:04.489 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 50
    2021-04-04 00:00:04.489 [notice] <0.104.0> Changed loglevel of /<email address hidden> to info

// With the fixed package, this should no longer be a problem.

[Where Problems Could Occur]
============================

If the user has done some manual intervention to work around this issue, maybe then the upgrade could cause their hacks to break.

[Utkarsh Gupta (utkarsh)]

Hi Jean,

Thanks for taking the time to file a bug and help in making the Ubuntu server better.

This looks like a valid bug and I am glad that you've already found the cause and the workaround for this. That said, I can trace its origin in Debian (see: https://salsa.debian.org/openstack-team/third-party/rabbitmq-server/-/blob/02ca091d15ac35df0fba06b4e0ea4158f5325223/debian/rabbitmq-server.logrotate). So maybe you can file a bug in Debian and when this is fixed there, it'll automatically sync-in here for the next cycle.

Given it's trivial and not really affecting the package use or resulting in a crash or something, I'm marking this as "low" importance. However, if you think otherwise, please let me know and we can discuss this further.

Thanks, again! :)

[Jean-Luc D. (jderrien)]

Hi Utkarsh,

From what I've seen, after a few weeks running, it becomes a mess (some logs are not compressed, duplicate filenames like .log.2 and .log.2.gz).

Depending on the disk space available, it can became an issue and it might be critical in production environments.

Since Focal is a LTS version, I'd expect to get it fixed.

That's said I can still report it to Debian.

Thank you

[Paride Legovini (paride)]

Given that Utkarsh confirmed this is a bug and even found where it originates from I think this can be considered Triaged.

I also subscribed the ubuntu-server team.

[Utkarsh Gupta (utkarsh)]

Hi Jean,

> Depending on the disk space available, it can became an issue and
> it might be critical in production environments.
>
> Since Focal is a LTS version, I'd expect to get it fixed.

Fair enough, I've assigned this to myself. I hope to get this fixed within this week.

[Jean-Luc D. (jderrien)]

Hi Utkarsh,

Great, thank you.

Currently I'm not sure if this issue also affects Bionic. That's something I can test today or tomorrow if it can help.

It has been fixed in Debian per https://salsa.debian.org/openstack-team/third-party/rabbitmq-server/-/commit/20641fde278ad4d8bf7451e3c396f8ae976ff2f0 -- Thank you, Thomas.

[Utkarsh Gupta (utkarsh)]

Yeap, I asked Thomas to include this fix in the next release so that I could sync in with Hirsute (the release happening next month), which happened already. So likely Hirsute will have the fix already.

I'll backport this to Focal and Groovy by today or tomorrow.

[Launchpad Janitor (janitor)]

This bug was fixed in the package rabbitmq-server - 3.8.9-2

---------------
rabbitmq-server (3.8.9-2) unstable; urgency=medium

  * Do not use the /usr/sbin/rabbitmq-server wrapper in systemd service file
    (Closes: #947873).
  * Use logrotate daily instead of weekly, and do not override the number of
    logs, so we don't keep too much of them.
  * Do not use a sharedscripts, as rabbitmq-server detects the log rotation
    by itself (LP: #1921425).

 -- Thomas Goirand <email address hidden> Fri, 26 Mar 2021 14:24:52 +0100

[Brian Murray (brian-murray)]

Hello Jean-Luc, or anyone else affected,

Accepted rabbitmq-server into groovy-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/rabbitmq-server/3.8.5-1ubuntu0.1 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-groovy to verification-done-groovy. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-groovy. 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.

[Brian Murray (brian-murray)]

Hello Jean-Luc, or anyone else affected,

Accepted rabbitmq-server into focal-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/rabbitmq-server/3.8.2-0ubuntu1.2 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-focal to verification-done-focal. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed-focal. 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.

[Jean-Luc D. (jderrien)]

Hello Brian,

I tested rabbitmq-server 3.8.2-0ubuntu1.2

I've forced a log rotation to happen and ended up with the expected result:

vagrant@ubuntu-focal:~$ ls -l /var/log/rabbitmq/
total 32
drwxr-x--- 2 rabbitmq rabbitmq 4096 Apr 21 12:56 log
-rw-r----- 1 rabbitmq rabbitmq 0 May 7 23:58 <email address hidden>
-rw-r----- 1 rabbitmq rabbitmq 16216 Apr 21 12:56 <email address hidden>
-rw-r----- 1 rabbitmq rabbitmq 0 May 7 23:58 rabbit@ubuntu-focal_upgrade.log
-rw-r----- 1 rabbitmq rabbitmq 66 Apr 21 12:56 rabbit@ubuntu-focal_upgrade.log.1
-rw-r----- 1 rabbitmq rabbitmq 61 Apr 21 12:56 startup_err
-rw-r----- 1 rabbitmq rabbitmq 573 Apr 21 12:56 startup_log

Thank you.

[Utkarsh Gupta (utkarsh)]

Hello Brian,

Tested 3.8.5-1ubuntu0.1 (for groovy) and I have similar outcome as of Jean. Therefore, confirm that the fix works for groovy w/o changing the stuff that was already working. So yay! \o/

[Launchpad Janitor (janitor)]

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

---------------
rabbitmq-server (3.8.5-1ubuntu0.1) groovy; urgency=medium

  [ Thomas Goirand ]
  * d/rabbitmq-server.logrotate: Do not use a sharedscripts, as
    rabbitmq-server detects the log rotation by itself. (LP: #1921425)

 -- Utkarsh Gupta <email address hidden> Tue, 06 Apr 2021 16:24:40 +0530

[Łukasz Zemczak (sil2100)]

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.

[Launchpad Janitor (janitor)]

This bug was fixed in the package rabbitmq-server - 3.8.2-0ubuntu1.2

---------------
rabbitmq-server (3.8.2-0ubuntu1.2) focal; urgency=medium

  [ Thomas Goirand ]
  * d/rabbitmq-server.logrotate: Do not use a sharedscripts, as
    rabbitmq-server detects the log rotation by itself. (LP: #1921425)

 -- Utkarsh Gupta <email address hidden> Tue, 06 Apr 2021 15:48:23 +0530