APIAddressUpdaterSuite.TestAddressChange

After running under stress, this test failed on 10th attempt:

FAIL: apiaddressupdater_test.go:90: APIAddressUpdaterSuite.TestAddressChange

[LOG] 0:00.058 DEBUG juju.environs.tools reading v1.* agent binaries
[LOG] 0:00.059 INFO juju.environs.testing uploading FAKE tools 2.7-beta1-bionic-amd64
[LOG] 0:00.084 INFO juju.environs.testing uploading FAKE tools 2.7-beta1-precise-amd64
[LOG] 0:00.100 INFO juju.environs.testing uploading FAKE tools 2.7-beta1-trusty-amd64
[LOG] 0:00.115 INFO juju.environs.testing uploading FAKE tools 2.7-beta1-xenial-amd64
[LOG] 0:00.141 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.142 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.142 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
[LOG] 0:00.205 DEBUG juju.environs.tools reading v1.* agent binaries
[LOG] 0:00.205 INFO juju.environs.testing uploading FAKE tools 2.7-beta1-bionic-amd64
[LOG] 0:00.221 INFO juju.environs.testing uploading FAKE tools 2.7-beta1-precise-amd64
[LOG] 0:00.242 INFO juju.environs.testing uploading FAKE tools 2.7-beta1-trusty-amd64
[LOG] 0:00.257 INFO juju.environs.testing uploading FAKE tools 2.7-beta1-xenial-amd64
[LOG] 0:00.291 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-2156753143034797682/5/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.295 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-2156753143034797682/5/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.298 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-2156753143034797682/5/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.305 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.306 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.307 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-devel-tools.json
[LOG] 0:00.392 DEBUG juju.environs.bootstrap model "controller" supports application/machine networks: true
[LOG] 0:00.392 DEBUG juju.environs.bootstrap network management by juju enabled: true
[LOG] 0:00.393 INFO cmd Loading image metadata
[LOG] 0:00.394 INFO juju.environs.bootstrap looking for bootstrap agent binaries: version=2.7-beta1
[LOG] 0:00.394 DEBUG juju.environs.tools finding agent binaries in stream: "devel, proposed, released"
[LOG] 0:00.394 DEBUG juju.environs.tools reading agent binaries with major.minor version 2.7
[LOG] 0:00.395 DEBUG juju.environs.tools filtering agent binaries by version: 2.7-beta1
[LOG] 0:00.395 DEBUG juju.environs.tools filtering agent binaries by architecture: amd64
[LOG] 0:00.422 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-2156753143034797682/5/tools/streams/v1/index2.sjson" because of missing information: "content-download" data not found
[LOG] 0:00.441 INFO juju.environs.bootstrap found 4 packaged agent binaries
[LOG] 0:00.449 INFO cmd Starting new instance for initial controller
[LOG] 0:00.450 INFO juju.provider.dummy would pick agent binaries from 2.7-beta1-bionic-amd64
[LOG] 0:00.450 INFO juju.provider.dummy creating bootstrap instance
[LOG] 0:00.450 INFO juju.environs.bootstrap newest version: 2.7-beta1
[LOG] 0:00.450 INFO juju.environs.bootstrap picked bootstrap agent binary version: 2.7-beta1
[LOG] 0:00.570 DEBUG juju.cloudconfig.instancecfg Setting numa ctl preference to false
[LOG] 0:00.575 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:00.578 INFO juju.state using client-side transactions
[LOG] 0:00.768 INFO juju.state controller settings not found, early stage initialization assumed
[LOG] 0:00.768 DEBUG juju.state mongodb initialised
[LOG] 0:00.769 INFO juju.state running state anonymously; using unique store id
[LOG] 0:00.769 INFO juju.state starting standard state workers
[LOG] 0:00.772 INFO juju.state creating cloud image metadata storage
[LOG] 0:00.773 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
[LOG] 0:00.773 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:00.775 DEBUG juju.state.presence using $bit operations with Mongo 3.6.3
[LOG] 0:00.776 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:00.776 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:00.777 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:00.780 INFO juju.state initializing controller model deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.783 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:00.994 INFO juju.state creating logs collection for deadbeef-0bad-400d-8000-4b1d0d06f00d, capped at 1 MiB
[LOG] 0:01.623 DEBUG juju.provider.dummy setting password for "admin" to "dummy-secret"
[LOG] 0:01.912 WARNING juju.apiserver.logsink Unable to prime /tmp/check-2156753143034797682/4/logsink.log (proceeding anyway): chown /tmp/check-2156753143034797682/4/logsink.log: operation not permitted
[LOG] 0:01.974 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:02.213 INFO juju.state using client-side transactions
[LOG] 0:02.215 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:02.448 INFO juju.state starting standard state workers
[LOG] 0:02.451 INFO juju.state creating cloud image metadata storage
[LOG] 0:02.451 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
[LOG] 0:02.452 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:02.453 DEBUG juju.state.presence using $bit operations with Mongo 3.6.3
[LOG] 0:02.453 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:02.453 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:02.456 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:02.461 DEBUG juju.api looked up localhost -> [127.0.0.1]
[LOG] 0:02.500 DEBUG juju.apiserver [1] API connection from 127.0.0.1:46122
[LOG] 0:02.501 DEBUG juju.api successfully dialed "wss://localhost:42943/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:02.502 INFO juju.api connection established to "wss://localhost:42943/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:02.506 DEBUG juju.apiserver <- [1] {"request-id":1,"type":"Admin","version":3,"request":"Login","params":"'params redacted'"}
[LOG] 0:02.541 DEBUG juju.apiserver model login: user admin has "superuser" for controller; "admin" for model deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:02.541 DEBUG juju.apiserver model login: user-admin for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:02.545 DEBUG juju.apiserver -> [1] 39.336814ms {"request-id":1,"response":"'body redacted'"} Admin[""].Login
[LOG] 0:02.565 DEBUG juju.state setting apiHostPorts: [[localhost:42943]]
[LOG] 0:02.567 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:02.718 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:42549"
[LOG] 0:02.807 DEBUG juju.state setting apiHostPortsForAgents: [[localhost:42943]]
[LOG] 0:02.909 DEBUG juju.state setting apiHostPorts: []
[LOG] 0:02.913 DEBUG juju.state setting apiHostPortsForAgents: []
[LOG] 0:02.990 INFO juju.state new machine "0" has preferred addresses: private "", public ""
[LOG] 0:03.169 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:03.176 DEBUG juju.api looked up localhost -> [127.0.0.1]
[LOG] 0:03.216 DEBUG juju.apiserver [2] API connection from 127.0.0.1:46128
[LOG] 0:03.217 DEBUG juju.api successfully dialed "wss://localhost:42943/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.218 INFO juju.api connection established to "wss://localhost:42943/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.224 DEBUG juju.apiserver <- [2] {"request-id":1,"type":"Admin","version":3,"request":"Login","params":"'params redacted'"}
[LOG] 0:03.345 INFO juju.apiserver.connection agent login: machine-0 for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:03.347 DEBUG juju.apiserver model login: machine-0 for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:03.351 DEBUG juju.apiserver -> [2] 127.320512ms {"request-id":1,"response":"'body redacted'"} Admin[""].Login
[LOG] 0:03.368 DEBUG juju.apiserver <- [2] machine-0 {"request-id":2,"type":"Machiner","version":1,"request":"WatchAPIHostPorts","params":"'params redacted'"}
[LOG] 0:03.380 DEBUG juju.apiserver -> [2] machine-0 11.874168ms {"request-id":2,"response":"'body redacted'"} Machiner[""].WatchAPIHostPorts
[LOG] 0:03.384 DEBUG juju.apiserver <- [2] machine-0 {"request-id":3,"type":"Machiner","version":1,"request":"APIHostPorts","params":"'params redacted'"}
[LOG] 0:03.386 DEBUG juju.apiserver <- [2] machine-0 {"request-id":4,"type":"NotifyWatcher","version":1,"id":"1","request":"Next","params":"'params redacted'"}
[LOG] 0:03.390 DEBUG juju.apiserver -> [2] machine-0 5.994106ms {"request-id":3,"response":"'body redacted'"} Machiner[""].APIHostPorts
[LOG] 0:03.391 DEBUG juju.worker.apiaddressupdater updating API hostPorts to []
[LOG] 0:03.392 DEBUG juju.state setting apiHostPorts: [[localhost:1234 127.0.0.1:1234]]
[LOG] 0:03.393 DEBUG juju.apiserver -> [2] machine-0 6.79924ms {"request-id":4,"response":"'body redacted'"} NotifyWatcher["1"].Next
[LOG] 0:03.395 DEBUG juju.apiserver <- [2] machine-0 {"request-id":5,"type":"NotifyWatcher","version":1,"id":"1","request":"Next","params":"'params redacted'"}
[LOG] 0:03.396 DEBUG juju.apiserver <- [2] machine-0 {"request-id":6,"type":"Machiner","version":1,"request":"APIHostPorts","params":"'params redacted'"}
[LOG] 0:03.397 DEBUG juju.state setting apiHostPortsForAgents: [[localhost:1234 127.0.0.1:1234]]
[LOG] 0:03.401 DEBUG juju.apiserver -> [2] machine-0 4.926289ms {"request-id":6,"response":"'body redacted'"} Machiner[""].APIHostPorts
[LOG] 0:03.402 DEBUG juju.worker.apiaddressupdater updating API hostPorts to []
apiaddressupdater_test.go:116:
    c.Assert(servers, gc.DeepEquals, updatedServers)
