keystone charm accessing database before db ready

[Gema Gomez]

keystone charm doesn't wait till keystone is started before accessing the database

fix suggestion: L202 in hooks/config-changed of current charm, add time.sleep(5)

How to reproduce:

1) Deploy ha openstack by running:

> juju-deployer --bootstrap -c default.yaml precise-havana

 -> from this branch:
lp:~openstack-charmers/+junk/openstack-charm-testing-ha

[James Page (james-page)]

Gema

can you provide some more detail around what issue this is actually causing? do you see a hook execution failure? What error message do you see?

[Edward Hope-Morley (hopem)]

I think I klnow what has happened here. I just hit an amulet as follows:

2015-01-08 13:11:17 INFO juju-log Migrating the keystone database.
2015-01-08 13:11:17 INFO config-changed keystone stop/waiting
2015-01-08 13:11:18 INFO config-changed Traceback (most recent call last):
2015-01-08 13:11:18 INFO config-changed File "/usr/bin/keystone-manage", line 51, in <module>
2015-01-08 13:11:18 INFO config-changed cli.main(argv=sys.argv, config_files=config_files)
2015-01-08 13:11:18 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystone/cli.py", line 190, in main
2015-01-08 13:11:18 INFO config-changed config.setup_logging()
2015-01-08 13:11:18 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystone/config.py", line 56, in setup_logging
2015-01-08 13:11:18 INFO config-changed log.setup('keystone')
2015-01-08 13:11:18 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystone/openstack/common/log.py", line 459, in setup
2015-01-08 13:11:18 INFO config-changed _load_log_config(CONF.log_config_append)
2015-01-08 13:11:18 INFO config-changed File "/usr/lib/python2.7/dist-packages/keystone/openstack/common/log.py", line 451, in _load_log_config
2015-01-08 13:11:18 INFO config-changed disable_existing_loggers=False)
2015-01-08 13:11:18 INFO config-changed File "/usr/lib/python2.7/logging/config.py", line 78, in fileConfig
2015-01-08 13:11:18 INFO config-changed handlers = _install_handlers(cp, formatters)
2015-01-08 13:11:18 INFO config-changed File "/usr/lib/python2.7/logging/config.py", line 156, in _install_handlers
2015-01-08 13:11:18 INFO config-changed h = klass(*args)
2015-01-08 13:11:18 INFO config-changed File "/usr/lib/python2.7/logging/handlers.py", line 386, in __init__
2015-01-08 13:11:18 INFO config-changed logging.FileHandler.__init__(self, filename, mode, encoding, delay)
2015-01-08 13:11:18 INFO config-changed File "/usr/lib/python2.7/logging/__init__.py", line 897, in __init__
2015-01-08 13:11:18 INFO config-changed StreamHandler.__init__(self, self._open())
2015-01-08 13:11:18 INFO config-changed File "/usr/lib/python2.7/logging/__init__.py", line 916, in _open
2015-01-08 13:11:18 INFO config-changed stream = open(self.baseFilename, self.mode)
2015-01-08 13:11:18 INFO config-changed IOError: [Errno 13] Permission denied: '/var/lib/juju/agents/unit-keystone-0/charm/error.log'
2015-01-08 13:11:18 INFO config-changed Traceback (most recent call last):
2015-01-08 13:11:18 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/config-changed", line 400, in <module>
2015-01-08 13:11:18 INFO config-changed main()
2015-01-08 13:11:18 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/config-changed", line 394, in main
2015-01-08 13:11:18 INFO config-changed hooks.execute(sys.argv)
2015-01-08 13:11:18 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charmhelpers/core/hookenv.py", line 528, in execute
2015-01-08 13:11:18 INFO config-changed self._hooks[hook_name]()
2015-01-08 13:11:18 INFO config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/charm...

[James Page (james-page)]

I think this is also a problem for reboots; if the keystone charm is located under LXC on the same machine as the mysql charm, the config-changed hook will fail; we should refactor the bits that rely on db connectivity and use the exec retry helper to try a few times to complete that code path.

[Ryan Beisner (1chb1n)]

We are seeing this on Trusty-Kilo deploys (with and without keystone under LXC). Is it the same issue or should we file a separate bug?

    units:
      keystone/0:
        agent-state: error
        agent-state-info: 'hook failed: "config-changed"'

keystoneclient.openstack.common.apiclient.exceptions.InternalServerError: An unexpected error prevented the server from fulfilling your request. (HTTP 500)

http://paste.ubuntu.com/10017855/

[Edward Hope-Morley (hopem)]

/var/log/keystone/keystone.log has:

...
  File "/usr/lib/python2.7/dist-packages/keystone/token/persistence/core.py", line 53, in __init__
    super(PersistenceManager, self).__init__(CONF.token.driver)
  File "/usr/lib/python2.7/dist-packages/keystone/common/manager.py", line 70, in __init__
    self.driver = importutils.import_object(driver_name)
  File "/usr/lib/python2.7/dist-packages/oslo/utils/importutils.py", line 38, in import_object
    return import_class(import_str)(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/oslo/utils/importutils.py", line 27, in import_class
    __import__(mod_str)
ImportError: No module named backends.sql

Looks like broken package to me.