hook failed: "leader-settings-changed" (double bootstrap-pxc due to a leadership change before cluster bootstrap completion)

I can confirm that alitvinov and I have seen exactly that behavior a few weeks ago on stable/17.08.

Leader UUID ('0dde54c4-c961-11e7-9775-2f72db67cbda') != Unit UUID ('b3e1b7e8-c95f-11e7-91fa-56c8581eb616')

In our case all leader-get invocations returned the same result (so the Juju leader bucket is consistent across units).

http://paste.ubuntu.com/25962876/

As the code suggests, this is case 1 and it seems that there were two concurrent bootstrap attempts.

    elif lead_cluster_state_uuid != cluster_state_uuid:
        # this may mean 2 things:
        # 1) the units have diverged, which it's bad and we do stop.
        # 2) cluster_state_uuid could not be retrieved because it
        # hasn't been bootstrapped, mysqld is stopped, etc.

The question is how is that even possible with a single leader?

render_config_restart_on_changed -> bootstrap_pxc

https://github.com/openstack/charm-percona-cluster/blob/stable/17.08/hooks/percona_hooks.py#L323-L327
    if is_leader():
        log("Leader unit - bootstrap required=%s" % (not bootstrapped),
            DEBUG)
        render_config_restart_on_changed(clustered, hosts,
                                         bootstrap=not bootstrapped)

https://github.com/openstack/charm-percona-cluster/blob/stable/17.08/hooks/percona_hooks.py#L221-L224
            bootstrap_pxc()
            # NOTE(dosaboy): this will not actually do anything if no cluster
            # relation id exists yet.
            notify_bootstrapped()

If both units have passed is_leader gate than they were both leaders at the same time.

===

Each time a new leader is elected there will be a resignation operation by the operation resolver in uniter:

https://github.com/juju/juju/blob/juju-2.2.6/worker/uniter/leadership/resolver.go#L56-L60

Normally, a current leader will keep its lease (lease renewal).

https://github.com/juju/juju/blob/juju-2.2.6/worker/leadership/tracker.go#L249

===

Looking at the logs:

unit-mysql-0 - never elected as a leader
unit-mysql-1 - elected as a once leader at 2017-11-14 17:27:07, never resigned
unit-mysql-2 - first leader ever for this app, elected as a leader once at 2017-11-14 17:17:00, resigned at 2017-11-14 17:21:33

unit-mysql-2.log

# there is no leader-elected hook implemented in percona-cluster so this is fine

post-install queued leader-elected event
2017-11-14 17:16:33 INFO juju.worker.uniter resolver.go:104 found queued "leader-elected" hook

2017-11-14 17:16:33 DEBUG juju.worker.uniter agent.go:17 [AGENT-STATUS] executing: running leader-elected hook

2017-11-14 17:16:35 INFO juju-log Unknown hook leader-elected - skipping.

2017-11-14 17:17:00 INFO juju.worker.uniter.operation runhook.go:113 ran "leader-elected" hook
2017-11-14 17:17:00 DEBUG juju.worker.uniter.operation executor.go:100 committing operation "run leader-elected hook"

...

2017-11-14 17:17:00 INFO juju.worker.uniter.operation runhook.go:113 ran "leader-elected" hook
2017-11-14 17:17:00 DEBUG juju.worker.uniter.operation executor.go:100 committing operation "run leader-elected hook"

...

2017-11-14 17:17:28 DEBUG juju-log Leader unit - bootstrap required=True

2017-11-14 17:17:32 DEBUG config-changed Unknown oper...

What I think happens is that there is a percona-level contention on who's cluster UUID is the right one as we technically ran bootstrap-pxc two times due to a leadership flip to a different unit.

I don't think concurrent bootstrap-pxc is generally a good idea (https://www.percona.com/doc/percona-xtradb-cluster/LATEST/bootstrap.html this doesn't discuss consequential bootstrap-pxc executions on different nodes - I think there is a high chance that the cluster will go crazy like our cluster did).

1.
mysql/2 (the first leader) has set a cluster_state_uuid to b3e1b7e8-c95f-11e7-91fa-56c8581eb616

2017-11-14 17:17:43 DEBUG juju-log Bootstrap PXC Succeeded

2.

mysql/1 - the new leader doesn't error out so it must have generated 0dde54c4-c961-11e7-9775-2f72db67cbda and set is to leader settings.

2017-11-14 17:27:24 DEBUG juju-log Bootstrap PXC Succeeded

3.

mysql/0 - a minion "for life"

Used the correct UUID of the new leader (mysql/1) (0dde54c4-c961-11e7-9775-2f72db67cbda) at first and even started notifying peer units, so:

somehow got past

    if wsrep_ready.lower() in ['on', 'ready']:
        cluster_state_uuid = get_wsrep_value('wsrep_cluster_state_uuid')

and

    elif lead_cluster_state_uuid != cluster_state_uuid:

        log('bootstrap uuid differs: %s != %s' % (lead_cluster_state_uuid,
                                                  cluster_state_uuid),

and got to

    for rid in relation_ids('cluster'):
        notify_bootstrapped(cluster_rid=rid,
                            cluster_uuid=cluster_state_uuid)

2017-11-14 17:31:07 DEBUG juju-log cluster:28: Notifying peers that percona is bootstrapped (uuid=0dde54c4-c961-11e7-9775-2f72db67cbda)

Notice the time stamp: 17:31:07 - this happened way after mysql/2 set up wsrep_cluster_state to b3e1b7e8-c95f-11e7-91fa-56c8581eb616

4. mysql/0 (minion) started saying that wsrep_cluster_uuid == b3e1b7e8-c95f-11e7-91fa-56c8581eb616

2017-11-14 17:31:57 ERROR juju-log bootstrap uuid differs: 0dde54c4-c961-11e7-9775-2f72db67cbda != b3e1b7e8-c95f-11e7-91fa-56c8581eb616