failed when try to create a volume from a image

[li,chen]

I'm working under CentOS 6.4 + Havava.

I'm using ceph working as cinder backend.
For, glance, image is stored in local file system.

I want to create a volume from a image.
So I run command
        "cinder create --image-id ${image_id} --display-name ${name} ${size}"

First the volume is under status "downloading":

    cinder list
    +--------------------------------------+-------------+--------------+------+-------------+----------+-------------+
    | ID | Status | Display Name | Size | Volume Type | Bootable | Attached to |
    +--------------------------------------+-------------+--------------+------+-------------+----------+-------------+
    | d626adb7-5220-4e39-a0a6-0de34a9f651c | downloading | my_image_volume| 70 | None | false | |
    +--------------------------------------+-------------+--------------+------+-------------+----------+-------------+

I assume cinder is copy the image file from glance.

But then, I get error in ciner volume.log, and the volume's status turned into error.

    cinder list
    +--------------------------------------+--------+--------------+------+-------------+----------+-------------+
    | ID | Status | Display Name | Size | Volume Type | Bootable | Attached to |
    +--------------------------------------+--------+--------------+------+-------------+----------+-------------+
    | d626adb7-5220-4e39-a0a6-0de34a9f651c | error | my_image_volume| 70 | None | false | |
    +--------------------------------------+--------+--------------+------+-------------+----------+-------------+

Anyone know why this happening ???

Error message in volume.log:

2014-03-04 05:49:11 ERROR [cinder.volume.manager] Error: ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 250, in create_volume\n image_location)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 189, in _create_volume\n image_id)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 602, in _copy_image_to_volume\n image_id)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/drivers/rbd.py", line 275, in copy_image_to_volume\n tmp.name)\n', ' File "/usr/lib/python2.6/site-packages/cinder/image/image_utils.py", line 218, in fetch_to_raw\n fetch(context, image_service, image_id, tmp, user_id, project_id)\n', ' File "/usr/lib/python2.6/site-packages/cinder/image/image_utils.py", line 201, in fetch\n image_service.download(context, image_id, image_file)\n', ' File "/usr/lib64/python2.6/contextlib.py", line 34, in __exit__\n self.gen.throw(type, value, traceback)\n', ' File "/usr/lib/python2.6/site-packages/cinder/utils.py", line 946, in remove_path_on_error\n delete_if_exists(path)\n', ' File "/usr/lib64/python2.6/contextlib.py", line 23, in __exit__\n self.gen.next()\n', ' File "/usr/lib/python2.6/site-packages/cinder/utils.py", line 943, in remove_path_on_error\n yield\n', ' File "/usr/lib/python2.6/site-packages/cinder/image/image_utils.py", line 201, in fetch\n image_service.download(context, image_id, image_file)\n', ' File "/usr/lib/python2.6/site-packages/cinder/image/glance.py", line 235, in download\n data.write(chunk)\n', 'IOError: [Errno 28] No space left on device\n']
2014-03-04 05:49:11 ERROR [cinder.volume.driver] Recovering from a failed execute. Try number 1
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/cinder/volume/driver.py", line 88, in _try_execute
    self._execute(*command, **kwargs)
  File "/usr/lib/python2.6/site-packages/cinder/utils.py", line 190, in execute
    cmd=' '.join(cmd))
ProcessExecutionError: Unexpected error while running command.
Command: rbd create --pool specweb --size 71680 volume-d626adb7-5220-4e39-a0a6-0de34a9f651c --new-format
Exit code: 1
Stdout: ''
Stderr: 'rbd: create error: (17) File exists\n2014-03-04 05:49:11.565446 7fb55f8f2760 -1 librbd: rbd image volume-d626adb7-5220-4e39-a0a6-0de34a9f651c already exists\n'
2014-03-04 05:49:12 ERROR [cinder.volume.driver] Recovering from a failed execute. Try number 2
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/cinder/volume/driver.py", line 88, in _try_execute
    self._execute(*command, **kwargs)
  File "/usr/lib/python2.6/site-packages/cinder/utils.py", line 190, in execute
    cmd=' '.join(cmd))
