cinder create failed to copy image to volume (then stuck in cinder delete attempt)

[Wendy Mitchell]

Brief Description
-----------------
Volume in error on cinder create (then stuck deleting)

Severity
--------
Major

Steps to Reproduce
------------------
This testcase creates a 20g volume from default guest, collects image download rate, image conversion rate, and total volume creation time

# ceph -v
ceph version 13.2.2 (67ecc2fbbca4f602f1172fa8e561b813eb564df5) mimic (stable)

1. create glance image
glance image-create --visibility public --file /home/wrsroot//images/tis-centos-guest.qcow2 --container-format bare --name tis-centos-guest-qcow2 --disk-format qcow2

2. create volume as tenant2 user
eg. 20g
[2019-05-11 17:34:39,990] cinder create --display-name 20g-1 --image-id ecfd2352-1f13-4989-8e74-a5e6211ecfdd 20

[2019-05-11 17:34:50,625]
id | 79a603f6-e3a2-4153-a9da-e52c1b67e0a5
| name | 20g-1
status | downloading

[2019-05-11 17:34:55,860]
 id | 79a603f6-e3a2-4153-a9da-e52c1b67e0a5
| name | 20g-1
| status | error
| updated_at | 2019-05-11T17:34:52.000000
E utils.exceptions.VolumeError: Volume error.

Expected Behavior
------------------
Did not expect volume error

Actual Behavior
----------------
The first error reported in cinder log on controller-0 as follows (see log attached)

error in request req-af8e6850-9962-4e9f-bd2c-2e6df88f54e2

{"log":"2019-05-11 17:34:49.067 19 INFO cinder.image.image_utils [req-af8e6850-9962-4e9f-bd2c-2e6df88f54e2 49be8d2df9f64a358d94fd583dd8c8ae 9f6cdf6c70c84883ac0c91e38fe3193b - default default] Image download 1133.00 MB at 146.41 MB/s\n","stream":"stdout","time":"2019-05-11T17:34:49.068267276Z"}
 {"log":"2019-05-11 17:34:49.067 19 INFO cinder.image.image_utils [req-af8e6850-9962-4e9f-bd2c-2e6df88f54e2 49be8d2df9f64a358d94fd583dd8c8ae 9f6cdf6c70c84883ac0c91e38fe3193b - default default] Image download 1133.00 MB at 146.41 MB/s\n","stream":"stdout","time":"2019-05-11T17:34:49.068286854Z"}
{"log":"2019-05-11 17:34:52.288 19 INFO cinder.image.image_utils [req-af8e6850-9962-4e9f-bd2c-2e6df88f54e2 49be8d2df9f64a358d94fd583dd8c8ae 9f6cdf6c70c84883ac0c91e38fe3193b - default default] Converted 1537.00 MB image at 917.44 MB/s\n","stream":"stdout","time":"2019-05-11T17:34:52.288876647Z"}
{"log":"2019-05-11 17:34:52.288 19 INFO cinder.image.image_utils [req-af8e6850-9962-4e9f-bd2c-2e6df88f54e2 49be8d2df9f64a358d94fd583dd8c8ae 9f6cdf6c70c84883ac0c91e38fe3193b - default default] Converted 1537.00 MB image at 917.44 MB/s\n","stream":"stdout","time":"2019-05-11T17:34:52.288972121Z"}
{"log":"2019-05-11 17:34:52.474 19 ERROR cinder.volume.utils [req-af8e6850-9962-4e9f-bd2c-2e6df88f54e2 49be8d2df9f64a358d94fd583dd8c8ae 9f6cdf6c70c84883ac0c91e38fe3193b - default default] Failed to copy image ecfd2352-1f13-4989-8e74-a5e6211ecfdd to volume: 79a603f6-e3a2-4153-a9da-e52c1b67e0a5: TypeError: _init_() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-11T17:34:52.476256591Z"}
{"log":"2019-05-11 17:34:52.474 19 ERROR cinder.volume.utils [req-af8e6850-9962-4e9f-bd2c-2e6df88f54e2 49be8d2df9f64a358d94fd583dd8c8ae 9f6cdf6c70c84883ac0c91e38fe3193b - default default] Failed to copy image ecfd2352-1f13-4989-8e74-a5e6211ecfdd to volume: 79a603f6-e3a2-4153-a9da-e52c1b67e0a5: TypeError: _init_() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-11T17:34:52.476808543Z"}

E utils.exceptions.VolumeError: Volume error.

 id | 79a603f6-e3a2-4153-a9da-e52c1b67e0a5
| name | 20g-1
| status | error
| updated_at | 2019-05-11T17:34:52.000000

and volume can also not be deleted.
| 79a603f6-e3a2-4153-a9da-e52c1b67e0a5 | 9f6cdf6c70c84883ac0c91e38fe3193b | error_deleting | 20g-1 | 20 | - | false |

Subsequent tests fail after that and volumes also were unable to be deleted (so cinder quota eventually becomes an issue)

Reproducibility
---------------
Reproducible

System Configuration
--------------------
effecting many systems

Lab-name: WP_3-7

Branch/Pull Time/Commit
-----------------------
20190508T013000Z

Last Pass
---------

Timestamp/Logs
--------------
see inline

[Wendy Mitchell (wmitchellwr)]

This appears to be effecting many test scenarios

