If I SSH into that machine directly, and run
$ lxc image delete ubuntu-trusty
$ time lxc image copy ubuntu:trusty --alias ubuntu-trusty local:
it takes only 5s for the image to actually copy.
However, our logging seems to say
2016-03-17 12:16:02 INFO juju.tools.lxdclient client_image.go:85 copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 5%
2016-03-17 12:16:02 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId":352,"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: 5%","Data":null}]}}
2016-03-17 12:16:02 TRACE juju.apiserver apiserver.go:289 -> [4] machine-0 {"RequestId":352,"Response":{"Results":[{"Error":null}]}}
2016-03-17 12:16:02 INFO juju.tools.lxdclient client_image.go:85 copying image for ubuntu-trusty from https://cloud-images.ubuntu.com/releases: 6%
2016-03-17 12:16:02 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId":353,"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: 6%","Data":null}]}}
2016-03-17 12:16:03 TRACE juju.apiserver apiserver.go:289 -> [4] machine-0 {"RequestId":353,"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: 7%
2016-03-17 12:16:03 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId":354,"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: 7%","Data":null}]}}
That it is taking 1s for every % of copy being finished. So it appears that maybe we're just being too slow to record the copy progress.
If I SSH into that machine directly, and run
$ lxc image delete ubuntu-trusty
$ time lxc image copy ubuntu:trusty --alias ubuntu-trusty local:
it takes only 5s for the image to actually copy.
However, our logging seems to say lxdclient client_image.go:85 copying image for ubuntu-trusty from https:/ /cloud- images. ubuntu. com/releases: 5% :352,"Type" :"Provisioner" ,"Version" :2,"Request" :"SetInstanceSt atus"," Params" :{"Entities" :[{"Tag" :"machine- 0-lxd-5" ,"Status" :"allocating" ,"Info" :"copying image for ubuntu-trusty from https:/ /cloud- images. ubuntu. com/releases: 5%","Data":null}]}} :352,"Response" :{"Results" :[{"Error" :null}] }} lxdclient client_image.go:85 copying image for ubuntu-trusty from https:/ /cloud- images. ubuntu. com/releases: 6% :353,"Type" :"Provisioner" ,"Version" :2,"Request" :"SetInstanceSt atus"," Params" :{"Entities" :[{"Tag" :"machine- 0-lxd-5" ,"Status" :"allocating" ,"Info" :"copying image for ubuntu-trusty from https:/ /cloud- images. ubuntu. com/releases: 6%","Data":null}]}} :353,"Response" :{"Results" :[{"Error" :null}] }} lxdclient client_image.go:85 copying image for ubuntu-trusty from https:/ /cloud- images. ubuntu. com/releases: 7% :354,"Type" :"Provisioner" ,"Version" :2,"Request" :"SetInstanceSt atus"," Params" :{"Entities" :[{"Tag" :"machine- 0-lxd-5" ,"Status" :"allocating" ,"Info" :"copying image for ubuntu-trusty from https:/ /cloud- images. ubuntu. com/releases: 7%","Data":null}]}}
2016-03-17 12:16:02 INFO juju.tools.
2016-03-17 12:16:02 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId"
2016-03-17 12:16:02 TRACE juju.apiserver apiserver.go:289 -> [4] machine-0 {"RequestId"
2016-03-17 12:16:02 INFO juju.tools.
2016-03-17 12:16:02 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId"
2016-03-17 12:16:03 TRACE juju.apiserver apiserver.go:289 -> [4] machine-0 {"RequestId"
2016-03-17 12:16:03 INFO juju.tools.
2016-03-17 12:16:03 TRACE juju.apiserver apiserver.go:275 <- [4] machine-0 {"RequestId"
That it is taking 1s for every % of copy being finished. So it appears that maybe we're just being too slow to record the copy progress.