keystoneauth1 exception on juju upgrade-charm

[José Pekkarinen]

Hi,

Performing little changes on the config templates of the charm I moved an environment from
cs charm to local. Tossing to get it back to cs charm with juju upgrade-charm
cs:~openstack-charmers-next/keystone keystone, renders the charm stuck in error state
with the following backtrace:

2017-04-24 05:18:27 INFO upgrade-charm Traceback (most recent call last):
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/upgrade-charm", line 842, in <module>
2017-04-24 05:18:27 INFO upgrade-charm main()
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/upgrade-charm", line 835, in main
2017-04-24 05:18:27 INFO upgrade-charm hooks.execute(sys.argv)
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/hookenv.py", line 731, in execute
2017-04-24 05:18:27 INFO upgrade-charm self._hooks[hook_name]()
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1864, in wrapped_f
2017-04-24 05:18:27 INFO upgrade-charm restart_functions)
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/host.py", line 655, in restart_on_change_helper
2017-04-24 05:18:27 INFO upgrade-charm r = lambda_f()
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/openstack/utils.py", line 1863, in <lambda>
2017-04-24 05:18:27 INFO upgrade-charm (lambda: f(*args, **kwargs)), restart_map, stopstart,
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1610, in inner_synchronize_ca_if_changed2
2017-04-24 05:18:27 INFO upgrade-charm ret = f(*args, **kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/contrib/hardening/harden.py", line 79, in _harden_inner2
2017-04-24 05:18:27 INFO upgrade-charm return f(*args, **kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/upgrade-charm", line 803, in upgrade_charm
2017-04-24 05:18:27 INFO upgrade-charm leader_init_db_if_ready()
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/upgrade-charm", line 374, in leader_init_db_if_ready
2017-04-24 05:18:27 INFO upgrade-charm update_all_identity_relation_units(check_db_ready=False)
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/upgrade-charm", line 336, in update_all_identity_relation_units
2017-04-24 05:18:27 INFO upgrade-charm ensure_initial_admin(config)
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1072, in ensure_initial_admin
2017-04-24 05:18:27 INFO upgrade-charm return _ensure_initial_admin(config)
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/decorators.py", line 40, in _retry_on_exception_inner_2
2017-04-24 05:18:27 INFO upgrade-charm return f(*args, **kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1015, in _ensure_initial_admin
2017-04-24 05:18:27 INFO upgrade-charm manager = get_manager()
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 868, in get_manager
2017-04-24 05:18:27 INFO upgrade-charm api_version)
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/decorators.py", line 40, in _retry_on_exception_inner_2
2017-04-24 05:18:27 INFO upgrade-charm return f(*args, **kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/manager.py", line 75, in get_keystone_manager
2017-04-24 05:18:27 INFO upgrade-charm for svc in manager.api.services.list():
2017-04-24 05:18:27 INFO upgrade-charm File "/usr/lib/python2.7/dist-packages/positional/__init__.py", line 101, in inner
2017-04-24 05:18:27 INFO upgrade-charm return wrapped(*args, **kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/usr/lib/python2.7/dist-packages/keystoneclient/v3/services.py", line 97, in list
2017-04-24 05:18:27 INFO upgrade-charm **kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/usr/lib/python2.7/dist-packages/keystoneclient/base.py", line 75, in func
2017-04-24 05:18:27 INFO upgrade-charm return f(*args, **new_kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/usr/lib/python2.7/dist-packages/keystoneclient/base.py", line 390, in list
2017-04-24 05:18:27 INFO upgrade-charm self.collection_key)
2017-04-24 05:18:27 INFO upgrade-charm File "/usr/lib/python2.7/dist-packages/keystoneclient/base.py", line 125, in _list
2017-04-24 05:18:27 INFO upgrade-charm resp, body = self.client.get(url, **kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/usr/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 217, in get
2017-04-24 05:18:27 INFO upgrade-charm return self.request(url, 'GET', **kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/usr/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 374, in request
2017-04-24 05:18:27 INFO upgrade-charm resp = super(LegacyJsonAdapter, self).request(*args, **kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/usr/lib/python2.7/dist-packages/keystoneauth1/adapter.py", line 142, in request
2017-04-24 05:18:27 INFO upgrade-charm return self.session.request(url, method, **kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/usr/lib/python2.7/dist-packages/positional/__init__.py", line 101, in inner
2017-04-24 05:18:27 INFO upgrade-charm return wrapped(*args, **kwargs)
2017-04-24 05:18:27 INFO upgrade-charm File "/usr/lib/python2.7/dist-packages/keystoneclient/session.py", line 445, in request
2017-04-24 05:18:27 INFO upgrade-charm raise exceptions.from_response(resp, method, url)
2017-04-24 05:18:27 INFO upgrade-charm keystoneauth1.exceptions.http.InternalServerError: Internal Server Error (HTTP 500)

Nothing relevant comes out from keystone logs.

Way to reproduce:

1) charm pull cs:~openstack-charmers-next/keystone
2) make some modification, like copying the file in https://review.openstack.org/#/c/458842/ to the
templates/newton folder.
3) juju upgrade-charm --path <path-to-local-charm> keystone
4) juju upgrade-charm --path cs:~openstack-charmers-next/keystone keystone

unit will come to:

keystone/0* error idle 3/lxd/1 X.X.X.X 5000/tcp hook failed: "upgrade-charm"

Expected is to go back to the charm in cs without further errors.

Thanks!

José

[José Pekkarinen (koalinux)]

Some more tracebacks found duringfurther debugging:

2017-04-24 11:13:41.068238 mod_wsgi (pid=494992): Exception occurred processing WSGI script '/usr/bin/keystone-wsgi-admin'.
2017-04-24 11:13:41.068272 Traceback (most recent call last):
2017-04-24 11:13:41.068303 File "/usr/bin/keystone-wsgi-admin", line 51, in <module>
2017-04-24 11:13:41.068349 application = initialize_admin_application()
2017-04-24 11:13:41.068362 File "/usr/lib/python2.7/dist-packages/keystone/server/wsgi.py", line 132, in initialize_admin_application
2017-04-24 11:13:41.068386 config_files=_get_config_files())
2017-04-24 11:13:41.068397 File "/usr/lib/python2.7/dist-packages/keystone/server/wsgi.py", line 56, in initialize_application
2017-04-24 11:13:41.068415 common.configure(config_files=config_files)
2017-04-24 11:13:41.068426 File "/usr/lib/python2.7/dist-packages/keystone/server/common.py", line 30, in configure
2017-04-24 11:13:41.068444 keystone.conf.configure()
2017-04-24 11:13:41.068454 File "/usr/lib/python2.7/dist-packages/keystone/conf/__init__.py", line 126, in configure
2017-04-24 11:13:41.068473 help='Do not monkey-patch threading system modules.'))
2017-04-24 11:13:41.068483 File "/usr/lib/python2.7/dist-packages/oslo_config/cfg.py", line 2288, in __inner
2017-04-24 11:13:41.068502 result = f(self, *args, **kwargs)
2017-04-24 11:13:41.068512 File "/usr/lib/python2.7/dist-packages/oslo_config/cfg.py", line 2478, in register_cli_opt
2017-04-24 11:13:41.068528 raise ArgsAlreadyParsedError("cannot register CLI option")
2017-04-24 11:13:41.068559 ArgsAlreadyParsedError: arguments already parsed: cannot register CLI option
2017-04-24 11:13:42.985851 mod_wsgi (pid=494991): Target WSGI script '/usr/bin/keystone-wsgi-admin' cannot be loaded as Python module.
2017-04-24 11:13:42.985900 mod_wsgi (pid=494991): Exception occurred processing WSGI script '/usr/bin/keystone-wsgi-admin'.
2017-04-24 11:13:42.985933 Traceback (most recent call last):
2017-04-24 11:13:42.985962 File "/usr/bin/keystone-wsgi-admin", line 51, in <module>
2017-04-24 11:13:42.986004 application = initialize_admin_application()
2017-04-24 11:13:42.986018 File "/usr/lib/python2.7/dist-packages/keystone/server/wsgi.py", line 132, in initialize_admin_application
2017-04-24 11:13:42.986063 config_files=_get_config_files())
2017-04-24 11:13:42.986076 File "/usr/lib/python2.7/dist-packages/keystone/server/wsgi.py", line 56, in initialize_application
2017-04-24 11:13:42.986093 common.configure(config_files=config_files)
2017-04-24 11:13:42.986103 File "/usr/lib/python2.7/dist-packages/keystone/server/common.py", line 30, in configure
2017-04-24 11:13:42.986121 keystone.conf.configure()
2017-04-24 11:13:42.986131 File "/usr/lib/python2.7/dist-packages/keystone/conf/__init__.py", line 126, in configure
2017-04-24 11:13:42.986149 help='Do not monkey-patch threading system modules.'))
2017-04-24 11:13:42.986159 File "/usr/lib/python2.7/dist-packages/oslo_config/cfg.py", line 2288, in __inner
2017-04-24 11:13:42.986178 result = f(self, *args, **kwargs)
2017-04-24 11:13:42.986187 File "/usr/lib/python2.7/dist-packages/oslo_confi...

