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.
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/rabbitmqct l', 'set_permissions', '-p', u'openstack', u'ceilometer', '.*', '.*', '.*'] changed Setting permissions for user "ceilometer" in vhost "openstack" ...
2017-01-26 23:00:09 INFO amqp-relation-
But then, they start taking ~20-30 seconds:
2017-01-26 23:01:37 DEBUG juju-log amqp:48: Running ['/usr/ sbin/rabbitmqct l', 'set_permissions', '-p', u'openstack', u'ceilometer', '.*', '.*', '.*'] changed Setting permissions for user "ceilometer" in vhost "openstack" ...
2017-01-26 23:02:03 INFO amqp-relation-
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 org.freedesktop .login1. service' freedesktop. login1' unit='dbus- org.freedesktop .login1. service' freedesktop. login1' unit='dbus- org.freedesktop .login1. service' freedesktop. login1' unit='dbus- org.freedesktop .login1. service'
' unit='dbus-
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.
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.
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.
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 su:session) : session opened for user rabbitmq by (uid=0) p.login1' : timed out su:session) : Failed to create session: Failed to activate service 'org.freedeskto p.login1' : timed out su:session) : session closed for user rabbitmq su:session) : session opened for user rabbitmq by (uid=0) su:session) : Failed to create session: Connection timed out p.login1' : timed out su:session) : session closed for user rabbitmq
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(
Jan 26 23:02:02 juju-ce6020-4-lxd-3 dbus[292]: [system] Failed to activate service 'org.freedeskto
Jan 26 23:02:02 juju-ce6020-4-lxd-3 su[14693]: pam_systemd(
Jan 26 23:02:03 juju-ce6020-4-lxd-3 su[14693]: pam_unix(
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(
Jan 26 23:02:28 juju-ce6020-4-lxd-3 su[14822]: pam_systemd(
Jan 26 23:02:28 juju-ce6020-4-lxd-3 dbus[292]: [system] Failed to activate service 'org.freedeskto
Jan 26 23:02:28 juju-ce6020-4-lxd-3 su[14822]: pam_unix(
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.