os-image-api-version 2 with RBD backend causes glance to resize-before-write

[Andreas Karis]

Description of problem:
glance with image APIv2 shows the following warning message when using RBD as a backend
~~~
5d2edea478ec4bdba74b6bd5e108fe3d - - -] since image size is zero we will be doing resize-before-write for each chunk which will be considerably slower than normal
~~~
All uploads with APIv2 then resize the image. This does not happen with APIv1.

Version-Release number of selected component (if applicable):
[root@undercloud-1 ~]# rpm -qa | grep glance
python-glance-12.0.0-1.el7ost.noarch
python-glance-tests-12.0.0-1.el7ost.noarch
python-glanceclient-2.0.0-1.el7ost.noarch
python-glance-store-0.13.1-2.el7ost.noarch
openstack-glance-12.0.0-1.el7ost.noarch

How reproducible:
all the time

Steps to Reproduce:
1. create raw image without sparse sectors (option -S 0):
~~~
sudo /usr/bin/qemu-img convert -f qcow2 -O raw -S 0 rhel-guest-image-7.2-20160302.0.x86_64.qcow2 rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw
~~~
2. run the following 2 commands:
~~~
stack@undercloud-1 disks]$ date && time glance --os-image-api-version 1 image-create --progress --is-public true --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7 --container-format bare --disk-format raw; date && time glance --os-image-api-version 2 image-create --progress --is-public true --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7b --container-format bare --disk-format raw
~~~

~~~
[stack@undercloud-1 disks]$ date && time glance --os-image-api-version 2 image-create --progress --visibility public --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7b --container-format bare --disk-format raw
~~~
3. compare log output

Actual results:
API v1:

/var/log/glance/api.log
~~~
2016-09-06 21:51:41.714 12327 DEBUG glance.registry.client.v1.client [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Registry request PUT /im
ages/ce5163c9-d919-47f1-bdaf-a010026a85b3 HTTP 200 request id req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c do_request /usr/lib/python2.7/site-packages/glance/registry/client/v1/client.py:128
2016-09-06 21:51:41.715 12327 DEBUG glance.api.v1.images [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Uploading image data for image ce516
3c9-d919-47f1-bdaf-a010026a85b3 to rbd store _upload /usr/lib/python2.7/site-packages/glance/api/v1/images.py:650
2016-09-06 21:51:41.754 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] creating image ce5163c9-d919-47
f1-bdaf-a010026a85b3 with order 23 and size 10737418240 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:407
2016-09-06 21:51:41.807 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 0 add /
usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 21:51:42.090 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 8388608
 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
(...)
~~~

API v2
~~~
2016-09-06 21:58:17.414 12327 DEBUG glance_store.capabilities [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Store glance_store._drivers.rbd.Store doesn't support updating dynamic storage capabilities. Please overwrite 'update_capabilities' method of the store to implement updating logics if needed. update_capabilities /usr/lib/python2.7/site-packages/glance_store/capabilities.py:98
2016-09-06 21:58:17.415 12327 DEBUG glance_store.driver [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Late loading location class glance_store._drivers.rbd.StoreLocation get_store_location_class /usr/lib/python2.7/site-packages/glance_store/driver.py:95
2016-09-06 21:58:17.415 12327 DEBUG glance_store.location [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Registering scheme rbd with {'location_class': <class 'glance_store._drivers.rbd.StoreLocation'>, 'store': <glance_store._drivers.rbd.Store object at 0x714bf50>, 'store_entry': 'glance.store.rbd.Store'} register_scheme_map /usr/lib/python2.7/site-packages/glance_store/location.py:90
2016-09-06 21:58:17.451 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] creating image 6d13a228-1b77-4815-abdd-21e8c977fe47 with order 23 and size 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:407
2016-09-06 21:58:17.451 12327 WARNING glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] since image size is zero we will be doing resize-before-write for each chunk which will be considerably slower than normal
2016-09-06 21:58:17.509 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] resizing image to 8192 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 21:58:17.513 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 21:58:17.799 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] resizing image to 16384 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 21:58:17.802 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 8388608 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
(...)
~~~

