** Description changed:
[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 protected]
-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 protected]
-rw-r----- 1 rabbitmq rabbitmq 66 Apr 4 00:00
[email protected]
-rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:25
[email protected]
-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
/var/log/rabbitmq/[email protected]
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
/var/log/rabbitmq/[email protected] to 50
2021-03-25 18:25:38.045 [info] <0.8.0> Server startup complete; 0 plugins
started.
vagrant@ubuntu-focal:~$ sudo cat
/var/log/rabbitmq/[email protected]
2021-04-04 00:00:03.036 [info] <0.748.0> Log file rotation forced
vagrant@ubuntu-focal:~$ sudo cat /var/log/rabbitmq/[email protected]
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 protected]
-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 protected]
-rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:37
[email protected]
-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
/var/log/rabbitmq/[email protected]
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
/var/log/rabbitmq/[email protected] to 50
2021-03-25 18:37:07.529 [info] <0.8.0> Server startup complete; 0 plugins
started.
# [email protected] 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 protected]
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
/var/log/rabbitmq/[email protected] to 50
2021-04-03 23:59:58.795 [notice] <0.104.0> Changed loglevel of
/var/log/rabbitmq/[email protected] 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
/var/log/rabbitmq/[email protected] to 5000
2021-04-04 00:00:00.120 [notice] <0.104.0> Changed loglevel of
/var/log/rabbitmq/[email protected] 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 protected]
2021-04-04 00:00:01.317 [notice] <0.104.0> Changed loghwm of
/var/log/rabbitmq/[email protected] to 50
2021-04-04 00:00:01.320 [notice] <0.104.0> Changed loglevel of
/var/log/rabbitmq/[email protected] 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
/var/log/rabbitmq/[email protected] to 5000
2021-04-04 00:00:02.939 [notice] <0.104.0> Changed loglevel of
/var/log/rabbitmq/[email protected] 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
/var/log/rabbitmq/[email protected] to 50
2021-04-04 00:00:04.489 [notice] <0.104.0> Changed loglevel of
/var/log/rabbitmq/[email protected] 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. The addition of
- SO/SE could cause some confusion to some users but that should be a no-
- brainer.
+ maybe then the upgrade could cause their hacks to break.
--
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/1921425
Title:
rabbitmq-server logrotate issue
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/rabbitmq-server/+bug/1921425/+subscriptions
--
ubuntu-bugs mailing list
[email protected]
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
