http://ci.jujucharms.com/job/github-check-merge-juju/1878/testReport/junit/github/com_juju_juju_worker_peergrouper/TestPackage/
----------------------------------------------------------------------
FAIL: worker_test.go:899: workerSuite.TestRemovePrimaryValidSecondaries
[LOG] 0:00.000 INFO juju.worker.peergrouper fakeState.addMachine "10"
[LOG] 0:00.000 INFO juju.worker.peergrouper setting replicaset members to
Id: 0, Tags: map[juju-machine-id:10], voting
mustNext init
mustNext init done, ok: true, val:
Id: 0, Tags: map[juju-machine-id:10], voting
[LOG] 0:00.000 INFO juju.worker.peergrouper fakeState.addMachine "11"
[LOG] 0:00.000 INFO juju.worker.peergrouper fakeState.addMachine "12"
mustNext nonvoting members
[LOG] 0:00.000 TRACE juju.worker.peergrouper waiting...
[LOG] 0:00.000 TRACE juju.worker.peergrouper <-controllerChanges
[LOG] 0:00.000 DEBUG juju.worker.peergrouper controller machines in state: []string{"10", "11", "12"}
[LOG] 0:00.000 DEBUG juju.worker.peergrouper found new machine "10"
[LOG] 0:00.000 DEBUG juju.worker.peergrouper machine "10" has started, adding it to peergrouper list
[LOG] 0:00.000 DEBUG juju.worker.peergrouper found new machine "11"
[LOG] 0:00.000 DEBUG juju.worker.peergrouper machine "11" has started, adding it to peergrouper list
[LOG] 0:00.000 DEBUG juju.worker.peergrouper found new machine "12"
[LOG] 0:00.000 DEBUG juju.worker.peergrouper machine "12" has started, adding it to peergrouper list
[LOG] 0:00.000 TRACE juju.worker.peergrouper controller added or removed, update replica now
[LOG] 0:00.001 TRACE juju.worker.peergrouper read peer group info: &replicaset.Status{
Name: "",
Members: {
{Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
{Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:6, Uptime:0, Ping:0},
{Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:6, Uptime:0, Ping:0},
},
}
[]replicaset.Member{
{
Id: 0,
Address: "0.1.2.10:1234",
Priority: (*float64)(nil),
Tags: {"juju-machine-id":"10"},
Votes: (*int)(nil),
},
}
[LOG] 0:00.001 DEBUG juju.worker.peergrouper calculating desired peer group
desired voting members: (maxId: 0)
&peergrouper.machine{id: "10", wantsVote: true, addresses: [public:0.1.2.10]}: rs_id=0, rs_addr=0.1.2.10:1234
[LOG] 0:00.001 DEBUG juju.worker.peergrouper assessing possible peer group changes:
[LOG] 0:00.001 DEBUG juju.worker.peergrouper machine "10" is already voting
[LOG] 0:00.001 DEBUG juju.worker.peergrouper machine "11" does not exist and is not ready (status: STARTUP, healthy: false)
[LOG] 0:00.001 DEBUG juju.worker.peergrouper machine "12" does not exist and is not ready (status: STARTUP, healthy: false)
[LOG] 0:00.001 DEBUG juju.worker.peergrouper assessed
[LOG] 0:00.001 DEBUG juju.worker.peergrouper number of voters is odd
[LOG] 0:00.001 DEBUG juju.worker.peergrouper create member with id "11"
[LOG] 0:00.001 DEBUG juju.worker.peergrouper create member with id "12"
[LOG] 0:00.001 DEBUG juju.worker.peergrouper machine "10" selected address "0.1.2.10:1234" by scope from [0.1.2.10:1234]
[LOG] 0:00.003 DEBUG juju.worker.peergrouper machine "11" selected address "0.1.2.11:1234" by scope from [0.1.2.11:1234]
[LOG] 0:00.003 DEBUG juju.worker.peergrouper machine "12" selected address "0.1.2.12:1234" by scope from [0.1.2.12:1234]
[LOG] 0:00.003 DEBUG juju.worker.peergrouper desired peer group members:
Id: 0, Tags: map[juju-machine-id:10], voting
Id: 1, Tags: map[juju-machine-id:11], not-voting
Id: 2, Tags: map[juju-machine-id:12], not-voting
[LOG] 0:00.003 INFO juju.worker.peergrouper setting replicaset members to
Id: 0, Tags: map[juju-machine-id:10], voting
Id: 1, Tags: map[juju-machine-id:11], not-voting
Id: 2, Tags: map[juju-machine-id:12], not-voting
[LOG] 0:00.003 INFO juju.worker.peergrouper successfully updated replica set
[LOG] 0:00.003 TRACE juju.worker.peergrouper succeeded, waking up after: 1m0s
mustNext nonvoting members done, ok: true, val:
Id: 0, Tags: map[juju-machine-id:10], voting
Id: 1, Tags: map[juju-machine-id:11], not-voting
Id: 2, Tags: map[juju-machine-id:12], not-voting
[LOG] 0:00.003 TRACE juju.worker.peergrouper waiting...
[LOG] 0:00.003 TRACE juju.worker.peergrouper <-w.configChanges
mustNext status ok
[LOG] 0:00.004 TRACE juju.worker.peergrouper read peer group info: &replicaset.Status{
Name: "",
Members: {
{Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
{Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
{Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
},
}
[]replicaset.Member{
{
Id: 2,
Address: "0.1.2.12:1234",
Priority: &float64(0),
Tags: {"juju-machine-id":"12"},
Votes: &int(0),
},
{
Id: 0,
Address: "0.1.2.10:1234",
Priority: (*float64)(nil),
Tags: {"juju-machine-id":"10"},
Votes: (*int)(nil),
},
{
Id: 1,
Address: "0.1.2.11:1234",
Priority: &float64(0),
Tags: {"juju-machine-id":"11"},
Votes: &int(0),
},
}
[LOG] 0:00.004 DEBUG juju.worker.peergrouper calculating desired peer group
desired voting members: (maxId: 2)
&peergrouper.machine{id: "10", wantsVote: true, addresses: [public:0.1.2.10]}: rs_id=0, rs_addr=0.1.2.10:1234
&peergrouper.machine{id: "11", wantsVote: true, addresses: [public:0.1.2.11]}: rs_id=1, rs_addr=0.1.2.11:1234
&peergrouper.machine{id: "12", wantsVote: true, addresses: [public:0.1.2.12]}: rs_id=2, rs_addr=0.1.2.12:1234
[LOG] 0:00.004 DEBUG juju.worker.peergrouper assessing possible peer group changes:
[LOG] 0:00.004 DEBUG juju.worker.peergrouper machine "10" is already voting
[LOG] 0:00.004 DEBUG juju.worker.peergrouper machine "11" is a potential voter
[LOG] 0:00.004 DEBUG juju.worker.peergrouper machine "12" is a potential voter
[LOG] 0:00.004 DEBUG juju.worker.peergrouper assessed
[LOG] 0:00.004 DEBUG juju.worker.peergrouper number of voters is odd
[LOG] 0:00.004 DEBUG juju.worker.peergrouper machine "10" selected address "0.1.2.10:1234" by scope from [0.1.2.10:1234]
[LOG] 0:00.004 DEBUG juju.worker.peergrouper machine "11" selected address "0.1.2.11:1234" by scope from [0.1.2.11:1234]
[LOG] 0:00.004 DEBUG juju.worker.peergrouper machine "12" selected address "0.1.2.12:1234" by scope from [0.1.2.12:1234]
[LOG] 0:00.004 DEBUG juju.worker.peergrouper desired peer group members:
Id: 0, Tags: map[juju-machine-id:10], voting
Id: 1, Tags: map[juju-machine-id:11], voting
Id: 2, Tags: map[juju-machine-id:12], voting
[LOG] 0:00.004 INFO juju.worker.peergrouper setting HasVote=true on machines [11 12]
[LOG] 0:00.004 INFO juju.worker.peergrouper setting replicaset members to
Id: 0, Tags: map[juju-machine-id:10], voting
Id: 1, Tags: map[juju-machine-id:11], voting
Id: 2, Tags: map[juju-machine-id:12], voting
[LOG] 0:00.004 INFO juju.worker.peergrouper successfully updated replica set
mustNext status ok done, ok: true, val:
Id: 0, Tags: map[juju-machine-id:10], voting
Id: 1, Tags: map[juju-machine-id:11], voting
Id: 2, Tags: map[juju-machine-id:12], voting
mustNextStatus init
mustNextStatus init done, ok: true, val: &replicaset.Status{
Name: "",
Members: {
{Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
{Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
{Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
},
}
mustNextStatus stepping down primary
[LOG] 0:00.005 TRACE juju.worker.peergrouper succeeded, waking up after: 1m0s
[LOG] 0:00.005 TRACE juju.worker.peergrouper waiting...
[LOG] 0:00.005 TRACE juju.worker.peergrouper <-w.machineChanges
[LOG] 0:00.011 TRACE juju.worker.peergrouper read peer group info: &replicaset.Status{
Name: "",
Members: {
{Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
{Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
{Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
},
}
[]replicaset.Member{
{
Id: 2,
Address: "0.1.2.12:1234",
Priority: (*float64)(nil),
Tags: {"juju-machine-id":"12"},
Votes: (*int)(nil),
},
{
Id: 0,
Address: "0.1.2.10:1234",
Priority: (*float64)(nil),
Tags: {"juju-machine-id":"10"},
Votes: (*int)(nil),
},
{
Id: 1,
Address: "0.1.2.11:1234",
Priority: (*float64)(nil),
Tags: {"juju-machine-id":"11"},
Votes: (*int)(nil),
},
}
[LOG] 0:00.011 DEBUG juju.worker.peergrouper calculating desired peer group
desired voting members: (maxId: 2)
&peergrouper.machine{id: "10", wantsVote: false, addresses: [public:0.1.2.10]}: rs_id=0, rs_addr=0.1.2.10:1234
&peergrouper.machine{id: "11", wantsVote: true, addresses: [public:0.1.2.11]}: rs_id=1, rs_addr=0.1.2.11:1234
&peergrouper.machine{id: "12", wantsVote: true, addresses: [public:0.1.2.12]}: rs_id=2, rs_addr=0.1.2.12:1234
[LOG] 0:00.011 DEBUG juju.worker.peergrouper assessing possible peer group changes:
[LOG] 0:00.016 DEBUG juju.worker.peergrouper primary machine "10" is a potential non-voter
[LOG] 0:00.016 DEBUG juju.worker.peergrouper machine "11" is already voting
[LOG] 0:00.016 DEBUG juju.worker.peergrouper machine "12" is already voting
[LOG] 0:00.016 DEBUG juju.worker.peergrouper assessed
[LOG] 0:00.016 DEBUG juju.worker.peergrouper removing vote from "11" to maintain odd number of voters
[LOG] 0:00.016 DEBUG juju.worker.peergrouper machine "10" selected address "0.1.2.10:1234" by scope from [0.1.2.10:1234]
[LOG] 0:00.016 DEBUG juju.worker.peergrouper machine "11" selected address "0.1.2.11:1234" by scope from [0.1.2.11:1234]
[LOG] 0:00.016 DEBUG juju.worker.peergrouper machine "12" selected address "0.1.2.12:1234" by scope from [0.1.2.12:1234]
[LOG] 0:00.016 DEBUG juju.worker.peergrouper desired peer group members:
Id: 0, Tags: map[juju-machine-id:10], not-voting
Id: 1, Tags: map[juju-machine-id:11], not-voting
Id: 2, Tags: map[juju-machine-id:12], voting
[LOG] 0:00.016 INFO juju.worker.peergrouper mongo primary machine needs to be removed, first requesting it to step down
[LOG] 0:00.016 DEBUG juju.worker.peergrouper StepDownPrimary
[LOG] 0:00.016 DEBUG juju.worker.peergrouper StepDownPrimary nominated 2 to be the new primary from: [0: current primary 1: eligible secondary 2: eligible secondary]
mustNextStatus stepping down primary done, ok: true, val: &replicaset.Status{
Name: "",
Members: {
{Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
{Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
{Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
},
}
[LOG] 0:00.017 TRACE juju.worker.peergrouper failed, waking up after: 2s
[LOG] 0:00.017 TRACE juju.worker.peergrouper waiting...
worker_test.go:922:
// Now we have to wait for time to advance for us to reevaluate the system
c.Assert(s.clock.WaitAdvance(2*pollInterval, coretesting.ShortWait, 2), jc.ErrorIsNil)
... value *errors.Err = &errors.Err{message:"got 1 timers added after waiting 50ms: wanted 2", cause:error(nil), previous:error(nil), file:"github.com/juju/testing/clock.go", line:133} ("got 1 timers added after waiting 50ms: wanted 2")
... error stack:
github.com/juju/testing/clock.go:133: got 1 timers added after waiting 50ms: wanted 2
OOPS: 44 passed, 1 FAILED
I swear I fixed a bug like this recently.