Canonical Juju

workerSuite.TestRemovePrimaryValidSecondaries fails with: testclock/clock.go:134: got 1 timers added after waiting 50ms: wanted 2

Bug #1802590 reported by Heather Lanigan on 2018-11-09

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	Canonical Juju	Fix Released	Medium	Tim Penhey	Canonical Juju 2.7-beta1

Bug Description

http://ci.jujucharms.com/job/make-check-juju/1280/console

15:01:33 ----------------------------------------------------------------------
15:01:33 FAIL: worker_test.go:897: workerSuite.TestRemovePrimaryValidSecondaries
15:01:33
15:01:33 [LOG] 0:00.000 INFO juju.worker.peergrouper fakeState.addMachine "10"
15:01:33 [LOG] 0:00.000 INFO juju.worker.peergrouper setting replicaset members to
15:01:33 Id: 0, Tags: map[juju-machine-id:10], voting
15:01:33 mustNext init
15:01:33 mustNext init done, ok: true, val:
15:01:33 Id: 0, Tags: map[juju-machine-id:10], voting
15:01:33 [LOG] 0:00.000 INFO juju.worker.peergrouper fakeState.addMachine "11"
15:01:33 [LOG] 0:00.000 INFO juju.worker.peergrouper fakeState.addMachine "12"
15:01:33 mustNext nonvoting members
15:01:33 [LOG] 0:00.000 TRACE juju.worker.peergrouper waiting...
15:01:33 [LOG] 0:00.000 TRACE juju.worker.peergrouper <-controllerChanges
15:01:33 [LOG] 0:00.000 DEBUG juju.worker.peergrouper controller machines in state: []string{"10", "11", "12"}
15:01:33 [LOG] 0:00.000 DEBUG juju.worker.peergrouper found new machine "10"
15:01:33 [LOG] 0:00.000 DEBUG juju.worker.peergrouper machine "10" has started, adding it to peergrouper list
15:01:33 [LOG] 0:00.000 DEBUG juju.worker.peergrouper found new machine "11"
15:01:33 [LOG] 0:00.000 DEBUG juju.worker.peergrouper machine "11" has started, adding it to peergrouper list
15:01:33 [LOG] 0:00.000 DEBUG juju.worker.peergrouper found new machine "12"
15:01:33 [LOG] 0:00.000 DEBUG juju.worker.peergrouper machine "12" has started, adding it to peergrouper list
15:01:33 [LOG] 0:00.000 TRACE juju.worker.peergrouper controller added or removed, update replica now
15:01:33 [LOG] 0:00.001 TRACE juju.worker.peergrouper read peer group info: &replicaset.Status{
15:01:33 Name: "",
15:01:33 Members: {
15:01:33 {Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
15:01:33 {Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:6, Uptime:0, Ping:0},
15:01:33 {Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:6, Uptime:0, Ping:0},
15:01:33 },
15:01:33 }
15:01:33 []replicaset.Member{
15:01:33 {
15:01:33 Id: 0,
15:01:33 Address: "0.1.2.10:1234",
15:01:33 Priority: (*float64)(nil),
15:01:33 Tags: {"juju-machine-id":"10"},
15:01:33 Votes: (*int)(nil),
15:01:33 },
15:01:33 }
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper calculating desired peer group
15:01:33 desired voting members: (maxId: 0)
15:01:33 &peergrouper.machine{id: "10", wantsVote: true, addresses: [public:0.1.2.10]}: rs_id=0, rs_addr=0.1.2.10:1234
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper assessing possible peer group changes:
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper machine "10" is already voting
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper machine "11" does not exist and is not ready (status: STARTUP, healthy: false)
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper machine "12" does not exist and is not ready (status: STARTUP, healthy: false)
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper assessed
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper number of voters is odd
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper create member with id "11"
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper create member with id "12"
15:01:33 [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]
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper machine "11" selected address "0.1.2.11:1234" by scope from [0.1.2.11:1234]
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper machine "12" selected address "0.1.2.12:1234" by scope from [0.1.2.12:1234]
15:01:33 [LOG] 0:00.001 DEBUG juju.worker.peergrouper desired peer group members:
15:01:33 Id: 0, Tags: map[juju-machine-id:10], voting
15:01:33 Id: 1, Tags: map[juju-machine-id:11], not-voting
15:01:33 Id: 2, Tags: map[juju-machine-id:12], not-voting
15:01:33 [LOG] 0:00.001 INFO juju.worker.peergrouper setting replicaset members to
15:01:33 Id: 0, Tags: map[juju-machine-id:10], voting
15:01:33 Id: 1, Tags: map[juju-machine-id:11], not-voting
15:01:33 Id: 2, Tags: map[juju-machine-id:12], not-voting
15:01:33 [LOG] 0:00.001 INFO juju.worker.peergrouper successfully updated replica set
15:01:33 mustNext nonvoting members done, ok: true, val:
15:01:33 Id: 0, Tags: map[juju-machine-id:10], voting
15:01:33 Id: 1, Tags: map[juju-machine-id:11], not-voting
15:01:33 Id: 2, Tags: map[juju-machine-id:12], not-voting
15:01:33 [LOG] 0:00.001 TRACE juju.worker.peergrouper succeeded, waking up after: 1m0s
15:01:33 [LOG] 0:00.001 TRACE juju.worker.peergrouper waiting...
15:01:33 [LOG] 0:00.001 TRACE juju.worker.peergrouper <-w.configChanges
15:01:33 [LOG] 0:00.002 TRACE juju.worker.peergrouper read peer group info: &replicaset.Status{
15:01:33 Name: "",
15:01:33 Members: {
15:01:33 {Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
15:01:33 {Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:01:33 {Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:01:33 },
15:01:33 }
15:01:33 []replicaset.Member{
15:01:33 {
15:01:33 Id: 1,
15:01:33 Address: "0.1.2.11:1234",
15:01:33 Priority: &float64(0),
15:01:33 Tags: {"juju-machine-id":"11"},
15:01:33 Votes: &int(0),
15:01:33 },
15:01:33 {
15:01:33 Id: 2,
15:01:33 Address: "0.1.2.12:1234",
15:01:33 Priority: &float64(0),
15:01:33 Tags: {"juju-machine-id":"12"},
15:01:33 Votes: &int(0),
15:01:33 },
15:01:33 {
15:01:33 Id: 0,
15:01:33 Address: "0.1.2.10:1234",
15:01:33 Priority: (*float64)(nil),
15:01:33 Tags: {"juju-machine-id":"10"},
15:01:33 Votes: (*int)(nil),
15:01:33 },
15:01:33 }
15:01:33 [LOG] 0:00.002 DEBUG juju.worker.peergrouper calculating desired peer group
15:01:33 desired voting members: (maxId: 2)
15:01:33 &peergrouper.machine{id: "10", wantsVote: true, addresses: [public:0.1.2.10]}: rs_id=0, rs_addr=0.1.2.10:1234
15:01:33 &peergrouper.machine{id: "11", wantsVote: true, addresses: [public:0.1.2.11]}: rs_id=1, rs_addr=0.1.2.11:1234
15:01:33 &peergrouper.machine{id: "12", wantsVote: true, addresses: [public:0.1.2.12]}: rs_id=2, rs_addr=0.1.2.12:1234
15:01:33 [LOG] 0:00.002 DEBUG juju.worker.peergrouper assessing possible peer group changes:
15:01:33 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "10" is already voting
15:01:33 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "11" is a potential voter
15:01:33 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "12" is a potential voter
15:01:33 [LOG] 0:00.002 DEBUG juju.worker.peergrouper assessed
15:01:33 [LOG] 0:00.002 DEBUG juju.worker.peergrouper number of voters is odd
15:01:33 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "10" selected address "0.1.2.10:1234" by scope from [0.1.2.10:1234]
15:01:33 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "11" selected address "0.1.2.11:1234" by scope from [0.1.2.11:1234]
15:01:33 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "12" selected address "0.1.2.12:1234" by scope from [0.1.2.12:1234]
15:01:33 [LOG] 0:00.002 DEBUG juju.worker.peergrouper desired peer group members:
15:01:33 Id: 0, Tags: map[juju-machine-id:10], voting
15:01:33 Id: 1, Tags: map[juju-machine-id:11], voting
15:01:33 Id: 2, Tags: map[juju-machine-id:12], voting
15:01:33 [LOG] 0:00.002 INFO juju.worker.peergrouper setting HasVote=true on machines [11 12]
15:01:33 [LOG] 0:00.002 INFO juju.worker.peergrouper setting replicaset members to
15:01:33 Id: 0, Tags: map[juju-machine-id:10], voting
15:01:33 Id: 1, Tags: map[juju-machine-id:11], voting
15:01:33 Id: 2, Tags: map[juju-machine-id:12], voting
15:01:33 [LOG] 0:00.003 INFO juju.worker.peergrouper successfully updated replica set
15:01:33 [LOG] 0:00.003 TRACE juju.worker.peergrouper succeeded, waking up after: 1m0s
15:01:33 [LOG] 0:00.003 TRACE juju.worker.peergrouper waiting...
15:01:33 mustNext status ok
15:01:33 mustNext status ok done, ok: true, val:
15:01:33 Id: 0, Tags: map[juju-machine-id:10], voting
15:01:33 Id: 1, Tags: map[juju-machine-id:11], voting
15:01:33 Id: 2, Tags: map[juju-machine-id:12], voting
15:01:33 mustNextStatus init
15:01:33 mustNextStatus init done, ok: true, val: &replicaset.Status{
15:01:33 Name: "",
15:01:33 Members: {
15:01:33 {Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
15:01:33 {Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:01:33 {Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:01:33 },
15:01:33 }
15:01:33 mustNextStatus stepping down primary
15:01:33 [LOG] 0:00.111 TRACE juju.worker.peergrouper <-updateChan
15:01:33 [LOG] 0:00.113 TRACE juju.worker.peergrouper read peer group info: &replicaset.Status{
15:01:33 Name: "",
15:01:33 Members: {
15:01:33 {Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
15:01:33 {Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:01:33 {Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:01:33 },
15:01:33 }
15:01:33 []replicaset.Member{
15:01:33 {
15:01:33 Id: 1,
15:01:33 Address: "0.1.2.11:1234",
15:01:33 Priority: (*float64)(nil),
15:01:33 Tags: {"juju-machine-id":"11"},
15:01:33 Votes: (*int)(nil),
15:01:33 },
15:01:33 {
15:01:33 Id: 2,
15:01:33 Address: "0.1.2.12:1234",
15:01:33 Priority: (*float64)(nil),
15:01:33 Tags: {"juju-machine-id":"12"},
15:01:33 Votes: (*int)(nil),
15:01:33 },
15:01:33 {
15:01:33 Id: 0,
15:01:33 Address: "0.1.2.10:1234",
15:01:33 Priority: (*float64)(nil),
15:01:33 Tags: {"juju-machine-id":"10"},
15:01:33 Votes: (*int)(nil),
15:01:33 },
15:01:33 }
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper calculating desired peer group
15:01:33 desired voting members: (maxId: 2)
15:01:33 &peergrouper.machine{id: "10", wantsVote: false, addresses: [public:0.1.2.10]}: rs_id=0, rs_addr=0.1.2.10:1234
15:01:33 &peergrouper.machine{id: "11", wantsVote: true, addresses: [public:0.1.2.11]}: rs_id=1, rs_addr=0.1.2.11:1234
15:01:33 &peergrouper.machine{id: "12", wantsVote: true, addresses: [public:0.1.2.12]}: rs_id=2, rs_addr=0.1.2.12:1234
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper assessing possible peer group changes:
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper primary machine "10" is a potential non-voter
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper machine "11" is already voting
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper machine "12" is already voting
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper assessed
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper removing vote from "11" to maintain odd number of voters
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper machine "10" selected address "0.1.2.10:1234" by scope from [0.1.2.10:1234]
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper machine "11" selected address "0.1.2.11:1234" by scope from [0.1.2.11:1234]
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper machine "12" selected address "0.1.2.12:1234" by scope from [0.1.2.12:1234]
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper desired peer group members:
15:01:33 Id: 0, Tags: map[juju-machine-id:10], not-voting
15:01:33 Id: 1, Tags: map[juju-machine-id:11], not-voting
15:01:33 Id: 2, Tags: map[juju-machine-id:12], voting
15:01:33 [LOG] 0:00.113 INFO juju.worker.peergrouper mongo primary machine needs to be removed, first requesting it to step down
15:01:33 [LOG] 0:00.113 DEBUG juju.worker.peergrouper StepDownPrimary
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper StepDownPrimary nominated 2 to be the new primary from: [0: current primary 1: eligible secondary 2: eligible secondary]
15:01:33 [LOG] 0:00.114 TRACE juju.worker.peergrouper failed, waking up after: 2s
15:01:33 [LOG] 0:00.114 TRACE juju.worker.peergrouper waiting...
15:01:33 [LOG] 0:00.114 TRACE juju.worker.peergrouper <-w.machineChanges
15:01:33 [LOG] 0:00.114 TRACE juju.worker.peergrouper read peer group info: &replicaset.Status{
15:01:33 Name: "",
15:01:33 Members: {
15:01:33 {Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:01:33 {Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:01:33 {Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
15:01:33 },
15:01:33 }
15:01:33 []replicaset.Member{
15:01:33 {
15:01:33 Id: 1,
15:01:33 Address: "0.1.2.11:1234",
15:01:33 Priority: (*float64)(nil),
15:01:33 Tags: {"juju-machine-id":"11"},
15:01:33 Votes: (*int)(nil),
15:01:33 },
15:01:33 {
15:01:33 Id: 2,
15:01:33 Address: "0.1.2.12:1234",
15:01:33 Priority: (*float64)(nil),
15:01:33 Tags: {"juju-machine-id":"12"},
15:01:33 Votes: (*int)(nil),
15:01:33 },
15:01:33 {
15:01:33 Id: 0,
15:01:33 Address: "0.1.2.10:1234",
15:01:33 Priority: (*float64)(nil),
15:01:33 Tags: {"juju-machine-id":"10"},
15:01:33 Votes: (*int)(nil),
15:01:33 },
15:01:33 }
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper calculating desired peer group
15:01:33 desired voting members: (maxId: 2)
15:01:33 &peergrouper.machine{id: "10", wantsVote: false, addresses: [public:0.1.2.10]}: rs_id=0, rs_addr=0.1.2.10:1234
15:01:33 &peergrouper.machine{id: "11", wantsVote: true, addresses: [public:0.1.2.11]}: rs_id=1, rs_addr=0.1.2.11:1234
15:01:33 &peergrouper.machine{id: "12", wantsVote: true, addresses: [public:0.1.2.12]}: rs_id=2, rs_addr=0.1.2.12:1234
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper assessing possible peer group changes:
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper machine "10" is a potential non-voter
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper machine "11" is already voting
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper machine "12" is already voting
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper assessed
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper removing vote from "11" to maintain odd number of voters
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper machine "10" selected address "0.1.2.10:1234" by scope from [0.1.2.10:1234]
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper machine "11" selected address "0.1.2.11:1234" by scope from [0.1.2.11:1234]
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper machine "12" selected address "0.1.2.12:1234" by scope from [0.1.2.12:1234]
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper desired peer group members:
15:01:33 Id: 0, Tags: map[juju-machine-id:10], not-voting
15:01:33 Id: 1, Tags: map[juju-machine-id:11], not-voting
15:01:33 Id: 2, Tags: map[juju-machine-id:12], voting
15:01:33 [LOG] 0:00.114 INFO juju.worker.peergrouper setting replicaset members to
15:01:33 Id: 0, Tags: map[juju-machine-id:10], not-voting
15:01:33 Id: 1, Tags: map[juju-machine-id:11], not-voting
15:01:33 Id: 2, Tags: map[juju-machine-id:12], voting
15:01:33 [LOG] 0:00.114 INFO juju.worker.peergrouper successfully updated replica set
15:01:33 [LOG] 0:00.114 INFO juju.worker.peergrouper setting HasVote=false on machines [10 11]
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper vote removed from 10 but machine is alive
15:01:33 [LOG] 0:00.114 DEBUG juju.worker.peergrouper vote removed from 11 but machine is alive
15:01:33 [LOG] 0:00.114 TRACE juju.worker.peergrouper succeeded, waking up after: 1m0s
15:01:33 [LOG] 0:00.114 TRACE juju.worker.peergrouper waiting...
15:01:33 mustNextStatus stepping down primary done, ok: true, val: &replicaset.Status{
15:01:33 Name: "",
15:01:33 Members: {
15:01:33 {Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:01:33 {Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:01:33 {Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
15:01:33 },
15:01:33 }
15:01:33 worker_test.go:920:
15:01:33 // Now we have to wait for time to advance for us to reevaluate the system
15:01:33 c.Assert(s.clock.WaitAdvance(2*pollInterval, coretesting.ShortWait, 2), jc.ErrorIsNil)
15:01:33 ... value *errors.Err = &errors.unformatter{message:"got 1 timers added after waiting 50ms: wanted 2", cause:error(nil), previous:error(nil), file:"github.com/juju/juju/vendor/github.com/juju/clock/testclock/clock.go", line:134} ()
15:01:33 ... error stack:
15:01:33 github.com/juju/juju/vendor/github.com/juju/clock/testclock/clock.go:134: got 1 timers added after waiting 50ms: wanted 2
15:01:33
15:01:33