... obtained [][]network.HostPort = [][]network.HostPort{}
... expected [][]network.HostPort = [][]network.HostPort{[]network.HostPort{localhost:1234, 127.0.0.1:1234}}

[LOG] 0:03.448 DEBUG juju.apiserver <- [2] machine-0 {"request-id":7,"type":"NotifyWatcher","version":1,"id":"1","request":"Stop","params":"'params redacted'"}
[LOG] 0:03.449 DEBUG juju.apiserver -> [2] machine-0 1.309321ms {"request-id":7,"response":"'body redacted'"} NotifyWatcher["1"].Stop
[LOG] 0:03.449 DEBUG juju.apiserver -> [2] machine-0 54.030853ms {"request-id":5,"error":"watcher has been stopped","error-code":"stopped","response":"'body redacted'"} NotifyWatcher["1"].Next
[LOG] 0:03.452 DEBUG juju.api RPC connection died
[LOG] 0:03.453 DEBUG juju.rpc error closing codec: write tcp 127.0.0.1:42943->127.0.0.1:46128: write: broken pipe
[LOG] 0:03.454 INFO juju.apiserver.connection agent disconnected: machine-0 for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:03.454 DEBUG juju.rpc error closing codec: write tcp 127.0.0.1:42943->127.0.0.1:46122: write: broken pipe
[LOG] 0:03.454 DEBUG juju.apiserver [1] user-admin API connection terminated after 954.357027ms
[LOG] 0:03.456 DEBUG juju.apiserver [2] machine-0 API connection terminated after 240.147855ms
[LOG] 0:03.458 DEBUG juju.state closed state without error
[LOG] 0:03.458 INFO juju.provider.dummy reset model
[LOG] 0:03.458 DEBUG juju.provider.dummy closing httpServer
[LOG] 0:03.459 DEBUG juju.provider.dummy stopping apiServer
[LOG] 0:03.506 DEBUG juju.provider.dummy stopping modelCache worker
[LOG] 0:03.507 DEBUG juju.provider.dummy closing apiStatePool
[LOG] 0:03.511 DEBUG juju.state closed state without error
[LOG] 0:03.511 DEBUG juju.provider.dummy resetting MgoServer
[LOG] 0:03.518 INFO juju.testing reset successfully reset admin password
[LOG] 0:03.596 INFO juju.testing reset successfully reset admin password