----------------------------------------------------------------------
FAIL: upgrade_test.go:86: upgradeSuite.TestLoginsDuringUpgrade

[LOG] 0:00.001 DEBUG juju.environs.configstore Made dir /tmp/check-1487221792070852605/11/home/ubuntu/.local/share/juju/models
[LOG] 0:00.060 DEBUG juju.environs.configstore writing cache file
[LOG] 0:00.062 DEBUG juju.environs.tools reading v1.* tools
[LOG] 0:00.062 INFO juju.environs.testing uploading FAKE tools 2.0-alpha2-trusty-amd64
[LOG] 0:00.066 INFO juju.environs.testing uploading FAKE tools 2.0-alpha2-precise-amd64
[LOG] 0:00.066 INFO juju.environs.testing uploading FAKE tools 2.0-alpha2-trusty-amd64
[LOG] 0:00.067 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.067 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.067 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
[LOG] 0:00.153 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.153 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 2.0-alpha2 amd64   map[20160211:0xc20822c420]} com.ubuntu.juju:14.04:amd64:{ 2.0-alpha2 amd64   map[20160211:0xc20822c6c0]}] map[] Thu, 11 Feb 2016 13:36:25 +0000 products:1.0 com.ubuntu.juju:released:tools  }
[LOG] 0:00.154 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.154 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.154 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.154 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.154 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.154 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.154 INFO juju.environs.tools Metadata for stream "released" unchanged
[LOG] 0:00.154 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.154 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.154 DEBUG juju.environs.tools reading v1.* tools
[LOG] 0:00.154 INFO juju.environs.testing uploading FAKE tools 2.0-alpha2-trusty-amd64
[LOG] 0:00.155 INFO juju.environs.testing uploading FAKE tools 2.0-alpha2-precise-amd64
[LOG] 0:00.156 INFO juju.environs.testing uploading FAKE tools 2.0-alpha2-trusty-amd64
[LOG] 0:00.158 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.158 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 2.0-alpha2 amd64   map[20160211:0xc20882eea0]} com.ubuntu.juju:14.04:amd64:{ 2.0-alpha2 amd64   map[20160211:0xc20882f020]}] map[] Thu, 11 Feb 2016 13:36:25 +0000 products:1.0 com.ubuntu.juju:released:tools  }
[LOG] 0:00.158 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.158 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.158 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.158 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.158 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.158 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.159 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.159 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.159 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-devel-tools.json
[LOG] 0:00.275 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.276 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 2.0-alpha2 amd64   map[20160211:0xc20842fda0]} com.ubuntu.juju:14.04:amd64:{ 2.0-alpha2 amd64   map[20160211:0xc2086a8120]}] map[] Thu, 11 Feb 2016 13:36:25 +0000 products:1.0 com.ubuntu.juju:released:tools  }
[LOG] 0:00.276 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.276 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.277 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.277 DEBUG juju.environs.simplestreams skipping index "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.277 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.json"
[LOG] 0:00.278 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 2.0-alpha2 amd64   map[20160211:0xc2086c1b60]} com.ubuntu.juju:14.04:amd64:{ 2.0-alpha2 amd64   map[20160211:0xc2089c8060]}] map[] Thu, 11 Feb 2016 13:36:25 +0000 products:1.0 com.ubuntu.juju:devel:tools  }
[LOG] 0:00.278 INFO juju.environs.tools Metadata for stream "devel" unchanged
[LOG] 0:00.278 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.278 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.279 INFO juju.network setting prefer-ipv6 to true
[LOG] 0:00.279 DEBUG juju.environs.bootstrap model "dummymodel" supports service/machine networks: true
[LOG] 0:00.279 DEBUG juju.environs.bootstrap network management by juju enabled: true
[LOG] 0:00.279 INFO juju.environs.bootstrap looking for bootstrap tools: version=2.0-alpha2
[LOG] 0:00.279 INFO juju.environs.tools finding tools in stream "devel"
[LOG] 0:00.279 INFO juju.environs.tools reading tools with major.minor version 2.0
[LOG] 0:00.279 INFO juju.environs.tools filtering tools by version: 2.0-alpha2
[LOG] 0:00.279 DEBUG juju.environs.tools trying datasource "keystone catalog"
[LOG] 0:00.279 DEBUG juju.environs.simplestreams read metadata index at "file:///tmp/check-1487221792070852605/14/tools/streams/v1/index2.sjson"
[LOG] 0:00.280 DEBUG juju.environs.simplestreams metadata: &{map[com.ubuntu.juju:12.04:amd64:{ 2.0-alpha2 amd64   map[20160211:0xc2084c8660]} com.ubuntu.juju:14.04:amd64:{ 2.0-alpha2 amd64   map[20160211:0xc2084c8900]}] map[] Thu, 11 Feb 2016 13:36:25 +0000 products:1.0 com.ubuntu.juju:devel:tools  }
[LOG] 0:00.301 INFO juju.network setting prefer-ipv6 to true
[LOG] 0:00.301 INFO juju.provider.dummy would pick tools from 2.0-alpha2-trusty-amd64
[LOG] 0:00.301 INFO juju.provider.dummy creating bootstrap instance
[LOG] 0:00.301 INFO juju.state opening state, mongo addresses: ["[::1]:54849" "localhost:54849"]; entity <nil>
[LOG] 0:00.301 DEBUG juju.state dialing mongo
[LOG] 0:00.302 INFO juju.mongo dialled mongo successfully on address "[::1]:54849"
[LOG] 0:00.302 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:00.303 DEBUG juju.state connection established
[LOG] 0:00.303 DEBUG juju.state mongodb login successful
[LOG] 0:00.338 INFO juju.state initializing controller model deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.350 INFO juju.state running state anonymously; using unique client id
[LOG] 0:00.350 INFO juju.state creating lease clients as anon-ad334757-822d-4d80-854b-5f3d4b5b067c
[LOG] 0:00.351 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:00.353 INFO juju.state starting leadership lease manager
[LOG] 0:00.353 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:26.127865213 +0000 GMT
[LOG] 0:00.355 INFO juju.state starting singular lease manager
[LOG] 0:00.355 INFO juju.state creating cloud image metadata storage
[LOG] 0:00.355 INFO juju.state starting presence watcher
[LOG] 0:00.355 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:26.129929867 +0000 GMT
[LOG] 0:00.370 DEBUG juju.provider.dummy setting password for "dummy-admin" to "dummy-secret"
[LOG] 0:00.380 INFO juju.environs.bootstrap newest version: 2.0-alpha2
[LOG] 0:00.380 INFO juju.apiserver listening on "[::]:52964"
[LOG] 0:00.380 INFO juju.environs.bootstrap picked bootstrap tools version: 2.0-alpha2
[LOG] 0:00.380 INFO juju.state opening state, mongo addresses: ["[::1]:54849" "localhost:54849"]; entity <nil>
[LOG] 0:00.380 DEBUG juju.state dialing mongo
[LOG] 0:00.380 ERROR juju.apiserver Unable to prime /tmp/check-1487221792070852605/13/logsink.log (proceeding anyway): chown /tmp/check-1487221792070852605/13/logsink.log: operation not permitted
[LOG] 0:00.380 DEBUG juju.apiserver Starting API http server on address "[::]:52964"
[LOG] 0:00.381 INFO juju.mongo dialled mongo successfully on address "[::1]:54849"
[LOG] 0:00.381 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:00.381 DEBUG juju.state connection established
[LOG] 0:00.381 DEBUG juju.state mongodb login successful
[LOG] 0:00.389 INFO juju.state running state anonymously; using unique client id
[LOG] 0:00.389 INFO juju.state creating lease clients as anon-72af7578-d828-45dd-8bcf-253d0e3829f7
[LOG] 0:00.390 INFO juju.state starting leadership lease manager
[LOG] 0:00.390 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:26.164942349 +0000 GMT
[LOG] 0:00.390 INFO juju.state starting singular lease manager
[LOG] 0:00.391 INFO juju.state creating cloud image metadata storage
[LOG] 0:00.391 INFO juju.state starting presence watcher
[LOG] 0:00.391 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:26.165619418 +0000 GMT
[LOG] 0:00.405 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:00.405 WARNING juju.network no addresses found in space "default"
[LOG] 0:00.405 WARNING juju.environs using all API addresses (cannot pick by space "default"): [localhost]
[LOG] 0:00.406 INFO juju.api dialing "wss://localhost:52964/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.412 INFO juju.apiserver [D6] API connection from 127.0.0.1:54514, active connections: 1
[LOG] 0:00.412 DEBUG juju.apiserver validate model uuid: controller model - deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.412 INFO juju.api connection established to "wss://localhost:52964/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.412 DEBUG juju.apiserver <- [D6] <unknown> {"RequestId":1,"Type":"Admin","Version":2,"Request":"Login","Params":"'params redacted'"}
[LOG] 0:00.415 DEBUG juju.apiserver hostPorts: []
[LOG] 0:00.415 DEBUG juju.apiserver -> [D6] user-dummy-admin@local 2.746124ms {"RequestId":1,"Response":"'body redacted'"} Admin[""].Login
[LOG] 0:00.416 WARNING juju.network no hostPorts found in space "default"
[LOG] 0:00.416 WARNING juju.state cannot determine API addresses in space "default" to use as API endpoints; using all addresses
[LOG] 0:00.418 DEBUG juju.state setting API hostPorts: [[localhost:52964]]
[LOG] 0:00.418 DEBUG juju.environs.configstore writing cache file
jenv host ports: [][]network.HostPort{[]network.HostPort{localhost:52964}}
[LOG] 0:00.459 INFO juju.environs.testing uploading FAKE tools 1.16-alpha2-trusty-amd64
[LOG] 0:00.464 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:00.464 WARNING juju.network no addresses found in space "default"
[LOG] 0:00.464 WARNING juju.environs using all API addresses (cannot pick by space "default"): [localhost]
[LOG] 0:00.464 WARNING juju.network no hostPorts found in space "default"
[LOG] 0:00.464 WARNING juju.state cannot determine API addresses in space "default" to use as API endpoints; using all addresses
[LOG] 0:00.466 DEBUG juju.state setting API hostPorts: [[localhost:52964]]
api host ports primed []network.HostPort{localhost:52964}
priming agent machine-1
[LOG] 0:00.490 INFO juju.environs.testing uploading FAKE tools 2.0-alpha2-trusty-amd64
[LOG] 0:00.491 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.491 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.491 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
[LOG] 0:00.492 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:00.492 WARNING juju.network no addresses found in space "default"
[LOG] 0:00.492 WARNING juju.environs using all API addresses (cannot pick by space "default"): [localhost]
[LOG] 0:00.492 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:00.492 WARNING juju.network no addresses found in space "default"
[LOG] 0:00.492 WARNING juju.environs using all API addresses (cannot pick by space "default"): [localhost]
[LOG] 0:00.492 WARNING juju.network no hostPorts found in space "default"
[LOG] 0:00.492 WARNING juju.state cannot determine API addresses in space "default" to use as API endpoints; using all addresses
[LOG] 0:00.494 DEBUG juju.state setting API hostPorts: [[localhost:52964]]
api host ports primed []network.HostPort{localhost:52964}
[LOG] 0:00.494 DEBUG juju.agent read agent config, format "1.18"
[LOG] 0:00.494 DEBUG juju.agent read agent config, format "1.18"
[LOG] 0:00.494 INFO juju.cmd.jujud machine agent machine-0 start (2.0-alpha2 [gc])
[LOG] 0:00.516 INFO juju.network setting prefer-ipv6 to false
[LOG] 0:00.516 INFO juju.worker start "statestarter"
[LOG] 0:00.516 INFO juju.worker start "engine"
[LOG] 0:00.516 DEBUG juju.worker "statestarter" started
[LOG] 0:00.517 INFO juju.worker start "state"
[LOG] 0:00.517 DEBUG juju.worker.dependency "agent" manifold worker started
[LOG] 0:00.517 DEBUG juju.worker.dependency "termination" manifold worker started
[LOG] 0:00.517 DEBUG juju.worker.dependency "upgradewaiter" manifold worker stopped: dependency not available
[LOG] 0:00.517 DEBUG juju.worker.dependency "upgrader" manifold worker stopped: dependency not available
[LOG] 0:00.517 DEBUG juju.worker.dependency "apiworkers" manifold worker stopped: dependency not available
[LOG] 0:00.517 DEBUG juju.worker.dependency "serving-info-setter" manifold worker stopped: dependency not available
[LOG] 0:00.518 DEBUG juju.worker.dependency "reboot" manifold worker stopped: dependency not available
[LOG] 0:00.518 DEBUG juju.worker.dependency "logging-config-updater" manifold worker stopped: dependency not available
[LOG] 0:00.518 DEBUG juju.worker.dependency "upgrade-steps-gate" manifold worker started
[LOG] 0:00.518 INFO juju.api dialing "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.518 DEBUG juju.worker.dependency "upgradesteps" manifold worker stopped: dependency not available
[LOG] 0:00.518 INFO juju.api error dialing "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api": websocket.Dial wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api: dial tcp 127.0.0.1:49193: connection refused
[LOG] 0:00.518 DEBUG juju.worker "engine" started
[LOG] 0:00.518 DEBUG juju.worker.dependency "upgrade-check-gate" manifold worker started
[LOG] 0:00.519 DEBUG juju.worker.dependency "api-caller" manifold worker stopped: cannot open api: unable to connect to API: websocket.Dial wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api: dial tcp 127.0.0.1:49193: connection refused
[LOG] 0:00.519 ERROR juju.worker.dependency "api-caller" manifold worker returned unexpected error: cannot open api: unable to connect to API: websocket.Dial wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api: dial tcp 127.0.0.1:49193: connection refused
[LOG] 0:00.519 DEBUG juju.worker.dependency "uninstaller" manifold worker stopped: dependency not available
[LOG] 0:00.527 DEBUG juju.worker.dependency "upgrader" manifold worker stopped: dependency not available
[LOG] 0:00.528 DEBUG juju.worker.dependency "upgradewaiter" manifold worker stopped: dependency not available
[LOG] 0:00.538 DEBUG juju.worker.dependency "upgrader" manifold worker stopped: dependency not available
[LOG] 0:00.538 DEBUG juju.worker.dependency "upgradewaiter" manifold worker started
[LOG] 0:00.548 DEBUG juju.worker.dependency "reboot" manifold worker stopped: dependency not available
[LOG] 0:00.548 DEBUG juju.worker.dependency "apiworkers" manifold worker stopped: dependency not available
[LOG] 0:00.548 DEBUG juju.worker.dependency "logging-config-updater" manifold worker stopped: dependency not available
[LOG] 0:00.610 DEBUG juju.service discovered init system "upstart" from local host
[LOG] 0:00.610 INFO juju.state opening state, mongo addresses: ["127.0.0.1:54849"]; entity machine-0
[LOG] 0:00.610 DEBUG juju.state dialing mongo
[LOG] 0:00.611 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:00.611 DEBUG juju.state connection established
[LOG] 0:00.611 DEBUG juju.state mongodb login successful
[LOG] 0:00.617 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:00.617 INFO juju.state creating lease clients as machine-0
[LOG] 0:00.618 INFO juju.state starting leadership lease manager
[LOG] 0:00.618 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:26.392754553 +0000 GMT
[LOG] 0:00.618 INFO juju.state starting singular lease manager
[LOG] 0:00.618 INFO juju.state creating cloud image metadata storage
[LOG] 0:00.618 INFO juju.state starting presence watcher
[LOG] 0:00.618 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:26.393075711 +0000 GMT
[LOG] 0:00.618 INFO juju.worker.singular runner created; isMaster true
[LOG] 0:00.618 DEBUG juju.utils setting GOMAXPROCS to 8
[LOG] 0:00.618 INFO juju.worker start "peergrouper"
[LOG] 0:00.618 INFO juju.worker start "restore"
[LOG] 0:00.618 INFO juju.worker start "model worker manager"
[LOG] 0:00.618 INFO juju.worker start "apiserver"
[LOG] 0:00.618 DEBUG juju.cmd.jujud opening state for apistate worker
[LOG] 0:00.618 DEBUG juju.worker "peergrouper" started
[LOG] 0:00.618 DEBUG juju.worker "restore" started
[LOG] 0:00.618 INFO juju.state opening state, mongo addresses: ["127.0.0.1:54849"]; entity machine-0
[LOG] 0:00.618 INFO juju.worker start "certupdater"
[LOG] 0:00.618 INFO juju.worker.singular starting "dblogpruner"
[LOG] 0:00.618 DEBUG juju.state dialing mongo
[LOG] 0:00.618 DEBUG juju.worker "model worker manager" started
[LOG] 0:00.618 DEBUG juju.worker "certupdater" started
[LOG] 0:00.618 INFO juju.worker.singular starting "txnpruner"
[LOG] 0:00.618 INFO juju.worker start "dblogpruner"
[LOG] 0:00.618 DEBUG juju.worker "state" started
[LOG] 0:00.618 DEBUG juju.worker "dblogpruner" started
[LOG] 0:00.619 INFO juju.worker start "txnpruner"
[LOG] 0:00.619 DEBUG juju.worker "txnpruner" started
[LOG] 0:00.619 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:00.619 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:00.619 DEBUG juju.state connection established
[LOG] 0:00.619 DEBUG juju.state mongodb login successful
[LOG] 0:00.624 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:00.625 INFO juju.state creating lease clients as machine-0
[LOG] 0:00.625 INFO juju.state starting leadership lease manager
[LOG] 0:00.625 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:26.400321487 +0000 GMT
[LOG] 0:00.626 INFO juju.state starting singular lease manager
[LOG] 0:00.626 INFO juju.state creating cloud image metadata storage
[LOG] 0:00.626 INFO juju.state starting presence watcher
[LOG] 0:00.626 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:26.400657127 +0000 GMT
[LOG] 0:00.626 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:00.632 INFO juju.apiserver listening on "[::]:49193"
[LOG] 0:00.632 DEBUG juju.worker "apiserver" started
[LOG] 0:00.632 ERROR juju.apiserver Unable to prime /var/log/juju/logsink.log (proceeding anyway): open /var/log/juju/logsink.log: no such file or directory
[LOG] 0:00.632 DEBUG juju.apiserver Starting API http server on address "[::]:49193"
[LOG] 0:03.519 INFO juju.api dialing "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.528 INFO juju.apiserver [D7] API connection from 127.0.0.1:41378, active connections: 1
[LOG] 0:03.528 DEBUG juju.apiserver validate model uuid: controller model - deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:03.528 INFO juju.api connection established to "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.528 DEBUG juju.apiserver <- [D7] <unknown> {"RequestId":1,"Type":"Admin","Version":2,"Request":"Login","Params":"'params redacted'"}
[LOG] 0:03.530 DEBUG juju.apiserver hostPorts: [[localhost:52964]]
[LOG] 0:03.533 DEBUG juju.apiserver -> [D7] machine-0 4.760752ms {"RequestId":1,"Response":"'body redacted'"} Admin[""].Login
[LOG] 0:03.534 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":2,"Type":"Agent","Version":2,"Request":"GetEntities","Params":"'params redacted'"}
[LOG] 0:03.534 DEBUG juju.apiserver -> [D7] machine-0 510.281µs {"RequestId":2,"Response":"'body redacted'"} Agent[""].GetEntities
[LOG] 0:03.534 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":4,"Type":"Agent","Version":2,"Request":"SetPasswords","Params":"'params redacted'"}
[LOG] 0:03.535 INFO juju.apiserver.common setting mongo password for "machine-0"
[LOG] 0:03.537 INFO juju.apiserver.common setting password for "machine-0"
[LOG] 0:03.537 DEBUG juju.apiserver -> [D7] machine-0 3.029636ms {"RequestId":4,"Response":"'body redacted'"} Agent[""].SetPasswords
[LOG] 0:03.537 DEBUG juju.worker.dependency "api-caller" manifold worker started
[LOG] 0:03.548 DEBUG juju.worker.dependency "apiworkers" manifold worker stopped: dependency not available
[LOG] 0:03.548 DEBUG juju.worker.dependency "reboot" manifold worker stopped: dependency not available
[LOG] 0:03.548 DEBUG juju.worker.dependency "logging-config-updater" manifold worker stopped: dependency not available
[LOG] 0:03.548 DEBUG juju.worker.dependency "upgrader" manifold worker started
[LOG] 0:03.548 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":5,"Type":"Agent","Version":2,"Request":"GetEntities","Params":"'params redacted'"}
[LOG] 0:03.548 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":6,"Type":"Agent","Version":2,"Request":"GetEntities","Params":"'params redacted'"}
[LOG] 0:03.548 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":7,"Type":"Agent","Version":2,"Request":"GetEntities","Params":"'params redacted'"}
[LOG] 0:03.548 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":8,"Type":"Upgrader","Version":1,"Request":"SetTools","Params":"'params redacted'"}
[LOG] 0:03.548 DEBUG juju.apiserver -> [D7] machine-0 543.113µs {"RequestId":5,"Response":"'body redacted'"} Agent[""].GetEntities
[LOG] 0:03.548 DEBUG juju.worker.dependency "uninstaller" manifold worker stopped: resource permanently unavailable
[LOG] 0:03.549 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.549 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.549 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.550 DEBUG juju.apiserver -> [D7] machine-0 2.031818ms {"RequestId":6,"Response":"'body redacted'"} Agent[""].GetEntities
[LOG] 0:03.550 DEBUG juju.apiserver -> [D7] machine-0 2.065795ms {"RequestId":7,"Response":"'body redacted'"} Agent[""].GetEntities
[LOG] 0:03.550 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":9,"Type":"Machiner","Version":1,"Request":"Life","Params":"'params redacted'"}
[LOG] 0:03.550 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":10,"Type":"Agent","Version":2,"Request":"StateServingInfo","Params":"'params redacted'"}
[LOG] 0:03.550 DEBUG juju.apiserver -> [D7] machine-0 327.632µs {"RequestId":9,"Response":"'body redacted'"} Machiner[""].Life
[LOG] 0:03.550 DEBUG juju.cmd.jujud mongo is already initialized
[LOG] 0:03.551 INFO juju.state opening state, mongo addresses: ["127.0.0.1:54849"]; entity machine-0
[LOG] 0:03.551 DEBUG juju.state dialing mongo
[LOG] 0:03.551 DEBUG juju.apiserver -> [D7] machine-0 385.686µs {"RequestId":10,"Response":"'body redacted'"} Agent[""].StateServingInfo
[LOG] 0:03.551 DEBUG juju.worker.dependency "upgradesteps" manifold worker started
[LOG] 0:03.551 DEBUG juju.worker.dependency "serving-info-setter" manifold worker stopped: resource permanently unavailable
[LOG] 0:03.552 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.552 DEBUG juju.apiserver -> [D7] machine-0 4.265477ms {"RequestId":8,"Response":"'body redacted'"} Upgrader[""].SetTools
[LOG] 0:03.552 DEBUG juju.state connection established
[LOG] 0:03.552 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":11,"Type":"Upgrader","Version":1,"Request":"WatchAPIVersion","Params":"'params redacted'"}
[LOG] 0:03.553 DEBUG juju.apiserver -> [D7] machine-0 216.261µs {"RequestId":11,"Response":"'body redacted'"} Upgrader[""].WatchAPIVersion
[LOG] 0:03.553 DEBUG juju.state mongodb login successful
[LOG] 0:03.553 INFO juju.worker.upgrader abort check blocked until version event received
[LOG] 0:03.553 INFO juju.worker.upgrader unblocking abort check
[LOG] 0:03.553 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":12,"Type":"NotifyWatcher","Version":1,"Id":"2","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.553 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":13,"Type":"Upgrader","Version":1,"Request":"DesiredVersion","Params":"'params redacted'"}
[LOG] 0:03.554 DEBUG juju.apiserver -> [D7] machine-0 629.621µs {"RequestId":13,"Response":"'body redacted'"} Upgrader[""].DesiredVersion
[LOG] 0:03.554 INFO juju.worker.upgrader desired tool version: 2.0-alpha2
[LOG] 0:03.561 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.561 INFO juju.state creating lease clients as machine-0
[LOG] 0:03.562 INFO juju.state starting leadership lease manager
[LOG] 0:03.562 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:29.336827853 +0000 GMT
[LOG] 0:03.562 INFO juju.state starting singular lease manager
[LOG] 0:03.562 INFO juju.state creating cloud image metadata storage
[LOG] 0:03.562 INFO juju.state starting presence watcher
[LOG] 0:03.562 DEBUG juju.environs new user image datasource registered: model storage
[LOG] 0:03.562 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:29.337202701 +0000 GMT
[LOG] 0:03.562 INFO juju.worker.upgradesteps checking that upgrade can proceed
[LOG] 0:03.565 INFO juju.upgrade updating distro-info
[LOG] 0:03.565 INFO juju.utils.packaging.manager Running: apt-get --option=Dpkg::Options::=--force-confold --option=Dpkg::options::=--force-unsafe-io --assume-yes --quiet update
[LOG] 0:03.565 INFO juju.utils.packaging.manager Running: apt-get --option=Dpkg::Options::=--force-confold --option=Dpkg::options::=--force-unsafe-io --assume-yes --quiet install distro-info
[LOG] 0:03.565 INFO juju.worker.upgradesteps signalling that this controller is ready for upgrade
[LOG] 0:03.565 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.569 INFO juju.worker.upgradesteps waiting for other controllers to be ready for upgrade
[LOG] 0:03.571 INFO juju.worker.upgradesteps finished waiting - all controllers are ready to run upgrade steps
[LOG] 0:03.571 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":14,"Type":"Machiner","Version":1,"Request":"SetStatus","Params":"'params redacted'"}
[LOG] 0:03.573 DEBUG juju.apiserver -> [D7] machine-0 2.171436ms {"RequestId":14,"Response":"'body redacted'"} Machiner[""].SetStatus
[LOG] 0:03.574 INFO juju.worker.upgradesteps starting upgrade from 1.16-alpha2 to 2.0-alpha2 for "machine-0"
[LOG] 0:03.574 INFO juju.api dialing "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.582 INFO juju.apiserver [D8] API connection from 127.0.0.1:41389, active connections: 2
[LOG] 0:03.582 DEBUG juju.apiserver validate model uuid: controller model - deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:03.582 INFO juju.api connection established to "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.582 DEBUG juju.apiserver <- [D8] <unknown> {"RequestId":1,"Type":"Admin","Version":2,"Request":"Login","Params":"'params redacted'"}
[LOG] 0:03.584 DEBUG juju.apiserver hostPorts: [[localhost:52964]]
[LOG] 0:03.584 DEBUG juju.apiserver -> [D8] user-dummy-admin@local 1.532477ms {"RequestId":1,"Response":"'body redacted'"} Admin[""].Login
[LOG] 0:03.584 DEBUG juju.apiserver <- [D8] user-dummy-admin@local {"RequestId":2,"Type":"Client","Version":1,"Request":"FullStatus","Params":"'params redacted'"}
[LOG] 0:03.585 DEBUG juju.api health ping failed: upgrade in progress - Juju functionality is limited
[LOG] 0:03.586 DEBUG juju.apiserver.client Services: map[]
[LOG] 0:03.586 DEBUG juju.apiserver.client error fetching public address: "public no address"
[LOG] 0:03.587 DEBUG juju.apiserver.client error fetching public address: "public no address"
[LOG] 0:03.587 DEBUG juju.apiserver -> [D8] user-dummy-admin@local 2.58643ms {"RequestId":2,"Response":"'body redacted'"} Client[""].FullStatus
[LOG] 0:03.587 DEBUG juju.apiserver <- [D8] user-dummy-admin@local {"RequestId":4,"Type":"Client","Version":1,"Request":"WatchAll","Params":"'params redacted'"}
[LOG] 0:03.587 DEBUG juju.apiserver -> [D8] user-dummy-admin@local 23.884µs {"RequestId":4,"Error":"upgrade in progress - Juju functionality is limited","Response":"'body redacted'"} Client[""].WatchAll
[LOG] 0:03.588 INFO juju.apiserver [D8] user-dummy-admin@local API connection terminated after 5.61469ms, active connections: 1
[LOG] 0:03.588 INFO juju.api dialing "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.593 INFO juju.apiserver [D9] API connection from 127.0.0.1:41398, active connections: 2
[LOG] 0:03.593 DEBUG juju.apiserver validate model uuid: controller model - deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:03.593 INFO juju.api connection established to "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.594 DEBUG juju.apiserver <- [D9] <unknown> {"RequestId":1,"Type":"Admin","Version":2,"Request":"Login","Params":"'params redacted'"}
[LOG] 0:03.595 DEBUG juju.apiserver hostPorts: [[localhost:52964]]
[LOG] 0:03.595 DEBUG juju.apiserver -> [D9] machine-0 1.533182ms {"RequestId":1,"Response":"'body redacted'"} Admin[""].Login
[LOG] 0:03.596 DEBUG juju.api health ping failed: connection is shut down
[LOG] 0:03.596 INFO juju.api dialing "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.596 INFO juju.apiserver [D9] machine-0 API connection terminated after 2.947394ms, active connections: 1
[LOG] 0:03.604 INFO juju.apiserver [DA] API connection from 127.0.0.1:41399, active connections: 2
[LOG] 0:03.604 INFO juju.api connection established to "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.604 DEBUG juju.apiserver validate model uuid: controller model - deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:03.605 DEBUG juju.apiserver <- [DA] <unknown> {"RequestId":1,"Type":"Admin","Version":2,"Request":"Login","Params":"'params redacted'"}
[LOG] 0:03.605 DEBUG juju.apiserver -> [DA] <unknown> 137.729µs {"RequestId":1,"Error":"login for \"machine-1\" blocked because upgrade in progress","Response":"'body redacted'"} Admin[""].Login
[LOG] 0:03.605 INFO juju.apiserver [DA] <unknown> API connection terminated after 859.076µs, active connections: 1
[LOG] 0:03.605 DEBUG juju.agent read agent config, format "1.18"
[LOG] 0:03.612 INFO juju.worker.upgradesteps upgrade to 2.0-alpha2 completed successfully.
[LOG] 0:03.612 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":15,"Type":"Machiner","Version":1,"Request":"SetStatus","Params":"'params redacted'"}
[LOG] 0:03.614 DEBUG juju.apiserver -> [D7] machine-0 1.944787ms {"RequestId":15,"Response":"'body redacted'"} Machiner[""].SetStatus
[LOG] 0:03.614 DEBUG juju.cmd.jujud upgrades done, starting worker "peergrouper"
[LOG] 0:03.614 DEBUG juju.cmd.jujud upgrades done, starting worker "restore"
[LOG] 0:03.614 DEBUG juju.cmd.jujud upgrades done, starting worker "model worker manager"
[LOG] 0:03.614 DEBUG juju.cmd.jujud upgrades done, starting worker "certupdater"
[LOG] 0:03.614 DEBUG juju.cmd.jujud upgrades done, starting worker "dblogpruner"
[LOG] 0:03.614 DEBUG juju.cmd.jujud upgrades done, starting worker "txnpruner"
[LOG] 0:03.614 INFO juju.worker.upgradewaiter startup upgrade operations complete
[LOG] 0:03.614 DEBUG juju.worker.dependency "upgradewaiter" manifold worker stopped: restart immediately
[LOG] 0:03.615 DEBUG juju.state closed state without error
[LOG] 0:03.615 DEBUG juju.worker.dependency "upgradesteps" manifold worker stopped: <nil>
[LOG] 0:03.615 DEBUG juju.worker.certupdater new machine addresses: []network.Address(nil)
[LOG] 0:03.618 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.618 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.620 INFO juju.worker start "deadbeef-0bad-400d-8000-4b1d0d06f00d"
[LOG] 0:03.620 INFO juju.state opening state, mongo addresses: ["127.0.0.1:54849"]; entity machine-0
[LOG] 0:03.620 DEBUG juju.state dialing mongo
[LOG] 0:03.620 DEBUG juju.worker.peergrouper found new machine "0"
[LOG] 0:03.624 ERROR juju.worker.peergrouper cannot publish API server addresses: no api servers specified
[LOG] 0:03.624 ERROR juju.worker.peergrouper peergrouper loop terminated: cannot get replica set status: cannot get replica set status: not running with --replSet
[LOG] 0:03.624 DEBUG juju.cmd.jujud worker "peergrouper" exited with cannot get replica set status: cannot get replica set status: not running with --replSet
[LOG] 0:03.624 INFO juju.worker stopped "peergrouper", err: cannot get replica set status: cannot get replica set status: not running with --replSet
[LOG] 0:03.624 DEBUG juju.worker "peergrouper" done: cannot get replica set status: cannot get replica set status: not running with --replSet
[LOG] 0:03.624 ERROR juju.worker exited "peergrouper": cannot get replica set status: cannot get replica set status: not running with --replSet
[LOG] 0:03.624 INFO juju.worker restarting "peergrouper" in 3s
[LOG] 0:03.625 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.626 DEBUG juju.state connection established
[LOG] 0:03.626 DEBUG juju.state mongodb login successful
[LOG] 0:03.628 DEBUG juju.worker.dependency "upgradewaiter" manifold worker started
[LOG] 0:03.628 DEBUG juju.worker.dependency "reboot" manifold worker stopped: dependency not available
[LOG] 0:03.628 DEBUG juju.worker.dependency "logging-config-updater" manifold worker stopped: dependency not available
[LOG] 0:03.628 DEBUG juju.worker.dependency "apiworkers" manifold worker stopped: dependency not available
[LOG] 0:03.628 DEBUG juju.worker.certupdater existing cert addresses map[]
[LOG] 0:03.628 DEBUG juju.worker.certupdater new addresses [localhost juju-apiserver juju-mongodb anything]
[LOG] 0:03.633 INFO juju.state creating lease clients as machine-0
[LOG] 0:03.633 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.634 INFO juju.state starting leadership lease manager
[LOG] 0:03.634 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:29.409171441 +0000 GMT
[LOG] 0:03.634 INFO juju.state starting singular lease manager
[LOG] 0:03.634 INFO juju.state creating cloud image metadata storage
[LOG] 0:03.634 INFO juju.state starting presence watcher
[LOG] 0:03.634 INFO juju.cmd.jujud starting workers for env deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:03.635 DEBUG juju.worker.lease waking to check leases at 2016-02-11 13:37:29.409700297 +0000 GMT
[LOG] 0:03.635 INFO juju.api dialing "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.638 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":16,"Type":"Agent","Version":2,"Request":"GetEntities","Params":"'params redacted'"}
[LOG] 0:03.638 DEBUG juju.worker.reboot Reboot worker setup
[LOG] 0:03.638 DEBUG juju.worker.logger initial log config: "<root>=DEBUG"
[LOG] 0:03.639 DEBUG juju.worker.dependency "reboot" manifold worker started
[LOG] 0:03.639 DEBUG juju.worker.dependency "logging-config-updater" manifold worker started
[LOG] 0:03.639 DEBUG juju.worker.logger logger setup
[LOG] 0:03.639 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":17,"Type":"Reboot","Version":2,"Request":"WatchForRebootEvent","Params":"'params redacted'"}
[LOG] 0:03.639 DEBUG juju.apiserver -> [D7] machine-0 284.809µs {"RequestId":16,"Response":"'body redacted'"} Agent[""].GetEntities
[LOG] 0:03.639 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":18,"Type":"Logger","Version":1,"Request":"LoggingConfig","Params":"'params redacted'"}
[LOG] 0:03.639 INFO juju.worker start "proxyupdater"
[LOG] 0:03.639 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":19,"Type":"Agent","Version":2,"Request":"ModelConfig","Params":"'params redacted'"}
[LOG] 0:03.639 DEBUG juju.worker "proxyupdater" started
[LOG] 0:03.639 INFO juju.worker start "logsender"
[LOG] 0:03.639 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":20,"Type":"ProxyUpdater","Version":1,"Request":"ModelConfig","Params":"'params redacted'"}
[LOG] 0:03.639 DEBUG juju.worker "logsender" started
[LOG] 0:03.641 INFO juju.apiserver [DB] API connection from 127.0.0.1:41420, active connections: 2
[LOG] 0:03.641 DEBUG juju.apiserver validate model uuid: controller model - deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:03.642 INFO juju.api connection established to "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.642 DEBUG juju.apiserver <- [DB] <unknown> {"RequestId":1,"Type":"Admin","Version":2,"Request":"Login","Params":"'params redacted'"}
[LOG] 0:03.645 DEBUG juju.apiserver -> [D7] machine-0 6.912073ms {"RequestId":17,"Response":"'body redacted'"} Reboot[""].WatchForRebootEvent
[LOG] 0:03.646 DEBUG juju.apiserver -> [D7] machine-0 7.206501ms {"RequestId":19,"Response":"'body redacted'"} Agent[""].ModelConfig
[LOG] 0:03.646 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":21,"Type":"Reboot","Version":2,"Request":"GetRebootAction","Params":"'params redacted'"}
[LOG] 0:03.647 DEBUG juju.apiserver -> [D7] machine-0 7.389301ms {"RequestId":18,"Response":"'body redacted'"} Logger[""].LoggingConfig
[LOG] 0:03.647 DEBUG juju.worker.logger reconfiguring logging from "<root>=DEBUG" to "<root>=DEBUG;unit=DEBUG"
[LOG] 0:03.647 DEBUG juju.apiserver -> [D7] machine-0 995.482µs {"RequestId":21,"Response":"'body redacted'"} Reboot[""].GetRebootAction
[LOG] 0:03.647 INFO juju.worker start "apiaddressupdater"
[LOG] 0:03.647 DEBUG juju.worker "apiaddressupdater" started
[LOG] 0:03.647 INFO juju.worker start "machiner"
[LOG] 0:03.647 INFO juju.worker start "diskmanager"
[LOG] 0:03.647 DEBUG juju.worker.reboot Reboot worker got action: noop
[LOG] 0:03.647 INFO juju.worker start "storageprovisioner-machine"
[LOG] 0:03.647 DEBUG juju.worker "machiner" started
[LOG] 0:03.647 DEBUG juju.worker "diskmanager" started
[LOG] 0:03.647 DEBUG juju.worker "storageprovisioner-machine" started
[LOG] 0:03.647 INFO juju.worker start "authenticationworker"
[LOG] 0:03.649 DEBUG juju.worker "authenticationworker" started
[LOG] 0:03.650 DEBUG juju.apiserver validate model uuid: controller model - deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:03.651 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":22,"Type":"NotifyWatcher","Version":1,"Id":"3","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.651 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":23,"Type":"Logger","Version":1,"Request":"WatchLoggingConfig","Params":"'params redacted'"}
[LOG] 0:03.651 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":24,"Type":"Machiner","Version":1,"Request":"WatchAPIHostPorts","Params":"'params redacted'"}
[LOG] 0:03.651 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":25,"Type":"Machiner","Version":1,"Request":"Life","Params":"'params redacted'"}
[LOG] 0:03.651 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":26,"Type":"StorageProvisioner","Version":2,"Request":"WatchForModelConfigChanges","Params":"'params redacted'"}
[LOG] 0:03.651 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":27,"Type":"KeyUpdater","Version":1,"Request":"AuthorisedKeys","Params":"'params redacted'"}
[LOG] 0:03.651 DEBUG juju.apiserver -> [D7] machine-0 266.186µs {"RequestId":23,"Response":"'body redacted'"} Logger[""].WatchLoggingConfig
[LOG] 0:03.651 DEBUG juju.apiserver -> [D7] machine-0 12.453759ms {"RequestId":20,"Response":"'body redacted'"} ProxyUpdater[""].ModelConfig
[LOG] 0:03.652 DEBUG juju.apiserver -> [D7] machine-0 314.684µs {"RequestId":26,"Response":"'body redacted'"} StorageProvisioner[""].WatchForModelConfigChanges
[LOG] 0:03.652 DEBUG juju.apiserver -> [D7] machine-0 452.756µs {"RequestId":25,"Response":"'body redacted'"} Machiner[""].Life
[LOG] 0:03.652 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":28,"Type":"Logger","Version":1,"Request":"LoggingConfig","Params":"'params redacted'"}
[LOG] 0:03.652 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":29,"Type":"NotifyWatcher","Version":1,"Id":"4","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.652 DEBUG juju.apiserver -> [D7] machine-0 730.227µs {"RequestId":24,"Response":"'body redacted'"} Machiner[""].WatchAPIHostPorts
[LOG] 0:03.652 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":30,"Type":"StorageProvisioner","Version":2,"Request":"WatchBlockDevices","Params":"'params redacted'"}
[LOG] 0:03.652 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":31,"Type":"NotifyWatcher","Version":1,"Id":"5","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.652 DEBUG juju.worker.proxyupdater new proxy settings proxy.Settings{Http:"", Https:"", Ftp:"", NoProxy:""}
[LOG] 0:03.652 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":32,"Type":"Machiner","Version":1,"Request":"APIHostPorts","Params":"'params redacted'"}
[LOG] 0:03.652 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":33,"Type":"NotifyWatcher","Version":1,"Id":"6","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.653 DEBUG juju.apiserver hostPorts: [[localhost:52964]]
[LOG] 0:03.656 DEBUG juju.apiserver -> [D7] machine-0 4.412968ms {"RequestId":30,"Response":"'body redacted'"} StorageProvisioner[""].WatchBlockDevices
[LOG] 0:03.656 DEBUG juju.apiserver -> [DB] machine-0 14.826623ms {"RequestId":1,"Response":"'body redacted'"} Admin[""].Login
[LOG] 0:03.657 DEBUG juju.container.kvm kvm-ok output:
INFO: /dev/kvm exists
KVM acceleration can be used

