As seen here:
http://ci.jujucharms.com/job/github-merge-juju/1047/console
FAIL: container_initialisation_test.go:182: ContainerSetupSuite.TestContainerProvisionerStarted
[LOG] 0:00.003 DEBUG juju.environs.tools reading v1.* agent binaries
[LOG] 0:00.003 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-bionic-amd64
[LOG] 0:00.008 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-precise-amd64
[LOG] 0:00.008 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-trusty-amd64
[LOG] 0:00.008 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-xenial-amd64
[LOG] 0:00.010 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.010 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.010 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-released-tools.json
[LOG] 0:00.019 DEBUG juju.environs.tools reading v1.* agent binaries
[LOG] 0:00.019 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-bionic-amd64
[LOG] 0:00.020 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-precise-amd64
[LOG] 0:00.020 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-trusty-amd64
[LOG] 0:00.021 INFO juju.environs.testing uploading FAKE tools 2.5-beta1-xenial-amd64
[LOG] 0:00.022 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-5058440958375485438/23/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.022 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-5058440958375485438/23/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.022 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-5058440958375485438/23/tools/streams/v1/index2.json" because of missing information: "content-download" data not found
[LOG] 0:00.023 INFO juju.environs.tools Writing tools/streams/v1/index2.json
[LOG] 0:00.023 INFO juju.environs.tools Writing tools/streams/v1/index.json
[LOG] 0:00.023 INFO juju.environs.tools Writing tools/streams/v1/com.ubuntu.juju-devel-tools.json
[LOG] 0:00.034 DEBUG juju.environs.bootstrap model "controller" supports application/machine networks: true
[LOG] 0:00.034 DEBUG juju.environs.bootstrap network management by juju enabled: true
[LOG] 0:00.034 INFO cmd Loading image metadata
[LOG] 0:00.034 INFO juju.environs.bootstrap looking for bootstrap agent binaries: version=2.5-beta1
[LOG] 0:00.034 DEBUG juju.environs.tools finding agent binaries in stream: "devel, proposed, released"
[LOG] 0:00.034 DEBUG juju.environs.tools reading agent binaries with major.minor version 2.5
[LOG] 0:00.034 DEBUG juju.environs.tools filtering agent binaries by version: 2.5-beta1
[LOG] 0:00.034 DEBUG juju.environs.tools filtering agent binaries by architecture: amd64
[LOG] 0:00.036 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-5058440958375485438/23/tools/streams/v1/index2.sjson" because of missing information: "content-download" data not found
[LOG] 0:00.037 INFO juju.environs.bootstrap found 4 packaged agent binaries
[LOG] 0:00.037 INFO cmd Starting new instance for initial controller
[LOG] 0:00.037 INFO juju.provider.dummy would pick agent binaries from 2.5-beta1-bionic-amd64
[LOG] 0:00.037 INFO juju.provider.dummy creating bootstrap instance
[LOG] 0:00.037 INFO juju.environs.bootstrap newest version: 2.5-beta1
[LOG] 0:00.037 INFO juju.environs.bootstrap picked bootstrap agent binary version: 2.5-beta1
[LOG] 0:00.057 DEBUG juju.cloudconfig.instancecfg Setting numa ctl preference to false
[LOG] 0:00.058 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:43266"
[LOG] 0:00.087 DEBUG juju.state mongodb initialised
[LOG] 0:00.087 INFO juju.state running state anonymously; using unique store id
[LOG] 0:00.087 INFO juju.state starting standard state workers
[LOG] 0:00.087 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:43266"
[LOG] 0:00.087 INFO juju.state creating cloud image metadata storage
[LOG] 0:00.087 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
[LOG] 0:00.087 DEBUG juju.state.presence using $bit operations with Mongo 3.2.15
[LOG] 0:00.087 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:43266"
[LOG] 0:00.087 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:43266"
[LOG] 0:00.087 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:43266"
[LOG] 0:00.091 INFO juju.state initializing controller model deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.202 DEBUG juju.provider.dummy setting password for "admin" to "dummy-secret"
[LOG] 0:00.210 WARNING juju.apiserver.logsink Unable to prime /tmp/juju-unittestfs/check-5058440958375485438/22/logsink.log (proceeding anyway): chown /tmp/juju-unittestfs/check-5058440958375485438/22/logsink.log: operation not permitted
[LOG] 0:00.216 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:43266"
[LOG] 0:00.237 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:43266"
[LOG] 0:00.252 INFO juju.state starting standard state workers
[LOG] 0:00.252 INFO juju.state creating cloud image metadata storage
[LOG] 0:00.252 INFO juju.state started state for model-deadbeef-0bad-400d-8000-4b1d0d06f00d successfully
[LOG] 0:00.254 DEBUG juju.state.presence using $bit operations with Mongo 3.2.15
[LOG] 0:00.254 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:43266"
[LOG] 0:00.254 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:43266"
[LOG] 0:00.254 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:43266"
[LOG] 0:00.255 DEBUG juju.mongo dialled mongodb server at "127.0.0.1:43266"
[LOG] 0:00.285 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:00.285 DEBUG juju.api looked up localhost -> [127.0.0.1]
[LOG] 0:00.295 DEBUG juju.apiserver [1] API connection from 127.0.0.1:53792
[LOG] 0:00.295 DEBUG juju.api successfully dialed "wss://localhost:42279/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.295 INFO juju.api connection established to "wss://localhost:42279/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.295 DEBUG juju.apiserver <- [1] {"request-id":1,"type":"Admin","version":3,"request":"Login","params":"'params redacted'"}
[LOG] 0:00.300 DEBUG juju.apiserver model login: user admin has "superuser" for controller; "admin" for model deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.300 DEBUG juju.apiserver model login: user-admin for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:00.301 DEBUG juju.apiserver -> [1] 5.411459ms {"request-id":1,"response":"'body redacted'"} Admin[""].Login
[LOG] 0:00.302 DEBUG juju.state setting apiHostPorts: [[localhost:42279]]
[LOG] 0:00.302 DEBUG juju.state setting apiHostPortsForAgents: [[localhost:42279]]
[LOG] 0:00.315 DEBUG juju.state.cloudimagemetadata inserting cloud image metadata for released:region:trusty:amd64:::test
[LOG] 0:00.324 INFO juju.state new machine "0" has preferred addresses: private "localhost", public "localhost"
[LOG] 0:00.357 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:00.358 DEBUG juju.api looked up localhost -> [127.0.0.1]
[LOG] 0:00.367 DEBUG juju.apiserver [2] API connection from 127.0.0.1:53828
[LOG] 0:00.367 DEBUG juju.api successfully dialed "wss://localhost:42279/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.367 INFO juju.api connection established to "wss://localhost:42279/model/deadbeef-0bad-400d-8000-4b1d0d06f00d/api"
[LOG] 0:00.367 DEBUG juju.apiserver <- [2] {"request-id":1,"type":"Admin","version":3,"request":"Login","params":"'params redacted'"}
[LOG] 0:01.232 INFO juju.apiserver.connection agent login: machine-0 for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:01.232 DEBUG juju.apiserver model login: machine-0 for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:01.233 DEBUG juju.apiserver -> [2] 865.35284ms {"request-id":1,"response":"'body redacted'"} Admin[""].Login
API: login as "machine-0" successful
[LOG] 0:01.234 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:01.234 DEBUG juju.apiserver <- [2] machine-0 {"request-id":2,"type":"Provisioner","version":6,"request":"WatchForModelConfigChanges","params":"'params redacted'"}
[LOG] 0:01.245 INFO juju.state new machine "1" has preferred addresses: private "", public ""
[LOG] 0:01.262 DEBUG juju.apiserver -> [2] machine-0 27.393335ms {"request-id":2,"response":"'body redacted'"} Provisioner[""].WatchForModelConfigChanges
[LOG] 0:01.262 DEBUG juju.apiserver <- [2] machine-0 {"request-id":3,"type":"Provisioner","version":6,"request":"StateAddresses","params":"'params redacted'"}
[LOG] 0:01.262 DEBUG juju.apiserver <- [2] machine-0 {"request-id":4,"type":"NotifyWatcher","version":1,"id":"1","request":"Next","params":"'params redacted'"}
[LOG] 0:01.263 DEBUG juju.network selected "localhost" as controller address, using scope ""
[LOG] 0:01.263 DEBUG juju.apiserver -> [2] machine-0 1.11932ms {"request-id":3,"response":"'body redacted'"} Provisioner[""].StateAddresses
[LOG] 0:01.263 DEBUG juju.apiserver <- [2] machine-0 {"request-id":5,"type":"Provisioner","version":6,"request":"APIAddresses","params":"'params redacted'"}
[LOG] 0:01.266 DEBUG juju.apiserver -> [2] machine-0 2.988701ms {"request-id":5,"response":"'body redacted'"} Provisioner[""].APIAddresses
[LOG] 0:01.267 DEBUG juju.apiserver <- [2] machine-0 {"request-id":6,"type":"Provisioner","version":6,"request":"CACert","params":"'params redacted'"}
[LOG] 0:01.267 DEBUG juju.apiserver -> [2] machine-0 329.226µs {"request-id":6,"response":"'body redacted'"} Provisioner[""].CACert
[LOG] 0:01.267 DEBUG juju.apiserver <- [2] machine-0 {"request-id":7,"type":"Provisioner","version":6,"request":"ModelUUID","params":"'params redacted'"}
[LOG] 0:01.267 DEBUG juju.apiserver -> [2] machine-0 50.881µs {"request-id":7,"response":"'body redacted'"} Provisioner[""].ModelUUID
[LOG] 0:01.267 DEBUG juju.apiserver <- [2] machine-0 {"request-id":8,"type":"Provisioner","version":6,"request":"WatchModelMachines","params":"'params redacted'"}
[LOG] 0:01.268 DEBUG juju.apiserver -> [2] machine-0 650.247µs {"request-id":8,"response":"'body redacted'"} Provisioner[""].WatchModelMachines
[LOG] 0:01.268 DEBUG juju.apiserver <- [2] machine-0 {"request-id":9,"type":"Provisioner","version":6,"request":"WatchMachineErrorRetry","params":"'params redacted'"}
[LOG] 0:01.268 DEBUG juju.apiserver -> [2] machine-0 76.844µs {"request-id":9,"response":"'body redacted'"} Provisioner[""].WatchMachineErrorRetry
[LOG] 0:01.268 DEBUG juju.apiserver <- [2] machine-0 {"request-id":10,"type":"StringsWatcher","version":1,"id":"2","request":"Next","params":"'params redacted'"}
[LOG] 0:01.269 DEBUG juju.apiserver <- [2] machine-0 {"request-id":11,"type":"Provisioner","version":6,"request":"ModelConfig","params":"'params redacted'"}
[LOG] 0:01.269 DEBUG juju.apiserver <- [2] machine-0 {"request-id":12,"type":"NotifyWatcher","version":1,"id":"3","request":"Next","params":"'params redacted'"}
[LOG] 0:01.269 DEBUG juju.apiserver -> [2] machine-0 789.413µs {"request-id":11,"response":"'body redacted'"} Provisioner[""].ModelConfig
[LOG] 0:01.270 DEBUG juju.apiserver <- [2] machine-0 {"request-id":13,"type":"Provisioner","version":6,"request":"ControllerConfig","params":"'params redacted'"}
[LOG] 0:01.270 DEBUG juju.apiserver -> [2] machine-0 297.206µs {"request-id":13,"response":"'body redacted'"} Provisioner[""].ControllerConfig
[LOG] 0:01.270 DEBUG juju.apiserver <- [2] machine-0 {"request-id":14,"type":"Provisioner","version":6,"request":"ModelConfig","params":"'params redacted'"}
[LOG] 0:01.271 DEBUG juju.apiserver <- [2] machine-0 {"request-id":15,"type":"Provisioner","version":6,"request":"MachinesWithTransientErrors","params":"'params redacted'"}
[LOG] 0:01.271 DEBUG juju.apiserver -> [2] machine-0 694.136µs {"request-id":14,"response":"'body redacted'"} Provisioner[""].ModelConfig
[LOG] 0:01.286 DEBUG juju.apiserver -> [2] machine-0 14.966707ms {"request-id":15,"response":"'body redacted'"} Provisioner[""].MachinesWithTransientErrors
[LOG] 0:01.286 DEBUG juju.apiserver <- [2] machine-0 {"request-id":16,"type":"Provisioner","version":6,"request":"Life","params":"'params redacted'"}
[LOG] 0:01.286 DEBUG juju.apiserver -> [2] machine-0 569.984µs {"request-id":16,"response":"'body redacted'"} Provisioner[""].Life
[LOG] 0:01.287 DEBUG juju.apiserver <- [2] machine-0 {"request-id":17,"type":"Provisioner","version":6,"request":"InstanceId","params":"'params redacted'"}
[LOG] 0:01.287 DEBUG juju.apiserver -> [2] machine-0 540.073µs {"request-id":17,"response":"'body redacted'"} Provisioner[""].InstanceId
[LOG] 0:01.287 DEBUG juju.apiserver <- [2] machine-0 {"request-id":18,"type":"Provisioner","version":6,"request":"Status","params":"'params redacted'"}
[LOG] 0:01.291 DEBUG juju.apiserver -> [2] machine-0 3.613105ms {"request-id":18,"response":"'body redacted'"} Provisioner[""].Status
[LOG] 0:01.291 INFO juju.provisioner found machine pending provisioning id:1, details:1
[LOG] 0:01.291 DEBUG juju.apiserver <- [2] machine-0 {"request-id":19,"type":"Provisioner","version":6,"request":"InstanceId","params":"'params redacted'"}
[LOG] 0:01.292 DEBUG juju.apiserver -> [2] machine-0 747.794µs {"request-id":19,"response":"'body redacted'"} Provisioner[""].InstanceId
[LOG] 0:01.292 INFO juju.provisioner machine 0 already started as instance "localhost"
[LOG] 0:01.292 DEBUG juju.apiserver <- [2] machine-0 {"request-id":20,"type":"Provisioner","version":6,"request":"InstanceId","params":"'params redacted'"}
[LOG] 0:01.293 DEBUG juju.apiserver -> [2] machine-0 559.959µs {"request-id":20,"response":"'body redacted'"} Provisioner[""].InstanceId
[LOG] 0:01.293 DEBUG juju.apiserver <- [2] machine-0 {"request-id":21,"type":"Provisioner","version":6,"request":"InstanceId","params":"'params redacted'"}
[LOG] 0:01.293 DEBUG juju.apiserver -> [2] machine-0 443.243µs {"request-id":21,"response":"'body redacted'"} Provisioner[""].InstanceId
[LOG] 0:01.294 INFO juju.provisioner provisioner-harvest-mode is set to destroyed; unknown instances not stopped []
[LOG] 0:01.294 DEBUG juju.apiserver <- [2] machine-0 {"request-id":22,"type":"Provisioner","version":6,"request":"DistributionGroupByMachineId","params":"'params redacted'"}
[LOG] 0:01.294 DEBUG juju.apiserver -> [2] machine-0 283.716µs {"request-id":22,"response":"'body redacted'"} Provisioner[""].DistributionGroupByMachineId
[LOG] 0:01.294 DEBUG juju.apiserver <- [2] machine-0 {"request-id":23,"type":"Provisioner","version":6,"request":"ModelConfig","params":"'params redacted'"}
[LOG] 0:01.295 DEBUG juju.apiserver -> [2] machine-0 576.68µs {"request-id":23,"response":"'body redacted'"} Provisioner[""].ModelConfig
[LOG] 0:01.295 DEBUG juju.apiserver <- [2] machine-0 {"request-id":24,"type":"Provisioner","version":6,"request":"ProvisioningInfo","params":"'params redacted'"}
[LOG] 0:01.306 DEBUG juju.state.cloudimagemetadata searching for image metadata cloudimagemetadata.MetadataFilter{Region:"", Series:[]string{"bionic"}, Arches:[]string{"amd64"}, Stream:"released", VirtType:"", RootStorageType:""}
[LOG] 0:01.306 DEBUG juju.apiserver.provisioner got from controller 0 metadata
[LOG] 0:01.306 DEBUG juju.state.cloudimagemetadata searching for image metadata cloudimagemetadata.MetadataFilter{Region:"", Series:[]string{"bionic"}, Arches:[]string{"amd64"}, Stream:"released", VirtType:"", RootStorageType:""}
[LOG] 0:01.306 DEBUG juju.apiserver.provisioner got from data sources 0 metadata
[LOG] 0:01.306 DEBUG juju.apiserver.provisioner available image metadata for provisioning: []
[LOG] 0:01.307 DEBUG juju.apiserver -> [2] machine-0 11.389199ms {"request-id":24,"response":"'body redacted'"} Provisioner[""].ProvisioningInfo
[LOG] 0:01.307 DEBUG juju.apiserver <- [2] machine-0 {"request-id":25,"type":"Provisioner","version":6,"request":"SetPasswords","params":"'params redacted'"}
[LOG] 0:01.310 INFO juju.apiserver.common setting password for "machine-1"
[LOG] 0:01.310 DEBUG juju.apiserver -> [2] machine-0 2.781088ms {"request-id":25,"response":"'body redacted'"} Provisioner[""].SetPasswords
[LOG] 0:01.310 DEBUG juju.apiserver <- [2] machine-0 {"request-id":26,"type":"Provisioner","version":6,"request":"FindTools","params":"'params redacted'"}
[LOG] 0:01.315 DEBUG juju.environs.tools finding agent binaries in stream: "devel, proposed, released"
[LOG] 0:01.315 DEBUG juju.environs.tools reading agent binaries with major version -1
[LOG] 0:01.315 DEBUG juju.environs.tools filtering agent binaries by version: 2.5-beta1
[LOG] 0:01.315 DEBUG juju.environs.tools filtering agent binaries by series: bionic
[LOG] 0:01.315 DEBUG juju.environs.tools filtering agent binaries by architecture: amd64
[LOG] 0:01.316 DEBUG juju.environs.simplestreams skipping index "file:///tmp/juju-unittestfs/check-5058440958375485438/23/tools/streams/v1/index2.sjson" because of missing information: "content-download" data not found
[LOG] 0:01.317 DEBUG juju.apiserver -> [2] machine-0 7.229839ms {"request-id":26,"response":"'body redacted'"} Provisioner[""].FindTools
[LOG] 0:01.318 DEBUG juju.apiserver <- [2] machine-0 {"request-id":27,"type":"Provisioner","version":6,"request":"SetInstanceStatus","params":"'params redacted'"}
[LOG] 0:01.318 DEBUG juju.apiserver.provisioner SetInstanceStatus called with: params.EntityStatusArgs{Tag:"machine-1", Status:"allocating", Info:"starting", Data:map[string]interface {}(nil)}
[LOG] 0:01.321 DEBUG juju.apiserver -> [2] machine-0 3.344949ms {"request-id":27,"response":"'body redacted'"} Provisioner[""].SetInstanceStatus
[LOG] 0:01.321 INFO juju.provisioner trying machine 1 StartInstance in availability zone zone1
[LOG] 0:01.321 INFO juju.provider.dummy dummy startinstance, machine 1
[LOG] 0:01.321 INFO juju.provider.dummy would pick agent binaries from 2.5-beta1-bionic-amd64
[LOG] 0:01.321 DEBUG juju.provider.dummy StartInstance addresses: [controller-0.dns local-machine:127.0.0.1 local-machine:::1]
[LOG] 0:01.321 DEBUG juju.apiserver <- [2] machine-0 {"request-id":28,"type":"Provisioner","version":6,"request":"SetInstanceInfo","params":"'params redacted'"}
[LOG] 0:01.322 DEBUG juju.state no device addresses to set
[LOG] 0:01.332 DEBUG juju.apiserver -> [2] machine-0 10.513793ms {"request-id":28,"response":"'body redacted'"} Provisioner[""].SetInstanceInfo
[LOG] 0:01.332 INFO juju.provisioner started machine 1 as instance controller-0 with hardware "arch=amd64 cores=1 mem=4096M root-disk=8192M availability-zone=zone1", network config [], volumes [], volume attachments map[], subnets to zones map[]
[LOG] 0:01.333 DEBUG juju.apiserver <- [2] machine-0 {"request-id":29,"type":"Provisioner","version":6,"request":"Life","params":"'params redacted'"}
[LOG] 0:01.333 DEBUG juju.apiserver -> [2] machine-0 402.309µs {"request-id":29,"response":"'body redacted'"} Provisioner[""].Life
[LOG] 0:01.333 DEBUG juju.apiserver <- [2] machine-0 {"request-id":30,"type":"Provisioner","version":6,"request":"SetSupportedContainers","params":"'params redacted'"}
[LOG] 0:01.339 DEBUG juju.apiserver -> [2] machine-0 5.296024ms {"request-id":30,"response":"'body redacted'"} Provisioner[""].SetSupportedContainers
[LOG] 0:01.339 DEBUG juju.environs ControllerInstances returned: [localhost]
[LOG] 0:01.340 DEBUG juju.apiserver <- [2] machine-0 {"request-id":31,"type":"Provisioner","version":6,"request":"WatchContainers","params":"'params redacted'"}
[LOG] 0:01.341 DEBUG juju.apiserver -> [2] machine-0 1.203751ms {"request-id":31,"response":"'body redacted'"} Provisioner[""].WatchContainers
[LOG] 0:01.341 DEBUG juju.apiserver <- [2] machine-0 {"request-id":32,"type":"StringsWatcher","version":1,"id":"4","request":"Next","params":"'params redacted'"}
[LOG] 0:01.343 INFO juju.state new machine "1/kvm/0" has preferred addresses: private "", public ""
[LOG] 0:01.507 DEBUG juju.apiserver -> [2] machine-0 238.71208ms {"request-id":10,"response":"'body redacted'"} StringsWatcher["2"].Next
[LOG] 0:01.507 DEBUG juju.apiserver <- [2] machine-0 {"request-id":33,"type":"StringsWatcher","version":1,"id":"2","request":"Next","params":"'params redacted'"}
[LOG] 0:01.507 DEBUG juju.apiserver <- [2] machine-0 {"request-id":34,"type":"Provisioner","version":6,"request":"Life","params":"'params redacted'"}
[LOG] 0:01.508 DEBUG juju.apiserver -> [2] machine-0 784.355µs {"request-id":34,"response":"'body redacted'"} Provisioner[""].Life
[LOG] 0:01.508 DEBUG juju.apiserver <- [2] machine-0 {"request-id":35,"type":"Provisioner","version":6,"request":"InstanceId","params":"'params redacted'"}
[LOG] 0:01.509 DEBUG juju.apiserver -> [2] machine-0 479.791µs {"request-id":35,"response":"'body redacted'"} Provisioner[""].InstanceId
[LOG] 0:01.509 DEBUG juju.apiserver <- [2] machine-0 {"request-id":36,"type":"Provisioner","version":6,"request":"KeepInstance","params":"'params redacted'"}
[LOG] 0:01.510 DEBUG juju.apiserver -> [2] machine-0 485.545µs {"request-id":36,"response":"'body redacted'"} Provisioner[""].KeepInstance
[LOG] 0:01.510 DEBUG juju.apiserver <- [2] machine-0 {"request-id":37,"type":"Provisioner","version":6,"request":"InstanceId","params":"'params redacted'"}
[LOG] 0:01.510 DEBUG juju.apiserver -> [2] machine-0 436.334µs {"request-id":37,"response":"'body redacted'"} Provisioner[""].InstanceId
[LOG] 0:01.510 DEBUG juju.apiserver <- [2] machine-0 {"request-id":38,"type":"Provisioner","version":6,"request":"InstanceId","params":"'params redacted'"}
[LOG] 0:01.511 DEBUG juju.apiserver -> [2] machine-0 449.17µs {"request-id":38,"response":"'body redacted'"} Provisioner[""].InstanceId
[LOG] 0:01.511 INFO juju.provisioner provisioner-harvest-mode is set to destroyed; unknown instances not stopped []
[LOG] 0:01.511 INFO juju.provisioner stopping known instances [0xc4206ae580]
[LOG] 0:01.511 INFO juju.provisioner removing dead machine "1"
[LOG] 0:01.511 DEBUG juju.apiserver <- [2] machine-0 {"request-id":39,"type":"Provisioner","version":6,"request":"MarkMachinesForRemoval","params":"'params redacted'"}
[LOG] 0:01.519 DEBUG juju.apiserver -> [2] machine-0 7.347934ms {"request-id":39,"response":"'body redacted'"} Provisioner[""].MarkMachinesForRemoval
container_initialisation_test.go:205:
s.assertContainerProvisionerStarted(c, m, ctype)
container_initialisation_test.go:179:
// the container worker should have created the provisioner
c.Assert(atomic.LoadUint32(&provisionerStarted) > 0, jc.IsTrue)
... obtained bool = false
[LOG] 0:01.535 INFO juju.provisioner Shutting down provisioner task machine-0
[LOG] 0:01.535 DEBUG juju.apiserver <- [2] machine-0 {"request-id":40,"type":"NotifyWatcher","version":1,"id":"1","request":"Stop","params":"'params redacted'"}
[LOG] 0:01.535 DEBUG juju.apiserver <- [2] machine-0 {"request-id":41,"type":"NotifyWatcher","version":1,"id":"3","request":"Stop","params":"'params redacted'"}
[LOG] 0:01.535 DEBUG juju.apiserver <- [2] machine-0 {"request-id":42,"type":"StringsWatcher","version":1,"id":"2","request":"Stop","params":"'params redacted'"}
[LOG] 0:01.535 DEBUG juju.apiserver -> [2] machine-0 193.361µs {"request-id":40,"response":"'body redacted'"} NotifyWatcher["1"].Stop
[LOG] 0:01.535 DEBUG juju.apiserver -> [2] machine-0 266.68619ms {"request-id":12,"error":"watcher has been stopped","error-code":"stopped","response":"'body redacted'"} NotifyWatcher["3"].Next
[LOG] 0:01.535 DEBUG juju.apiserver -> [2] machine-0 124.721µs {"request-id":41,"response":"'body redacted'"} NotifyWatcher["3"].Stop
[LOG] 0:01.535 DEBUG juju.apiserver -> [2] machine-0 98.492µs {"request-id":42,"response":"'body redacted'"} StringsWatcher["2"].Stop
[LOG] 0:01.535 DEBUG juju.apiserver -> [2] machine-0 273.283538ms {"request-id":4,"error":"watcher has been stopped","error-code":"stopped","response":"'body redacted'"} NotifyWatcher["1"].Next
[LOG] 0:01.536 DEBUG juju.apiserver -> [2] machine-0 28.197787ms {"request-id":33,"error":"watcher has been stopped","error-code":"stopped","response":"'body redacted'"} StringsWatcher["2"].Next
[LOG] 0:01.536 DEBUG juju.api RPC connection died
[LOG] 0:01.536 DEBUG juju.api RPC connection died
[LOG] 0:01.536 DEBUG juju.apiserver -> [2] machine-0 194.835694ms {"request-id":32,"error":"watcher has been stopped","error-code":"stopped","response":"'body redacted'"} StringsWatcher["4"].Next
[LOG] 0:01.536 DEBUG juju.rpc error closing codec: write tcp 127.0.0.1:42279->127.0.0.1:53828: write: broken pipe
[LOG] 0:01.536 INFO juju.apiserver.connection agent disconnected: machine-0 for deadbeef-0bad-400d-8000-4b1d0d06f00d
[LOG] 0:01.536 DEBUG juju.state closed state without error
[LOG] 0:01.536 INFO juju.provider.dummy reset model
[LOG] 0:01.536 DEBUG juju.apiserver [2] machine-0 API connection terminated after 1.169604529s
[LOG] 0:01.536 DEBUG juju.provider.dummy closing httpServer
[LOG] 0:01.536 DEBUG juju.provider.dummy stopping apiServer
[LOG] 0:01.536 DEBUG juju.rpc error closing codec: write tcp 127.0.0.1:42279->127.0.0.1:53792: write: broken pipe
[LOG] 0:01.536 DEBUG juju.apiserver [1] user-admin API connection terminated after 1.241766487s
[LOG] 0:01.543 DEBUG juju.provider.dummy closing apiStatePool
[LOG] 0:01.544 DEBUG juju.state closed state without error
[LOG] 0:01.544 DEBUG juju.provider.dummy resetting MgoServer
[LOG] 0:01.545 INFO juju.testing reset successfully reset admin password
[LOG] 0:01.547 INFO juju.testing reset successfully reset admin password
You can get (un)lucky and replicate this locally.