[Bug 1921425] Re: rabbitmq-server logrotate issue (focal)
Jean-Luc D.
1921425 at bugs.launchpad.net
Fri Mar 26 15:56:07 UTC 2021
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
--
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 (focal)
Status in rabbitmq-server package in Ubuntu:
Confirmed
Bug description:
Tested with rabbitmq-server 3.8.2-0ubuntu1.1 (focal)
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:
sharedscripts
postrotate
/etc/init.d/rabbitmq-server rotate-logs > /dev/null
endscript
It seems the daemon detects itself the log rotation, no postrotate
command needed.
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
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