ERROR cannot write leadership settings: not the leader

[Aurelien Lourot]

Happened here in a full xenial-newton deploy: http://osci:8080/view/MojoMatrix/job/mojo_runner/23316/

2020-08-03 15:41:00 DEBUG juju-log shared-db:31: Creating service credentials for 'nova'
2020-08-03 15:41:01 DEBUG juju-log shared-db:31: User 'nova' already exists
2020-08-03 15:41:01 DEBUG shared-db-relation-changed ERROR cannot write leadership settings: cannot write settings: not the leader
2020-08-03 15:41:02 DEBUG shared-db-relation-changed Traceback (most recent call last):
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 935, in <module>
2020-08-03 15:41:02 DEBUG shared-db-relation-changed main()
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 928, in main
2020-08-03 15:41:02 DEBUG shared-db-relation-changed hooks.execute(sys.argv)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/core/hookenv.py", line 945, in execute
2020-08-03 15:41:02 DEBUG shared-db-relation-changed self._hooks[hook_name]()
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/contrib/openstack/utils.py", line 1720, in wrapped_f
2020-08-03 15:41:02 DEBUG shared-db-relation-changed stopstart, restart_functions)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/core/host.py", line 747, in restart_on_change_helper
2020-08-03 15:41:02 DEBUG shared-db-relation-changed r = lambda_f()
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/contrib/openstack/utils.py", line 1719, in <lambda>
2020-08-03 15:41:02 DEBUG shared-db-relation-changed (lambda: f(*args, **kwargs)), __restart_map_cache['cache'],
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 410, in db_changed
2020-08-03 15:41:02 DEBUG shared-db-relation-changed leader_init_db_if_ready(use_current_context=True)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/contrib/openstack/utils.py", line 1720, in wrapped_f
2020-08-03 15:41:02 DEBUG shared-db-relation-changed stopstart, restart_functions)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/core/host.py", line 747, in restart_on_change_helper
2020-08-03 15:41:02 DEBUG shared-db-relation-changed r = lambda_f()
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/contrib/openstack/utils.py", line 1719, in <lambda>
2020-08-03 15:41:02 DEBUG shared-db-relation-changed (lambda: f(*args, **kwargs)), __restart_map_cache['cache'],
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 380, in leader_init_db_if_ready
2020-08-03 15:41:02 DEBUG shared-db-relation-changed update_all_identity_relation_units()
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 340, in update_all_identity_relation_units
2020-08-03 15:41:02 DEBUG shared-db-relation-changed identity_changed(relation_id=rid, remote_unit=unit)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/contrib/openstack/utils.py", line 1720, in wrapped_f
2020-08-03 15:41:02 DEBUG shared-db-relation-changed stopstart, restart_functions)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/core/host.py", line 747, in restart_on_change_helper
2020-08-03 15:41:02 DEBUG shared-db-relation-changed r = lambda_f()
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/contrib/openstack/utils.py", line 1719, in <lambda>
2020-08-03 15:41:02 DEBUG shared-db-relation-changed (lambda: f(*args, **kwargs)), __restart_map_cache['cache'],
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/shared-db-relation-changed", line 445, in identity_changed
2020-08-03 15:41:02 DEBUG shared-db-relation-changed add_service_to_keystone(relation_id, remote_unit)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1898, in add_service_to_keystone
2020-08-03 15:41:02 DEBUG shared-db-relation-changed new_roles=roles)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1720, in create_service_credentials
2020-08-03 15:41:02 DEBUG shared-db-relation-changed domain=None)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1678, in create_user_credentials
2020-08-03 15:41:02 DEBUG shared-db-relation-changed passwd_set_callback(passwd, user=user)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/hooks/keystone_utils.py", line 1648, in set_service_password
2020-08-03 15:41:02 DEBUG shared-db-relation-changed leader_set({"{}_passwd".format(user): passwd})
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/core/hookenv.py", line 1166, in inner_translate_exc2
2020-08-03 15:41:02 DEBUG shared-db-relation-changed return f(*args, **kwargs)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/var/lib/juju/agents/unit-keystone-0/charm/charmhelpers/core/hookenv.py", line 1227, in leader_set
2020-08-03 15:41:02 DEBUG shared-db-relation-changed subprocess.check_call(cmd)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed File "/usr/lib/python3.5/subprocess.py", line 581, in check_call
2020-08-03 15:41:02 DEBUG shared-db-relation-changed raise CalledProcessError(retcode, cmd)
2020-08-03 15:41:02 DEBUG shared-db-relation-changed subprocess.CalledProcessError: Command '['leader-set', 'nova_passwd=7C4r63pwfXBH3XkdzsbPTVfSH3GZW2nJfVLJnS3mXpky4fjn57rnMyG9yTmZccnm']' returned non-zero exit status 1
2020-08-03 15:41:02 ERROR juju.worker.uniter.operation runhook.go:132 hook "shared-db-relation-changed" failed: exit status 1
2020-08-03 15:41:02 WARNING juju.worker.uniter.operation leader.go:116 we should run a leader-deposed hook here, but we can't yet

