Comment 3 for bug 1558061

for just some key points:

start of copying

2016-03-17 12:16:00 INFO juju.tools.lxdclient client_image.go:82 found image from https://cloud-images.ubuntu.com/releases for trusty = 75182b1241be475a64e68a518ce853e800e9b50397d2f152816c24f038c94d6e
2016-03-17 12:16:01 INFO juju.tools.lxdclient client_image.go:85 copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 1%
2016-03-17 12:16:01 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId":348,"Type":"Provisioner","Version":2,"Request":"SetInstanceStatus","Params":{"Entities":[{"Tag":"machine-0-lxd-5","Status":"allocating","Info":"copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 1%","Data":null}]}}

copying is still very early, but we think we're ready to start the instance:
2016-03-17 12:16:03 TRACE juju.apiserver apiserver.go:289 -> [4] machine-0 {"RequestId":355,"Response":{"Results":[{"Error":null}]}}
2016-03-17 12:16:03 INFO juju.tools.lxdclient client_image.go:85 copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 9%
2016-03-17 12:16:03 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId":356,"Type":"Provisioner","Version":2,"Request":"SetInstanceStatus","Params":{"Entities":[{"Tag":"machine-0-lxd-5","Status":"allocating","Info":"copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 9%","Data":null}]}}
2016-03-17 12:16:04 INFO juju.container.lxd lxd.go:131 starting instance "juju-machine-0-lxd-5" (image "ubuntu-trusty")...
2016-03-17 12:16:04 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId":357,"Type":"Provisioner","Version":2,"Request":"SetInstanceStatus","Params":{"Entities":[{"Tag":"machine-0-lxd-5","Status":"allocating","Info":"Starting container","Data":null}]}}

^^ we're at the point of "Starting container" which doesn't get called until after EnsureImageExists() returns.

when the copying is close to done:

2016-03-17 12:16:48 INFO juju.tools.lxdclient client_image.go:85 copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 79%
2016-03-17 12:16:48 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId":429,"Type":"Provisioner","Version":2,"Request":"SetInstanceStatus","Params":{"Entities":[{"Tag":"machine-0-lxd-5","Status":"allocating","Info":"copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 79%","Data":null}]}}
2016-03-17 12:16:48 INFO juju.tools.lxdclient client_image.go:85 copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 80%
2016-03-17 12:16:48 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId":430,"Type":"Provisioner","Version":2,"Request":"SetInstanceStatus","Params":{"Entities":[{"Tag":"machine-0-lxd-5","Status":"allocating","Info":"copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 80%","Data":null}]}}
2016-03-17 12:16:49 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId":431,"Type":"Provisioner","Version":2,"Request":"SetInstanceStatus","Params":{"Entities":[{"Tag":"machine-0-lxd-5","Status":"running","Info":"Container started","Data":null}]}}

^- We're at the point where we think we're actually starting the container, but the Copy is still listed as only 80% done.

2016-03-17 12:16:55 INFO juju.tools.lxdclient client_image.go:85 copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 100%
2016-03-17 12:16:55 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId":452,"Type":"Provisioner","Version":2,"Request":"SetInstanceStatus","Params":{"Entities":[{"Tag":"machine-0-lxd-5","Status":"allocating","Info":"copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 100%","Data":null}]}}
2016-03-17 12:16:56 TRACE juju.apiserver apiserver.go:289 -> [4] machine-0 {"RequestId":452,"Response":{"Results":[{"Error":null}]}}

nearly 6s later we get the last "Copying" message. Which is long after we think the container has already started.