Bug 1373571

Summary: A successful image upload using glance taskflow with ceph as backend ends with "Unknown scheme 'file' found in URI" response status and errors in the log. (
Product: Red Hat OpenStack Reporter: Andreas Karis <akaris>
Component: openstack-glanceAssignee: Cyril Roelandt <cyril>
Status: CLOSED WONTFIX QA Contact: nlevinki <nlevinki>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 8.0 (Liberty)CC: aavraham, cschwede, egafford, eglynn, fpercoco, pgrist, srevivo, tshefi
Target Milestone: ---Keywords: Triaged, ZStream
Target Release: 8.0 (Liberty)Flags: tshefi: automate_bug-
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-09-08 14:57:08 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Andreas Karis 2016-09-06 15:28:48 UTC 
Description of problem:
This is the exact same bug as in https://bugzilla.redhat.com/show_bug.cgi?id=1242149

Although this bug was fixed in a recent ERRATA, I can reproduce it with the most recent packages for OSP 8.

Using ceph as backend, uploaded a glance image using the taskflow option. The image is converted and uploaded successfully. However the glance task-create command ends with a response ""Unknown scheme 'file' found in URI" with traceback errors in the logs 

Version-Release number of selected component (if applicable):
[root@overcloud-controller-0 ~]# rpm -qa | egrep 'ceph|glance'
ceph-osd-0.94.5-13.el7cp.x86_64
python-glance-store-0.9.1-3.el7ost.noarch
openstack-glance-11.0.1-4.el7ost.noarch
python-glanceclient-1.1.1-1.el7ost.noarch
ceph-common-0.94.5-13.el7cp.x86_64
python-glance-11.0.1-4.el7ost.noarch
ceph-0.94.5-13.el7cp.x86_64
ceph-mon-0.94.5-13.el7cp.x86_64

[root@overcloud-cephstorage-0 ~]#  rpm -qa | egrep 'ceph|glance'
ceph-osd-0.94.5-13.el7cp.x86_64
python-glance-store-0.9.1-3.el7ost.noarch
openstack-glance-11.0.1-4.el7ost.noarch
python-glanceclient-1.1.1-1.el7ost.noarch
ceph-common-0.94.5-13.el7cp.x86_64
python-glance-11.0.1-4.el7ost.noarch
ceph-0.94.5-13.el7cp.x86_64
ceph-mon-0.94.5-13.el7cp.x86_64

[stack@undercloud-1 ~]$ rpm -qa | egrep 'ceph|glance'
python-glance-store-0.9.1-3.el7ost.noarch
openstack-glance-11.0.1-4.el7ost.noarch
python-glance-11.0.1-4.el7ost.noarch
python-glanceclient-1.1.1-1.el7ost.noarch


How reproducible:
Always

Steps to Reproduce:
1. Configure glance to use rbd. 
2. Configure taskflow option.
[root@overcloud-controller-0 ~]# egrep -v '^$|^#' /etc/glance/glance-api.conf 
[DEFAULT]
show_image_direct_url=True
enable_v2_api=true
bind_host=172.18.0.14
bind_port=9292
workers=0
backlog=4096
image_cache_dir=/var/lib/glance/image-cache
registry_host=172.16.2.5
registry_port=9191
registry_client_protocol=http
debug=True
verbose=True
log_file=/var/log/glance/api.log
log_dir=/var/log/glance
use_syslog=False
syslog_log_facility=LOG_USER
use_stderr=True
notification_driver =messaging
[database]
connection=mysql+pymysql://glance:jNDd6KnbCHjkkTeHWYabfPPeM.2.5/glance
idle_timeout=3600
[glance_store]
stores=glance.store.http.Store,glance.store.rbd.Store
default_store=rbd
rbd_store_chunk_size=8
rbd_store_pool=images
rbd_store_user=openstack
rbd_store_ceph_conf=/etc/ceph/ceph.conf
rados_connect_timeout=0
os_region_name=RegionOne
[image_format]
[keystone_authtoken]
auth_uri=http://172.16.2.5:5000/v2.0
identity_uri=http://192.0.2.21:35357
admin_user=glance
admin_password=jNDd6KnbCHjkkTeHWYabfPPeM
admin_tenant_name=service
[matchmaker_redis]
[matchmaker_ring]
[oslo_concurrency]
[oslo_messaging_amqp]
[oslo_messaging_qpid]
[oslo_messaging_rabbit]
amqp_durable_queues=False
rabbit_hosts=172.16.2.7
rabbit_use_ssl=False
rabbit_userid=guest
rabbit_password=8qafWw9EmTT8EfNehwZjPecCe
rabbit_virtual_host=/
rabbit_ha_queues=True
heartbeat_timeout_threshold=0
heartbeat_rate=2
rabbit_notification_exchange=glance
rabbit_notification_topic=notifications
[oslo_policy]
[paste_deploy]
flavor=keystone
[store_type_location_strategy]
[task]
task_executor=taskflow
work_dir=/tmp
[taskflow_executor]
engine_mode=serial
max_workers=10
conversion_format=raw

3.Upload a local image to glance stored on controller node using task-create command.
[stack@undercloud-1 ~]$ glance --os-image-api-version 2 task-create --type import --input '{"import_from_format": "qcow2", "import_from": "http://10.0.0.250/rhel-guest-image-7.2-20160302.0.x86_64.qcow2", "image_properties": {"name": "rhel-guest-image-7.2-RAW", "disk_format": "qcow2", "container_format": "bare"}}'
+------------+----------------------------------------------------------------------------------+
| Property   | Value                                                                            |
+------------+----------------------------------------------------------------------------------+
| created_at | 2016-09-06T15:09:07Z                                                             |
| id         | b685fa32-3655-4ab1-97a4-2614d26d1093                                             |
| input      | {"image_properties": {"container_format": "bare", "disk_format": "qcow2",        |
|            | "name": "rhel-guest-image-7.2-RAW"}, "import_from_format": "qcow2",              |
|            | "import_from": "http://10.0.0.250/rhel-guest-image-7.2-20160302.0.x86_64.qcow2"} |
| message    |                                                                                  |
| owner      | 5d2edea478ec4bdba74b6bd5e108fe3d                                                 |
| result     | None                                                                             |
| status     | pending                                                                          |
| type       | import                                                                           |
| updated_at | 2016-09-06T15:09:07Z                                                             |
+------------+----------------------------------------------------------------------------------|

Used the undercloud as a simple HTTP server to fetch a qcow2 image from.

4.Glance image is converted to raw and uploaded successfully.

[stack@undercloud-1 ~]$ glance --os-image-api-version 1 image-list
+--------------------------------------+--------------------------+-------------+------------------+-------------+--------+
| ID                                   | Name                     | Disk Format | Container Format | Size        | Status |
+--------------------------------------+--------------------------+-------------+------------------+-------------+--------+
| f746cecf-7f89-4ba0-870a-6b0f2e961651 | rhel-guest-image-7.2-RAW | raw         | bare             | 10737418240 | active |
+--------------------------------------+--------------------------+-------------+------------------+-------------+--------+


5. On ceph image pool the glance image is created successfully.

[root@overcloud-cephstorage-1 ~]# df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/sda3       112G   16G   97G  14% /
devtmpfs         32G     0   32G   0% /dev
tmpfs            32G     0   32G   0% /dev/shm
tmpfs            32G  820K   32G   1% /run
tmpfs            32G     0   32G   0% /sys/fs/cgroup
tmpfs           6.3G     0  6.3G   0% /run/user/1000


[root@overcloud-cephstorage-0 ~]# rbd info images/f746cecf-7f89-4ba0-870a-6b0f2e961651
rbd image 'f746cecf-7f89-4ba0-870a-6b0f2e961651':
	size 10240 MB in 1280 objects
	order 23 (8192 kB objects)
	block_name_prefix: rbd_data.faa71b9e64e9
	format: 2
	features: layering, striping
	flags: 
	stripe unit: 8192 kB
	stripe count: 1


Actual results:
"Unknown scheme 'file' found in URI

2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor Traceback (most recent call last):
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor   File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/executor.py", line 82, in _execute_task
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor     result = task.execute(**arguments)
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor   File "/usr/lib/python2.7/site-packages/glance/async/flows/base_import.py", line 202, in execute
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor     store_api.delete_from_backend(file_path)
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor   File "/usr/lib/python2.7/site-packages/glance_store/backend.py", line 289, in delete_from_backend
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor     loc = location.get_location_from_uri(uri, conf=CONF)
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor   File "/usr/lib/python2.7/site-packages/glance_store/location.py", line 75, in get_location_from_uri
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor     raise exceptions.UnknownScheme(scheme=pieces.scheme)
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor UnknownScheme: Unknown scheme 'file' found in URI
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor 
2016-09-06 15:15:54.077 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-DeleteFromFS-b685fa32-3655-4ab1-97a4-2614d26d1093' (55f8fcde-ca36-4c02-a2cc-9a2f44eee165)

Expected results:
A valid response status.

Additional info:

Errors in glance api log file:

15:09:10.148080 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.148083 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
2016-09-06 15:09:11.972 12327 DEBUG glance_store._drivers.filesystem [-] Wrote 492692992 bytes to /tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651 with checksum 5907366ad7abe80c63d2936b92dec704 add /usr/lib/python2.7/site-packages/glance_store/_drivers/filesystem.py:618
2016-09-06 15:09:11.974 12327 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): qemu-img info --output=json file:///tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651 execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230
2016-09-06 15:09:12.033 12327 DEBUG oslo_concurrency.processutils [-] CMD "qemu-img info --output=json file:///tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651" returned: 0 in 0.060s execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260
2016-09-06 15:09:12.035 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-ImportToFS-b685fa32-3655-4ab1-97a4-2614d26d1093' (c3165102-ea94-429f-8811-aaa3941edc87) transitioned into state 'SUCCESS' from state 'RUNNING' with result 'file:///tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:178
2016-09-06 15:09:12.036 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-Convert-b685fa32-3655-4ab1-97a4-2614d26d1093' (e197a34b-290c-4f515:09:10.148223 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 20272
c-a659-fe9016f727bb) transitioned into state 'RUNNING' from state 'PENDING' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:190
2016-09-06 15:09:12.037 12327 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): qemu-img convert -O raw file:///tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651 /tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651.converted execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230
15:09:10.148223 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 20272
15:09:10.148267 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.148269 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.148423 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 7240
15:09:10.148428 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 15928
15:09:10.148423 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 7240
15:09:10.148428 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 15928
15:09:10.148453 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.148455 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.148615 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 23168
15:09:10.148615 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 23168
15:09:10.148664 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.148668 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.148805 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 21720
15:09:10.148805 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 21720
15:09:10.148998 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 23168
15:09:10.148998 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 23168
15:09:10.149074 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.149077 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.149183 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 21720
15:09:10.149183 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 21720
15:09:10.149279 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.149281 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.149375 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 21720
15:09:10.149375 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 21720
15:09:10.149404 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.149406 IP 10.0.0.5.39784 > 10.0.0.250.80: tcp 0
15:09:10.149563 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 2896
15:09:10.149568 IP 10.0.0.250.80 > 10.0.0.5.39784: tcp 20272
2016-09-06 15:09:17.810 12327 DEBUG oslo_concurrency.processutils [-] CMD "qemu-img convert -O raw file:///tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651 /tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651.converted" returned: 0 in 5.772s execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260
2016-09-06 15:09:17.882 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-Convert-b685fa32-3655-4ab1-97a4-2614d26d1093' (e197a34b-290c-4f5c-a659-fe9016f727bb) transitioned into state 'SUCCESS' from state 'RUNNING' with result 'file:///tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:178
2016-09-06 15:09:17.883 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-Introspect-b685fa32-3655-4ab1-97a4-2614d26d1093' (a94bacb8-1074-4a98-8273-619cdba56e8e) transitioned into state 'RUNNING' from state 'PENDING' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:190
2016-09-06 15:09:17.884 12327 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): qemu-img info --output=json file:///tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651 execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230
2016-09-06 15:09:17.945 12327 DEBUG oslo_concurrency.processutils [-] CMD "qemu-img info --output=json file:///tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651" returned: 0 in 0.061s execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260
2016-09-06 15:09:17.986 12327 DEBUG glance.async.flows.introspect [-] b685fa32-3655-4ab1-97a4-2614d26d1093: Introspection successful: file:///tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651 execute /usr/lib/python2.7/site-packages/glance/async/flows/introspect.py:74
2016-09-06 15:09:17.987 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-Introspect-b685fa32-3655-4ab1-97a4-2614d26d1093' (a94bacb8-1074-4a98-8273-619cdba56e8e) transitioned into state 'SUCCESS' from state 'RUNNING' with result '<glance.api.authorization.ImageProxy object at 0x7132f10>' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:178
2016-09-06 15:09:17.988 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-ImportToStore-b685fa32-3655-4ab1-97a4-2614d26d1093' (3b480d39-273c-4168-aeed-c8ad1d607225) transitioned into state 'RUNNING' from state 'PENDING' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:190
2016-09-06 15:09:18.027 12327 INFO glance.common.scripts.image_import.main [-] Task b685fa32-3655-4ab1-97a4-2614d26d1093: Got image data uri file:///tmp/f746cecf-7f89-4ba0-870a-6b0f2e961651 to be imported
2016-09-06 15:09:18.029 12327 DEBUG glance_store.backend [-] Attempting to import store glance.store.rbd.Store _load_store /usr/lib/python2.7/site-packages/glance_store/backend.py:149
2016-09-06 15:09:18.030 12327 DEBUG glance_store.capabilities [-] 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 15:09:18.031 12327 DEBUG glance_store.driver [-] 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 15:09:18.031 12327 DEBUG glance_store.location [-] Registering scheme rbd with {'location_class': <class 'glance_store._drivers.rbd.StoreLocation'>, 'store': <glance_store._drivers.rbd.Store object at 0x716e8d0>, 'store_entry': 'glance.store.rbd.Store'} register_scheme_map /usr/lib/python2.7/site-packages/glance_store/location.py:90
2016-09-06 15:09:18.064 12327 DEBUG glance_store._drivers.rbd [-] creating image f746cecf-7f89-4ba0-870a-6b0f2e961651 with order 23 and size 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:407
2016-09-06 15:09:18.065 12327 WARNING glance_store._drivers.rbd [-] 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 15:09:18.095 12327 DEBUG glance_store._drivers.rbd [-] resizing image to 8192 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 15:09:18.098 12327 DEBUG glance_store._drivers.rbd [-] writing chunk at offset 0 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 15:09:18.377 12327 DEBUG glance_store._drivers.rbd [-] resizing image to 16384 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 15:09:18.381 12327 DEBUG glance_store._drivers.rbd [-] writing chunk at offset 8388608 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 15:09:18.660 12327 DEBUG glance_store._drivers.rbd [-] resizing image to 24576 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 15:09:18.663 12327 DEBUG glance_store._drivers.rbd [-] writing chunk at offset 16777216 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 15:09:18.939 12327 DEBUG glance_store._drivers.rbd [-] resizing image to 32768 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 15:09:18.943 12327 DEBUG glance_store._drivers.rbd [-] writing chunk at offset 25165824 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 15:09:19.219 12327 DEBUG glance_store._drivers.rbd [-] resizing image to 40960 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 15:09:19.223 12327 DEBUG glance_store._drivers.rbd [-] writing chunk at offset 33554432 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 15:09:19.505 12327 DEBUG glance_store._drivers.rbd [-] resizing image to 49152 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 15:09:19.528 12327 DEBUG glance_store._drivers.rbd [-] writing chunk at offset 41943040 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 15:09:19.806 12327 DEBUG glance_store._drivers.rbd [-] resizing image to 57344 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 15:09:19.829 12327 DEBUG glance_store._drivers.rbd [-] writing chunk at offset 50331648 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 15:09:20.105 12327 DEBUG glance_store._drivers.rbd [-] resizing image to 65536 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 15:09:20.128 12327 DEBUG glance_store._drivers.rbd [-] writing chunk at offset 58720256 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
(...)
2016-09-06 15:15:53.337 12327 DEBUG glance_store._drivers.rbd [-] resizing image to 10477568 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 15:15:53.359 12327 DEBUG glance_store._drivers.rbd [-] writing chunk at offset 10720641024 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 15:15:53.642 12327 DEBUG glance_store._drivers.rbd [-] resizing image to 10485760 KiB add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:436
2016-09-06 15:15:53.664 12327 DEBUG glance_store._drivers.rbd [-] writing chunk at offset 10729029632 add /usr/lib/python2.7/site-packages/glance_store/_drivers/rbd.py:439
2016-09-06 15:15:54.063 12327 DEBUG glance_store.backend [-] Attempting to import store glance.store.rbd.Store _load_store /usr/lib/python2.7/site-packages/glance_store/backend.py:149
2016-09-06 15:15:54.064 12327 DEBUG glance_store.capabilities [-] 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 15:15:54.064 12327 DEBUG glance_store.driver [-] 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 15:15:54.064 12327 DEBUG glance_store.location [-] Registering scheme rbd with {'location_class': <class 'glance_store._drivers.rbd.StoreLocation'>, 'store': <glance_store._drivers.rbd.Store object at 0x732cad0>, 'store_entry': 'glance.store.rbd.Store'} register_scheme_map /usr/lib/python2.7/site-packages/glance_store/location.py:90
2016-09-06 15:15:54.065 12327 DEBUG glance_store.backend [-] Skipping store.set_acls... not implemented. set_acls /usr/lib/python2.7/site-packages/glance_store/backend.py:383
2016-09-06 15:15:54.067 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-ImportToStore-b685fa32-3655-4ab1-97a4-2614d26d1093' (3b480d39-273c-4168-aeed-c8ad1d607225) transitioned into state 'SUCCESS' from state 'RUNNING' with result 'None' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:178
2016-09-06 15:15:54.069 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-DeleteFromFS-b685fa32-3655-4ab1-97a4-2614d26d1093' (55f8fcde-ca36-4c02-a2cc-9a2f44eee165) transitioned into state 'RUNNING' from state 'PENDING' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:190
2016-09-06 15:15:54.071 12327 WARNING glance.async.taskflow_executor [-] Task 'import-DeleteFromFS-b685fa32-3655-4ab1-97a4-2614d26d1093' (55f8fcde-ca36-4c02-a2cc-9a2f44eee165) transitioned into state 'FAILURE' from state 'RUNNING'
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor Traceback (most recent call last):
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor   File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/executor.py", line 82, in _execute_task
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor     result = task.execute(**arguments)
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor   File "/usr/lib/python2.7/site-packages/glance/async/flows/base_import.py", line 202, in execute
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor     store_api.delete_from_backend(file_path)
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor   File "/usr/lib/python2.7/site-packages/glance_store/backend.py", line 289, in delete_from_backend
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor     loc = location.get_location_from_uri(uri, conf=CONF)
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor   File "/usr/lib/python2.7/site-packages/glance_store/location.py", line 75, in get_location_from_uri
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor     raise exceptions.UnknownScheme(scheme=pieces.scheme)
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor UnknownScheme: Unknown scheme 'file' found in URI
2016-09-06 15:15:54.071 12327 ERROR glance.async.taskflow_executor 
2016-09-06 15:15:54.077 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-DeleteFromFS-b685fa32-3655-4ab1-97a4-2614d26d1093' (55f8fcde-ca36-4c02-a2cc-9a2f44eee165) transitioned into state 'REVERTING' from state 'FAILURE' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:190
2016-09-06 15:15:54.078 12327 WARNING glance.async.taskflow_executor [-] Task 'import-DeleteFromFS-b685fa32-3655-4ab1-97a4-2614d26d1093' (55f8fcde-ca36-4c02-a2cc-9a2f44eee165) transitioned into state 'REVERTED' from state 'REVERTING' with result 'None'
2016-09-06 15:15:54.080 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-ImportToStore-b685fa32-3655-4ab1-97a4-2614d26d1093' (3b480d39-273c-4168-aeed-c8ad1d607225) transitioned into state 'REVERTING' from state 'SUCCESS' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:190
2016-09-06 15:15:54.081 12327 WARNING glance.async.taskflow_executor [-] Task 'import-ImportToStore-b685fa32-3655-4ab1-97a4-2614d26d1093' (3b480d39-273c-4168-aeed-c8ad1d607225) transitioned into state 'REVERTED' from state 'REVERTING' with result 'None'
2016-09-06 15:15:54.082 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-Introspect-b685fa32-3655-4ab1-97a4-2614d26d1093' (a94bacb8-1074-4a98-8273-619cdba56e8e) transitioned into state 'REVERTING' from state 'SUCCESS' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:190
2016-09-06 15:15:54.083 12327 WARNING glance.async.taskflow_executor [-] Task 'import-Introspect-b685fa32-3655-4ab1-97a4-2614d26d1093' (a94bacb8-1074-4a98-8273-619cdba56e8e) transitioned into state 'REVERTED' from state 'REVERTING' with result 'None'
2016-09-06 15:15:54.085 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-Convert-b685fa32-3655-4ab1-97a4-2614d26d1093' (e197a34b-290c-4f5c-a659-fe9016f727bb) transitioned into state 'REVERTING' from state 'SUCCESS' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:190
2016-09-06 15:15:54.938 12327 WARNING glance.async.taskflow_executor [-] Task 'import-Convert-b685fa32-3655-4ab1-97a4-2614d26d1093' (e197a34b-290c-4f5c-a659-fe9016f727bb) transitioned into state 'REVERTED' from state 'REVERTING' with result 'None'
2016-09-06 15:15:54.940 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-ImportToFS-b685fa32-3655-4ab1-97a4-2614d26d1093' (c3165102-ea94-429f-8811-aaa3941edc87) transitioned into state 'REVERTING' from state 'SUCCESS' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:190
2016-09-06 15:15:54.941 12327 WARNING glance.async.taskflow_executor [-] Task 'import-ImportToFS-b685fa32-3655-4ab1-97a4-2614d26d1093' (c3165102-ea94-429f-8811-aaa3941edc87) transitioned into state 'REVERTED' from state 'REVERTING' with result 'None'
2016-09-06 15:15:54.942 12327 DEBUG glance.async.taskflow_executor [-] Task 'import-CreateImage-b685fa32-3655-4ab1-97a4-2614d26d1093' (01b8b8ca-fa98-4e29-adda-9d599cbc6ed2) transitioned into state 'REVERTING' from state 'SUCCESS' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:190
2016-09-06 15:15:54.943 12327 WARNING glance.async.taskflow_executor [-] Task 'import-CreateImage-b685fa32-3655-4ab1-97a4-2614d26d1093' (01b8b8ca-fa98-4e29-adda-9d599cbc6ed2) transitioned into state 'REVERTED' from state 'REVERTING' with result 'None'
2016-09-06 15:15:54.947 12327 WARNING glance.async.taskflow_executor [-] Flow 'import' (f6486f91-1faa-43b3-8106-42dc1f108cb4) transitioned into state 'REVERTED' from state 'RUNNING'
2016-09-06 15:15:54.948 12327 ERROR glance.async.taskflow_executor [-] Failed to execute task b685fa32-3655-4ab1-97a4-2614d26d1093: Unknown scheme '%(scheme)s' found in URI
2016-09-06 15:15:54.948 12327 INFO glance.domain [-] Task [b685fa32-3655-4ab1-97a4-2614d26d1093] status changing from failure to failure