[LOG] 0:03.657 ERROR juju.worker.diskmanager error checking if "sda" is in use: open /dev/sda: permission denied
[LOG] 0:03.657 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":34,"Type":"Provisioner","Version":2,"Request":"Life","Params":"'params redacted'"}
[LOG] 0:03.657 DEBUG juju.agent read agent config, format "1.18"
[LOG] 0:03.658 INFO juju.util.exec run result: exit status 1
[LOG] 0:03.658 ERROR juju.worker.proxyupdater failed writing new proxy values: 

/tmp/juju-exec254772538/script.sh: line 1: /home/ubuntu/.juju-proxy: Permission denied

[LOG] 0:03.658 DEBUG juju.worker.proxyupdater new apt proxy settings proxy.Settings{Http:"", Https:"", Ftp:"", NoProxy:""}
[LOG] 0:03.659 ERROR juju.worker.proxyupdater error writing apt proxy config file: open /etc/apt/apt.conf.d/42-juju-proxy-settings: permission denied
[LOG] 0:03.659 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":35,"Type":"ProxyUpdater","Version":1,"Request":"WatchForModelConfigChanges","Params":"'params redacted'"}
[LOG] 0:03.659 DEBUG juju.apiserver -> [D7] machine-0 4.506442ms {"RequestId":32,"Response":"'body redacted'"} Machiner[""].APIHostPorts
[LOG] 0:03.659 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":36,"Type":"StorageProvisioner","Version":2,"Request":"ModelConfig","Params":"'params redacted'"}
[LOG] 0:03.659 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":37,"Type":"NotifyWatcher","Version":1,"Id":"7","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.659 WARNING juju.network no hostPorts found in space "default"
[LOG] 0:03.659 WARNING juju.worker.apiaddressupdater cannot determine API addresses by space "default" (using all as fallback)
[LOG] 0:03.660 INFO juju.api dialing "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.660 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.661 DEBUG juju.apiserver -> [D7] machine-0 9.200263ms {"RequestId":28,"Response":"'body redacted'"} Logger[""].LoggingConfig
[LOG] 0:03.661 DEBUG juju.network "lxcbr0" has addresses [10.0.3.1/24 fe80::cc58:3aff:feea:c479/64]
[LOG] 0:03.661 DEBUG juju.network not filtering address local-machine:127.0.0.1 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-cloud:192.168.1.64 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-cloud:172.17.0.1 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-cloud:172.16.0.1 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-cloud:10.17.18.1 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-cloud:10.17.21.1 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-cloud:10.17.20.1 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-cloud:192.168.254.1 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-cloud:10.17.22.1 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-cloud:10.17.17.1 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-cloud:10.10.0.1 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-cloud:192.168.122.1 for machine
[LOG] 0:03.661 DEBUG juju.network filtering "lxcbr0" address 10.0.3.1/24 for machine
[LOG] 0:03.661 DEBUG juju.network not filtering address local-machine:::1 for machine
[LOG] 0:03.661 DEBUG juju.network addresses after filtering: [local-machine:127.0.0.1 local-cloud:192.168.1.64 local-cloud:172.17.0.1 local-cloud:172.16.0.1 local-cloud:10.17.18.1 local-cloud:10.17.21.1 local-cloud:10.17.20.1 local-cloud:192.168.254.1 local-cloud:10.17.22.1 local-cloud:10.17.17.1 local-cloud:10.10.0.1 local-cloud:192.168.122.1 local-machine:::1]
[LOG] 0:03.661 INFO juju.worker.machiner setting addresses for machine-0 to ["local-machine:127.0.0.1" "local-cloud:192.168.1.64" "local-cloud:172.17.0.1" "local-cloud:172.16.0.1" "local-cloud:10.17.18.1" "local-cloud:10.17.21.1" "local-cloud:10.17.20.1" "local-cloud:192.168.254.1" "local-cloud:10.17.22.1" "local-cloud:10.17.17.1" "local-cloud:10.10.0.1" "local-cloud:192.168.122.1" "local-machine:::1"]
[LOG] 0:03.662 DEBUG juju.network "lxcbr0" has addresses [10.0.3.1/24 fe80::cc58:3aff:feea:c479/64]
[LOG] 0:03.662 DEBUG juju.network not filtering address localhost for machine
[LOG] 0:03.662 DEBUG juju.network addresses after filtering: [localhost]
[LOG] 0:03.662 DEBUG juju.worker.apiaddressupdater updating API hostPorts to [[localhost:52964]]
[LOG] 0:03.662 WARNING juju.network no hostPorts found in space "default"
[LOG] 0:03.662 INFO juju.agent API server address details [["localhost:52964"]] written to agent config as ["localhost:52964"]
[LOG] 0:03.662 DEBUG juju.apiserver -> [D7] machine-0 3.140614ms {"RequestId":35,"Response":"'body redacted'"} ProxyUpdater[""].WatchForModelConfigChanges
[LOG] 0:03.662 DEBUG juju.apiserver -> [D7] machine-0 5.603404ms {"RequestId":34,"Response":"'body redacted'"} Provisioner[""].Life
[LOG] 0:03.663 DEBUG juju.apiserver -> [D7] machine-0 3.573203ms {"RequestId":36,"Response":"'body redacted'"} StorageProvisioner[""].ModelConfig
[LOG] 0:03.663 INFO juju.worker.singular runner created; isMaster true
[LOG] 0:03.663 INFO juju.worker.singular starting "minunitsworker"
[LOG] 0:03.663 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":38,"Type":"Machiner","Version":1,"Request":"SetMachineAddresses","Params":"'params redacted'"}
[LOG] 0:03.663 INFO juju.worker.singular starting "environ-provisioner"
[LOG] 0:03.663 INFO juju.worker.singular starting "environ-storageprovisioner"
[LOG] 0:03.663 INFO juju.worker start "minunitsworker"
[LOG] 0:03.663 DEBUG juju.worker "minunitsworker" started
[LOG] 0:03.663 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":39,"Type":"Provisioner","Version":2,"Request":"SetSupportedContainers","Params":"'params redacted'"}
[LOG] 0:03.663 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":40,"Type":"ProxyUpdater","Version":1,"Request":"ModelConfig","Params":"'params redacted'"}
[LOG] 0:03.663 INFO juju.worker start "environ-provisioner"
[LOG] 0:03.663 INFO juju.worker.singular starting "charm-revision-updater"
[LOG] 0:03.663 INFO juju.worker start "environ-storageprovisioner"
[LOG] 0:03.663 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":41,"Type":"NotifyWatcher","Version":1,"Id":"8","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.663 DEBUG juju.worker "environ-provisioner" started
[LOG] 0:03.663 DEBUG juju.worker "environ-storageprovisioner" started
[LOG] 0:03.663 INFO juju.worker.singular starting "instancepoller"
[LOG] 0:03.663 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":3,"Type":"Provisioner","Version":2,"Request":"WatchForModelConfigChanges","Params":"'params redacted'"}
[LOG] 0:03.663 INFO juju.worker start "metricmanagerworker"
[LOG] 0:03.663 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":4,"Type":"StorageProvisioner","Version":2,"Request":"WatchForModelConfigChanges","Params":"'params redacted'"}
[LOG] 0:03.663 INFO juju.worker start "charm-revision-updater"
[LOG] 0:03.663 INFO juju.worker start "sender"
[LOG] 0:03.663 DEBUG juju.worker "sender" started
[LOG] 0:03.663 DEBUG juju.worker "metricmanagerworker" started
[LOG] 0:03.663 DEBUG juju.worker "charm-revision-updater" started
[LOG] 0:03.663 INFO juju.worker start "cleanup"
[LOG] 0:03.663 INFO juju.worker start "instancepoller"
[LOG] 0:03.664 INFO juju.worker.singular starting "cleaner"
[LOG] 0:03.664 DEBUG juju.worker "cleanup" started
[LOG] 0:03.664 DEBUG juju.worker "instancepoller" started
[LOG] 0:03.664 INFO juju.worker.singular starting "addresserworker"
[LOG] 0:03.664 INFO juju.worker.singular starting "discoverspaces"
[LOG] 0:03.664 INFO juju.worker start "cleaner"
[LOG] 0:03.664 DEBUG juju.worker "cleaner" started
[LOG] 0:03.664 DEBUG juju.apiserver -> [D7] machine-0 683.062µs {"RequestId":40,"Response":"'body redacted'"} ProxyUpdater[""].ModelConfig
[LOG] 0:03.664 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":5,"Type":"InstancePoller","Version":2,"Request":"ModelConfig","Params":"'params redacted'"}
[LOG] 0:03.664 INFO juju.worker start "addresserworker"
[LOG] 0:03.664 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":6,"Type":"Cleaner","Version":2,"Request":"WatchCleanups","Params":"'params redacted'"}
[LOG] 0:03.664 DEBUG juju.apiserver -> [DB] machine-0 526.62µs {"RequestId":4,"Response":"'body redacted'"} StorageProvisioner[""].WatchForModelConfigChanges
[LOG] 0:03.664 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":7,"Type":"Addresser","Version":2,"Request":"CanDeallocateAddresses","Params":"'params redacted'"}
[LOG] 0:03.664 INFO juju.worker.singular starting "unitassigner"
[LOG] 0:03.664 INFO juju.worker start "discoverspaces"
[LOG] 0:03.664 DEBUG juju.worker "discoverspaces" started
[LOG] 0:03.664 DEBUG juju.apiserver -> [DB] machine-0 642.503µs {"RequestId":3,"Response":"'body redacted'"} Provisioner[""].WatchForModelConfigChanges
[LOG] 0:03.664 INFO juju.worker start "unitassigner"
[LOG] 0:03.664 DEBUG juju.worker "unitassigner" started
[LOG] 0:03.664 DEBUG juju.apiserver -> [DB] machine-0 298.111µs {"RequestId":6,"Response":"'body redacted'"} Cleaner[""].WatchCleanups
[LOG] 0:03.664 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":8,"Type":"Agent","Version":2,"Request":"ModelConfig","Params":"'params redacted'"}
[LOG] 0:03.664 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":9,"Type":"StorageProvisioner","Version":2,"Request":"ModelConfig","Params":"'params redacted'"}
[LOG] 0:03.664 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":10,"Type":"NotifyWatcher","Version":1,"Id":"2","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.664 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":11,"Type":"DiscoverSpaces","Version":2,"Request":"ModelConfig","Params":"'params redacted'"}
[LOG] 0:03.664 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":12,"Type":"UnitAssigner","Version":1,"Request":"WatchUnitAssignments","Params":"'params redacted'"}
[LOG] 0:03.664 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":13,"Type":"Provisioner","Version":2,"Request":"ModelConfig","Params":"'params redacted'"}
[LOG] 0:03.664 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":14,"Type":"NotifyWatcher","Version":1,"Id":"3","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.665 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":15,"Type":"Cleaner","Version":2,"Request":"Cleanup","Params":"'params redacted'"}
[LOG] 0:03.665 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":16,"Type":"NotifyWatcher","Version":1,"Id":"4","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.665 DEBUG juju.apiserver -> [DB] machine-0 1.079249ms {"RequestId":5,"Response":"'body redacted'"} InstancePoller[""].ModelConfig
[LOG] 0:03.665 DEBUG juju.apiserver -> [DB] machine-0 1.227179ms {"RequestId":7,"Response":"'body redacted'"} Addresser[""].CanDeallocateAddresses
[LOG] 0:03.666 DEBUG juju.apiserver -> [DB] machine-0 1.409707ms {"RequestId":9,"Response":"'body redacted'"} StorageProvisioner[""].ModelConfig
[LOG] 0:03.666 DEBUG juju.worker.addresser address deallocation not supported; not starting worker
[LOG] 0:03.666 INFO juju.worker stopped "addresserworker", err: <nil>
[LOG] 0:03.666 DEBUG juju.worker "addresserworker" started
[LOG] 0:03.666 DEBUG juju.worker "addresserworker" done: <nil>
[LOG] 0:03.666 DEBUG juju.worker removing "addresserworker" from known workers
[LOG] 0:03.666 INFO juju.worker.instancepoller instance poller received inital environment configuration
[LOG] 0:03.666 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":17,"Type":"InstancePoller","Version":2,"Request":"WatchForModelConfigChanges","Params":"'params redacted'"}
[LOG] 0:03.666 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":18,"Type":"InstancePoller","Version":2,"Request":"WatchModelMachines","Params":"'params redacted'"}
[LOG] 0:03.666 DEBUG juju.apiserver -> [DB] machine-0 2.022691ms {"RequestId":8,"Response":"'body redacted'"} Agent[""].ModelConfig
[LOG] 0:03.667 DEBUG juju.apiserver -> [DB] machine-0 981.213µs {"RequestId":17,"Response":"'body redacted'"} InstancePoller[""].WatchForModelConfigChanges
[LOG] 0:03.667 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":19,"Type":"StorageProvisioner","Version":2,"Request":"WatchVolumes","Params":"'params redacted'"}
[LOG] 0:03.667 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.667 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":20,"Type":"MetricsManager","Version":1,"Request":"CleanupOldMetrics","Params":"'params redacted'"}
[LOG] 0:03.668 INFO juju.worker.singular starting "firewaller"
[LOG] 0:03.668 INFO juju.worker.singular starting "statushistorypruner"
[LOG] 0:03.668 DEBUG juju.worker.environ waiting for environ watch notification
[LOG] 0:03.668 INFO juju.worker start "statushistorypruner"
[LOG] 0:03.668 DEBUG juju.worker "deadbeef-0bad-400d-8000-4b1d0d06f00d" started
[LOG] 0:03.668 INFO juju.worker start "firewaller"
[LOG] 0:03.668 DEBUG juju.worker "statushistorypruner" started
[LOG] 0:03.668 DEBUG juju.worker "firewaller" started
[LOG] 0:03.668 INFO juju.cmd.jujud update apiserver worker with new certificate
[LOG] 0:03.668 DEBUG juju.apiserver -> [DB] machine-0 1.877125ms {"RequestId":18,"Response":"'body redacted'"} InstancePoller[""].WatchModelMachines
[LOG] 0:03.668 DEBUG juju.apiserver -> [DB] machine-0 763.254µs {"RequestId":20,"Response":"'body redacted'"} MetricsManager[""].CleanupOldMetrics
[LOG] 0:03.668 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":21,"Type":"MetricsManager","Version":1,"Request":"SendMetrics","Params":"'params redacted'"}
[LOG] 0:03.668 INFO juju.worker.certupdater controller cerificate addresses updated to ["anything" "juju-apiserver" "juju-mongodb" "localhost"]
[LOG] 0:03.668 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":22,"Type":"CharmRevisionUpdater","Version":1,"Request":"UpdateLatestRevisions","Params":"'params redacted'"}
[LOG] 0:03.668 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":23,"Type":"NotifyWatcher","Version":1,"Id":"5","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.668 DEBUG juju.worker.environ reloading environ config
[LOG] 0:03.669 DEBUG juju.apiserver -> [DB] machine-0 4.108544ms {"RequestId":12,"Response":"'body redacted'"} UnitAssigner[""].WatchUnitAssignments
[LOG] 0:03.669 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":24,"Type":"InstancePoller","Version":2,"Request":"Life","Params":"'params redacted'"}
[LOG] 0:03.669 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":25,"Type":"StringsWatcher","Version":1,"Id":"6","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.669 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":26,"Type":"Firewaller","Version":2,"Request":"WatchForModelConfigChanges","Params":"'params redacted'"}
[LOG] 0:03.669 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":27,"Type":"InstancePoller","Version":2,"Request":"ModelConfig","Params":"'params redacted'"}
[LOG] 0:03.669 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":28,"Type":"StringsWatcher","Version":1,"Id":"7","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.670 DEBUG juju.apiserver -> [DB] machine-0 812.772µs {"RequestId":27,"Response":"'body redacted'"} InstancePoller[""].ModelConfig
[LOG] 0:03.670 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.670 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.670 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.670 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.670 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.670 DEBUG juju.worker.environ waiting for environ watch notification
[LOG] 0:03.671 DEBUG juju.worker.certupdater new machine addresses: []network.Address{}
[LOG] 0:03.671 DEBUG juju.apiserver -> [DB] machine-0 6.691638ms {"RequestId":15,"Response":"'body redacted'"} Cleaner[""].Cleanup
[LOG] 0:03.672 ERROR juju.worker.diskmanager error checking if "sdb" is in use: open /dev/sdb: permission denied
[LOG] 0:03.673 INFO juju.apiserver.charmrevisionupdater retrieving revision information for 0 charms
[LOG] 0:03.673 DEBUG juju.apiserver -> [DB] machine-0 4.535114ms {"RequestId":22,"Response":"'body redacted'"} CharmRevisionUpdater[""].UpdateLatestRevisions
[LOG] 0:03.677 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":29,"Type":"StatusHistory","Version":2,"Request":"Prune","Params":"'params redacted'"}
[LOG] 0:03.677 DEBUG juju.apiserver -> [D7] machine-0 25.822597ms {"RequestId":27,"Response":"'body redacted'"} KeyUpdater[""].AuthorisedKeys
[LOG] 0:03.677 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.677 INFO juju.mongo dialled mongo successfully on address "127.0.0.1:54849"
[LOG] 0:03.677 INFO juju.apiserver [DC] API connection from 127.0.0.1:41424, active connections: 3
[LOG] 0:03.677 DEBUG juju.apiserver validate model uuid: controller model - deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:03.677 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":42,"Type":"StorageProvisioner","Version":2,"Request":"WatchVolumes","Params":"'params redacted'"}
[LOG] 0:03.678 INFO juju.worker.authenticationworker reading ssh authorized keys for "machine-0": no such user: user: unknown user ubuntu
[LOG] 0:03.678 INFO juju.api connection established to "wss://localhost:49193/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:03.678 INFO juju.worker stopped "authenticationworker", err: reading ssh authorized keys for "machine-0": no such user: user: unknown user ubuntu
[LOG] 0:03.678 DEBUG juju.worker "authenticationworker" done: reading ssh authorized keys for "machine-0": no such user: user: unknown user ubuntu
[LOG] 0:03.678 DEBUG juju.apiserver <- [DC] <unknown> {"RequestId":1,"Type":"Admin","Version":2,"Request":"Login","Params":"'params redacted'"}
[LOG] 0:03.678 DEBUG juju.apiserver -> [DC] <unknown> 97.882µs {"RequestId":1,"Error":"space discovery still in progress","Response":"'body redacted'"} Admin[""].Login
[LOG] 0:03.678 DEBUG juju.apiserver -> [D7] machine-0 625.292µs {"RequestId":42,"Response":"'body redacted'"} StorageProvisioner[""].WatchVolumes
upgrade_test.go:138:
[LOG] 0:03.678 DEBUG juju.apiserver -> [DB] machine-0 13.955594ms {"RequestId":13,"Response":"'body redacted'"} Provisioner[""].ModelConfig
[LOG] 0:03.679 DEBUG juju.apiserver -> [DB] machine-0 14.189749ms {"RequestId":11,"Response":"'body redacted'"} DiscoverSpaces[""].ModelConfig
[LOG] 0:03.679 ERROR juju.worker exited "authenticationworker": reading ssh authorized keys for "machine-0": no such user: user: unknown user ubuntu
[LOG] 0:03.679 INFO juju.worker restarting "authenticationworker" in 3s
[LOG] 0:03.679 INFO juju.apiserver [DC] <unknown> API connection terminated after 1.61313ms, active connections: 2
[LOG] 0:03.679 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":44,"Type":"StorageProvisioner","Version":2,"Request":"WatchFilesystems","Params":"'params redacted'"}
[LOG] 0:03.679 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":45,"Type":"StringsWatcher","Version":1,"Id":"9","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.680 DEBUG juju.apiserver -> [D7] machine-0 594.045µs {"RequestId":44,"Response":"'body redacted'"} StorageProvisioner[""].WatchFilesystems
    // All logins are allowed after upgrade
    s.checkLoginToAPIAsUser(c, machine0Conf, FullAPIExposed)
