[Bug 1921425] Re: rabbitmq-server logrotate issue
Utkarsh Gupta
1921425 at bugs.launchpad.net
Wed Apr 21 17:11:56 UTC 2021
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/
** Tags removed: verification-needed verification-needed-focal verification-needed-groovy
** Tags added: verification-done
--
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