Provisioning instances on an Openstack cloud provider/cinder volume fails


#1

Hello, I’m not sure if this is the right place to ask this, so please forgive me if it’s incorrect. I am working on an Openstack cluster, and have added it to ManageIQ as a cloud provider. It appears to work fine, I can see the instances/volumes and such. However, when I go to provision a vm it always fails on the storage creation step. In the cinder.log file, I see this:

|__Flow ‘volume_create_manager’: ProcessExecutionError: Unexpected error while running command.
Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf mmchattr -P system /gpfs/gpctestfs/openstack/cinder/volume-4db8d972-da16-49a6-b54e-63d53c94cb95
Exit code: 1
Stdout: u’’
Stderr: u"File cannot be assigned to storage pool ‘system’.\n"
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager Traceback (most recent call last):
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager File “/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/executor.py”, line 53, in _execute_task
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager result = task.execute(**arguments)
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager File “/usr/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py”, line 938, in execute
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager model_update = self._create_raw_volume(volume, **volume_spec)
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager File “/usr/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py”, line 906, in _create_raw_volume
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager ret = self.driver.create_volume(volume)
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager File “/usr/lib/python2.7/site-packages/cinder/volume/drivers/ibm/gpfs.py”, line 563, in create_volume
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager self._set_volume_attributes(volume, volume_path, volume.metadata)
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager File “/usr/lib/python2.7/site-packages/cinder/volume/drivers/ibm/gpfs.py”, line 538, in _set_volume_attributes
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager self._gpfs_change_attributes(options, path)
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager File “/usr/lib/python2.7/site-packages/cinder/volume/drivers/ibm/gpfs.py”, line 510, in _gpfs_change_attributes
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager self.gpfs_execute(*cmd)
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager File “/usr/lib/python2.7/site-packages/cinder/volume/drivers/ibm/gpfs.py”, line 173, in _gpfs_local_execute
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager return utils.execute(*cmd, **kwargs)
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager File “/usr/lib/python2.7/site-packages/cinder/utils.py”, line 123, in execute
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager return processutils.execute(*cmd, **kwargs)
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager File “/usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py”, line 419, in execute
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager cmd=sanitized_cmd)
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager ProcessExecutionError: Unexpected error while running command.
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf mmchattr -P system /gpfs/gpctestfs/openstack/cinder/volume-4db8d972-da16-49a6-b54e-63d53c94cb95
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager Exit code: 1
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager Stdout: u’’
2018-06-19 16:00:09.016 32123 ERROR cinder.volume.manager Stderr: u"File cannot be assigned to storage pool ‘system’.\n"

I can create volumes/vms just fine from Horizon. Anybody have an idea what’s wrong?


#2

Ok, so that GPFS error is an issue with our filesystem, but since Horizon works it appears there’s a differenct between how it calls for provisioning and ManageIQ. When I look at the logs, I see that ManageIQ never calls the Glance API to download the image:

