Public bug reported:
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@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 rab...@ubuntu-focal.log
-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 rab...@ubuntu-focal.log
-rw-r----- 1 rabbitmq rabbitmq 66 Apr 4 00:00 rab...@ubuntu-focal.log.0
-rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:25 rab...@ubuntu-focal.log.2
-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/rab...@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@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/rab...@ubuntu-focal.log 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/rab...@ubuntu-focal.log.0
2021-04-04 00:00:03.036 [info] <0.748.0> Log file rotation forced
vagrant@ubuntu-focal:~$ sudo cat /var/log/rabbitmq/rab...@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@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 rab...@ubuntu-focal.log
-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 rab...@ubuntu-focal.log
-rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:37 rab...@ubuntu-focal.log.1
-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/rab...@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@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/rab...@ubuntu-focal.log to 50
2021-03-25 18:37:07.529 [info] <0.8.0> Server startup complete; 0 plugins
started.
# rab...@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@ubuntu-focal:/var/log/rabbitmq$ sudo tail rab...@ubuntu-focal.log.1
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/rab...@ubuntu-focal.log to 50
2021-04-03 23:59:58.795 [notice] <0.104.0> Changed loglevel of
/var/log/rabbitmq/rab...@ubuntu-focal.log 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/rab...@ubuntu-focal.log to 5000
2021-04-04 00:00:00.120 [notice] <0.104.0> Changed loglevel of
/var/log/rabbitmq/rab...@ubuntu-focal.log 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 rab...@ubuntu-focal.log
2021-04-04 00:00:01.317 [notice] <0.104.0> Changed loghwm of
/var/log/rabbitmq/rab...@ubuntu-focal.log to 50
2021-04-04 00:00:01.320 [notice] <0.104.0> Changed loglevel of
/var/log/rabbitmq/rab...@ubuntu-focal.log 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/rab...@ubuntu-focal.log to 5000
2021-04-04 00:00:02.939 [notice] <0.104.0> Changed loglevel of
/var/log/rabbitmq/rab...@ubuntu-focal.log 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/rab...@ubuntu-focal.log to 50
2021-04-04 00:00:04.489 [notice] <0.104.0> Changed loglevel of
/var/log/rabbitmq/rab...@ubuntu-focal.log to info
** Affects: rabbitmq-server (Ubuntu)
Importance: Undecided
Status: New
--
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 (focal)
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/rabbitmq-server/+bug/1921425/+subscriptions
--
ubuntu-bugs mailing list
ubuntu-bugs@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