[root@overcloud-controller-0 ~]# 
[root@overcloud-controller-0 ~]# fg
tcpdump -nnq -iany port 80 and host 10.0.0.250
^C
120678 packets captured
198184 packets received by filter
77506 packets dropped by kernel
[root@overcloud-controller-0 ~]# 2016-09-06 15:16:16.195 12327 DEBUG eventlet.wsgi.server [-] (12327) accepted ('172.18.0.14', 47398) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:826
2016-09-06 15:16:16.198 12327 DEBUG glance.api.middleware.version_negotiation [-] Determining version of request: GET /versions Accept: */* process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:47
2016-09-06 15:16:16.198 12327 INFO eventlet.wsgi.server [-] 172.18.0.14 - - [06/Sep/2016 15:16:16] "GET /versions HTTP/1.1" 200 778 0.001182
2016-09-06 15:16:16.275 12327 DEBUG eventlet.wsgi.server [-] (12327) accepted ('172.18.0.14', 47402) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:826
2016-09-06 15:16:16.276 12327 DEBUG glance.api.middleware.version_negotiation [-] Determining version of request: GET /v2/tasks Accept: */* process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:47
2016-09-06 15:16:16.276 12327 DEBUG glance.api.middleware.version_negotiation [-] Using url versioning process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:60
2016-09-06 15:16:16.276 12327 DEBUG glance.api.middleware.version_negotiation [-] Matched version: v2 process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:72
2016-09-06 15:16:16.277 12327 DEBUG glance.api.middleware.version_negotiation [-] new path /v2/tasks process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:73
2016-09-06 15:16:16.278 12327 DEBUG keystoneclient.session [-] REQ: curl -g -i -X GET http://192.0.2.21:35357/v3/auth/tokens -H "X-Subject-Token: {SHA1}df2251d0467b393846de22ea1d280541fe04ae65" -H "User-Agent: python-keystoneclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c3bb8b7bc897b686e847aacbf7790596ee8fc395" _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198
2016-09-06 15:16:16.330 12327 DEBUG keystoneclient.session [-] RESP: [200] content-length: 5955 x-subject-token: {SHA1}df2251d0467b393846de22ea1d280541fe04ae65 vary: X-Auth-Token date: Tue, 06 Sep 2016 15:16:16 GMT content-type: application/json x-openstack-request-id: req-94699df2-1289-43e0-830d-45983a6d0a91 
RESP BODY: {"token": {"methods": ["password", "token"], "roles": [{"id": "f922e4331a6c4e09800514b2fd530de6", "name": "admin"}], "expires_at": "2016-09-06T16:16:16.000000Z", "project": {"domain": {"id": "default", "name": "Default"}, "id": "5d2edea478ec4bdba74b6bd5e108fe3d", "name": "admin"}, "catalog": "<removed>", "extras": {}, "user": {"domain": {"id": "default", "name": "Default"}, "id": "9acb10b3918c4eeb9e9d31eeee76dbdd", "name": "admin"}, "audit_ids": ["rY_iZ5LXSzOIfjHFELcDTA"], "issued_at": "2016-09-06T15:16:16.268468"}}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215
2016-09-06 15:16:16.337 12327 INFO eventlet.wsgi.server [req-8db077a5-86f1-48b6-af8a-58fb500859b6 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] 172.18.0.14 - - [06/Sep/2016 15:16:16] "GET /v2/tasks?sort_key=status&sort_dir=desc&limit=20 HTTP/1.1" 200 2252 0.061634
2016-09-06 15:16:16.339 12327 DEBUG glance.api.middleware.version_negotiation [req-8db077a5-86f1-48b6-af8a-58fb500859b6 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Determining version of request: GET /v2/schemas/task Accept: */* process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:47
2016-09-06 15:16:16.340 12327 DEBUG glance.api.middleware.version_negotiation [req-8db077a5-86f1-48b6-af8a-58fb500859b6 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Using url versioning process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:60
2016-09-06 15:16:16.340 12327 DEBUG glance.api.middleware.version_negotiation [req-8db077a5-86f1-48b6-af8a-58fb500859b6 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Matched version: v2 process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:72
2016-09-06 15:16:16.340 12327 DEBUG glance.api.middleware.version_negotiation [req-8db077a5-86f1-48b6-af8a-58fb500859b6 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] new path /v2/schemas/task process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:73
2016-09-06 15:16:16.342 12327 INFO eventlet.wsgi.server [req-9eca28a9-5777-4fef-a71a-283939aafc74 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] 172.18.0.14 - - [06/Sep/2016 15:16:16] "GET /v2/schemas/task HTTP/1.1" 200 1448 0.003266
2016-09-06 15:16:29.032 12327 DEBUG eventlet.wsgi.server [-] (12327) accepted ('172.18.0.14', 47648) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:826
2016-09-06 15:16:29.034 12327 DEBUG glance.api.middleware.version_negotiation [-] Determining version of request: GET /versions Accept: */* process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:47
2016-09-06 15:16:29.035 12327 INFO eventlet.wsgi.server [-] 172.18.0.14 - - [06/Sep/2016 15:16:29] "GET /versions HTTP/1.1" 200 778 0.001061
2016-09-06 15:16:29.111 12327 DEBUG eventlet.wsgi.server [-] (12327) accepted ('172.18.0.14', 47652) server /usr/lib/python2.7/site-packages/eventlet/wsgi.py:826
2016-09-06 15:16:29.113 12327 DEBUG glance.api.middleware.version_negotiation [-] Determining version of request: GET /v2/tasks Accept: */* process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:47
2016-09-06 15:16:29.113 12327 DEBUG glance.api.middleware.version_negotiation [-] Using url versioning process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:60
2016-09-06 15:16:29.113 12327 DEBUG glance.api.middleware.version_negotiation [-] Matched version: v2 process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:72
2016-09-06 15:16:29.114 12327 DEBUG glance.api.middleware.version_negotiation [-] new path /v2/tasks process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:73
2016-09-06 15:16:29.115 12327 DEBUG keystoneclient.session [-] REQ: curl -g -i -X GET http://192.0.2.21:35357/v3/auth/tokens -H "X-Subject-Token: {SHA1}1eb792d4666e8ed9bf6a11a51d82471a50aa9e9a" -H "User-Agent: python-keystoneclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}c3bb8b7bc897b686e847aacbf7790596ee8fc395" _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198
2016-09-06 15:16:29.165 12327 DEBUG keystoneclient.session [-] RESP: [200] content-length: 5955 x-subject-token: {SHA1}1eb792d4666e8ed9bf6a11a51d82471a50aa9e9a vary: X-Auth-Token date: Tue, 06 Sep 2016 15:16:29 GMT content-type: application/json x-openstack-request-id: req-b330ddd9-ae99-4fb4-943b-535a42bbe733 
RESP BODY: {"token": {"methods": ["password", "token"], "roles": [{"id": "f922e4331a6c4e09800514b2fd530de6", "name": "admin"}], "expires_at": "2016-09-06T16:16:29.000000Z", "project": {"domain": {"id": "default", "name": "Default"}, "id": "5d2edea478ec4bdba74b6bd5e108fe3d", "name": "admin"}, "catalog": "<removed>", "extras": {}, "user": {"domain": {"id": "default", "name": "Default"}, "id": "9acb10b3918c4eeb9e9d31eeee76dbdd", "name": "admin"}, "audit_ids": ["mWK1fRuhS-KtDa51Sg4MNQ"], "issued_at": "2016-09-06T15:16:29.105863"}}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215
2016-09-06 15:16:29.172 12327 INFO eventlet.wsgi.server [req-74cd1082-f156-46ea-af95-339ebcda353a 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] 172.18.0.14 - - [06/Sep/2016 15:16:29] "GET /v2/tasks?sort_key=status&sort_dir=desc&limit=20 HTTP/1.1" 200 2252 0.060204
2016-09-06 15:16:29.175 12327 DEBUG glance.api.middleware.version_negotiation [req-74cd1082-f156-46ea-af95-339ebcda353a 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Determining version of request: GET /v2/schemas/task Accept: */* process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:47
2016-09-06 15:16:29.175 12327 DEBUG glance.api.middleware.version_negotiation [req-74cd1082-f156-46ea-af95-339ebcda353a 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Using url versioning process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:60
2016-09-06 15:16:29.175 12327 DEBUG glance.api.middleware.version_negotiation [req-74cd1082-f156-46ea-af95-339ebcda353a 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] Matched version: v2 process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:72
2016-09-06 15:16:29.176 12327 DEBUG glance.api.middleware.version_negotiation [req-74cd1082-f156-46ea-af95-339ebcda353a 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] new path /v2/schemas/task process_request /usr/lib/python2.7/site-packages/glance/api/middleware/version_negotiation.py:73
2016-09-06 15:16:29.178 12327 INFO eventlet.wsgi.server [req-1b3e1385-2f1b-44f7-b7d2-0557a7c1d657 9acb10b3918c4eeb9e9d31eeee76dbdd 5d2edea478ec4bdba74b6bd5e108fe3d - - -] 172.18.0.14 - - [06/Sep/2016 15:16:29] "GET /v2/schemas/task HTTP/1.1" 200 1448 0.003393
^C
Comment 2 Cyril Roelandt 2016-09-12 13:39:14 UTC 
"Attempting to import store glance.store.rbd.Store". There is no attempt to load the "glance.store.http.Store" store, hence the failure. I'm not sure exactly what happens here, it would help to be able to reproduce the issue on my side. Avi, do you think I could SSH into an OSP-8 setup where this bug is reproducible?
Comment 3 Avi Avraham 2016-10-31 12:14:42 UTC 
(In reply to Cyril Roelandt from comment #2)
> "Attempting to import store glance.store.rbd.Store". There is no attempt to
> load the "glance.store.http.Store" store, hence the failure. I'm not sure
> exactly what happens here, it would help to be able to reproduce the issue
> on my side. Avi, do you think I could SSH into an OSP-8 setup where this bug
> is reproducible?

I can try to reproduce this bug on rhos8 environment. I will need some some help with the configuration to taskflow
Comment 4 Cyril Roelandt 2017-09-08 14:57:08 UTC 
This is an old bug, and OP hasn't been active in a long time. Closing it, feel free to re-open if needed.
Comment 5 Tzach Shefi 2019-04-30 06:12:45 UTC 
Nothing to test/automate as this was closed/wontfix.