Keytone charm intermittently: keystoneclient.exceptions.ConnectionRefused: Unable to establish connection to http://localhost:35347/v2.0/OS-KSADM/services

[David Ames]

2016-04-14 17:56:45 DEBUG juju-log Database is initialised
2016-04-14 17:56:46 INFO juju-log Retrying 'get_keystone_manager' 5 more times (delay=3)
2016-04-14 17:56:49 INFO juju-log Retrying 'get_keystone_manager' 4 more times (delay=6)
2016-04-14 17:56:55 INFO juju-log Retrying 'get_keystone_manager' 3 more times (delay=9)
2016-04-14 17:57:04 INFO juju-log Retrying 'get_keystone_manager' 2 more times (delay=12)
2016-04-14 17:57:16 INFO juju-log Retrying 'get_keystone_manager' 1 more times (delay=15)
2016-04-14 17:57:31 INFO config-changed Traceback (most recent call last):
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/config-changed", line 699, in <module>
2016-04-14 17:57:31 INFO config-changed main()
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/config-changed", line 692, in main
2016-04-14 17:57:31 INFO config-changed hooks.execute(sys.argv)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/hookenv.py", line 717, in execute
2016-04-14 17:57:31 INFO config-changed self._hooks[hook_name]()
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1573, in wrapped_f
2016-04-14 17:57:31 INFO config-changed restart_functions)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/host.py", line 478, in restart_on_change_helper
2016-04-14 17:57:31 INFO config-changed r = lambda_f()
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1572, in <lambda>
2016-04-14 17:57:31 INFO config-changed (lambda: f(*args, **kwargs)), restart_map, stopstart,
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1459, in inner_synchronize_ca_if_changed2
2016-04-14 17:57:31 INFO config-changed ret = f(*args, **kwargs)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/hardening/harden.py", line 81, in _harden_inner2
2016-04-14 17:57:31 INFO config-changed return f(*args, **kwargs)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/config-changed", line 173, in config_changed
2016-04-14 17:57:31 INFO config-changed config_changed_postupgrade()
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1573, in wrapped_f
2016-04-14 17:57:31 INFO config-changed restart_functions)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/host.py", line 478, in restart_on_change_helper
2016-04-14 17:57:31 INFO config-changed r = lambda_f()
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1572, in <lambda>
2016-04-14 17:57:31 INFO config-changed (lambda: f(*args, **kwargs)), restart_map, stopstart,
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1447, in inner_synchronize_ca_if_changed2
2016-04-14 17:57:31 INFO config-changed return f(*args, **kwargs)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/hardening/harden.py", line 81, in _harden_inner2
2016-04-14 17:57:31 INFO config-changed return f(*args, **kwargs)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/config-changed", line 198, in config_changed_postupgrade
2016-04-14 17:57:31 INFO config-changed update_all_identity_relation_units()
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/config-changed", line 287, in update_all_identity_relation_units
2016-04-14 17:57:31 INFO config-changed ensure_initial_admin(config)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 941, in ensure_initial_admin
2016-04-14 17:57:31 INFO config-changed return _ensure_initial_admin(config)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/decorators.py", line 42, in _retry_on_exception_inner_2
2016-04-14 17:57:31 INFO config-changed return f(*args, **kwargs)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 906, in _ensure_initial_admin
2016-04-14 17:57:31 INFO config-changed create_tenant("admin")
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 691, in create_tenant
2016-04-14 17:57:31 INFO config-changed manager = get_manager()
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 770, in get_manager
2016-04-14 17:57:31 INFO config-changed api_version)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/decorators.py", line 42, in _retry_on_exception_inner_2
2016-04-14 17:57:31 INFO config-changed return f(*args, **kwargs)
2016-04-14 17:57:31 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/manager.py", line 60, in get_keystone_manager
2016-04-14 17:57:31 INFO config-changed for svc in manager.api.services.list():
2016-04-14 17:57:31 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystoneclient/v2_0/services.py", line 32, in list
2016-04-14 17:57:31 INFO config-changed return self._list("/OS-KSADM/services", "OS-KSADM:services")
2016-04-14 17:57:31 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystoneclient/base.py", line 124, in _list
2016-04-14 17:57:31 INFO config-changed resp, body = self.client.get(url, **kwargs)
2016-04-14 17:57:31 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystoneclient/adapter.py", line 170, in get
2016-04-14 17:57:31 INFO config-changed return self.request(url, 'GET', **kwargs)
2016-04-14 17:57:31 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystoneclient/adapter.py", line 206, in request
2016-04-14 17:57:31 INFO config-changed resp = super(LegacyJsonAdapter, self).request(*args, **kwargs)
2016-04-14 17:57:31 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystoneclient/adapter.py", line 95, in request
2016-04-14 17:57:31 INFO config-changed return self.session.request(url, method, **kwargs)
2016-04-14 17:57:31 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystoneclient/utils.py", line 337, in inner
2016-04-14 17:57:31 INFO config-changed return func(*args, **kwargs)
2016-04-14 17:57:31 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystoneclient/session.py", line 386, in request
2016-04-14 17:57:31 INFO config-changed resp = send(**kwargs)
2016-04-14 17:57:31 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystoneclient/session.py", line 430, in _send_request
2016-04-14 17:57:31 INFO config-changed raise exceptions.ConnectionRefused(msg)
2016-04-14 17:57:31 INFO config-changed keystoneclient.exceptions.ConnectionRefused: Unable to establish connection to http://localhost:35347/v2.0/OS-KSADM/services
2016-04-14 17:57:31 ERROR juju.worker.uniter.operation runhook.go:107 hook "config-changed" failed: exit status 1