Expected results:
v2 should not need to resize

Additional info:

1) create raw image without sparse sectors (option -S 0):
~~~
sudo /usr/bin/qemu-img convert -f qcow2 -O raw -S 0 rhel-guest-image-7.2-20160302.0.x86_64.qcow2 rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw
~~~

I am not sure if this is necessary or not. However, I wanted to be sure that the apparent size and occupied space really are the same prior to this test. Compare this to the other war image, which was created without the -S 0 option.
~~~
[stack@undercloud-1 disks]$ du -sh *
11G rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw
470M rhel-guest-image-7.2-20160302.0.x86_64.qcow2
1.4G rhel-guest-image-7.2-20160302.0.x86_64.raw
~~~

I am running this on a lab system, so the `time` command isn't really the best reference ... however, the logs reveal that a switch between glance API version 1 and 2 makes a difference. Keep in mind that `date` returns EDT vs UTC in logs (4 hours difference):
### --os-image-api-version 1 ###
~~~
stack@undercloud-1 disks]$ date && time glance --os-image-api-version 1 image-create --progress --is-public true --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7 --container-format bare --disk-format raw; date && time glance --os-image-api-version 2 image-create --progress --is-public true --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7b --container-format bare --disk-format raw
Tue Sep 6 17:51:41 EDT 2016
[=============================>] 100%
+------------------+--------------------------------------+
| Property | Value |
+------------------+--------------------------------------+
| checksum | 62f33fb78ed23539b0871d1ab8c86725 |
| container_format | bare |
| created_at | 2016-09-06T21:51:41.000000 |
| deleted | False |
| deleted_at | None |
| disk_format | raw |
| id | ce5163c9-d919-47f1-bdaf-a010026a85b3 |
| is_public | True |
| min_disk | 0 |
| min_ram | 0 |
| name | rhel7 |
| owner | 5d2edea478ec4bdba74b6bd5e108fe3d |
| protected | False |
| size | 10737418240 |
| status | active |
| updated_at | 2016-09-06T21:57:49.000000 |
| virtual_size | None |
+------------------+--------------------------------------+

real 6m8.575s
user 0m3.949s
sys 0m6.812s
~~~

