Canonical Juju

TestDyingMachinesAreRemoved intermittent failure, expect 3 found 2.

Bug #1803778 reported by Canonical Juju QA Bot
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Canonical Juju
Fix Released
Medium
Anastasia
Canonical Juju 2.6-rc1

Bug Description

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

15:04:50 FAIL: worker_test.go:919: workerSuite.TestDyingMachinesAreRemoved
15:04:50
15:04:50 [LOG] 0:00.000 INFO juju.worker.peergrouper fakeState.addMachine "10"
15:04:50 [LOG] 0:00.000 INFO juju.worker.peergrouper setting replicaset members to
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 mustNext init
15:04:50 mustNext init done, ok: true, val:
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 [LOG] 0:00.001 INFO juju.worker.peergrouper fakeState.addMachine "11"
15:04:50 [LOG] 0:00.001 TRACE juju.worker.peergrouper waiting...
15:04:50 [LOG] 0:00.001 INFO juju.worker.peergrouper fakeState.addMachine "12"
15:04:50 mustNext nonvoting members
15:04:50 [LOG] 0:00.002 TRACE juju.worker.peergrouper <-w.configChanges
15:04:50 [LOG] 0:00.002 TRACE juju.worker.peergrouper no controller information, ignoring config change
15:04:50 [LOG] 0:00.002 TRACE juju.worker.peergrouper waiting...
15:04:50 [LOG] 0:00.002 TRACE juju.worker.peergrouper <-controllerChanges
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper controller machines in state: []string{"10", "11", "12"}
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper found new machine "10"
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "10" has started, adding it to peergrouper list
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper found new machine "11"
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "11" has started, adding it to peergrouper list
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper found new machine "12"
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "12" has started, adding it to peergrouper list
15:04:50 [LOG] 0:00.002 TRACE juju.worker.peergrouper controller added or removed, update replica now
15:04:50 [LOG] 0:00.002 TRACE juju.worker.peergrouper read peer group info: &replicaset.Status{
15:04:50 Name: "",
15:04:50 Members: {
15:04:50 {Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
15:04:50 {Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:6, Uptime:0, Ping:0},
15:04:50 {Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:6, Uptime:0, Ping:0},
15:04:50 },
15:04:50 }
15:04:50 []replicaset.Member{
15:04:50 {
15:04:50 Id: 0,
15:04:50 Address: "0.1.2.10:1234",
15:04:50 Priority: (*float64)(nil),
15:04:50 Tags: {"juju-machine-id":"10"},
15:04:50 Votes: (*int)(nil),
15:04:50 },
15:04:50 }
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper calculating desired peer group
15:04:50 desired voting members: (maxId: 0)
15:04:50 &peergrouper.machine{id: "10", wantsVote: true, addresses: [public:0.1.2.10]}: rs_id=0, rs_addr=0.1.2.10:1234
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper assessing possible peer group changes:
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "10" is already voting
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "11" does not exist and is not ready (status: STARTUP, healthy: false)
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper machine "12" does not exist and is not ready (status: STARTUP, healthy: false)
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper assessed
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper number of voters is odd
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper create member with id "11"
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper create member with id "12"
15:04:50 [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:04:50 [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:04:50 [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:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper desired peer group members:
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 Id: 1, Tags: map[juju-machine-id:11], not-voting
15:04:50 Id: 2, Tags: map[juju-machine-id:12], not-voting
15:04:50 [LOG] 0:00.002 INFO juju.worker.peergrouper setting replicaset members to
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 Id: 1, Tags: map[juju-machine-id:11], not-voting
15:04:50 Id: 2, Tags: map[juju-machine-id:12], not-voting
15:04:50 [LOG] 0:00.002 INFO juju.worker.peergrouper successfully updated replica set
15:04:50 [LOG] 0:00.002 TRACE juju.worker.peergrouper succeeded, waking up after: 1m0s
15:04:50 [LOG] 0:00.002 TRACE juju.worker.peergrouper waiting...
15:04:50 [LOG] 0:00.002 TRACE juju.worker.peergrouper <-controllerChanges
15:04:50 [LOG] 0:00.002 DEBUG juju.worker.peergrouper controller machines in state: []string{"10", "11", "12"}
15:04:50 [LOG] 0:00.002 TRACE juju.worker.peergrouper waiting...
15:04:50 mustNext nonvoting members done, ok: true, val:
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 Id: 1, Tags: map[juju-machine-id:11], not-voting
15:04:50 Id: 2, Tags: map[juju-machine-id:12], not-voting
15:04:50 mustNext status ok
15:04:50 [LOG] 0:00.003 TRACE juju.worker.peergrouper <-updateChan
15:04:50 [LOG] 0:00.003 TRACE juju.worker.peergrouper read peer group info: &replicaset.Status{
15:04:50 Name: "",
15:04:50 Members: {
15:04:50 {Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
15:04:50 {Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:04:50 {Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:04:50 },
15:04:50 }
15:04:50 []replicaset.Member{
15:04:50 {
15:04:50 Id: 0,
15:04:50 Address: "0.1.2.10:1234",
15:04:50 Priority: (*float64)(nil),
15:04:50 Tags: {"juju-machine-id":"10"},
15:04:50 Votes: (*int)(nil),
15:04:50 },
15:04:50 {
15:04:50 Id: 1,
15:04:50 Address: "0.1.2.11:1234",
15:04:50 Priority: &float64(0),
15:04:50 Tags: {"juju-machine-id":"11"},
15:04:50 Votes: &int(0),
15:04:50 },
15:04:50 {
15:04:50 Id: 2,
15:04:50 Address: "0.1.2.12:1234",
15:04:50 Priority: &float64(0),
15:04:50 Tags: {"juju-machine-id":"12"},
15:04:50 Votes: &int(0),
15:04:50 },
15:04:50 }
15:04:50 [LOG] 0:00.003 DEBUG juju.worker.peergrouper calculating desired peer group
15:04:50 desired voting members: (maxId: 2)
15:04:50 &peergrouper.machine{id: "10", wantsVote: true, addresses: [public:0.1.2.10]}: rs_id=0, rs_addr=0.1.2.10:1234
15:04:50 &peergrouper.machine{id: "11", wantsVote: true, addresses: [public:0.1.2.11]}: rs_id=1, rs_addr=0.1.2.11:1234
15:04:50 &peergrouper.machine{id: "12", wantsVote: true, addresses: [public:0.1.2.12]}: rs_id=2, rs_addr=0.1.2.12:1234
15:04:50 [LOG] 0:00.003 DEBUG juju.worker.peergrouper assessing possible peer group changes:
15:04:50 [LOG] 0:00.003 DEBUG juju.worker.peergrouper machine "10" is already voting
15:04:50 [LOG] 0:00.003 DEBUG juju.worker.peergrouper machine "11" is a potential voter
15:04:50 [LOG] 0:00.003 DEBUG juju.worker.peergrouper machine "12" is a potential voter
15:04:50 [LOG] 0:00.003 DEBUG juju.worker.peergrouper assessed
15:04:50 [LOG] 0:00.003 DEBUG juju.worker.peergrouper number of voters is odd
15:04:50 [LOG] 0:00.003 DEBUG juju.worker.peergrouper machine "10" selected address "0.1.2.10:1234" by scope from [0.1.2.10:1234]
15:04:50 [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]
15:04:50 [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]
15:04:50 [LOG] 0:00.003 DEBUG juju.worker.peergrouper desired peer group members:
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 Id: 1, Tags: map[juju-machine-id:11], voting
15:04:50 Id: 2, Tags: map[juju-machine-id:12], voting
15:04:50 [LOG] 0:00.003 INFO juju.worker.peergrouper setting HasVote=true on machines [11 12]
15:04:50 [LOG] 0:00.003 INFO juju.worker.peergrouper setting replicaset members to
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 Id: 1, Tags: map[juju-machine-id:11], voting
15:04:50 Id: 2, Tags: map[juju-machine-id:12], voting
15:04:50 [LOG] 0:00.003 INFO juju.worker.peergrouper successfully updated replica set
15:04:50 [LOG] 0:00.003 TRACE juju.worker.peergrouper succeeded, waking up after: 1m0s
15:04:50 [LOG] 0:00.003 TRACE juju.worker.peergrouper waiting...
15:04:50 mustNext status ok done, ok: true, val:
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 Id: 1, Tags: map[juju-machine-id:11], voting
15:04:50 Id: 2, Tags: map[juju-machine-id:12], voting
15:04:50 [LOG] 0:00.003 TRACE juju.worker.peergrouper <-w.machineChanges
15:04:50 [LOG] 0:00.004 TRACE juju.worker.peergrouper read peer group info: &replicaset.Status{
15:04:50 Name: "",
15:04:50 Members: {
15:04:50 {Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
15:04:50 {Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:04:50 {Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:04:50 },
15:04:50 }
15:04:50 []replicaset.Member{
15:04:50 {
15:04:50 Id: 0,
15:04:50 Address: "0.1.2.10:1234",
15:04:50 Priority: (*float64)(nil),
15:04:50 Tags: {"juju-machine-id":"10"},
15:04:50 Votes: (*int)(nil),
15:04:50 },
15:04:50 {
15:04:50 Id: 1,
15:04:50 Address: "0.1.2.11:1234",
15:04:50 Priority: (*float64)(nil),
15:04:50 Tags: {"juju-machine-id":"11"},
15:04:50 Votes: (*int)(nil),
15:04:50 },
15:04:50 {
15:04:50 Id: 2,
15:04:50 Address: "0.1.2.12:1234",
15:04:50 Priority: (*float64)(nil),
15:04:50 Tags: {"juju-machine-id":"12"},
15:04:50 Votes: (*int)(nil),
15:04:50 },
15:04:50 }
15:04:50 [LOG] 0:00.004 DEBUG juju.worker.peergrouper calculating desired peer group
15:04:50 desired voting members: (maxId: 2)
15:04:50 &peergrouper.machine{id: "10", wantsVote: true, addresses: [public:0.1.2.10]}: rs_id=0, rs_addr=0.1.2.10:1234
15:04:50 &peergrouper.machine{id: "11", wantsVote: false, addresses: [public:0.1.2.11]}: rs_id=1, rs_addr=0.1.2.11:1234
15:04:50 &peergrouper.machine{id: "12", wantsVote: true, addresses: [public:0.1.2.12]}: rs_id=2, rs_addr=0.1.2.12:1234
15:04:50 [LOG] 0:00.004 DEBUG juju.worker.peergrouper assessing possible peer group changes:
15:04:50 [LOG] 0:00.004 DEBUG juju.worker.peergrouper machine "10" is already voting
15:04:50 [LOG] 0:00.004 DEBUG juju.worker.peergrouper machine "11" is a potential non-voter
15:04:50 [LOG] 0:00.004 DEBUG juju.worker.peergrouper machine "12" is already voting
15:04:50 [LOG] 0:00.004 DEBUG juju.worker.peergrouper assessed
15:04:50 [LOG] 0:00.004 DEBUG juju.worker.peergrouper removing vote from "12" to maintain odd number of voters
15:04:50 [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]
15:04:50 [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]
15:04:50 [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]
15:04:50 [LOG] 0:00.004 DEBUG juju.worker.peergrouper desired peer group members:
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 Id: 1, Tags: map[juju-machine-id:11], not-voting
15:04:50 Id: 2, Tags: map[juju-machine-id:12], not-voting
15:04:50 [LOG] 0:00.004 INFO juju.worker.peergrouper setting replicaset members to
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 Id: 1, Tags: map[juju-machine-id:11], not-voting
15:04:50 Id: 2, Tags: map[juju-machine-id:12], not-voting
15:04:50 [LOG] 0:00.004 INFO juju.worker.peergrouper successfully updated replica set
15:04:50 [LOG] 0:00.004 INFO juju.worker.peergrouper setting HasVote=false on machines [11 12]
15:04:50 [LOG] 0:00.004 DEBUG juju.worker.peergrouper removing dying controller machine 11
15:04:50 [LOG] 0:00.004 DEBUG juju.worker.peergrouper vote removed from 12 but machine is alive
15:04:50 [LOG] 0:00.004 TRACE juju.worker.peergrouper succeeded, waking up after: 1m0s
15:04:50 [LOG] 0:00.004 TRACE juju.worker.peergrouper waiting...
15:04:50 [LOG] 0:00.004 TRACE juju.worker.peergrouper <-controllerChanges
15:04:50 [LOG] 0:00.004 DEBUG juju.worker.peergrouper controller machines in state: []string{"10", "12"}
15:04:50 [LOG] 0:00.004 TRACE juju.worker.peergrouper controller added or removed, update replica now
15:04:50 [LOG] 0:00.005 TRACE juju.worker.peergrouper read peer group info: &replicaset.Status{
15:04:50 Name: "",
15:04:50 Members: {
15:04:50 {Id:0, Address:"0.1.2.10:1234", Self:false, ErrMsg:"", Healthy:true, State:1, Uptime:0, Ping:0},
15:04:50 {Id:1, Address:"0.1.2.11:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:04:50 {Id:2, Address:"0.1.2.12:1234", Self:false, ErrMsg:"", Healthy:true, State:2, Uptime:0, Ping:0},
15:04:50 },
15:04:50 }
15:04:50 []replicaset.Member{
15:04:50 {
15:04:50 Id: 2,
15:04:50 Address: "0.1.2.12:1234",
15:04:50 Priority: &float64(0),
15:04:50 Tags: {"juju-machine-id":"12"},
15:04:50 Votes: &int(0),
15:04:50 },
15:04:50 {
15:04:50 Id: 0,
15:04:50 Address: "0.1.2.10:1234",
15:04:50 Priority: (*float64)(nil),
15:04:50 Tags: {"juju-machine-id":"10"},
15:04:50 Votes: (*int)(nil),
15:04:50 },
15:04:50 {
15:04:50 Id: 1,
15:04:50 Address: "0.1.2.11:1234",
15:04:50 Priority: &float64(0),
15:04:50 Tags: {"juju-machine-id":"11"},
15:04:50 Votes: &int(0),
15:04:50 },
15:04:50 }
15:04:50 [LOG] 0:00.005 DEBUG juju.worker.peergrouper calculating desired peer group
15:04:50 desired voting members: (maxId: 2)
15:04:50 &peergrouper.machine{id: "10", wantsVote: true, addresses: [public:0.1.2.10]}: rs_id=0, rs_addr=0.1.2.10:1234
15:04:50 &peergrouper.machine{id: "12", wantsVote: true, addresses: [public:0.1.2.12]}: rs_id=2, rs_addr=0.1.2.12:1234
15:04:50 other members:
15:04:50 rs_id=1, rs_addr=0.1.2.11:1234, tags=map[juju-machine-id:11], vote=false
15:04:50 [LOG] 0:00.005 DEBUG juju.worker.peergrouper assessing possible peer group changes:
15:04:50 [LOG] 0:00.005 DEBUG juju.worker.peergrouper machine "10" is already voting
15:04:50 [LOG] 0:00.005 DEBUG juju.worker.peergrouper machine "12" is a potential voter
15:04:50 [LOG] 0:00.005 DEBUG juju.worker.peergrouper assessed
15:04:50 [LOG] 0:00.005 DEBUG juju.worker.peergrouper number of voters would be even, not adding "12" to maintain odd
15:04:50 [LOG] 0:00.005 DEBUG juju.worker.peergrouper machine "10" selected address "0.1.2.10:1234" by scope from [0.1.2.10:1234]
15:04:50 [LOG] 0:00.005 DEBUG juju.worker.peergrouper machine "12" selected address "0.1.2.12:1234" by scope from [0.1.2.12:1234]
15:04:50 [LOG] 0:00.005 DEBUG juju.worker.peergrouper desired peer group members:
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 Id: 2, Tags: map[juju-machine-id:12], not-voting
15:04:50 [LOG] 0:00.005 INFO juju.worker.peergrouper setting replicaset members to
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 Id: 2, Tags: map[juju-machine-id:12], not-voting
15:04:50 [LOG] 0:00.005 INFO juju.worker.peergrouper successfully updated replica set
15:04:50 [LOG] 0:00.005 TRACE juju.worker.peergrouper succeeded, waking up after: 1m0s
15:04:50 [LOG] 0:00.005 TRACE juju.worker.peergrouper waiting...
15:04:50 mustNext removing vote
15:04:50 mustNext removing vote done, ok: true, val:
15:04:50 Id: 0, Tags: map[juju-machine-id:10], voting
15:04:50 Id: 2, Tags: map[juju-machine-id:12], not-voting
15:04:50 worker_test.go:929:
15:04:50 assertMembers(c, memberWatcher.Value(), mkMembers("0v 1 2", testIPv4))
15:04:50 desired_test.go:628:
15:04:50 c.Assert(membersToTestMembers(obtainedMembers), jc.DeepEquals, membersToTestMembers(expected))
15:04:50 ... obtained []peergrouper.TestMember = []peergrouper.TestMember{peergrouper.TestMember{Id:0, Address:"0.1.2.10:1234", Priority:1, Tags:map[string]string{"juju-machine-id":"10"}, Votes:1}, peergrouper.TestMember{Id:2, Address:"0.1.2.12:1234", Priority:0, Tags:map[string]string{"juju-machine-id":"12"}, Votes:0}}
15:04:50 ... expected []peergrouper.TestMember = []peergrouper.TestMember{peergrouper.TestMember{Id:0, Address:"0.1.2.10:1234", Priority:1, Tags:map[string]string{"juju-machine-id":"10"}, Votes:1}, peergrouper.TestMember{Id:1, Address:"0.1.2.11:1234", Priority:0, Tags:map[string]string{"juju-machine-id":"11"}, Votes:0}, peergrouper.TestMember{Id:2, Address:"0.1.2.12:1234", Priority:0, Tags:map[string]string{"juju-machine-id":"12"}, Votes:0}}
15:04:50 ... mismatch at top level: length mismatch, 2 vs 3; obtained []peergrouper.TestMember{peergrouper.TestMember{Id:0, Address:"0.1.2.10:1234", Priority:1, Tags:map[string]string{"juju-machine-id":"10"}, Votes:1}, peergrouper.TestMember{Id:2, Address:"0.1.2.12:1234", Priority:0, Tags:map[string]string{"juju-machine-id":"12"}, Votes:0}}; expected []peergrouper.TestMember{peergrouper.TestMember{Id:0, Address:"0.1.2.10:1234", Priority:1, Tags:map[string]string{"juju-machine-id":"10"}, Votes:1}, peergrouper.TestMember{Id:1, Address:"0.1.2.11:1234", Priority:0, Tags:map[string]string{"juju-machine-id":"11"}, Votes:0}, peergrouper.TestMember{Id:2, Address:"0.1.2.12:1234", Priority:0, Tags:map[string]string{"juju-machine-id":"12"}, Votes:0}}
15:04:50

Revision history for this message
Anastasia (anastasia-macmood) wrote :

There have been a bit of renovations done in the destruction area since
this bug was filed and this failure was observed.

I have run this test under stress locally 116 times and could not
reproduce. I'll mark as Fix Committed for 2.6-rc1.

If we observe further failures in this test, we'd need a new report
anyway due to all the internal changes.

Changed in juju:
status: Triaged → Fix Committed
assignee: nobody → Anastasia (anastasia-macmood)
milestone: none → 2.6-rc1
Anastasia (anastasia-macmood)
Changed in juju:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

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