Syslog processes RabbitMQ log file very slowly

[Ilya Shakhat]

As result of failures RabbitMQ created huge log file (~3Gb). rsyslog processes this file very slowly, resulting in large delay between a moment when message was generated and when it is put into files at Fuel master node. Even a week after the issue syslog still processes old messages.

In average rsyslog is able to process 100M file in 3.5 hours:

[root@fuel ~]# ls -al rabbitmq.log.1
-rw-------. 1 root root 108237878 May 10 13:25 rabbitmq.log.1

[root@fuel ~]# head rabbitmq.log.1
2016-05-10T07:30:35.388293+00:00 notice: =ERROR REPORT==== 4-May-2016::00:18:48 ===
2016-05-10T07:30:35.388293+00:00 notice: Channel error on connection <0.9727.15> (192.168.0.49:48984 -> 192.168.0.88:5673, vhost: '/', user: 'nova'), channel 1:
2016-05-10T07:30:35.388293+00:00 notice: operation basic.consume caused a channel exception not_found: "no queue 'reply_611b2b8a718049219bf62ca37ef9d906' in vhost '/'"
2016-05-10T07:30:35.388293+00:00 notice: =ERROR REPORT==== 4-May-2016::00:18:48 ===
2016-05-10T07:30:35.388293+00:00 notice: Channel error on connection <0.9727.15> (192.168.0.49:48984 -> 192.168.0.88:5673, vhost: '/', user: 'nova'), channel 1:
2016-05-10T07:30:35.388293+00:00 notice: operation basic.consume caused a channel exception not_found: "no queue 'reply_611b2b8a718049219bf62ca37ef9d906' in vhost '/'"
2016-05-10T07:30:35.388293+00:00 notice: =ERROR REPORT==== 4-May-2016::00:18:48 ===
2016-05-10T07:30:35.388293+00:00 notice: Channel error on connection <0.9727.15> (192.168.0.49:48984 -> 192.168.0.88:5673, vhost: '/', user: 'nova'), channel 1:
2016-05-10T07:30:35.388293+00:00 notice: operation basic.consume caused a channel exception not_found: "no queue 'reply_611b2b8a718049219bf62ca37ef9d906' in vhost '/'"
2016-05-10T07:30:35.388293+00:00 notice: =ERROR REPORT==== 4-May-2016::00:18:48 ===

[root@fuel ~]# tail rabbitmq.log.1
2016-05-10T11:00:38.001870+00:00 notice: Channel error on connection <0.9727.15> (192.168.0.49:48984 -> 192.168.0.88:5673, vhost: '/', user: 'nova'), channel 1:
2016-05-10T11:00:38.001870+00:00 notice: operation basic.consume caused a channel exception not_found: "no queue 'reply_611b2b8a718049219bf62ca37ef9d906' in vhost '/'"
2016-05-10T11:00:38.001876+00:00 notice: =ERROR REPORT==== 4-May-2016::00:23:56 ===
2016-05-10T11:00:38.001876+00:00 notice: Channel error on connection <0.9727.15> (192.168.0.49:48984 -> 192.168.0.88:5673, vhost: '/', user: 'nova'), channel 1:
2016-05-10T11:00:38.001882+00:00 notice: operation basic.consume caused a channel exception not_found: "no queue 'reply_611b2b8a718049219bf62ca37ef9d906' in vhost '/'"
2016-05-10T11:00:38.001882+00:00 notice: =ERROR REPORT==== 4-May-2016::00:23:56 ===
2016-05-10T11:00:38.001889+00:00 notice: Channel error on connection <0.9727.15> (192.168.0.49:48984 -> 192.168.0.88:5673, vhost: '/', user: 'nova'), channel 1:
2016-05-10T11:00:38.001889+00:00 notice: operation basic.consume caused a channel exception not_found: "no queue 'reply_611b2b8a718049219bf62ca37ef9d906' in vhost '/'"
2016-05-10T11:00:38.001894+00:00 notice: =ERROR REPORT==== 4-May-2016::00:23:56 ===
2016-05-10T11:00:38.001894+00:00 notice: Channel error on connection <0.9727.15> (192.168.0.49:48984 -> 192.168.0.88:5673, vhost: '/', user: 'nova'), channel 1:

Steps to reproduce:
1. Emulate large RabbitMQ log file by creating a file similar to the one written by RabbitMQ to "/var/log/rabbitmq/rabbit@messaging-node-XXX". The size should be hundreds of Mb.
2. Check how syslog processes messages and how fast they are copied to Fuel master node

Note. This bug impacts supportability since logs are not available at Fuel master node and thus in the snapshot.

[Ilya Shakhat (shakhat)]

[root@fuel ~]# fuel2 fuel-version
api: '1'
auth_required: true
feature_groups: []
openstack_version: mitaka-9.0
release: '9.0'

[Bug Checker Bot (bug-checker)]

(This check performed automatically)
Please, make sure that bug description contains the following sections filled in with the appropriate data related to the bug you are describing:

actual result

version

expected result

For more detailed information on the contents of each of the listed sections see https://wiki.openstack.org/wiki/Fuel/How_to_contribute#Here_is_how_you_file_a_bug

[Peter Zhurba (pzhurba)]

Hi, thank you for your report!
But some important thins still unclear.
How often did you face this issue. On what environment
Please provide diagnostic snapshot from the failed environment if it is possible.
Also recheck please is there atop log in snapshot.

[Bogdan Dobrelya (bogdando)]

Firstly, the logrotate should handle big files so there normally never a 3G file shall be created.
The default logging template that comes with the rabbitmq-server v3.6.1 package in Fuel 10 is:

# 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
}

If it provides non optimal config, please either report upstream bug or/and let's override it with the Fuel logging configuration as well.

2nd, we should switch to rsyslog native support once it get to the RabbitMQ. Perhaps it is 3.7? See https://github.com/rabbitmq/rabbitmq-server/releases :
"RabbitMQ 3.7.0 Milestone 4 ... (snip) ... pluggable logging
backends (e.g. logging to Syslog no longer requires external tools)

For now Fuel leverages rsyslog's imfile, which is a non native way, for capturing logs from files and maybe slow, indeed

[Maksim Malchuk (mmalchuk)]

looks like this bug is related to https://bugs.launchpad.net/fuel/+bug/1580200

[Bogdan Dobrelya (bogdando)]

I believe it doesn't. The latter use syslog via native calls. While the rabbit uses imfile band aids

[Maksim Malchuk (mmalchuk)]

I believe that rsyslogd slows down due to imfile usage, so both related.
Still waiting for a scale env to run performance tests.

[Maksim Malchuk (mmalchuk)]

Won't fix for 9.0 due to HCF. Moving to 10.0.

[Maksim Malchuk (mmalchuk)]

Dmitry, do you have an environment with an issue or diagnostic snapshot?

[Maksim Malchuk (mmalchuk)]

Close as Invalid, due to no activity more than month.