upgrade_test.go:316:
[LOG] 0:03.680 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":46,"Type":"StorageProvisioner","Version":2,"Request":"WatchVolumeAttachments","Params":"'params redacted'"}
[LOG] 0:03.680 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":47,"Type":"StringsWatcher","Version":1,"Id":"10","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.681 DEBUG juju.apiserver -> [D7] machine-0 592.856µs {"RequestId":46,"Response":"'body redacted'"} StorageProvisioner[""].WatchVolumeAttachments
[LOG] 0:03.681 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":48,"Type":"StorageProvisioner","Version":2,"Request":"WatchFilesystemAttachments","Params":"'params redacted'"}
[LOG] 0:03.681 DEBUG juju.apiserver <- [D7] machine-0 {"RequestId":49,"Type":"VolumeAttachmentsWatcher","Version":2,"Id":"11","Request":"Next","Params":"'params redacted'"}
    c.Assert(err, jc.ErrorIsNil)
... value *errors.Err = &errors.Err{message:"", cause:(*params.Error)(0xc208ab34d0), previous:(*errors.Err)(0xc2085d8780), file:"github.com/juju/juju/api/state.go", line:51} ("space discovery still in progress")
... error stack:
	space discovery still in progress
	github.com/juju/juju/api/state.go:81: 
	github.com/juju/juju/api/state.go:51: 

