Comment 12 for bug 1728111

So digging through the code we call
func (ctx *leadershipContext) ensureLeader() error {
...
success := ctx.tracker.ClaimLeader().Wait()

which submits a claim ticket and waits for it to respond, claim tickets are
handled here:
if err := t.resolveClaim(ticketCh); err != nil {
resolve claim calls
if leader, err := t.isLeader(); err != nil {
which then:
func (t *Tracker) isLeader() (bool, error) {
if !t.isMinion {
// Last time we looked, we were leader.
select {
case <-t.tomb.Dying():
return false, errors.Trace(tomb.ErrDying)
case <-t.renewLease:
logger.Tracef("%s renewing lease for %s leadership", t.unitName,
t.applicationName)
t.renewLease = nil
if err := t.refresh(); err != nil {
return false, errors.Trace(err)
}
default:
logger.Tracef("%s still has %s leadership", t.unitName, t.applicationName)
}
}
return !t.isMinion, nil
}

*that* looks to me like we only renew the lease if we are currently pending
a renewal (so on a 1min lease we only renew on IsLeader if we're past the
30s mark).
Otherwise the:
default: still leader
code triggers and we just return true.

So if the timing was:
 0s: renew leadership for 60s
 25s: call IsLeader (no actual refresh)
 There doesn't appear to be any database activity after isLeader returns
true

All that refreshing would do is increase the window, which we could
probably do in a different way (just increase the lease time).

The other curious bit is the timing from the log:
2017-10-27 16:28:13 DEBUG worker.uniter.jujuc server.go:178 running hook
tool "leader-get"
2017-10-27 16:28:13 DEBUG worker.uniter.jujuc server.go:178 running hook
tool "is-leader"
2017-10-27 16:30:48 DEBUG worker.uniter.jujuc server.go:178 running hook
tool "leader-set"

That is a full 2m35s from the time we see "is-leader" being called before
"leader-set" is then called.

Given the comment here:

    _password = leader_get(key)
    if not _password and is_leader():
        _password = config(key) or pwgen()
        leader_set({key: _password})
    return _password

Is pwgen() actually quite slow on a heavily loaded machine? Is it grabbing
lots of entropy/reading from /dev/random rather than /dev/urandom and
getting blocked?

So 2m45s is quite a long time. But also note that other things are
surprisingly slow:
2017-10-27 16:30:48 DEBUG worker.uniter.jujuc server.go:178 running hook
tool "leader-set"
2017-10-27 16:36:10 INFO juju.worker.leadership tracker.go:208 mysql
leadership for mysql/2 denied

Is it really taking us ~5minutes to deal with the leader-set call? or are
these 2 separate calls we're dealing with?

I'm assuming mysql/2 is the one running in the "something wonky went on
early".

We see that mysql/2 was set to be the leader at 16:24:

2017-10-27 16:23:14 DEBUG juju.worker.leadership tracker.go:126 mysql/2
making initial claim for mysql leadership
2017-10-27 16:24:52 INFO juju.worker.leadership tracker.go:185 mysql/2
promoted to leadership of mysql

At 16:36:10 mysql/2 is told its no longer the leader, but at 16:35:30 is
where mysql/0 is told that is now the leader:

2017-10-27 16:35:30 INFO juju.worker.uniter resolver.go:104 found queued
"leader-elected" hook

I'm heading back to the raw logs now, but nearly 3min from a is-leader to a
leader-set is *very* long.

If we have a reproducible test case there are some TRACE level logs that
might be informative if they aren't too spammy. (then again, if this is all
load related, we're likely to lose logs/crush the system by increasing
verbosity.)

John
=:->
<https://bugs.launchpad.net/charm-percona-cluster/+bug/1728111/+index#>

On Tue, Oct 31, 2017 at 9:46 AM, Andrew Wilkins <
<email address hidden>> wrote:

> "is-leader" does refresh. You can see the details here:
> https://github.com/juju/juju/blob/develop/worker/uniter/
> runner/context/leader.go#L54.
>
> If the clock was jumping on the controller, then this could be
> explained. I've looked over the worker/lease and worker/leadership code,
> and it should now be sound when compiled with Go 1.9+ (which we now do),
> from Juju 2.3-beta2+ (new lease manager code).
>
> --
> You received this bug notification because you are subscribed to juju.
> Matching subscriptions: juju bugs
> https://bugs.launchpad.net/bugs/1728111
>
> Title:
> pxc cluster build failed due to leadership change in early unit
> lifecycle
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/charm-helpers/+bug/1728111/+subscriptions
>