[David Ames (thedac)]

It seems they keystone service is down and simply restarting it fixes things.

Last log entry is:
(keystone.cmd.cli): 2016-04-14 17:56:43,959 WARNING keystone-manage pki_setup is not recommended for production use.

[David Ames (thedac)]

This is liberty specific.

run_in_apache returns true and then keystone is paused (stops and never gets restarted) but config continues and throws an exception the next time it needs to connect to itself.

[Liam Young (gnuoy)]

If its liberty keystone should not be running, it should be served via apache

[Liam Young (gnuoy)]

Perhaps you've hit Bug #1567741 and the fix needs some extra work?

[David Ames (thedac)]

This does seem to be a duplicate of Bug #1567741. This one may be due to the stable to next upgrade. Apache never seems to get started. I'll have to re-create this and see it again.

[Liam Young (gnuoy)]

I've just hit the same thing running the Openstack kilo -> liberty upgrade tests which has the same effect of going from keystone standalone to keystone mod_wsgi. Looking into it now

[Liam Young (gnuoy)]

Having looked at a keystone unit displaying these symptoms I found that the keystone service was down, apache2 was up but not listening on 35347 despite having the config it site enabled for that vhost.

Reloading apache2 caused:
AH00526: Syntax error on line 7 of /etc/apache2/sites-enabled/wsgi-keystone.conf:
Invalid command 'WSGIDaemonProcess', perhaps misspelled or defined by a module not included in the server configuration
Action 'configtest' failed.
The Apache error log may have more information

So it looks to me like there are 2 things that need to happen:
1) When keystone is stopped apache2 needs reloading immediatly
2) mod_wsgi package needs intalling if its not present in config-changed

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/306435

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/306435
Committed: https://git.openstack.org/cgit/openstack/charm-keystone/commit/?id=d39e03628fbf025500589c32bed35f327069cb7c
Submitter: Jenkins
Branch: master

commit d39e03628fbf025500589c32bed35f327069cb7c
Author: Liam Young <email address hidden>
Date: Fri Apr 15 13:46:44 2016 +0000

    Ensure apache2 ready when keystone is disabled

    If the charm moves from a state where keystone is running as a
    standalone service to one where it is running from within apache then
    as soon as the keystone service is stopped it needs to be accessable
    via apache as the charm queries its local keystone. This cannot wait
    for a decorator to restart services

    Change-Id: I026ef9f6548c38eed9850af1233a03a3d293dd4b
    Closes-Bug: 1570579

[David Ames (thedac)]

It seems a reload is insufficient. I just ran into this again with apache stopped.

a restart does seem to work. Testing that now.

[David Ames (thedac)]

The leader ran into this bug. The non-leaders have:
 Services not running that should be: apache2

[David Ames (thedac)]

service_restart('apache2') seems to work

We can discuss if it is too much of a hammer:

https://review.openstack.org/307480

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/307480
Committed: https://git.openstack.org/cgit/openstack/charm-keystone/commit/?id=6370c98e55c3aa5216e0b6671d94079a022f7fb9
Submitter: Jenkins
Branch: master

commit 6370c98e55c3aa5216e0b6671d94079a022f7fb9
Author: David Ames <email address hidden>
Date: Mon Apr 18 13:57:48 2016 -0700

    Restart rather than reload in run_in_apache()

    The service_reload('apache2') is not sufficient when upgrading
    the charm from a scenario that did not run keystone as WSGI to
    one that does. Apache is stopped and reload does not start it.
    service_restart('apache2') fixes this.

    Change-Id: Id999b162c780f9939884d3e21a20b337e595b58b
    Closes-Bug: #1570579