[Bug 1921425] Re: rabbitmq-server logrotate issue
Utkarsh Gupta
1921425 at bugs.launchpad.net
Tue Apr 6 10:49:54 UTC 2021
** Description changed:
- Tested with rabbitmq-server 3.8.2-0ubuntu1.1 (focal)
+ [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).
- Hence, these lines should be removed from the logrotate config:
+ After a few weeks running, it becomes a mess (some logs are not
+ compressed, duplicate filenames like .log.2 and .log.2.gz).
- sharedscripts
- postrotate
- /etc/init.d/rabbitmq-server rotate-logs > /dev/null
- endscript
+ Depending on the disk space available, it can became an issue and it
+ might be critical in production environments.
- It seems the daemon detects itself the log rotation, no postrotate
- command needed.
+
+ [Test Plan]
+ ===========
Tested with Vagrant (VirtualBox) and a fresh install on each run.
Clock syncing needs to be disabled with:
- v.customize ["setextradata", :id,
+ 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:~$ 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 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.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
-
+ 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:~$ 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.
+ 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
-
+ # 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
+ # 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
+ 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. The addition of
+ SO/SE could cause some confusion to some users but that should be a no-
+ brainer.
** Also affects: rabbitmq-server (Ubuntu Focal)
Importance: Undecided
Status: New
** Changed in: rabbitmq-server (Ubuntu Focal)
Assignee: (unassigned) => Utkarsh Gupta (utkarsh)
** Changed in: rabbitmq-server (Ubuntu Focal)
Status: New => Triaged
** Changed in: rabbitmq-server (Ubuntu Focal)
Status: Triaged => In Progress
** Changed in: rabbitmq-server (Ubuntu Focal)
Importance: Undecided => Low
--
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:
In Progress
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. The
addition of SO/SE could cause some confusion to some users but that
should be a no-brainer.
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