[Bug 1921425] Please test proposed package
Brian Murray
1921425 at bugs.launchpad.net
Wed Apr 21 00:57:20 UTC 2021
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.
--
You received this bug notification because you are a member of Ubuntu
OpenStack, which is subscribed to rabbitmq-server in Ubuntu.
https://bugs.launchpad.net/bugs/1921425
Title:
rabbitmq-server logrotate issue
Status in rabbitmq-server package in Ubuntu:
Fix Released
Status in rabbitmq-server source package in Focal:
Fix Committed
Status in rabbitmq-server source package in Groovy:
Fix Committed
Status in rabbitmq-server package in Debian:
Fix Released
Bug description:
[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 at 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 at 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 rabbit at ubuntu-focal.log
-rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:25 rabbit at 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 at ubuntu-focal:~$ sudo date --utc 04032358
Sat Apr 3 23:58:00 UTC 2021
vagrant at 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 rabbit at ubuntu-focal.log
-rw-r----- 1 rabbitmq rabbitmq 66 Apr 4 00:00 rabbit at ubuntu-focal.log.0
-rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:25 rabbit at ubuntu-focal.log.2
-rw-r----- 1 rabbitmq rabbitmq 82 Apr 4 00:00 rabbit at ubuntu-focal_upgrade.log
-rw-r----- 1 rabbitmq rabbitmq 66 Apr 4 00:00 rabbit at ubuntu-focal_upgrade.log.0
-rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:25 rabbit at 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 at ubuntu-focal:~$ sudo tail /var/log/rabbitmq/rabbit at ubuntu-focal.log.2
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 at 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 /var/log/rabbitmq/rabbit at ubuntu-focal.log to 50
2021-03-25 18:25:38.045 [info] <0.8.0> Server startup complete; 0 plugins started.
vagrant at ubuntu-focal:~$ sudo cat /var/log/rabbitmq/rabbit at ubuntu-focal.log.0
2021-04-04 00:00:03.036 [info] <0.748.0> Log file rotation forced
vagrant at ubuntu-focal:~$ sudo cat /var/log/rabbitmq/rabbit at ubuntu-focal.log
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 at ubuntu-focal:~$ cat /etc/logrotate.d/rabbitmq-server
/var/log/rabbitmq/*.log {
weekly
missingok
rotate 20
compress
delaycompress
notifempty
}
vagrant at 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 rabbit at ubuntu-focal.log
-rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:37 rabbit at 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 at ubuntu-focal:~$ sudo date --utc 04032358
Sat Apr 3 23:58:00 UTC 2021
vagrant at 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 rabbit at ubuntu-focal.log
-rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:37 rabbit at ubuntu-focal.log.1
-rw-r----- 1 rabbitmq rabbitmq 0 Apr 4 00:00 rabbit at ubuntu-focal_upgrade.log
-rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:37 rabbit at 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 at ubuntu-focal:~$ sudo tail /var/log/rabbitmq/rabbit at ubuntu-focal.log.1
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 at 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 /var/log/rabbitmq/rabbit at ubuntu-focal.log to 50
2021-03-25 18:37:07.529 [info] <0.8.0> Server startup complete; 0 plugins started.
# rabbit at ubuntu-focal.log 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 at ubuntu-focal:/var/log/rabbitmq$ sudo tail rabbit at ubuntu-focal.log.1
2021-04-03 23:59:57.544 [notice] <0.146.0> Changed loghwm of /var/log/rabbitmq/rabbit at ubuntu-focal_upgrade.log to 5000
2021-04-03 23:59:57.544 [notice] <0.146.0> Changed loglevel of /var/log/rabbitmq/rabbit at ubuntu-focal_upgrade.log to debug
2021-04-03 23:59:58.795 [notice] <0.104.0> Changed loghwm of /var/log/rabbitmq/rabbit at ubuntu-focal.log to 50
2021-04-03 23:59:58.795 [notice] <0.104.0> Changed loglevel of /var/log/rabbitmq/rabbit at ubuntu-focal.log to info
2021-04-03 23:59:58.796 [notice] <0.146.0> Changed loghwm of /var/log/rabbitmq/rabbit at ubuntu-focal_upgrade.log to 50
2021-04-03 23:59:58.796 [notice] <0.146.0> Changed loglevel of /var/log/rabbitmq/rabbit at ubuntu-focal_upgrade.log to info
2021-04-04 00:00:00.119 [notice] <0.104.0> Changed loghwm of /var/log/rabbitmq/rabbit at ubuntu-focal.log to 5000
2021-04-04 00:00:00.120 [notice] <0.104.0> Changed loglevel of /var/log/rabbitmq/rabbit at ubuntu-focal.log to debug
2021-04-04 00:00:00.121 [notice] <0.146.0> Changed loghwm of /var/log/rabbitmq/rabbit at ubuntu-focal_upgrade.log to 5000
2021-04-04 00:00:00.121 [notice] <0.146.0> Changed loglevel of /var/log/rabbitmq/rabbit at ubuntu-focal_upgrade.log to debug
vagrant at ubuntu-focal:/var/log/rabbitmq$ sudo head rabbit at ubuntu-focal.log
2021-04-04 00:00:01.317 [notice] <0.104.0> Changed loghwm of /var/log/rabbitmq/rabbit at ubuntu-focal.log to 50
2021-04-04 00:00:01.320 [notice] <0.104.0> Changed loglevel of /var/log/rabbitmq/rabbit at ubuntu-focal.log to info
2021-04-04 00:00:01.321 [notice] <0.146.0> Changed loghwm of /var/log/rabbitmq/rabbit at ubuntu-focal_upgrade.log to 50
2021-04-04 00:00:01.322 [notice] <0.146.0> Changed loglevel of /var/log/rabbitmq/rabbit at ubuntu-focal_upgrade.log to info
2021-04-04 00:00:02.938 [notice] <0.104.0> Changed loghwm of /var/log/rabbitmq/rabbit at ubuntu-focal.log to 5000
2021-04-04 00:00:02.939 [notice] <0.104.0> Changed loglevel of /var/log/rabbitmq/rabbit at ubuntu-focal.log to debug
2021-04-04 00:00:02.939 [notice] <0.146.0> Changed loghwm of /var/log/rabbitmq/rabbit at ubuntu-focal_upgrade.log to 5000
2021-04-04 00:00:02.940 [notice] <0.146.0> Changed loglevel of /var/log/rabbitmq/rabbit at ubuntu-focal_upgrade.log to debug
2021-04-04 00:00:04.489 [notice] <0.104.0> Changed loghwm of /var/log/rabbitmq/rabbit at ubuntu-focal.log to 50
2021-04-04 00:00:04.489 [notice] <0.104.0> Changed loglevel of /var/log/rabbitmq/rabbit at ubuntu-focal.log 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.
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/rabbitmq-server/+bug/1921425/+subscriptions
More information about the Ubuntu-openstack-bugs
mailing list