ProcessExecutionError: Unexpected error while running command.
Command: rbd create --pool specweb --size 71680 volume-d626adb7-5220-4e39-a0a6-0de34a9f651c --new-format
Exit code: 1
Stdout: ''
Stderr: 'rbd: create error: (17) File exists\n2014-03-04 05:49:12.675129 7f591067e760 -1 librbd: rbd image volume-d626adb7-5220-4e39-a0a6-0de34a9f651c already exists\n'
2014-03-04 05:49:16 ERROR [cinder.volume.manager] Error: ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 250, in create_volume\n image_location)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 180, in _create_volume\n model_update = self.driver.create_volume(volume_ref)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/drivers/rbd.py", line 116, in create_volume\n self._try_execute(*args)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/driver.py", line 88, in _try_execute\n self._execute(*command, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/cinder/utils.py", line 190, in execute\n cmd=\' \'.join(cmd))\n', "ProcessExecutionError: Unexpected error while running command.\nCommand: rbd create --pool specweb --size 71680 volume-d626adb7-5220-4e39-a0a6-0de34a9f651c --new-format\nExit code: 1\nStdout: ''\nStderr: 'rbd: create error: (17) File exists\\n2014-03-04 05:49:16.722241 7f9264b76760 -1 librbd: rbd image volume-d626adb7-5220-4e39-a0a6-0de34a9f651c already exists\\n'\n"]
2014-03-04 05:49:17 ERROR [cinder.volume.driver] Recovering from a failed execute. Try number 1
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/cinder/volume/driver.py", line 88, in _try_execute
    self._execute(*command, **kwargs)
  File "/usr/lib/python2.6/site-packages/cinder/utils.py", line 190, in execute
    cmd=' '.join(cmd))
ProcessExecutionError: Unexpected error while running command.
Command: rbd create --pool specweb --size 71680 volume-d626adb7-5220-4e39-a0a6-0de34a9f651c --new-format
Exit code: 1
Stdout: ''
Stderr: 'rbd: create error: (17) File exists\n2014-03-04 05:49:17.152936 7fd25dec2760 -1 librbd: rbd image volume-d626adb7-5220-4e39-a0a6-0de34a9f651c already exists\n'
2014-03-04 05:49:18 ERROR [cinder.volume.driver] Recovering from a failed execute. Try number 2
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/cinder/volume/driver.py", line 88, in _try_execute
    self._execute(*command, **kwargs)
  File "/usr/lib/python2.6/site-packages/cinder/utils.py", line 190, in execute
    cmd=' '.join(cmd))
ProcessExecutionError: Unexpected error while running command.
Command: rbd create --pool specweb --size 71680 volume-d626adb7-5220-4e39-a0a6-0de34a9f651c --new-format
Exit code: 1
Stdout: ''
Stderr: 'rbd: create error: (17) File exists2014-03-04 05:49:18.216348 7f6580deb760 -1 \nlibrbd: rbd image volume-d626adb7-5220-4e39-a0a6-0de34a9f651c already exists\n'
2014-03-04 05:49:22 ERROR [cinder.volume.manager] Error: ['Traceback (most recent call last):\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 250, in create_volume\n image_location)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 180, in _create_volume\n model_update = self.driver.create_volume(volume_ref)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/drivers/rbd.py", line 116, in create_volume\n self._try_execute(*args)\n', ' File "/usr/lib/python2.6/site-packages/cinder/volume/driver.py", line 88, in _try_execute\n self._execute(*command, **kwargs)\n', ' File "/usr/lib/python2.6/site-packages/cinder/utils.py", line 190, in execute\n cmd=\' \'.join(cmd))\n', "ProcessExecutionError: Unexpected error while running command.\nCommand: rbd create --pool specweb --size 71680 volume-d626adb7-5220-4e39-a0a6-0de34a9f651c --new-format\nExit code: 1\nStdout: ''\nStderr: 'rbd: create error: (17) File exists\\n2014-03-04 05:49:22.261890 7f1c32ecc760 -1 librbd: rbd image volume-d626adb7-5220-4e39-a0a6-0de34a9f651c already exists\\n'\n"]

