ERROR cannot write leadership settings: not the leader

Bug #1890256 reported by Aurelien Lourot
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Keystone Charm
Won't Fix
Medium
Unassigned

Bug Description

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

summary: - ERROR cannot write leadership settings: cannot write settings: not the
- leader
+ ERROR cannot write leadership settings: not the leader
Revision history for this message
Aurelien Lourot (aurelien-lourot) wrote :

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.

Changed in charm-keystone:
status: New → In Progress
assignee: nobody → Aurelien Lourot (aurelien-lourot)
importance: Undecided → High
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to charm-keystone (master)

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

Revision history for this message
Aurelien Lourot (aurelien-lourot) wrote :

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

Changed in charm-keystone:
importance: High → Medium
Changed in charm-keystone:
milestone: none → 20.10
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to charm-keystone (master)

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

Changed in charm-keystone:
status: In Progress → Triaged
assignee: Aurelien Lourot (aurelien-lourot) → nobody
David Ames (thedac)
Changed in charm-keystone:
milestone: 20.10 → 21.01
David Ames (thedac)
Changed in charm-keystone:
milestone: 21.01 → none
Revision history for this message
Aurelien Lourot (aurelien-lourot) wrote :

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

Changed in charm-keystone:
status: Triaged → Won't Fix
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.