2018-06-26 13:20:53.591 26431 DEBUG cinder.volume.flows.manager.create_volume [req-e88f844e-5d4a-4d7f-8489-ca00028d50cc fb4f6b622a408463d6f8eb09d3e5ec0526ca1efd0ec8f620f3abc83c3c743fb8 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Volume reschedule parameters: True retry: {u'num_attempts': 1, u'backends': [u'n006@gpfs#GPFS'], u'hosts': [u'n006@gpfs#GPFS']} get_flow /usr/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py:1071
2018-06-26 13:20:53.607 26431 DEBUG cinder.volume.manager [req-e88f844e-5d4a-4d7f-8489-ca00028d50cc fb4f6b622a408463d6f8eb09d3e5ec0526ca1efd0ec8f620f3abc83c3c743fb8 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Flow 'volume_create_manager' (b2ae36b4-d28e-420e-9c70-01e7d4469b94) transitioned into state 'RUNNING' from state 'PENDING' _flow_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:145
2018-06-26 13:20:53.611 26431 DEBUG cinder.volume.manager [req-e88f844e-5d4a-4d7f-8489-ca00028d50cc fb4f6b622a408463d6f8eb09d3e5ec0526ca1efd0ec8f620f3abc83c3c743fb8 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Task 'cinder.volume.flows.manager.create_volume.ExtractVolumeRefTask;volume:create' (27580391-5be1-482e-8660-6dd048333779) transitioned into state 'RUNNING' from state 'PENDING' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:194
2018-06-26 13:20:53.636 26431 DEBUG oslo_db.sqlalchemy.engines [req-e88f844e-5d4a-4d7f-8489-ca00028d50cc fb4f6b622a408463d6f8eb09d3e5ec0526ca1efd0ec8f620f3abc83c3c743fb8 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION _check_effective_sql_mode /usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/engines.py:285
2018-06-26 13:20:53.662 26431 DEBUG cinder.volume.manager [req-e88f844e-5d4a-4d7f-8489-ca00028d50cc fb4f6b622a408463d6f8eb09d3e5ec0526ca1efd0ec8f620f3abc83c3c743fb8 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Task 'cinder.volume.flows.manager.create_volume.ExtractVolumeRefTask;volume:create' (27580391-5be1-482e-8660-6dd048333779) transitioned into state 'SUCCESS' from state 'RUNNING' with result 'Volume(_name_id=None,admin_metadata={},attach_status='detached',availability_zone='gpctest',bootable=False,cluster=<?>,cluster_name=None,consistencygroup=<?>,consistencygroup_id=None,created_at=2018-06-26T17:20:52Z,deleted=False,deleted_at=None,display_description=None,display_name='testerror',ec2_id=None,encryption_key_id=None,glance_metadata=<?>,group=<?>,group_id=None,host='n006@gpfs#GPFS',id=a3df74a7-1c57-4837-99f0-f7418db17c0c,launched_at=None,metadata={},migration_status=None,multiattach=False,previous_status=None,project_id='53eb9db347a14bb580fdac1b744a911c',provider_auth=None,provider_geometry=None,provider_id=None,provider_location=None,replication_driver_data=None,replication_extended_status=None,replication_status=None,scheduled_at=2018-06-26T17:20:53Z,size=12,snapshot_id=None,snapshots=<?>,source_volid=None,status='creating',terminated_at=None,updated_at=2018-06-26T17:20:53Z,user_id='fb4f6b622a408463d6f8eb09d3e5ec0526ca1efd0ec8f620f3abc83c3c743fb8',volume_attachment=<?>,volume_type=<?>,volume_type_id=None)' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:183
2018-06-26 13:20:53.665 26431 DEBUG cinder.volume.manager [req-e88f844e-5d4a-4d7f-8489-ca00028d50cc fb4f6b622a408463d6f8eb09d3e5ec0526ca1efd0ec8f620f3abc83c3c743fb8 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Task 'cinder.volume.flows.manager.create_volume.OnFailureRescheduleTask;volume:create' (e38b7119-60a3-452f-9c1f-d44def3f9462) transitioned into state 'RUNNING' from state 'PENDING' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:194
2018-06-26 13:20:53.667 26431 DEBUG cinder.volume.manager [req-e88f844e-5d4a-4d7f-8489-ca00028d50cc fb4f6b622a408463d6f8eb09d3e5ec0526ca1efd0ec8f620f3abc83c3c743fb8 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Task 'cinder.volume.flows.manager.create_volume.OnFailureRescheduleTask;volume:create' (e38b7119-60a3-452f-9c1f-d44def3f9462) transitioned into state 'SUCCESS' from state 'RUNNING' with result 'None' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:183
2018-06-26 13:20:53.669 26431 DEBUG cinder.volume.manager [req-e88f844e-5d4a-4d7f-8489-ca00028d50cc fb4f6b622a408463d6f8eb09d3e5ec0526ca1efd0ec8f620f3abc83c3c743fb8 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Task 'cinder.volume.flows.manager.create_volume.ExtractVolumeSpecTask;volume:create' (b9844627-20f9-4a33-8bae-bb8fc28d8715) transitioned into state 'RUNNING' from state 'PENDING' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:194
2018-06-26 13:20:53.671 26431 DEBUG cinder.volume.manager [req-e88f844e-5d4a-4d7f-8489-ca00028d50cc fb4f6b622a408463d6f8eb09d3e5ec0526ca1efd0ec8f620f3abc83c3c743fb8 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Task 'cinder.volume.flows.manager.create_volume.ExtractVolumeSpecTask;volume:create' (b9844627-20f9-4a33-8bae-bb8fc28d8715) transitioned into state 'SUCCESS' from state 'RUNNING' with result '{'status': u'creating', 'volume_size': 12, 'volume_name': 'volume-a3df74a7-1c57-4837-99f0-f7418db17c0c', 'type': 'raw', 'volume_id': 'a3df74a7-1c57-4837-99f0-f7418db17c0c'}' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:183

When I look at Horizon, it calls the Glance API:

2018-06-26 13:47:27.126 26431 DEBUG cinder.volume.flows.manager.create_volume [req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Volume reschedule parameters: True retry: {u'num_attempts': 1, u'backends': [u'n006@gpfs#GPFS'], u'hosts': [u'n006@gpfs#GPFS']} get_flow /usr/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py:1071
2018-06-26 13:47:27.146 26431 DEBUG cinder.volume.manager [req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Flow 'volume_create_manager' (b63ab346-6a46-4031-876d-ef34f9bb80ad) transitioned into state 'RUNNING' from state 'PENDING' _flow_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:145
2018-06-26 13:47:27.149 26431 DEBUG cinder.volume.manager [req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Task 'cinder.volume.flows.manager.create_volume.ExtractVolumeRefTask;volume:create' (fee71212-f4bb-472b-96bb-719182af4e09) transitioned into state 'RUNNING' from state 'PENDING' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:194
2018-06-26 13:47:27.177 26431 DEBUG oslo_db.sqlalchemy.engines [req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION _check_effective_sql_mode /usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/engines.py:285
2018-06-26 13:47:27.206 26431 DEBUG cinder.volume.manager [req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Task 'cinder.volume.flows.manager.create_volume.ExtractVolumeRefTask;volume:create' (fee71212-f4bb-472b-96bb-719182af4e09) transitioned into state 'SUCCESS' from state 'RUNNING' with result 'Volume(_name_id=None,admin_metadata={},attach_status='detached',availability_zone='gpctest',bootable=False,cluster=<?>,cluster_name=None,consistencygroup=<?>,consistencygroup_id=None,created_at=2018-06-26T17:47:26Z,deleted=False,deleted_at=None,display_description='',display_name='',ec2_id=None,encryption_key_id=None,glance_metadata=<?>,group=<?>,group_id=None,host='n006@gpfs#GPFS',id=63c0e4af-60e9-46b5-9afb-ac87dcf4dd14,launched_at=None,metadata={},migration_status=None,multiattach=False,previous_status=None,project_id='53eb9db347a14bb580fdac1b744a911c',provider_auth=None,provider_geometry=None,provider_id=None,provider_location=None,replication_driver_data=None,replication_extended_status=None,replication_status=None,scheduled_at=2018-06-26T17:47:26Z,size=12,snapshot_id=None,snapshots=<?>,source_volid=None,status='creating',terminated_at=None,updated_at=2018-06-26T17:47:26Z,user_id='f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff',volume_attachment=<?>,volume_type=<?>,volume_type_id=None)' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:183
2018-06-26 13:47:27.209 26431 DEBUG cinder.volume.manager [req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Task 'cinder.volume.flows.manager.create_volume.OnFailureRescheduleTask;volume:create' (a4389421-9cd3-4740-bdbe-6b8346e69ff3) transitioned into state 'RUNNING' from state 'PENDING' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:194
2018-06-26 13:47:27.210 26431 DEBUG cinder.volume.manager [req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Task 'cinder.volume.flows.manager.create_volume.OnFailureRescheduleTask;volume:create' (a4389421-9cd3-4740-bdbe-6b8346e69ff3) transitioned into state 'SUCCESS' from state 'RUNNING' with result 'None' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:183
2018-06-26 13:47:27.212 26431 DEBUG cinder.volume.manager [req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] Task 'cinder.volume.flows.manager.create_volume.ExtractVolumeSpecTask;volume:create' (b250cd33-4cd1-40da-aa1a-a2d6c9b96dc9) transitioned into state 'RUNNING' from state 'PENDING' _task_receiver /usr/lib/python2.7/site-packages/taskflow/listeners/logging.py:194
2018-06-26 13:47:27.214 26431 DEBUG glanceclient.common.http [req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] curl -g -i -X GET -H 'Accept-Encoding: gzip, deflate' -H 'Accept: */*' -H 'X-Auth-Token: {SHA1}09f82b9e5764209e6c969437ea4e999651374aab' -H 'Connection: keep-alive' -H 'User-Agent: python-glanceclient' -H 'Content-Type: application/octet-stream' -H 'X-OpenStack-Request-ID: req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef'  --cacert /etc/openldap/cacerts/gpc_root_ca.pem  --cert None --key None https://glance.gpctest:9292/v2/images/a962b125-1b75-4eb0-a25e-210318a96450 log_curl_request /usr/lib/python2.7/site-packages/glanceclient/common/http.py:188
2018-06-26 13:47:27.257 26431 DEBUG glanceclient.common.http [req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8] GET call to image for https://glance.gpctest:9292/v2/images/a962b125-1b75-4eb0-a25e-210318a96450 used request id req-b5f17136-2ada-48eb-a032-6932ba989880 _request /usr/lib/python2.7/site-packages/glanceclient/common/http.py:276
2018-06-26 13:47:27.257 26431 DEBUG glanceclient.common.http [req-8fe07bf6-1d2e-4ae1-ac4d-104d239fefef f34779dfdc8e1f965866987a3aea715de08d87f6ffdd94dc3ec1c27935f665ff 53eb9db347a14bb580fdac1b744a911c - b5b5816a30fc4de2b62b9e16ae09a8c8 b5b5816a30fc4de2b62b9e16ae09a8c8]
HTTP/1.1 200 OK
Content-Length: 844
Content-Type: application/json
X-Openstack-Request-Id: req-b5f17136-2ada-48eb-a032-6932ba989880
Date: Tue, 26 Jun 2018 17:47:26 GMT

{"container_format": "bare", "min_ram": 0, "locations": [{"url": "file:///gpfs/gpctestfs/openstack/glance/a962b125-1b75-4eb0-a25e-210318a96450", "metadata": {}}], "file": "/v2/images/a962b125-1b75-4eb0-a25e-210318a96450/file", "owner": "53eb9db347a14bb580fdac1b744a911c", "id": "a962b125-1b75-4eb0-a25e-210318a96450", "size": 876740608, "self": "/v2/images/a962b125-1b75-4eb0-a25e-210318a96450", "disk_format": "qcow2", "direct_url": "file:///gpfs/gpctestfs/openstack/glance/a962b125-1b75-4eb0-a25e-210318a96450", "schema": "/v2/schemas/image", "status": "active", "tags": [], "visibility": "private", "updated_at": "2018-01-18T21:25:42Z", "min_disk": 0, "virtual_size": null, "name": "CentOS-7-x86_64-GenericCloud-1711", "checksum": "317ecf7d1128e0e53cb285b8704dc3d3", "created_at": "2017-12-14T18:57:34Z", "protected": false, "os": "windows"}
 log_http_response /usr/lib/python2.7/site-packages/glanceclient/common/http.py:202

Anybody know why the difference? This is a hard stop for us with ManageIQ, since we can’t provision anything at all.