Ubuntu
rabbitmq-server package

  1. Bug #1921425
  2. Comment #0

Comment 0 for bug 1921425

Revision history for this message
Jean-Luc D. (jderrien) wrote : rabbitmq-server logrotate issue (focal)

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 <email address hidden>
    -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 <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@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 /<email address hidden>
    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 /<email address hidden> to 50
    2021-03-25 18:25:38.045 [info] <0.8.0> Server startup complete; 0 plugins started.

    vagrant@ubuntu-focal:~$ sudo cat /<email address hidden>
    2021-04-04 00:00:03.036 [info] <0.748.0> Log file rotation forced

    vagrant@ubuntu-focal:~$ sudo cat /<email address hidden>
    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 <email address hidden>
    -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 <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@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 /<email address hidden>
    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 /<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@ubuntu-focal:/var/log/rabbitmq$ sudo tail <email address hidden>
    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 /<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/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 /<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/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 <email address hidden>
    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/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 /<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/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 /<email address hidden> to 50
    2021-04-04 00:00:04.489 [notice] <0.104.0> Changed loglevel of /<email address hidden> to info