My cinder config file /etc/cinder/cinder.conf
    [DEFAULT]
    logdir = /var/log/cinder
    state_path = /var/lib/cinder
    lock_path = /var/lib/cinder/tmp

    debug=False
    verbose=False

    # Backend using Ceph
    volume_driver = cinder.volume.drivers.rbd.RBDDriver

    rbd_pool = cinderpool
    rbd_ceph_conf=/etc/ceph/ceph.conf

    rbd_flatten_volume_from_snapshot=false
    rbd_max_clone_depth=5

    # glance
    glance_host = 192.101.11.10
    glance_api_version = 2

    # database
    sql_connection = mysql://cinder:cinder@192.168.11.11/cinder

    # rpc
    rpc_backend = cinder.openstack.common.rpc.impl_qpid
    qpid_hostname=192.168.11.11
    qpid_port=5672

    # rootwrap
    rootwrap_config = /etc/cinder/rootwrap.conf

    auth_strategy=keystone

[Avishay Traeger (avishay-il)]

According to the log you pasted, this is what happened:
1. The Ceph driver tried to download the image, but there was insufficient space
2. The operation was retried twice after that, but failed because the file already existed

This isn't a bug, because you simply ran out of space on your backend, and that's why you got the error. However, the fact that the retries failed in that way means that the partially-downloaded file was not cleaned up. In addition, having a retry here is useless - space won't magically appear right away.

[li,chen (chen-li)]

MY ceph backend has enough space.

I checked the host which is running cinder-volume service .

Looks like when the volume is under "downloading" status, cinder-volume is copying images file from glance to its local disks.

I find 2 files under /tmp:

        [root@cinder-volume tmp]# ll
        total 2849600
        -rw------- 1 cinder cinder 2917990400 Mar 4 06:38 tmphWwEM3
        -rw------- 1 cinder cinder 0 Mar 4 06:38 tmpxuj8Qo

The first file size keeps growing.

I mount a new disk which size is much bigger than my image to /tmp, and re-run the command, the I noticed:

1. First, it will copy the image from glance to /tmp, it cost 60GB space (my image size).

2. Then, it convert the image's format.

      Processes can be found on host:
                root 7464 7199 0 06:45 ? 00:00:00 sudo cinder-rootwrap /etc/cinder/rootwrap.conf qemu-img convert -O raw /tmp/tmphWwEM3 /tmp/tmpxuj8Qo
                root 7465 7464 0 06:45 ? 00:00:00 /usr/bin/python /usr/bin/cinder-rootwrap /etc/cinder/rootwrap.conf qemu-img convert -O raw /tmp/tmphWwEM3 /tmp/tmpxuj8Qo

    it cost about total 120GB space (2 * my image size)

3. Finally, it start to copy the file to ceph:

    Process can be found on host:
              cinder 9188 7199 1 07:09 ? 00:00:00 rbd import --pool specweb /tmp/tmpxuj8Qo volume-f757e5ed-0fb2-4fb8-bf48-f10c65462d2a --new-format

So, not just the backend, if request the host running cinder-volume has enough disk space too !!

Thanks.
-chen

[John Griffith (john-griffith)]

Yes, the intermediate temp file is a problem. This is something we know is a problem, but don't have a good way to fix it as of yet. qemu convert won't let you pipe or do things in place. My recommendation has been to pu this logic in Glance and just grab the raw bytes directly and avoid this whole problem altogether.

[Ray Chen (chenrano2002)]

This is one known issue as John said. you can find the comments from image.image_utils.fetch_to_volume_format function. To avoid copy image to volume, you can consider use RBD also glance image backend, in that way. create cinder workflow will call just clone the rbd volume which contain glance image. which will skip the extra big temp file

[Sean McGinnis (sean-mcginnis)]

Closing stale bug. If this is still an issue please reopen.