Comment 5 for bug 1660000

Revision history for this message
Francis Ginther (fginther) wrote : Re: rabbitmq-server takes a long time to process amqp-relation-joined

The 'slowness' appears to be related to the login service. When rabbitmq-server starts processing amqp-relation-hook events, rabbitmqctl responds in 1 sec or less:

2017-01-26 23:00:08 DEBUG juju-log amqp:64: Running ['/usr/sbin/rabbitmqctl', 'set_permissions', '-p', u'openstack', u'ceilometer', '.*', '.*', '.*']
2017-01-26 23:00:09 INFO amqp-relation-changed Setting permissions for user "ceilometer" in vhost "openstack" ...

But then, they start taking ~20-30 seconds:

2017-01-26 23:01:37 DEBUG juju-log amqp:48: Running ['/usr/sbin/rabbitmqctl', 'set_permissions', '-p', u'openstack', u'ceilometer', '.*', '.*', '.*']
2017-01-26 23:02:03 INFO amqp-relation-changed Setting permissions for user "ceilometer" in vhost "openstack" ...

At the same time, we start seeing login service activation messages in /var/log/syslog:

Jan 26 23:01:37 juju-ce6020-4-lxd-3 dbus[292]: [system] Activating via systemd: service name='org.freedesktop.login1
' unit='dbus-org.freedesktop.login1.service'
Jan 26 23:01:37 juju-ce6020-4-lxd-3 systemd[1]: Started Login Service.
Jan 26 23:02:03 juju-ce6020-4-lxd-3 dbus[292]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service'
Jan 26 23:02:03 juju-ce6020-4-lxd-3 systemd[1]: Started Login Service.
Jan 26 23:02:39 juju-ce6020-4-lxd-3 dbus[292]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service'
Jan 26 23:02:39 juju-ce6020-4-lxd-3 systemd[1]: Started Login Service.
Jan 26 23:03:05 juju-ce6020-4-lxd-3 dbus[292]: [system] Activating via systemd: service name='org.freedesktop.login1' unit='dbus-org.freedesktop.login1.service'
Jan 26 23:03:05 juju-ce6020-4-lxd-3 systemd[1]: Started Login Service.

And it looks like this impairs rabbitmq's ability to switch users (from /var/log/auth.log):

Jan 26 23:01:37 juju-ce6020-4-lxd-3 su[14693]: Successful su for rabbitmq by root
Jan 26 23:01:37 juju-ce6020-4-lxd-3 su[14693]: + ??? root:rabbitmq
Jan 26 23:01:37 juju-ce6020-4-lxd-3 su[14693]: pam_unix(su:session): session opened for user rabbitmq by (uid=0)
Jan 26 23:02:02 juju-ce6020-4-lxd-3 dbus[292]: [system] Failed to activate service 'org.freedesktop.login1': timed out
Jan 26 23:02:02 juju-ce6020-4-lxd-3 su[14693]: pam_systemd(su:session): Failed to create session: Failed to activate service 'org.freedesktop.login1': timed out
Jan 26 23:02:03 juju-ce6020-4-lxd-3 su[14693]: pam_unix(su:session): session closed for user rabbitmq
Jan 26 23:02:03 juju-ce6020-4-lxd-3 su[14822]: Successful su for rabbitmq by root
Jan 26 23:02:03 juju-ce6020-4-lxd-3 su[14822]: + ??? root:rabbitmq
Jan 26 23:02:03 juju-ce6020-4-lxd-3 su[14822]: pam_unix(su:session): session opened for user rabbitmq by (uid=0)
Jan 26 23:02:28 juju-ce6020-4-lxd-3 su[14822]: pam_systemd(su:session): Failed to create session: Connection timed out
Jan 26 23:02:28 juju-ce6020-4-lxd-3 dbus[292]: [system] Failed to activate service 'org.freedesktop.login1': timed out
Jan 26 23:02:28 juju-ce6020-4-lxd-3 su[14822]: pam_unix(su:session): session closed for user rabbitmq

The login service issues appear to be causing the slowness in the rabbitmq-server charm. A successful test does not show this login service activation events or the slow response times to rabbitmqctl.

Now to figure out what is causing this login service activations.