[José Pekkarinen (koalinux)]

another strange backtrace on the beginning of the file:

2017-04-24 06:25:41.865101 mod_wsgi (pid=337959): Target WSGI script '/usr/bin/keystone-wsgi-admin' cannot be loaded as Python module.
2017-04-24 06:25:41.865173 mod_wsgi (pid=337959): SystemExit exception raised by WSGI script '/usr/bin/keystone-wsgi-admin' ignored.
2017-04-24 06:25:41.865211 Traceback (most recent call last):
2017-04-24 06:25:41.865233 File "/usr/bin/keystone-wsgi-admin", line 51, in <module>
2017-04-24 06:25:41.865263 application = initialize_admin_application()
2017-04-24 06:25:41.865275 File "/usr/lib/python2.7/dist-packages/keystone/server/wsgi.py", line 132, in initialize_admin_application
2017-04-24 06:25:41.865294 config_files=_get_config_files())
2017-04-24 06:25:41.865302 File "/usr/lib/python2.7/dist-packages/keystone/server/wsgi.py", line 69, in initialize_application
2017-04-24 06:25:41.865318 startup_application_fn=loadapp)
2017-04-24 06:25:41.865326 File "/usr/lib/python2.7/dist-packages/keystone/server/common.py", line 48, in setup_backends
2017-04-24 06:25:41.865340 drivers = backends.load_backends()
2017-04-24 06:25:41.865348 File "/usr/lib/python2.7/dist-packages/keystone/server/backends.py", line 69, in load_backends
2017-04-24 06:25:41.865362 token_provider_api=token.provider.Manager())
2017-04-24 06:25:41.865370 File "/usr/lib/python2.7/dist-packages/keystone/common/dependency.py", line 96, in __wrapped_init__
2017-04-24 06:25:41.865385 init(self, *args, **kwargs)
2017-04-24 06:25:41.865393 File "/usr/lib/python2.7/dist-packages/keystone/common/dependency.py", line 155, in wrapper
2017-04-24 06:25:41.865407 self.__wrapped_init__(*args, **kwargs)
2017-04-24 06:25:41.865415 File "/usr/lib/python2.7/dist-packages/keystone/token/provider.py", line 73, in __init__
2017-04-24 06:25:41.865611 super(Manager, self).__init__(CONF.token.provider)
2017-04-24 06:25:41.865625 File "/usr/lib/python2.7/dist-packages/keystone/common/manager.py", line 182, in __init__
2017-04-24 06:25:41.865739 self.driver = load_driver(self.driver_namespace, driver_name)
2017-04-24 06:25:41.865752 File "/usr/lib/python2.7/dist-packages/keystone/common/manager.py", line 73, in load_driver
2017-04-24 06:25:41.865771 invoke_args=args)
2017-04-24 06:25:41.865783 File "/usr/lib/python2.7/dist-packages/stevedore/driver.py", line 61, in __init__
2017-04-24 06:25:41.865903 warn_on_missing_entrypoint=warn_on_missing_entrypoint
2017-04-24 06:25:41.865916 File "/usr/lib/python2.7/dist-packages/stevedore/named.py", line 81, in __init__
2017-04-24 06:25:41.866012 verify_requirements)
2017-04-24 06:25:41.866025 File "/usr/lib/python2.7/dist-packages/stevedore/extension.py", line 186, in _load_plugins
2017-04-24 06:25:41.866175 verify_requirements,
2017-04-24 06:25:41.866187 File "/usr/lib/python2.7/dist-packages/stevedore/named.py", line 158, in _load_one_plugin
2017-04-24 06:25:41.866205 verify_requirements,
2017-04-24 06:25:41.866215 File "/usr/lib/python2.7/dist-packages/stevedore/extension.py", line 218, in _load_one_plugin
2017-04-24 06:25:41.866230 obj = plugin(*invoke_args, **invoke_kwds)
2017-04-24...

[James Page (james-page)]

Your proposed change switches the token format from UUID to Fernet (below taken from mitaka):

{% if token_provider == 'pki' -%}
provider = keystone.token.providers.pki.Provider
{% elif token_provider == 'pkiz' -%}
provider = keystone.token.providers.pkiz.Provider
{% else -%}
provider = keystone.token.providers.uuid.Provider
{% endif -%}

and from your review (for newton onwards):

{% if token_provider == 'pki' -%}
provider = keystone.token.providers.pki.Provider
{% elif token_provider == 'pkiz' -%}
provider = keystone.token.providers.pkiz.Provider
{% endif -%}

I think the default token format switch to fernet in Newton; the charms don't support fernet yet so you'll either need to stick with the else -> uuid provider OR fully implement fernet support including key management into the charm.

As this does not actually impact either the master branch or a release charm, marking this bug as Invalid.

[José Pekkarinen (koalinux)]

Reverting the lines to restore the uuid provider doesn't allow the charm to
upgrade, neither to a new local version, nor back to the cs version, so in any
case I yet don't see the source of this problem.