rabbitmq-server logrotate issue
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
rabbitmq-server (Debian) |
Fix Released
|
Undecided
|
Unassigned | ||
rabbitmq-server (Ubuntu) |
Fix Released
|
Low
|
Utkarsh Gupta | ||
Focal |
Fix Released
|
Low
|
Utkarsh Gupta | ||
Groovy |
Fix Released
|
Low
|
Utkarsh Gupta |
Bug Description
[Problem]
=========
The postrotate script (`/etc/
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/
Test #1, current config (not expected, double log rotation)
vagrant@
/var/
weekly
rotate 20
}
vagrant@
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 address hidden>
-rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:25 rabbit@
-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@
Sat Apr 3 23:58:00 UTC 2021
vagrant@
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 address hidden>
-rw-r----- 1 rabbitmq rabbitmq 66 Apr 4 00:00 <email address hidden>
-rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:25 <email address hidden>
-rw-r----- 1 rabbitmq rabbitmq 82 Apr 4 00:00 rabbit@
-rw-r----- 1 rabbitmq rabbitmq 66 Apr 4 00:00 rabbit@
-rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:25 rabbit@
-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@
2021-03-25 18:25:37.453 [info] <0.267.0> Setting up a table for per-vhost connection counting on this node: 'tracked_
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 /<email address hidden> to 50
2021-03-25 18:25:38.045 [info] <0.8.0> Server startup complete; 0 plugins started.
vagrant@
2021-04-04 00:00:03.036 [info] <0.748.0> Log file rotation forced
vagrant@
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@
/var/
weekly
rotate 20
}
vagrant@
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 address hidden>
-rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:37 rabbit@
-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@
Sat Apr 3 23:58:00 UTC 2021
vagrant@
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 address hidden>
-rw-r----- 1 rabbitmq rabbitmq 16216 Mar 25 18:37 <email address hidden>
-rw-r----- 1 rabbitmq rabbitmq 0 Apr 4 00:00 rabbit@
-rw-r----- 1 rabbitmq rabbitmq 66 Mar 25 18:37 rabbit@
-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@
2021-03-25 18:37:06.863 [info] <0.267.0> Setting up a table for per-vhost connection counting on this node: 'tracked_
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 /<email address hidden> to 50
2021-03-25 18:37:07.529 [info] <0.8.0> Server startup complete; 0 plugins started.
# <email address hidden> 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@
2021-04-03 23:59:57.544 [notice] <0.146.0> Changed loghwm of /var/log/
2021-04-03 23:59:57.544 [notice] <0.146.0> Changed loglevel of /var/log/
2021-04-03 23:59:58.795 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 50
2021-04-03 23:59:58.795 [notice] <0.104.0> Changed loglevel of /<email address hidden> to info
2021-04-03 23:59:58.796 [notice] <0.146.0> Changed loghwm of /var/log/
2021-04-03 23:59:58.796 [notice] <0.146.0> Changed loglevel of /var/log/
2021-04-04 00:00:00.119 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 5000
2021-04-04 00:00:00.120 [notice] <0.104.0> Changed loglevel of /<email address hidden> to debug
2021-04-04 00:00:00.121 [notice] <0.146.0> Changed loghwm of /var/log/
2021-04-04 00:00:00.121 [notice] <0.146.0> Changed loglevel of /var/log/
vagrant@
2021-04-04 00:00:01.317 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 50
2021-04-04 00:00:01.320 [notice] <0.104.0> Changed loglevel of /<email address hidden> to info
2021-04-04 00:00:01.321 [notice] <0.146.0> Changed loghwm of /var/log/
2021-04-04 00:00:01.322 [notice] <0.146.0> Changed loglevel of /var/log/
2021-04-04 00:00:02.938 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 5000
2021-04-04 00:00:02.939 [notice] <0.104.0> Changed loglevel of /<email address hidden> to debug
2021-04-04 00:00:02.939 [notice] <0.146.0> Changed loghwm of /var/log/
2021-04-04 00:00:02.940 [notice] <0.146.0> Changed loglevel of /var/log/
2021-04-04 00:00:04.489 [notice] <0.104.0> Changed loghwm of /<email address hidden> to 50
2021-04-04 00:00:04.489 [notice] <0.104.0> Changed loglevel of /<email address hidden> 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.
Related branches
- Christian Ehrhardt (community): Approve
- Canonical Server packageset reviewers: Pending requested
- Canonical Server: Pending requested
-
Diff: 53 lines (+16/-11)3 files modifieddebian/changelog (+8/-0)
debian/control (+2/-1)
debian/rabbitmq-server.logrotate (+6/-10)
- Christian Ehrhardt (community): Approve
- Canonical Server: Pending requested
- Canonical Server packageset reviewers: Pending requested
-
Diff: 39 lines (+14/-10)2 files modifieddebian/changelog (+8/-0)
debian/rabbitmq-server.logrotate (+6/-10)
Changed in rabbitmq-server (Debian): | |
status: | New → Fix Released |
summary: |
- rabbitmq-server logrotate issue (focal) + rabbitmq-server logrotate issue |
description: | updated |
Changed in rabbitmq-server (Ubuntu Focal): | |
assignee: | nobody → Utkarsh Gupta (utkarsh) |
status: | New → Triaged |
status: | Triaged → In Progress |
importance: | Undecided → Low |
Changed in rabbitmq-server (Ubuntu Groovy): | |
importance: | Undecided → Low |
status: | New → In Progress |
assignee: | nobody → Utkarsh Gupta (utkarsh) |
description: | updated |
Changed in rabbitmq-server (Ubuntu Focal): | |
status: | In Progress → Fix Committed |
Changed in rabbitmq-server (Ubuntu Groovy): | |
status: | In Progress → Fix Committed |
tags: |
added: verification-done-focal verification-done-groovy removed: verification-done |
Hi Jean,
Thanks for taking the time to file a bug and help in making the Ubuntu server better.
This looks like a valid bug and I am glad that you've already found the cause and the workaround for this. That said, I can trace its origin in Debian (see: https:/ /salsa. debian. org/openstack- team/third- party/rabbitmq- server/ -/blob/ 02ca091d15ac35d f0fba06b4e0ea41 58f5325223/ debian/ rabbitmq- server. logrotate). So maybe you can file a bug in Debian and when this is fixed there, it'll automatically sync-in here for the next cycle.
Given it's trivial and not really affecting the package use or resulting in a crash or something, I'm marking this as "low" importance. However, if you think otherwise, please let me know and we can discuss this further.
Thanks, again! :)