[Bug 1921425] Re: rabbitmq-server logrotate issue

Utkarsh Gupta 1921425 at bugs.launchpad.net
Thu Apr 15 08:01:20 UTC 2021


** Changed in: rabbitmq-server (Ubuntu Focal)
       Status: In Progress => Fix Committed

** Changed in: rabbitmq-server (Ubuntu Groovy)
       Status: In Progress => Fix Committed

-- 
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:
  Fix Committed
Status in rabbitmq-server source package in Groovy:
  Fix Committed
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.

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