/var/log/glance/api.log
~~~
2016-09-06 21:51:41.714 12327 DEBUG glance.registry.client.v1.client [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Registry request PUT /im
ages/ce5163c9-d919-47f1-bdaf-a010026a85b3 HTTP 200 request id req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c do_request /usr/lib/python2.7/site-packages/glance/registry/client/v1/client.py:128
2016-09-06 21:51:41.715 12327 DEBUG glance.api.v1.images [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Uploading image data for image ce516
3c9-d919-47f1-bdaf-a010026a85b3 to rbd store _upload /usr/lib/python2.7/site-packages/glance/api/v1/images.py:650
2016-09-06 21:51:41.754 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] creating image ce5163c9-d919-47
f1-bdaf-a010026a85b3 with order 23 and size 10737418240 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:407
2016-09-06 21:51:41.807 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 0 add /
usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 21:51:42.090 12327 DEBUG glance_store._drivers.rbd [req-c013f54d-e8e9-4f19-a90d-e4cd77dcc83c 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 8388608
 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
(...)
~~~

### --os-image-api-version 2 ###
~~~
[stack@undercloud-1 disks]$ date && time glance --os-image-api-version 2 image-create --progress --visibility public --file rhel-guest-image-7.2-20160302.0.x86_64.no_sparse.raw --name rhel7b --container-format bare --disk-format rawTue Sep 6 17:58:16 EDT 2016
[=============================>] 100%
+------------------+----------------------------------------------------------------------------------+
| Property | Value |
+------------------+----------------------------------------------------------------------------------+
| checksum | 62f33fb78ed23539b0871d1ab8c86725 |
| container_format | bare |
| created_at | 2016-09-06T21:58:17Z |
| direct_url | rbd://25ca4074-6996-11e6-9f65-5254004c20ce/images/6d13a228-1b77-4815-abdd- |
| | 21e8c977fe47/snap |
| disk_format | raw |
| id | 6d13a228-1b77-4815-abdd-21e8c977fe47 |
| min_disk | 0 |
| min_ram | 0 |
| name | rhel7b |
| owner | 5d2edea478ec4bdba74b6bd5e108fe3d |
| protected | False |
| size | 10737418240 |
| status | active |
| tags | [] |
| updated_at | 2016-09-06T22:05:04Z |
| virtual_size | None |
| visibility | public |
+------------------+----------------------------------------------------------------------------------+

real 6m48.313s
user 0m4.106s
sys 0m6.186s
~~~

~~~
2016-09-06 21:58:17.414 12327 DEBUG glance_store.capabilities [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Store glance_store._drivers.rbd.Store doesn't support updating dynamic storage capabilities. Please overwrite 'update_capabilities' method of the store to implement updating logics if needed. update_capabilities /usr/lib/python2.7/site-packages/glance_store/capabilities.py:98
2016-09-06 21:58:17.415 12327 DEBUG glance_store.driver [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Late loading location class glance_store._drivers.rbd.StoreLocation get_store_location_class /usr/lib/python2.7/site-packages/glance_store/driver.py:95
2016-09-06 21:58:17.415 12327 DEBUG glance_store.location [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Registering scheme rbd with {'location_class': <class 'glance_store._drivers.rbd.StoreLocation'>, 'store': <glance_store._drivers.rbd.Store object at 0x714bf50>, 'store_entry': 'glance.store.rbd.Store'} register_scheme_map /usr/lib/python2.7/site-packages/glance_store/location.py:90
2016-09-06 21:58:17.451 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] creating image 6d13a228-1b77-4815-abdd-21e8c977fe47 with order 23 and size 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:407
2016-09-06 21:58:17.451 12327 WARNING glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] since image size is zero we will be doing resize-before-write for each chunk which will be considerably slower than normal
2016-09-06 21:58:17.509 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] resizing image to 8192 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 21:58:17.513 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 21:58:17.799 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] resizing image to 16384 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 21:58:17.802 12327 DEBUG glance_store._drivers.rbd [req-7583f705-cb4f-4030-bc46-d83733c0a3dd 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] writing chunk at offset 8388608 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
(...)
~~~

All of the above is related to this commit:
https://review.openstack.org/gitweb?p=openstack/glance.git;a=commitdiff;h=1414c3fa8e12604a35e2c299dcac13830a419aaf

However, I do not know (yet) why API version 2 does not send the actual size along with the image and why a resize is necessary with API version 2.

[Cyril Roelandt (cyril-roelandt)]

Ok, long post ahead.

So Flavio and I took a look at this issue. It seems like for some reason, glance does not know the size of the image when using v2. Looking at the relevant part of the code (https://github.com/openstack/glance/blob/master/glance/api/v2/image_data.py#L269-L278) it seems like the glanceclient does not set the 'Content-Length' field. Let's fix that!

1) This seems like an easy fix
-------------------------------
diff --git a/glanceclient/v2/images.py b/glanceclient/v2/images.py
index f69fed5..549d9a1 100644
--- a/glanceclient/v2/images.py
+++ b/glanceclient/v2/images.py
@@ -212,7 +212,10 @@ class Controller(object):
         :param image_size: Unused - present for backwards compatibility
         """
         url = '/v2/images/%s/file' % image_id
- hdrs = {'Content-Type': 'application/octet-stream'}
+ hdrs = {
+ 'Content-Type': 'application/octet-stream',
+ 'Content-Length': str(image_size)
+ }
         body = image_data
         self.http_client.put(url, headers=hdrs, data=body)

diff --git a/glanceclient/v2/shell.py b/glanceclient/v2/shell.py
index dfd91fb..b0b31ad 100644
--- a/glanceclient/v2/shell.py
+++ b/glanceclient/v2/shell.py
@@ -80,9 +80,10 @@ def do_image_create(gc, args):
                    "privileges to it" % file_name)
     image = gc.images.create(**fields)
     try:
- if utils.get_data_file(args) is not None:
+ image_data = utils.get_data_file(args)
+ if image_data is not None:
             args.id = image['id']
- args.size = None
+ args.size = utils.get_file_size(image_data)
             do_image_upload(gc, args)
             image = gc.images.get(args.id)
     finally:

Let's try to create the image using the same command as OP, and let's take a look at the output:
...
REQ: curl -g -i -X PUT http://10.0.2.15:9292/v2/images/7e5f0103-4aff-4aa7-82a1-213193fe6639/file -H "Content-Length: 41126400" -H "User-Agent: python-glanceclient" -H "Content-Type: application/octet-stream" -H "X-Auth-Token: {SHA1}e1dfe1ae3fe336c01b7e50c862689785db13de92" -d '<generator object _chunk_body at 0x7ffbe72d0c80>'
... Some very long stacktrace...
TypeError: must be string or buffer, not generator
must be string or buffer, not generator

Indeed, we have a generator object (see the request) because we send our image chunk by chunk. Apparently, you cannot send data "chunk by chunk" when specifying a content-length (because it implies you're giving the whole thing in one go). So, the fix is not as simple as expected, which raises one very important question...

2) How does v1 deal with this?
-------------------------------
The glanceclient does not set the Content-Length header when using v1. Instead it sets the x-image-meta-size header, and glance v1 uses that to retrieve the size of the image (https://github.com/openstack/glance/blob/master/glance/api/v1/images.py#L1229-L1236).

3) What should we do about v2?
------------------------------
I believe we should send the total length using a header other than 'Content-Length', like v1 does (possibly using the 'x-image-meta-size' header), and make sure it is read by RequestDeserializer.upload. T...

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/378953

[Brian Rosmaita (brian-rosmaita)]

> What do people think?

Reading through the comments on https://review.openstack.org/#/c/378953/, looks like people hate the idea of using the v1 header for this purpose. Stuart mentioned that maybe the client could set the size in the image record before calling PUT /file, which seems plausible, though I haven't thought through what kind of cascade of changes that would require on the server side. With RBD rapidly becoming the backend of choice and v1 being removed in Queens, however, it would be good to figure out a fix for this.

Cyril, are you still interested in working on this?

[Brian Rosmaita (brian-rosmaita)]

Removing "in-progress" due to lack of activity on the associated patches.

[OpenStack Infra (hudson-openstack)]

Change abandoned by Brian Rosmaita (<email address hidden>) on branch: master
Review: https://review.openstack.org/378953
Reason: Abandoning due to lack of activity. Bug has been updated.

[Ivan Borisov (ivan.borisov)]

The issue is the same as https://bugs.launchpad.net/glance/+bug/1792710.

In every case when Glance use RBD and client upload image from non-RBD source Glance will use resize-before-write.
When you need to upload large images or create large instance snapshots from non-RBD ephemeral storages it becomes a real problem.

As Stuart suggested in comment to the patch set, maybe optional size field should be added to the json during initial create image POST request?
Another possibility I can think of is to reuse min_disk field, since RBD stores image in raw anyway.

Would be happy to assist anyone interested in fixing this bug, but can't handle it alone.

[Acoss69 (acoss69)]

Hi Ivan,

I think my problem (https://bugs.launchpad.net/glance/+bug/1885252) could be related with the possible resolution of this one.

I would be happy to provide a test environment to try to fix this one.

Regards