Bootstrap failed on ussuri

[Liam Young]

Keystone bootstrap on focal ussuri, seen in swift-proxy focal-ussuri-gr_swift-proxy gate test: https://openstack-ci-reports.ubuntu.com/artifacts/8e4/814415/8/check/focal-ussuri-gr_swift-proxy/8e415d9/

Error from keystone unit:

2021-11-12 02:41:30 INFO juju-log Migrating the keystone database.
2021-11-12 02:41:30 DEBUG jujuc server.go:211 running hook tool "status-set" for keystone/0-config-changed-1062694034175204135
2021-11-12 02:41:47 DEBUG jujuc server.go:211 running hook tool "leader-set" for keystone/0-config-changed-1062694034175204135
2021-11-12 02:41:48 DEBUG jujuc server.go:211 running hook tool "juju-log" for keystone/0-config-changed-1062694034175204135
2021-11-12 02:41:48 INFO juju-log Bootstrapping keystone.
2021-11-12 02:41:48 DEBUG jujuc server.go:211 running hook tool "status-set" for keystone/0-config-changed-1062694034175204135
2021-11-12 02:41:48 DEBUG juju.worker.uniter.remotestate watcher.go:555 got leader settings change for keystone/0: ok=true
2021-11-12 02:41:48 DEBUG jujuc server.go:211 running hook tool "leader-get" for keystone/0-config-changed-1062694034175204135
2021-11-12 02:41:48 DEBUG jujuc server.go:211 running hook tool "network-get" for keystone/0-config-changed-1062694034175204135
2021-11-12 02:41:48 DEBUG jujuc server.go:211 running hook tool "network-get" for keystone/0-config-changed-1062694034175204135
2021-11-12 02:41:48 DEBUG jujuc server.go:211 running hook tool "network-get" for keystone/0-config-changed-1062694034175204135
2021-11-12 02:41:48 DEBUG jujuc server.go:211 running hook tool "network-get" for keystone/0-config-changed-1062694034175204135
2021-11-12 02:41:48 DEBUG jujuc server.go:211 running hook tool "network-get" for keystone/0-config-changed-1062694034175204135
2021-11-12 02:41:48 DEBUG jujuc server.go:211 running hook tool "network-get" for keystone/0-config-changed-1062694034175204135
2021-11-12 02:41:50 WARNING config-changed /etc/keystone/fernet-keys/ does not exist
2021-11-12 02:41:50 WARNING config-changed Traceback (most recent call last):
2021-11-12 02:41:50 WARNING config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/config-changed", line 937, in <module>
2021-11-12 02:41:50 WARNING config-changed main()
2021-11-12 02:41:50 WARNING config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/config-changed", line 930, in main
2021-11-12 02:41:50 WARNING config-changed hooks.execute(sys.argv)
2021-11-12 02:41:50 WARNING config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/core/hookenv.py", line 962, in execute
2021-11-12 02:41:50 WARNING config-changed self._hooks[hook_name]()
2021-11-12 02:41:50 WARNING config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/contrib/openstack/utils.py", line 1862, in wrapped_f
2021-11-12 02:41:50 WARNING config-changed return restart_on_change_helper(
2021-11-12 02:41:50 WARNING config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/core/host.py", line 837, in restart_on_change_helper
2021-11-12 02:41:50 WARNING config-changed r = lambda_f()
2021-11-12 02:41:50 WARNING config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/contrib/openstack/utils.py", line 1863, in <lambda>
2021-11-12 02:41:50 WARNING config-changed (lambda: f(*args, **kwargs)),
2021-11-12 02:41:50 WARNING config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/contrib/hardening/harden.py", line 93, in _harden_inner2
2021-11-12 02:41:50 WARNING config-changed return f(*args, **kwargs)
2021-11-12 02:41:50 WARNING config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/config-changed", line 235, in config_changed
2021-11-12 02:41:50 WARNING config-changed do_openstack_upgrade_reexec(configs=CONFIGS)
2021-11-12 02:41:50 WARNING config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 740, in do_openstack_upgrade_reexec
2021-11-12 02:41:50 WARNING config-changed do_openstack_upgrade(configs)
2021-11-12 02:41:50 WARNING config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 788, in do_openstack_upgrade
2021-11-12 02:41:50 WARNING config-changed bootstrap_keystone(configs=configs)
2021-11-12 02:41:50 WARNING config-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 876, in bootstrap_keystone
2021-11-12 02:41:50 WARNING config-changed subprocess.check_call((
2021-11-12 02:41:50 WARNING config-changed File "/usr/lib/python3.8/subprocess.py", line 364, in check_call
2021-11-12 02:41:50 WARNING config-changed raise CalledProcessError(retcode, cmd)
2021-11-12 02:41:50 WARNING config-changed subprocess.CalledProcessError: Command '('keystone-manage', 'bootstrap', '--bootstrap-username', '_charm-keystone-admin', '--bootstrap-password', 'wX6LLSCcMRtChnks8cnLWswKpG65rjBm3Zf8RWq5xdgZmrX2hMCyBMNrssnGLrXB', '--bootstrap-project-name', 'admin', '--bootstrap-role-name', 'Admin', '--bootstrap-service-name', 'keystone', '--bootstrap-admin-url', 'http://172.16.0.33:35357/v3', '--bootstrap-public-url', 'http://172.16.0.33:5000/v3', '--bootstrap-internal-url', 'http://172.16.0.33:5000/v3', '--bootstrap-region-id', 'RegionOne')' returned non-zero exit status 1.
2021-11-12 02:41:51 ERROR juju.worker.uniter.operation runhook.go:139 hook "config-changed" (via explicit, bespoke hook script) failed: exit status 1
2021-11-12 02:41:51 DEBUG juju.machinelock machinelock.go:186 machine lock released for keystone/0 uniter (run config-changed hook)
2021-11-12 02:41:51 DEBUG juju.worker.uniter.operation executor.go:115 lock released for keystone/0
2021-11-12 02:41:51 INFO juju.worker.uniter resolver.go:143 awaiting error resolution for "config-changed" hook
2021-11-12 02:41:51 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] error: hook failed: "config-changed"

[Corey Bryant (corey.bryant)]

I just hit this on focal-xena as well.

def key_write() in hooks/keystone_utils.py creates the /etc/keystone/fernet-keys/ directory. Something must have changed in the charm to cause key_write() to not be called before 'keystone-manage bootstrap'. Either that or this has always been a race?

[Corey Bryant (corey.bryant)]

Worth noting, I'm using: keystone charmstore stable 578

[Corey Bryant (corey.bryant)]

cs:keystone

[Corey Bryant (corey.bryant)]

key_write() is the only function that creates the /etc/keystone/fernet-keys/ directory and it only runs for non leaders so I'm not sure how leaders ever had /etc/keystone/fernet-keys/ created. It's possible that we had more leader settings changes in the past that allowed the directory to be created on the eventual leader prior to it becoming leader.

I think really the package should be creating that directory but a charm fix seems appropriate too since it is creating the directory already.

[Corey Bryant (corey.bryant)]

$ sudo keystone-manage bootstrap --bootstrap-username _charm-keystone-admin --bootstrap-password HShkySz6tJd3VnPGjcgnxXG2wzbg4kmgs8ryRKyJbtyp8BN7NWNMjLn6SZLpcbkn --bootstrap-project-name admin --bootstrap-role-name Admin --bootstrap-service-name keystone --bootstrap-admin-url http://10.246.114.22:35357/v3 --bootstrap-public-url http://10.246.114.22:5000/v3 --bootstrap-internal-url http://10.246.114.22:5000/v3 --bootstrap-region-id RegionOne

/etc/keystone/fernet-keys/ does not exist

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/charm-keystone/+/818412

[Corey Bryant (corey.bryant)]

I've pushed a fix to the package repository for this and it will be included in the next upload to jammy. I don't plan to backport it at this point.

[Alex Kavanagh (ajkavanagh)]

> key_write() is the only function that creates the /etc/keystone/fernet-keys/ directory and it only runs for non leaders so I'm not sure how leaders ever had /etc/keystone/fernet-keys/ created.

Corey, I think the keystone-manage initial bootstrap create the fernet-keys/ directory, so maybe something has changed there or there is a change in sequence of hooks. Is the juju 2.9 or 2.8?

[Corey Bryant (corey.bryant)]

I'm thinking it's a change in hook sequence. I'm not seeing any upstream changes that would change the behavior. keystone-manage bootstrap docs don't mention anything but keystone-manage fernet_setup mentions the directory needs to exist prior to running.
https://opendev.org/openstack/keystone/src/branch/master/keystone/conf/fernet_tokens.py#L22

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/charm-keystone/+/818412
Committed: https://opendev.org/openstack/charm-keystone/commit/1bc4b739db187239340b32633b29767205a29a4f
Submitter: "Zuul (22348)"
Branch: master

commit 1bc4b739db187239340b32633b29767205a29a4f
Author: Corey Bryant <email address hidden>
Date: Thu Nov 18 10:48:28 2021 -0500

    Ensure /etc/keystone/fernet-keys/ before bootstrap

    The /etc/keystone/fernet-keys/ directory must exist prior to
    keystone-manage bootstrap being called.

    Closes-Bug: #1951076
    Change-Id: Ifa1ca433a658011365376a38e20b2901202bca21

[Launchpad Janitor (janitor)]

This bug was fixed in the package keystone - 2:20.0.0+git2021120815.2ddf8f321-0ubuntu1

---------------
keystone (2:20.0.0+git2021120815.2ddf8f321-0ubuntu1) jammy; urgency=medium

  * d/keystone-common.dirs, d/keystone-common.postinst: Create
    /etc/keystone/fernet-keys directory (LP: #1951076).
  * New upstream snapshot for OpenStack Yoga.

 -- Corey Bryant <email address hidden> Wed, 08 Dec 2021 15:36:48 -0500