[Aurelien Lourot (aurelien-lourot)]

keystone/0 was clearly the leader when it called leader-set:

unit-keystone-0.log:2020-08-03 14:14:36 DEBUG juju.worker.leadership tracker.go:125 keystone/0 making initial claim for keystone leadership
unit-keystone-0.log:2020-08-03 14:21:35 DEBUG juju-log Unit has been elected leader.
unit-keystone-0.log:2020-08-03 14:21:45 DEBUG leader-elected none
unit-keystone-0.log:2020-08-03 14:21:46 DEBUG leader-elected ERROR no relation id specified
unit-keystone-0.log:2020-08-03 14:21:46 DEBUG leader-elected none
unit-keystone-2.log:2020-08-03 15:37:45 INFO juju-log identity-service:92: Deferring identity_changed() to service leader.
unit-keystone-0.log:2020-08-03 15:39:45 DEBUG juju-log shared-db:31: Unit is ready
unit-keystone-0.log:2020-08-03 15:39:45 DEBUG juju-log shared-db:31: cluster peers are in the following states: dict_values(['READY', 'READY'])
unit-keystone-0.log:2020-08-03 15:39:45 DEBUG juju-log shared-db:31: Application Ready
unit-keystone-0.log:2020-08-03 15:39:45 INFO juju-log shared-db:31: Firing identity_changed hook for all related services.
unit-keystone-0.log:2020-08-03 15:39:45 DEBUG juju-log shared-db:31: This unit (keystone/0) is in allowed unit list from mysql/1
unit-keystone-0.log:2020-08-03 15:39:45 DEBUG juju-log shared-db:31: Database is initialised
unit-keystone-0.log:2020-08-03 15:39:45 INFO juju-log shared-db:31: Updating endpoint for nova
unit-keystone-0.log:2020-08-03 15:40:57 DEBUG juju-log shared-db:31: Service entry for 'nova' already exists.
unit-keystone-0.log:2020-08-03 15:40:59 INFO juju-log shared-db:31: Endpoint template already exists for 'nova' in 'RegionOne'
unit-keystone-0.log:2020-08-03 15:41:00 DEBUG juju-log shared-db:31: Creating service credentials for 'nova'
unit-keystone-0.log:2020-08-03 15:41:01 DEBUG juju-log shared-db:31: User 'nova' already exists
unit-keystone-0.log:2020-08-03 15:41:01 DEBUG shared-db-relation-changed ERROR cannot write leadership settings: cannot write settings: not the leader
unit-keystone-0.log:2020-08-03 15:41:02 DEBUG shared-db-relation-changed subprocess.CalledProcessError: Command '['leader-set', 'nova_passwd=7C4r63pwfXBH3XkdzsbPTVfSH3GZW2nJfVLJnS3mXpky4fjn57rnMyG9yTmZccnm']' returned non-zero exit status 1
unit-keystone-2.log:2020-08-03 15:41:19 DEBUG juju-log Unit has been elected leader.
unit-keystone-2.log:2020-08-03 15:47:23 DEBUG leader-elected none
unit-keystone-2.log:2020-08-03 15:47:24 DEBUG leader-elected ERROR no relation id specified
unit-keystone-2.log:2020-08-03 15:47:25 DEBUG leader-elected none
unit-keystone-2.log:2020-08-03 15:47:28 DEBUG leader-elected active
unit-keystone-2.log:2020-08-03 15:47:28 DEBUG leader-elected active

It would be useful to log the stderr of leader-set, on the other hand the implementation of leader_set() states that it doesn't log in order not to leak credentials. But as you can see in the logs above the credentials have been leaked anyway.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/744690

[Aurelien Lourot (aurelien-lourot)]

The original issue is probably due to a very busy/overloaded cloud.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/744690
Committed: https://git.openstack.org/cgit/openstack/charm-keystone/commit/?id=f9aa92c7ce835a4e0790251469b1f817e17c0730
Submitter: Zuul
Branch: master

commit f9aa92c7ce835a4e0790251469b1f817e17c0730
Author: Aurelien Lourot <email address hidden>
Date: Tue Aug 4 12:40:47 2020 +0200

    Do not leak credentials on leader-set failure

    This will also give us more insights into the leader-set failure
    happening in the linked bug.

    Also updated project files from latest release-tools templates.

    Also blacklisted libjuju 2.8.3 which causes spurious
    JujuAPIError's.

    Change-Id: I51b890098df6d918c1d84adba272559ef45411bb
    Partial-Bug: #1890256

[Aurelien Lourot (aurelien-lourot)]

We haven't seen this issue since the 20.08 charms have been released. Closing for now.