Cinder scheduler cannot re-scheduler volume creation.
Error entry in cinder scheduler log:
2013-03-29 20:12:42.116 25623 DEBUG cinder.openstack.common.rpc.amqp [-] unpacked context: {'user_id': u'd23b99a77d784eb48de60ce44cf95616', 'roles': [u'_member_', u'admin'], 'timestamp': u'2013-03-30T01:12:26.830599', 'auth_token': '<SANITIZED>', 'remote_address': u'9.123.99.191', 'quota_class': None, 'is_admin': True, 'user': u'd23b99a77d784eb48de60ce44cf95616', 'request_id': u'req-d5410c88-762d-4197-b0fa-be03cbbfad37', 'project_id': u'5b4c5924656c4daa96f813608fa91a09', 'read_deleted': u'no', 'tenant': u'5b4c5924656c4daa96f813608fa91a09'} _safe_log /usr/lib/python2.6/site-packages/cinder/openstack/common/rpc/common.py:276
2013-03-29 20:12:42.121 ERROR cinder.scheduler.filter_scheduler [req-d5410c88-762d-4197-b0fa-be03cbbfad37 d23b99a77d784eb48de60ce44cf95616 5b4c5924656c4daa96f813608fa91a09] Error from last vol-service: localhost.localdomain : [u'Traceback (most recent call last):\n', u' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 256, in create_volume\n image_location)\n', u' File "/usr/lib/python2.6/site-packages/cinder/volume/manager.py", line 171, in _create_volume\n model_update = self.driver.create_volume(volume_ref)\n', u' File "/usr/lib/python2.6/site-packages/cinder/volume/drivers/lvm.py", line 156, in create_volume\n self._create_volume(volume[\'name\'], self._sizestr(volume[\'size\']))\n', u' File "/usr/lib/python2.6/site-packages/cinder/volume/drivers/lvm.py", line 95, in _create_volume\n self._try_execute(*cmd, run_as_root=True)\n', u' File "/usr/lib/python2.6/site-packages/cinder/volume/driver.py", line 93, in _try_execute\n self._execute(*command, **kwargs)\n', u' File "/usr/lib/python2.6/site-packages/cinder/utils.py", line 193, in execute\n cmd=\' \'.join(cmd))\n', u'ProcessExecutionError: Unexpected error while running command.\nCommand: sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvcreate -L 1G -n volume-254f05d7-5ca5-4245-b582-004ccf6db8af cinder-volumes\nExit code: 5\nStdout: \'\'\nStderr: \' Volume group "cinder-volumes" has insufficient free space (255 extents): 256 required.\\n\'\n']
2013-03-29 20:12:42.131 WARNING cinder.scheduler.filters.capacity_filter [req-d5410c88-762d-4197-b0fa-be03cbbfad37 d23b99a77d784eb48de60ce44cf95616 5b4c5924656c4daa96f813608fa91a09] Insufficient free space for volume creation (requested / avail): 1/0.0
2013-03-29 20:12:42.132 ERROR cinder.scheduler.manager [req-d5410c88-762d-4197-b0fa-be03cbbfad37 d23b99a77d784eb48de60ce44cf95616 5b4c5924656c4daa96f813608fa91a09] Failed to schedule_create_volume: No valid host was found.
2013-03-29 20:12:42.168 ERROR cinder.openstack.common.rpc.amqp [req-d5410c88-762d-4197-b0fa-be03cbbfad37 d23b99a77d784eb48de60ce44cf95616 5b4c5924656c4daa96f813608fa91a09] Exception during message handling
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp Traceback (most recent call last):
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/openstack/common/rpc/amqp.py", line 430, in _process_data
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp rval = self.proxy.dispatch(ctxt, version, method, **args)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/openstack/common/rpc/dispatcher.py", line 133, in dispatch
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/scheduler/manager.py", line 112, in create_volume
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp context, ex, request_spec)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/scheduler/manager.py", line 130, in _set_volume_state_and_notify
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp db.volume_update(context, volume_id, volume_state)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/db/api.py", line 268, in volume_update
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp return IMPL.volume_update(context, volume_id, values)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py", line 126, in wrapper
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp return f(*args, **kwargs)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py", line 1103, in volume_update
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp volume_ref = volume_get(context, volume_id, session=session)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py", line 126, in wrapper
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp return f(*args, **kwargs)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.6/site-packages/cinder/db/sqlalchemy/api.py", line 1019, in volume_get
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp filter_by(id=volume_id).\
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2156, in first
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp ret = list(self[0:1])
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2023, in __getitem__
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp return list(res)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2227, in __iter__
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp return self._execute_and_instances(context)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib64/python2.6/site-packages/sqlalchemy/orm/query.py", line 2242, in _execute_and_instances
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp result = conn.execute(querycontext.statement, self._params)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib64/python2.6/site-packages/sqlalchemy/engine/base.py", line 1449, in execute
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp params)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib64/python2.6/site-packages/sqlalchemy/engine/base.py", line 1584, in _execute_clauseelement
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp compiled_sql, distilled_params
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib64/python2.6/site-packages/sqlalchemy/engine/base.py", line 1698, in _execute_context
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp context)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib64/python2.6/site-packages/sqlalchemy/engine/base.py", line 1691, in _execute_context
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp context)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib64/python2.6/site-packages/sqlalchemy/engine/default.py", line 331, in do_execute
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp cursor.execute(statement, parameters)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib64/python2.6/site-packages/MySQLdb/cursors.py", line 173, in execute
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp self.errorhandler(self, exc, value)
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib64/python2.6/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp raise errorclass, errorvalue
2013-03-29 20:12:42.168 25623 TRACE cinder.openstack.common.rpc.amqp ProgrammingError: (ProgrammingError) (1064, "You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near ') \n LIMIT 1) AS anon_1 LEFT OUTER JOIN volume_metadata AS volume_metadata_1 ON v' at line 4") 'SELECT anon_1.volumes_created_at AS anon_1_volumes_created_at, anon_1.volumes_updated_at AS anon_1_volumes_updated_at, anon_1.volumes_deleted_at AS anon_1_volumes_deleted_at, anon_1.volumes_deleted AS anon_1_volumes_deleted, anon_1.volumes_id AS anon_1_volumes_id, anon_1.volumes_ec2_id AS anon_1_volumes_ec2_id, anon_1.volumes_user_id AS anon_1_volumes_user_id, anon_1.volumes_project_id AS anon_1_volumes_project_id, anon_1.volumes_snapshot_id AS anon_1_volumes_snapshot_id, anon_1.volumes_host AS anon_1_volumes_host, anon_1.volumes_size AS anon_1_volumes_size, anon_1.volumes_availability_zone AS anon_1_volumes_availability_zone, anon_1.volumes_instance_uuid AS anon_1_volumes_instance_uuid, anon_1.volumes_mountpoint AS anon_1_volumes_mountpoint, anon_1.volumes_attach_time AS anon_1_volumes_attach_time, anon_1.volumes_status AS anon_1_volumes_status, anon_1.volumes_attach_status AS anon_1_volumes_attach_status, anon_1.volumes_scheduled_at AS anon_1_volumes_scheduled_at, anon_1.volumes_launched_at AS anon_1_volumes_launched_at, anon_1.volumes_terminated_at AS anon_1_volumes_terminated_at, anon_1.volumes_display_name AS anon_1_volumes_display_name, anon_1.volumes_display_description AS anon_1_volumes_display_description, anon_1.volumes_provider_location AS anon_1_volumes_provider_location, anon_1.volumes_provider_auth AS anon_1_volumes_provider_auth, anon_1.volumes_volume_type_id AS anon_1_volumes_volume_type_id, anon_1.volumes_source_volid AS anon_1_volumes_source_volid, volume_metadata_1.created_at AS volume_metadata_1_created_at, volume_metadata_1.updated_at AS volume_metadata_1_updated_at, volume_metadata_1.deleted_at AS volume_metadata_1_deleted_at, volume_metadata_1.deleted AS volume_metadata_1_deleted, volume_metadata_1.id AS volume_metadata_1_id, volume_metadata_1.`key` AS volume_metadata_1_key, volume_metadata_1.value AS volume_metadata_1_value, volume_metadata_1.volume_id AS volume_metadata_1_volume_id, volume_types_1.created_at AS volume_types_1_created_at, volume_types_1.updated_at AS volume_types_1_updated_at, volume_types_1.deleted_at AS volume_types_1_deleted_at, volume_types_1.deleted AS volume_types_1_deleted, volume_types_1.id AS volume_types_1_id, volume_types_1.name AS volume_types_1_name \nFROM (SELECT volumes.created_at AS volumes_created_at, volumes.updated_at AS volumes_updated_at, volumes.deleted_at AS volumes_deleted_at, volumes.deleted AS volumes_deleted, volumes.id AS volumes_id, volumes.ec2_id AS volumes_ec2_id, volumes.user_id AS volumes_user_id, volumes.project_id AS volumes_project_id, volumes.snapshot_id AS volumes_snapshot_id, volumes.host AS volumes_host, volumes.size AS volumes_size, volumes.availability_zone AS volumes_availability_zone, volumes.instance_uuid AS volumes_instance_uuid, volumes.mountpoint AS volumes_mountpoint, volumes.attach_time AS volumes_attach_time, volumes.status AS volumes_status, volumes.attach_status AS volumes_attach_status, volumes.scheduled_at AS volumes_scheduled_at, volumes.launched_at AS volumes_launched_at, volumes.terminated_at AS volumes_terminated_at, volumes.display_name AS volumes_display_name, volumes.display_description AS volumes_display_description, volumes.provider_location AS volumes_provider_location, volumes.provider_auth AS volumes_provider_auth, volumes.volume_type_id AS volumes_volume_type_id, volumes.source_volid AS volumes_source_volid \nFROM volumes \nWHERE volumes.deleted = %s AND volumes.id = %s \n LIMIT %s) AS anon_1 LEFT OUTER JOIN volume_metadata AS volume_metadata_1 ON volume_metadata_1.volume_id = anon_1.volumes_id AND volume_metadata_1.deleted = %s LEFT OUTER JOIN volume_types AS volume_types_1 ON anon_1.volumes_volume_type_id = volume_types_1.id AND volume_types_1.deleted = %s' (0, [u'254f05d7-5ca5-4245-b582-004ccf6db8af'], 1, 0, 0)
Here is the culprit -- the scheduler expects a volume id string in request_
def _reschedule(self, context, request_spec, filter_properties,
"""Attempt to re-schedule a volume operation."""