{"log":"2019-05-11 17:34:52.647 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-11T17:34:52.649166938Z"}
{"log":"2019-05-11 23:49:06.212 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-11T23:49:06.213450594Z"}
{"log":"2019-05-12 00:47:05.351 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-12T00:47:05.352018668Z"}
{"log":"2019-05-12 14:26:48.242 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-12T14:26:48.243809572Z"}
{"log":"2019-05-12 14:28:03.855 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-12T14:28:03.856014005Z"}
{"log":"2019-05-12 14:47:58.466 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-12T14:47:58.467415383Z"}
{"log":"2019-05-12 14:50:37.247 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-12T14:50:37.24834896Z"}
{"log":"2019-05-12 14:53:20.737 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-12T14:53:20.738147912Z"}
{"log":"2019-05-12 15:13:47.839 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-12T15:13:47.840475073Z"}
{"log":"2019-05-12 15:35:34.366 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-12T15:35:34.367658819Z"}
{"log":"2019-05-12 15:38:26.709 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-12T15:38:26.710084499Z"}
{"log":"2019-05-12 15:58:00.333 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-12T15:58:00.334096859Z"}
{"log":"2019-05-12 16:01:19.908 19 ERROR oslo_messaging.rpc.server ImageCopyFailure: Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n","stream":"stdout","time":"2019-05-12T16:01:19.909708734Z"}

[Ghada Khalil (gkhalil)]

Marking as release gating; maybe ceph related.

A similar issue was reported in https://bugs.launchpad.net/starlingx/+bug/1828059

[Daniel Badea (daniel.badea)]

A commit was ported from Ceph Jewel to Mimic without updating __init__ parameters (errno is missing). This causes:

    Failed to copy image to volume: __init__() got an unexpected keyword argument 'errno'\n"

Fixed by https://github.com/starlingx-staging/stx-ceph/pull/31 (adds errno=None )

[Cindy Xie (xxie1)]

PR31 merged in 20190517T223724Z, please check if this bug can still repro?

[Wendy Mitchell (wmitchellwr)]

successfully created a volume from a ubuntu image (in qcow2 format)
BUILD_ID="2019-05-24_17-39-51"

{"log":"2019-05-27 17:36:19.812 19 INFO cinder.volume.flows.manager.create_volume [req-1cd60072-7133-43ff-9a1d-3cf0be6b3790 bd792b11e0014ae2aee2c562d9ee246d 549263dfcb73441a9436d6a934d62fba - default default] Volume 66c83b97-40a6-471e-913b-4f2797c199bb: being created as image with specification: {'status': u'creating', 'image_location': (u'rbd://45d2e1b8-6d93-4d62-b3d7-4b5dfecfa83a/images/60cfee11-686c-43ee-9991-0439403a3902/snap', None), 'volume_size': 20, 'volume_name': u'66c83b97-40a6-471e-913b-4f2797c199bb', 'image_id': u'60cfee11-686c-43ee-9991-0439403a3902', 'image_service': \u003ccinder.image.glance.GlanceImageService object at 0x7fb073dda4d0\u003e, 'image_meta': {u'container_format': u'bare', u'min_ram': 0, u'updated_at': datetime.datetime(2019, 5, 27, 14, 51, 15, tzinfo=\u003ciso8601.Utc\u003e), u'file': u'/v2/images/60cfee11-686c-43ee-9991-0439403a3902/file', u'owner': u'77d8bc21c72a44c6a185aab143e37116', u'id': u'60cfee11-686c-43ee-9991-0439403a3902', u'size': 260440576, u'disk_format': u'qcow2', u'os_hash_algo': u'sha512', u'direct_url': u'rbd://45d2e1b8-6d93-4d62-b3d7-4b5dfecfa83a/images/60cfee11-686c-43ee-9991-0439403a3902/snap', u'status': u'active', u'tags': [], u'visibility': u'public', u'min_disk': 0, u'virtual_size': None, 'properties': {}, u'name': u'ubuntu_14', u'checksum': u'c1b6664df43550fd5684fe85cdd3ddc3', u'created_at': datetime.datetime(2019, 5, 27, 14, 51, tzinfo=\u003ciso8601.Utc\u003e), u'os_hidden': False, u'protected': False, u'os_hash_value': u'e68b9faba509d917aa9994bc1a3f4d0c287313c28590f1e3fbda2d0e904123cb951b6dcb121dea10de6df4bb7da4573ae1625e8bb116fce382e6e067d9a32238'}}\n","stream":"stdout","time":"2019-05-27T17:36:19.813081446Z"}
{"log":"2019-05-27 17:38:16.430 19 INFO cinder.volume.flows.manager.create_volume [req-1cd60072-7133-43ff-9a1d-3cf0be6b3790 bd792b11e0014ae2aee2c562d9ee246d 549263dfcb73441a9436d6a934d62fba - default default] Volume 66c83b97-40a6-471e-913b-4f2797c199bb (66c83b97-40a6-471e-913b-4f2797c199bb): created successfully\n","stream":"stdout","time":"2019-05-27T17:38:16.431029438Z"}
{"log":"2019-05-27 17:38:16.430 19 INFO cinder.volume.flows.manager.create_volume [req-1cd60072-7133-43ff-9a1d-3cf0be6b3790 bd792b11e0014ae2aee2c562d9ee246d 549263dfcb73441a9436d6a934d62fba - default default] Volume 66c83b97-40a6-471e-913b-4f2797c199bb (66c83b97-40a6-471e-913b-4f2797c199bb): created successfully\n","stream":"stdout","time":"2019-05-27T17:38:16.43133285Z"}

Note also that if the original image is not qcow2 format the volume will launch in error (see cinder log output for the error). In this case it will successfully delete while in error.

ImageCopyFailure: Failed to copy image to volume: qemu-img: Could not open '/var/lib/cinder/conversion/tmpDBfYDLcinder-volume-worker@ceph-store': Image is not in qcow2 format\