[LOG] 0:03.681 DEBUG juju.worker killing runner 0xc2085bb500
[LOG] 0:03.681 INFO juju.worker runner is dying
[LOG] 0:03.681 DEBUG juju.worker killing "state"
[LOG] 0:03.681 DEBUG juju.worker killing runner 0xc2088f6660
[LOG] 0:03.681 DEBUG juju.worker killing "engine"
[LOG] 0:03.681 DEBUG juju.worker killing "statestarter"
[LOG] 0:03.681 INFO juju.worker runner is dying
[LOG] 0:03.681 DEBUG juju.worker killing "peergrouper"
[LOG] 0:03.681 DEBUG juju.worker killing "restore"
[LOG] 0:03.681 DEBUG juju.worker killing "apiserver"
[LOG] 0:03.681 DEBUG juju.worker killing "certupdater"
[LOG] 0:03.681 DEBUG juju.worker killing "dblogpruner"
[LOG] 0:03.681 DEBUG juju.worker killing "txnpruner"
[LOG] 0:03.681 DEBUG juju.worker killing "model worker manager"
[LOG] 0:03.682 DEBUG juju.cmd.jujud stopping so killing worker "restore"
[LOG] 0:03.682 DEBUG juju.cmd.jujud stopping so killing worker "certupdater"
[LOG] 0:03.682 DEBUG juju.cmd.jujud stopping so killing worker "dblogpruner"
[LOG] 0:03.682 DEBUG juju.cmd.jujud stopping so killing worker "txnpruner"
[LOG] 0:03.682 DEBUG juju.cmd.jujud stopping so killing worker "model worker manager"
[LOG] 0:03.682 DEBUG juju.worker "peergrouper" done: <nil>
[LOG] 0:03.682 DEBUG juju.worker no restart, removing "peergrouper" from known workers
[LOG] 0:03.682 INFO juju.worker stopped "statestarter", err: <nil>
[LOG] 0:03.682 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.682 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.682 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.682 DEBUG juju.worker "statestarter" done: <nil>
[LOG] 0:03.682 DEBUG juju.worker no restart, removing "statestarter" from known workers
[LOG] 0:03.682 DEBUG juju.worker killing runner 0xc2082a0360
[LOG] 0:03.682 DEBUG juju.apiserver -> [D7] machine-0 19.402188ms {"RequestId":38,"Response":"'body redacted'"} Machiner[""].SetMachineAddresses
[LOG] 0:03.682 DEBUG juju.worker.dependency "upgrade-steps-gate" manifold worker stopped: <nil>
[LOG] 0:03.682 DEBUG juju.worker.dependency "upgrade-check-gate" manifold worker stopped: <nil>
[LOG] 0:03.682 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.682 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.682 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.682 INFO juju.worker runner is dying
[LOG] 0:03.682 DEBUG juju.worker killing "proxyupdater"
[LOG] 0:03.682 DEBUG juju.worker killing "logsender"
[LOG] 0:03.682 DEBUG juju.worker killing "machiner"
[LOG] 0:03.682 DEBUG juju.worker killing "apiaddressupdater"
[LOG] 0:03.682 DEBUG juju.worker killing "diskmanager"
[LOG] 0:03.682 DEBUG juju.worker killing "storageprovisioner-machine"
[LOG] 0:03.682 DEBUG juju.worker killing "authenticationworker"
[LOG] 0:03.682 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.682 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.682 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.682 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.682 DEBUG juju.apiserver -> [DB] machine-0 13.369291ms {"RequestId":28,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} StringsWatcher["7"].Next
[LOG] 0:03.683 INFO juju.worker stopped "dblogpruner", err: <nil>
[LOG] 0:03.683 INFO juju.worker stopped "txnpruner", err: <nil>
[LOG] 0:03.683 DEBUG juju.worker.dependency "agent" manifold worker stopped: <nil>
[LOG] 0:03.683 DEBUG juju.worker.dependency "termination" manifold worker stopped: <nil>
[LOG] 0:03.683 DEBUG juju.worker.dependency "upgradewaiter" manifold worker stopped: <nil>
[LOG] 0:03.683 DEBUG juju.worker "authenticationworker" done: <nil>
[LOG] 0:03.683 DEBUG juju.worker no restart, removing "authenticationworker" from known workers
[LOG] 0:03.683 DEBUG juju.worker killing runner 0xc208840000
[LOG] 0:03.683 DEBUG juju.worker "dblogpruner" done: <nil>
[LOG] 0:03.683 DEBUG juju.worker no restart, removing "dblogpruner" from known workers
[LOG] 0:03.683 DEBUG juju.worker "txnpruner" done: <nil>
[LOG] 0:03.683 DEBUG juju.worker no restart, removing "txnpruner" from known workers
[LOG] 0:03.683 INFO juju.worker stopped "logsender", err: <nil>
[LOG] 0:03.683 INFO juju.worker stopped "machiner", err: setting machine addresses: connection is shut down
[LOG] 0:03.683 DEBUG juju.api health ping failed: connection is shut down
[LOG] 0:03.683 INFO juju.worker runner is dying
[LOG] 0:03.683 DEBUG juju.worker killing "deadbeef-0bad-400d-8000-4b1d0d06f00d"
[LOG] 0:03.683 DEBUG juju.worker killing runner 0xc2082a1860
[LOG] 0:03.683 INFO juju.worker stopped "restore", err: <nil>
[LOG] 0:03.683 DEBUG juju.apiserver -> [DB] machine-0 14.342228ms {"RequestId":25,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} StringsWatcher["6"].Next
[LOG] 0:03.683 DEBUG juju.worker "logsender" done: <nil>
[LOG] 0:03.683 DEBUG juju.worker no restart, removing "logsender" from known workers
[LOG] 0:03.683 DEBUG juju.worker "machiner" done: setting machine addresses: connection is shut down
[LOG] 0:03.683 INFO juju.cmd.jujud error pinging *api.state: connection is shut down
[LOG] 0:03.683 ERROR juju.worker fatal "machiner": setting machine addresses: connection is shut down
[LOG] 0:03.683 INFO juju.worker runner is dying
[LOG] 0:03.683 DEBUG juju.worker killing "charm-revision-updater"
[LOG] 0:03.683 DEBUG juju.worker killing "metricmanagerworker"
[LOG] 0:03.683 DEBUG juju.worker killing runner 0xc2083ee720
[LOG] 0:03.683 DEBUG juju.worker killing "discoverspaces"
[LOG] 0:03.683 DEBUG juju.worker killing "unitassigner"
[LOG] 0:03.683 DEBUG juju.worker killing "environ-provisioner"
[LOG] 0:03.683 DEBUG juju.worker killing "environ-storageprovisioner"
[LOG] 0:03.683 DEBUG juju.worker killing "instancepoller"
[LOG] 0:03.683 DEBUG juju.worker killing "cleaner"
[LOG] 0:03.683 DEBUG juju.worker killing "firewaller"
[LOG] 0:03.683 DEBUG juju.worker killing "statushistorypruner"
[LOG] 0:03.683 DEBUG juju.worker killing "minunitsworker"
[LOG] 0:03.683 DEBUG juju.worker "restore" done: <nil>
[LOG] 0:03.683 DEBUG juju.worker no restart, removing "restore" from known workers
[LOG] 0:03.683 INFO juju.worker runner is dying
[LOG] 0:03.683 DEBUG juju.worker killing "sender"
[LOG] 0:03.683 DEBUG juju.worker killing "cleanup"
[LOG] 0:03.683 DEBUG juju.apiserver -> [DB] machine-0 14.782582ms {"RequestId":23,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} NotifyWatcher["5"].Next
[LOG] 0:03.683 INFO juju.worker stopped "storageprovisioner-machine", err: watching filesystem attachments: connection is shut down
[LOG] 0:03.683 INFO juju.worker stopped "apiaddressupdater", err: connection is shut down
[LOG] 0:03.683 DEBUG juju.worker.dependency "reboot" manifold worker stopped: connection is shut down
[LOG] 0:03.683 DEBUG juju.worker.dependency "logging-config-updater" manifold worker stopped: connection is shut down
[LOG] 0:03.683 DEBUG juju.worker.dependency "upgrader" manifold worker stopped: connection is shut down
[LOG] 0:03.683 DEBUG juju.worker.dependency "api-caller" manifold worker stopped: <nil>
[LOG] 0:03.683 INFO juju.worker stopped "proxyupdater", err: connection is shut down
[LOG] 0:03.684 DEBUG juju.worker "storageprovisioner-machine" done: watching filesystem attachments: connection is shut down
[LOG] 0:03.684 INFO juju.cmd.jujud error pinging *api.state: connection is shut down
[LOG] 0:03.684 ERROR juju.worker fatal "storageprovisioner-machine": watching filesystem attachments: connection is shut down
[LOG] 0:03.684 DEBUG juju.worker "apiaddressupdater" done: connection is shut down
[LOG] 0:03.684 INFO juju.cmd.jujud error pinging *api.state: connection is shut down
[LOG] 0:03.684 ERROR juju.worker fatal "apiaddressupdater": connection is shut down
[LOG] 0:03.684 DEBUG juju.worker "proxyupdater" done: connection is shut down
[LOG] 0:03.684 INFO juju.cmd.jujud error pinging *api.state: connection is shut down
[LOG] 0:03.684 ERROR juju.worker fatal "proxyupdater": connection is shut down
[LOG] 0:03.684 INFO juju.worker stopped "cleanup", err: <nil>
[LOG] 0:03.684 DEBUG juju.worker "cleanup" done: <nil>
[LOG] 0:03.684 DEBUG juju.worker no restart, removing "cleanup" from known workers
[LOG] 0:03.684 INFO juju.worker stopped "minunitsworker", err: <nil>
[LOG] 0:03.684 DEBUG juju.worker "minunitsworker" done: <nil>
[LOG] 0:03.684 DEBUG juju.worker no restart, removing "minunitsworker" from known workers
[LOG] 0:03.684 DEBUG juju.apiserver -> [DB] machine-0 19.278648ms {"RequestId":16,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} NotifyWatcher["4"].Next
[LOG] 0:03.684 DEBUG juju.apiserver -> [DB] machine-0 15.362797ms {"RequestId":24,"Response":"'body redacted'"} InstancePoller[""].Life
[LOG] 0:03.684 DEBUG juju.apiserver -> [DB] machine-0 19.421251ms {"RequestId":14,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} NotifyWatcher["3"].Next
[LOG] 0:03.684 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":30,"Type":"StringsWatcher","Version":1,"Id":"7","Request":"Stop","Params":"'params redacted'"}
[LOG] 0:03.684 DEBUG juju.apiserver -> [DB] machine-0 19.721885ms {"RequestId":10,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} NotifyWatcher["2"].Next
[LOG] 0:03.684 DEBUG juju.apiserver -> [DB] machine-0 339.364µs {"RequestId":30,"Error":"connection is shut down","Response":"'body redacted'"} StringsWatcher["7"].Stop
[LOG] 0:03.684 DEBUG juju.apiserver -> [D7] machine-0 3.19948ms {"RequestId":48,"Response":"'body redacted'"} StorageProvisioner[""].WatchFilesystemAttachments
[LOG] 0:03.684 DEBUG juju.apiserver -> [D7] machine-0 3.156833ms {"RequestId":49,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} VolumeAttachmentsWatcher["11"].Next
[LOG] 0:03.684 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":31,"Type":"NotifyWatcher","Version":1,"Id":"3","Request":"Stop","Params":"'params redacted'"}
[LOG] 0:03.684 DEBUG juju.apiserver -> [DB] machine-0 23.858µs {"RequestId":31,"Error":"connection is shut down","Response":"'body redacted'"} NotifyWatcher["3"].Stop
[LOG] 0:03.684 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.684 DEBUG juju.apiserver -> [D7] machine-0 4.202665ms {"RequestId":47,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} StringsWatcher["10"].Next
[LOG] 0:03.684 INFO juju.worker stopped "charm-revision-updater", err: <nil>
[LOG] 0:03.684 DEBUG juju.apiserver -> [D7] machine-0 5.166596ms {"RequestId":45,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} StringsWatcher["9"].Next
[LOG] 0:03.684 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.684 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":32,"Type":"NotifyWatcher","Version":1,"Id":"2","Request":"Stop","Params":"'params redacted'"}
[LOG] 0:03.684 DEBUG juju.apiserver -> [DB] machine-0 103.621µs {"RequestId":32,"Error":"connection is shut down","Response":"'body redacted'"} NotifyWatcher["2"].Stop
[LOG] 0:03.684 DEBUG juju.apiserver -> [D7] machine-0 21.30045ms {"RequestId":41,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} NotifyWatcher["8"].Next
[LOG] 0:03.684 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.684 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":33,"Type":"StringsWatcher","Version":1,"Id":"6","Request":"Stop","Params":"'params redacted'"}
[LOG] 0:03.684 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.684 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.684 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.684 DEBUG juju.worker "charm-revision-updater" done: <nil>
[LOG] 0:03.684 INFO juju.worker stopped "unitassigner", err: <nil>
[LOG] 0:03.684 DEBUG juju.apiserver -> [DB] machine-0 26.744µs {"RequestId":33,"Error":"connection is shut down","Response":"'body redacted'"} StringsWatcher["6"].Stop
[LOG] 0:03.684 INFO juju.worker stopped "discoverspaces", err: <nil>
[LOG] 0:03.685 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.685 DEBUG juju.worker no restart, removing "charm-revision-updater" from known workers
[LOG] 0:03.685 DEBUG juju.worker "unitassigner" done: <nil>
[LOG] 0:03.685 DEBUG juju.worker no restart, removing "unitassigner" from known workers
[LOG] 0:03.685 DEBUG juju.worker "discoverspaces" done: <nil>
[LOG] 0:03.685 DEBUG juju.worker no restart, removing "discoverspaces" from known workers
[LOG] 0:03.685 DEBUG juju.apiserver -> [D7] machine-0 25.234945ms {"RequestId":37,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} NotifyWatcher["7"].Next
[LOG] 0:03.685 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.685 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":34,"Type":"NotifyWatcher","Version":1,"Id":"4","Request":"Stop","Params":"'params redacted'"}
[LOG] 0:03.685 DEBUG juju.apiserver -> [DB] machine-0 100.804µs {"RequestId":34,"Error":"connection is shut down","Response":"'body redacted'"} NotifyWatcher["4"].Stop
[LOG] 0:03.685 DEBUG juju.apiserver -> [D7] machine-0 32.425005ms {"RequestId":33,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} NotifyWatcher["6"].Next
[LOG] 0:03.685 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.685 DEBUG juju.apiserver -> [D7] machine-0 32.599453ms {"RequestId":31,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} NotifyWatcher["5"].Next
[LOG] 0:03.685 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":35,"Type":"NotifyWatcher","Version":1,"Id":"5","Request":"Stop","Params":"'params redacted'"}
[LOG] 0:03.685 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.685 DEBUG juju.apiserver -> [DB] machine-0 26.141µs {"RequestId":35,"Error":"connection is shut down","Response":"'body redacted'"} NotifyWatcher["5"].Stop
[LOG] 0:03.685 DEBUG juju.apiserver -> [D7] machine-0 32.931363ms {"RequestId":29,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} NotifyWatcher["4"].Next
[LOG] 0:03.685 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.685 DEBUG juju.apiserver -> [D7] machine-0 33.718096ms {"RequestId":22,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} NotifyWatcher["3"].Next
[LOG] 0:03.685 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.685 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":36,"Type":"Provisioner","Version":2,"Request":"StateAddresses","Params":"'params redacted'"}
[LOG] 0:03.685 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.685 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.685 DEBUG juju.apiserver -> [DB] machine-0 46.959µs {"RequestId":36,"Error":"connection is shut down","Response":"'body redacted'"} Provisioner[""].StateAddresses
[LOG] 0:03.685 DEBUG juju.apiserver -> [D7] machine-0 132.030939ms {"RequestId":12,"Error":"watcher has been stopped","ErrorCode":"stopped","Response":"'body redacted'"} NotifyWatcher["2"].Next
[LOG] 0:03.685 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.685 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.685 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.685 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":37,"Type":"InstancePoller","Version":2,"Request":"AreManuallyProvisioned","Params":"'params redacted'"}
[LOG] 0:03.685 DEBUG juju.apiserver -> [DB] machine-0 19.503µs {"RequestId":37,"Error":"connection is shut down","Response":"'body redacted'"} InstancePoller[""].AreManuallyProvisioned
[LOG] 0:03.685 INFO juju.worker stopped "cleaner", err: <nil>
[LOG] 0:03.685 DEBUG juju.worker "cleaner" done: <nil>
[LOG] 0:03.685 DEBUG juju.worker no restart, removing "cleaner" from known workers
[LOG] 0:03.685 INFO juju.worker stopped "environ-provisioner", err: connection is shut down
[LOG] 0:03.685 INFO juju.worker stopped "instancepoller", err: connection is shut down
[LOG] 0:03.685 DEBUG juju.worker "environ-provisioner" done: connection is shut down
[LOG] 0:03.685 DEBUG juju.apiserver -> [DB] machine-0 16.466585ms {"RequestId":26,"Response":"'body redacted'"} Firewaller[""].WatchForModelConfigChanges
[LOG] 0:03.685 INFO juju.cmd.jujud error pinging *api.state: connection is shut down
[LOG] 0:03.685 ERROR juju.worker fatal "environ-provisioner": connection is shut down
[LOG] 0:03.685 DEBUG juju.worker "instancepoller" done: connection is shut down
[LOG] 0:03.686 INFO juju.worker stopped "firewaller", err: <nil>
[LOG] 0:03.686 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":39,"Type":"NotifyWatcher","Version":1,"Id":"8","Request":"Stop","Params":"'params redacted'"}
[LOG] 0:03.686 DEBUG juju.apiserver -> [DB] machine-0 33.675µs {"RequestId":39,"Error":"connection is shut down","Response":"'body redacted'"} NotifyWatcher["8"].Stop
[LOG] 0:03.686 DEBUG juju.apiserver <- [DB] machine-0 {"RequestId":40,"Type":"NotifyWatcher","Version":1,"Id":"8","Request":"Next","Params":"'params redacted'"}
[LOG] 0:03.686 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.686 DEBUG juju.apiserver -> [DB] machine-0 26.006µs {"RequestId":40,"Error":"connection is shut down","Response":"'body redacted'"} NotifyWatcher["8"].Next
[LOG] 0:03.686 INFO juju.cmd.jujud error pinging *api.state: connection is shut down
[LOG] 0:03.686 DEBUG juju.apiserver -> [DB] machine-0 8.906938ms {"RequestId":29,"Response":"'body redacted'"} StatusHistory[""].Prune
[LOG] 0:03.686 ERROR juju.worker fatal "instancepoller": connection is shut down
[LOG] 0:03.686 DEBUG juju.worker "firewaller" done: <nil>
[LOG] 0:03.686 DEBUG juju.worker no restart, removing "firewaller" from known workers
[LOG] 0:03.686 INFO juju.worker stopped "statushistorypruner", err: <nil>
[LOG] 0:03.686 DEBUG juju.worker "statushistorypruner" done: <nil>
[LOG] 0:03.686 DEBUG juju.worker no restart, removing "statushistorypruner" from known workers
[LOG] 0:03.687 INFO juju.apiserver.metricsender nothing to send
[LOG] 0:03.687 INFO juju.apiserver.metricsender metrics collection summary: sent:0 unsent:0 (0 sent metrics stored)
[LOG] 0:03.687 DEBUG juju.apiserver -> [DB] machine-0 18.8593ms {"RequestId":21,"Response":"'body redacted'"} MetricsManager[""].SendMetrics
[LOG] 0:03.687 INFO juju.worker stopped "sender", err: <nil>
[LOG] 0:03.687 DEBUG juju.worker "sender" done: <nil>
[LOG] 0:03.687 DEBUG juju.worker no restart, removing "sender" from known workers
[LOG] 0:03.687 INFO juju.worker stopped "metricmanagerworker", err: <nil>
[LOG] 0:03.687 DEBUG juju.worker "metricmanagerworker" done: <nil>
[LOG] 0:03.687 DEBUG juju.worker no restart, removing "metricmanagerworker" from known workers
[LOG] 0:03.687 DEBUG juju.apiserver -> [D7] machine-0 24.516424ms {"RequestId":39,"Response":"'body redacted'"} Provisioner[""].SetSupportedContainers
[LOG] 0:03.687 ERROR juju.rpc error writing response: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.687 INFO juju.rpc error closing codec: write tcp 127.0.0.1:41378: broken pipe
[LOG] 0:03.687 ERROR juju.worker.diskmanager error checking if "sdc" is in use: open /dev/sdc: permission denied
[LOG] 0:03.688 INFO juju.apiserver [D7] machine-0 API connection terminated after 159.906098ms, active connections: 1
[LOG] 0:03.689 DEBUG juju.worker.certupdater existing cert addresses map[]
[LOG] 0:03.689 DEBUG juju.worker.certupdater new addresses [localhost juju-apiserver juju-mongodb anything]
[LOG] 0:03.689 DEBUG juju.apiserver -> [DB] machine-0 21.530792ms {"RequestId":19,"Response":"'body redacted'"} StorageProvisioner[""].WatchVolumes
[LOG] 0:03.689 INFO juju.apiserver [DB] machine-0 API connection terminated after 47.807929ms, active connections: 0
[LOG] 0:03.689 INFO juju.worker stopped "apiserver", err: <nil>
[LOG] 0:03.689 DEBUG juju.worker "apiserver" done: <nil>
[LOG] 0:03.689 DEBUG juju.worker no restart, removing "apiserver" from known workers
[LOG] 0:03.691 DEBUG juju.state closed state without error
[LOG] 0:03.691 INFO juju.apiserver closed listening socket "[::]:49193" with final error: <nil>
[LOG] 0:03.691 DEBUG juju.apiserver API http server exited, final error was: accept tcp [::]:49193: use of closed network connection
[LOG] 0:03.691 ERROR juju.api.watcher error trying to stop watcher: connection is shut down
[LOG] 0:03.691 INFO juju.worker stopped "environ-storageprovisioner", err: <nil>
[LOG] 0:03.691 DEBUG juju.worker "environ-storageprovisioner" done: <nil>
[LOG] 0:03.691 DEBUG juju.worker no restart, removing "environ-storageprovisioner" from known workers
[LOG] 0:03.691 INFO juju.worker stopped "deadbeef-0bad-400d-8000-4b1d0d06f00d", err: connection is shut down
[LOG] 0:03.691 DEBUG juju.worker "deadbeef-0bad-400d-8000-4b1d0d06f00d" done: connection is shut down
[LOG] 0:03.691 ERROR juju.worker exited "deadbeef-0bad-400d-8000-4b1d0d06f00d": connection is shut down
[LOG] 0:03.691 DEBUG juju.worker no restart, removing "deadbeef-0bad-400d-8000-4b1d0d06f00d" from known workers
[LOG] 0:03.691 DEBUG juju.api health ping failed: connection is shut down
[LOG] 0:03.692 INFO juju.worker stopped "model worker manager", err: <nil>
[LOG] 0:03.692 DEBUG juju.worker "model worker manager" done: <nil>
[LOG] 0:03.692 DEBUG juju.worker no restart, removing "model worker manager" from known workers
[LOG] 0:03.692 DEBUG juju.state closed state without error
[LOG] 0:03.693 INFO juju.apiserver updating api server certificate
[LOG] 0:03.693 INFO juju.apiserver new certificate addresses: 
[LOG] 0:03.698 ERROR juju.worker.diskmanager error checking if "sdd" is in use: open /dev/sdd: permission denied
[LOG] 0:03.700 ERROR juju.worker.diskmanager error checking if "sde" is in use: open /dev/sde: permission denied
[LOG] 0:03.702 ERROR juju.worker.diskmanager error checking if "sdf" is in use: open /dev/sdf: permission denied
[LOG] 0:03.704 ERROR juju.worker.diskmanager error checking if "sdg" is in use: open /dev/sdg: permission denied
[LOG] 0:03.706 ERROR juju.worker.diskmanager error checking if "sdh" is in use: open /dev/sdh: permission denied
[LOG] 0:03.708 INFO juju.worker.diskmanager block devices changed: [{sda [/dev/disk/by-id/ata-Crucial_CT240M500SSD1_1322093D5111 /dev/disk/by-id/wwn-0x500a0751093d5111]   ata-Crucial_CT240M500SSD1_1322093D5111  228936  true } {sdb [/dev/disk/by-id/ata-Crucial_CT240M500SSD1_14270C86F7ED /dev/disk/by-id/wwn-0x500a07510c86f7ed]   ata-Crucial_CT240M500SSD1_14270C86F7ED  228936  true } {sdc [/dev/disk/by-id/ata-Crucial_CT240M500SSD1_14260C77CAC3 /dev/disk/by-id/wwn-0x500a07510c77cac3]   ata-Crucial_CT240M500SSD1_14260C77CAC3  228936  true } {sdd [/dev/disk/by-id/ata-M4-CT256M4SSD2_000000001307092B4B12 /dev/disk/by-id/wwn-0x500a0751092b4b12]   ata-M4-CT256M4SSD2_000000001307092B4B12  244198  true } {sde [/dev/disk/by-id/ata-INTEL_SSDMCEAC060B3_CVLI251600X7060K /dev/disk/by-id/wwn-0x5001517803d610e9]   ata-INTEL_SSDMCEAC060B3_CVLI251600X7060K  57241  true } {sdf [/dev/disk/by-id/usb-Samsung_M3_Portable_82307DEB0F0000FF-0:0 /dev/disk/by-path/pci-0000:00:14.0-usb-0:1:1.0-scsi-0:0:0:0]   usb-Samsung_M3_Portable_82307DEB0F0000FF-0:0  953869  true } {sdg [/dev/disk/by-id/usb-WDC_WD20_EZRX-00D8PB0_000000000024-0:0 /dev/disk/by-path/pci-0000:00:1a.0-usb-0:1.5:1.0-scsi-0:0:0:0]   usb-WDC_WD20_EZRX-00D8PB0_000000000024-0:0  1907729  true } {sdh [/dev/disk/by-id/usb-Kingston_DataTraveler_3.0_08606E6D414CBF40F70C22C9-0:0 /dev/disk/by-path/pci-0000:00:1d.0-usb-0:1.6:1.0-scsi-0:0:0:0]   usb-Kingston_DataTraveler_3.0_08606E6D414CBF40F70C22C9-0:0  30016  true }]
[LOG] 0:03.708 INFO juju.worker stopped "diskmanager", err: connection is shut down
[LOG] 0:03.708 DEBUG juju.worker "diskmanager" done: connection is shut down
[LOG] 0:03.708 INFO juju.cmd.jujud error pinging *api.state: connection is shut down
[LOG] 0:03.708 ERROR juju.worker fatal "diskmanager": connection is shut down
[LOG] 0:03.708 DEBUG juju.worker.dependency "apiworkers" manifold worker stopped: setting up container support: setting supported containers for machine-0: connection is shut down
[LOG] 0:03.709 INFO juju.worker stopped "engine", err: <nil>
[LOG] 0:03.709 DEBUG juju.worker "engine" done: <nil>
[LOG] 0:03.709 DEBUG juju.worker no restart, removing "engine" from known workers
[LOG] 0:03.721 INFO juju.cmd.jujud update apiserver worker with new certificate
[LOG] 0:03.721 INFO juju.worker.certupdater controller cerificate addresses updated to ["anything" "juju-apiserver" "juju-mongodb" "localhost"]
[LOG] 0:03.721 INFO juju.worker stopped "certupdater", err: <nil>
[LOG] 0:03.721 DEBUG juju.worker "certupdater" done: <nil>
[LOG] 0:03.721 DEBUG juju.worker no restart, removing "certupdater" from known workers
[LOG] 0:03.722 DEBUG juju.state closed state without error
[LOG] 0:03.722 INFO juju.worker stopped "state", err: <nil>
[LOG] 0:03.722 DEBUG juju.worker "state" done: <nil>
[LOG] 0:03.722 DEBUG juju.worker no restart, removing "state" from known workers
[LOG] 0:03.724 DEBUG juju.api health ping failed: connection is shut down
[LOG] 0:03.724 INFO juju.apiserver [D6] user-dummy-admin@local API connection terminated after 3.311863027s, active connections: 0
[LOG] 0:03.724 DEBUG juju.state closed state without error
[LOG] 0:03.724 INFO juju.provider.dummy reset model
[LOG] 0:03.724 DEBUG juju.apiserver API http server exited, final error was: accept tcp [::]:52964: use of closed network connection
[LOG] 0:03.724 DEBUG juju.state closed state without error
[LOG] 0:03.724 INFO juju.apiserver closed listening socket "[::]:52964" with final error: use of closed network connection
[LOG] 0:03.724 DEBUG juju.state closed state without error
[LOG] 0:03.727 INFO juju.testing reset successfully reset admin password
[LOG] 0:03.730 INFO juju.testing reset successfully reset admin password
[LOG] 0:03.731 INFO juju.testing reset successfully reset admin password
OOPS: 112 passed, 1 FAILED
--- FAIL: TestPackage (103.35s)
FAIL