2015-03-25 14:59:54.968 INFO eventlet.wsgi.server [-] (13734) accepted ('192.168.21.107', 53874)
2015-03-25 14:59:54.970 DEBUG keystoneclient.auth.identity.v3 [-] Making authentication request to http://192.168.21.108:35357/v3/auth/tokens from (pid=13734) get_auth_ref /usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v3.py:125
2015-03-25 14:59:55.133 DEBUG keystoneclient.session [-] REQ: curl -g -i --cacert "/opt/stack/data/ca-bundle.pem" -X GET http://192.168.21.108:35357/v3/auth/tokens -H "X-Subject-Token: {SHA1}4165822a77a85b4f17b5bc1919f6f50d9ed978d3" -H "User-Agent: python-keystoneclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}5d24ebac8b891fde7fc87bae998e45277cb88c9a" from (pid=13734) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:195
2015-03-25 14:59:55.208 DEBUG keystoneclient.session [-] RESP: [200] content-length: 6030 x-subject-token: {SHA1}4165822a77a85b4f17b5bc1919f6f50d9ed978d3 vary: X-Auth-Token keep-alive: timeout=5, max=99 server: Apache/2.4.10 (Fedora) OpenSSL/1.0.1k-fips mod_wsgi/4.3.2 Python/2.7.8 connection: Keep-Alive date: Wed, 25 Mar 2015 09:29:55 GMT content-type: application/json 
RESP BODY: {"token": {"methods": ["password", "token"], "roles": [{"id": "0c685ace95154761ab35f20413510a3c", "name": "Member"}, {"id": "f84b2230aadb4a139e21c2f300c1ffa5", "name": "anotherrole"}], "expires_at": "2015-03-25T10:29:54.000000Z", "project": {"domain": {"id": "default", "name": "Default"}, "id": "3c513580c125402daf7976a54faf9e10", "name": "demo"}, "catalog": "<removed>", "extras": {}, "user": {"domain": {"id": "default", "name": "Default"}, "id": "5a4c8b6072fd4bc8bdbb42ea58fbdd00", "name": "demo"}, "audit_ids": ["X7K-TDbbSZSuC7UmMbRoHg"], "issued_at": "2015-03-25T09:29:54.937349"}}
 from (pid=13734) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:223
2015-03-25 14:59:55.211 INFO cinder.api.openstack.wsgi [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] POST http://192.168.21.108:8776/v1/3c513580c125402daf7976a54faf9e10/volumes
2015-03-25 14:59:55.212 DEBUG cinder.api.v1.volumes [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Create volume request body: {u'volume': {u'status': u'creating', u'user_id': None, u'imageRef': None, u'availability_zone': None, 'scheduler_hints': {}, u'attach_status': u'detached', u'display_description': None, u'metadata': {}, u'source_volid': None, u'snapshot_id': None, u'display_name': None, u'project_id': None, u'volume_type': None, u'size': 1}} from (pid=13734) create /opt/stack/cinder/cinder/api/v1/volumes.py:319
2015-03-25 14:59:55.212 INFO cinder.api.v1.volumes [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Create volume of 1 GB
2015-03-25 14:59:55.219 DEBUG cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Availability zone cache updated, next update will occur around 2015-03-25 10:29:55.219516 from (pid=13734) list_availability_zones /opt/stack/cinder/cinder/volume/api.py:148
2015-03-25 14:59:55.220 DEBUG taskflow.engines.helpers [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Looking for 'default' engine driver in 'taskflow.engines' from (pid=13734) load /usr/lib/python2.7/site-packages/taskflow/engines/helpers.py:176
2015-03-25 14:59:55.227 DEBUG cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Flow 'volume_create_api' (a2d5d4ec-cd12-48ea-a427-e6ba3d04afef) transitioned into state 'RUNNING' from state 'PENDING' from (pid=13734) _flow_receiver /opt/stack/cinder/cinder/flow_utils.py:83
2015-03-25 14:59:55.228 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'UNDEFINED' in response to event 'start' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.228 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'RESUMING' in response to event 'start' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.230 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'RESUMING' in response to event 'schedule_next' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.230 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'SCHEDULING' in response to event 'schedule_next' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.231 DEBUG cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.ExtractVolumeRequestTask;volume:create' (305945eb-cd20-4773-9e84-e768f43d0762) transitioned into state 'RUNNING' from (pid=13734) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:131
2015-03-25 14:59:55.233 DEBUG cinder.volume.flows.api.create_volume [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Validating volume 1 using validate_int from (pid=13734) _extract_size /opt/stack/cinder/cinder/volume/flows/api/create_volume.py:218
2015-03-25 14:59:55.233 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'SCHEDULING' in response to event 'wait_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.233 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'WAITING' in response to event 'wait_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.234 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'WAITING' in response to event 'examine_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.234 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'ANALYZING' in response to event 'examine_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.235 DEBUG cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.ExtractVolumeRequestTask;volume:create' (305945eb-cd20-4773-9e84-e768f43d0762) transitioned into state 'SUCCESS' with result '{'volume_type_id': None, 'availability_zone': 'nova', 'source_replicaid': None, 'volume_type': {}, 'qos_specs': None, 'encryption_key_id': None, 'source_volid': None, 'snapshot_id': None, 'consistencygroup_id': None, 'size': 1}' from (pid=13734) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:113
2015-03-25 14:59:55.236 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'ANALYZING' in response to event 'schedule_next' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.236 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'SCHEDULING' in response to event 'schedule_next' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.237 DEBUG cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.QuotaReserveTask;volume:create' (5023061f-f722-4141-9f6b-29da197463a6) transitioned into state 'RUNNING' from (pid=13734) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:131
2015-03-25 14:59:55.298 DEBUG cinder.quota [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Created reservations ['0ddaf11c-11e7-4c65-8579-29e26238b6af', '8da37609-a0bc-44ba-8d8b-733eed3c4493'] from (pid=13734) reserve /opt/stack/cinder/cinder/quota.py:761
2015-03-25 14:59:55.299 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'SCHEDULING' in response to event 'wait_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.299 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'WAITING' in response to event 'wait_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.299 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'WAITING' in response to event 'examine_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.300 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'ANALYZING' in response to event 'examine_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.301 DEBUG cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.QuotaReserveTask;volume:create' (5023061f-f722-4141-9f6b-29da197463a6) transitioned into state 'SUCCESS' with result '{'reservations': ['0ddaf11c-11e7-4c65-8579-29e26238b6af', '8da37609-a0bc-44ba-8d8b-733eed3c4493']}' from (pid=13734) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:113
2015-03-25 14:59:55.301 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'ANALYZING' in response to event 'schedule_next' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.302 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'SCHEDULING' in response to event 'schedule_next' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.302 DEBUG cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.EntryCreateTask;volume:create' (8a0ce9cd-15db-4f6e-a987-49d46d7aeb96) transitioned into state 'RUNNING' from (pid=13734) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:131
2015-03-25 14:59:55.309 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'SCHEDULING' in response to event 'wait_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.309 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'WAITING' in response to event 'wait_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.309 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'WAITING' in response to event 'examine_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.310 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'ANALYZING' in response to event 'examine_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.310 WARNING cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.EntryCreateTask;volume:create' (8a0ce9cd-15db-4f6e-a987-49d46d7aeb96) transitioned into state 'FAILURE'
2015-03-25 14:59:55.310 TRACE cinder.volume.api Traceback (most recent call last):
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/executor.py", line 67, in _execute_task
2015-03-25 14:59:55.310 TRACE cinder.volume.api     result = task.execute(**arguments)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/opt/stack/cinder/cinder/volume/flows/api/create_volume.py", line 502, in execute
2015-03-25 14:59:55.310 TRACE cinder.volume.api     volume = self.db.volume_create(context, volume_properties)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/opt/stack/cinder/cinder/db/api.py", line 178, in volume_create
2015-03-25 14:59:55.310 TRACE cinder.volume.api     return IMPL.volume_create(context, values)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 172, in wrapper
2015-03-25 14:59:55.310 TRACE cinder.volume.api     return f(*args, **kwargs)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 1056, in volume_create
2015-03-25 14:59:55.310 TRACE cinder.volume.api     session.add(volume_ref)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 470, in __exit__
2015-03-25 14:59:55.310 TRACE cinder.volume.api     self.rollback()
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2015-03-25 14:59:55.310 TRACE cinder.volume.api     compat.reraise(exc_type, exc_value, exc_tb)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 467, in __exit__
2015-03-25 14:59:55.310 TRACE cinder.volume.api     self.commit()
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 377, in commit
2015-03-25 14:59:55.310 TRACE cinder.volume.api     self._prepare_impl()
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 357, in _prepare_impl
2015-03-25 14:59:55.310 TRACE cinder.volume.api     self.session.flush()
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 1919, in flush
2015-03-25 14:59:55.310 TRACE cinder.volume.api     self._flush(objects)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2037, in _flush
2015-03-25 14:59:55.310 TRACE cinder.volume.api     transaction.rollback(_capture_exception=True)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2015-03-25 14:59:55.310 TRACE cinder.volume.api     compat.reraise(exc_type, exc_value, exc_tb)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2001, in _flush
2015-03-25 14:59:55.310 TRACE cinder.volume.api     flush_context.execute()
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 372, in execute
2015-03-25 14:59:55.310 TRACE cinder.volume.api     rec.execute(self)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 526, in execute
2015-03-25 14:59:55.310 TRACE cinder.volume.api     uow
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 65, in save_obj
2015-03-25 14:59:55.310 TRACE cinder.volume.api     mapper, table, insert)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 570, in _emit_insert_statements
2015-03-25 14:59:55.310 TRACE cinder.volume.api     execute(statement, multiparams)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 729, in execute
2015-03-25 14:59:55.310 TRACE cinder.volume.api     return meth(self, multiparams, params)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 322, in _execute_on_connection
2015-03-25 14:59:55.310 TRACE cinder.volume.api     return connection._execute_clauseelement(self, multiparams, params)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 826, in _execute_clauseelement
2015-03-25 14:59:55.310 TRACE cinder.volume.api     compiled_sql, distilled_params
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 958, in _execute_context
2015-03-25 14:59:55.310 TRACE cinder.volume.api     context)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/compat/handle_error.py", line 261, in _handle_dbapi_exception
2015-03-25 14:59:55.310 TRACE cinder.volume.api     e, statement, parameters, cursor, context)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1155, in _handle_dbapi_exception
2015-03-25 14:59:55.310 TRACE cinder.volume.api     util.raise_from_cause(newraise, exc_info)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
2015-03-25 14:59:55.310 TRACE cinder.volume.api     reraise(type(exception), exception, tb=exc_tb)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 951, in _execute_context
2015-03-25 14:59:55.310 TRACE cinder.volume.api     context)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 436, in do_execute
2015-03-25 14:59:55.310 TRACE cinder.volume.api     cursor.execute(statement, parameters)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/MySQLdb/cursors.py", line 174, in execute
2015-03-25 14:59:55.310 TRACE cinder.volume.api     self.errorhandler(self, exc, value)
2015-03-25 14:59:55.310 TRACE cinder.volume.api   File "/usr/lib64/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2015-03-25 14:59:55.310 TRACE cinder.volume.api     raise errorclass, errorvalue
2015-03-25 14:59:55.310 TRACE cinder.volume.api OperationalError: (OperationalError) (1054, "Unknown column 'instance_uuid' in 'field list'") 'INSERT INTO volumes (created_at, updated_at, deleted_at, id, _name_id, ec2_id, user_id, project_id, snapshot_id, host, size, availability_zone, instance_uuid, attached_host, mountpoint, attach_time, status, attach_status, migration_status, scheduled_at, launched_at, terminated_at, display_name, display_description, provider_location, provider_auth, provider_geometry, volume_type_id, source_volid, encryption_key_id, consistencygroup_id, deleted, bootable, replication_status, replication_extended_status, replication_driver_data) VALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s)' (datetime.datetime(2015, 3, 25, 9, 29, 55, 306816), None, None, '54fa12a2-b53a-4183-b1ef-1334e3f7b469', None, None, '5a4c8b6072fd4bc8bdbb42ea58fbdd00', '3c513580c125402daf7976a54faf9e10', None, None, 1, 'nova', None, None, None, None, 'creating', 'detached', None, None, None, None, None, None, None, None, None, None, None, None, None, 0, 0, 'disabled', None, None)
2015-03-25 14:59:55.310 TRACE cinder.volume.api 
2015-03-25 14:59:55.312 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Discarding failure 'Failure: sqlalchemy.exc.OperationalError: (OperationalError) (1054, "Unknown column 'instance_uuid' in 'field list'") 'INSERT INTO volumes (created_at, updated_at, deleted_at, id, _name_id, ec2_id, user_id, project_id, snapshot_id, host, size, availability_zone, instance_uuid, attached_host, mountpoint, attach_time, status, attach_status, migration_status, scheduled_at, launched_at, terminated_at, display_name, display_description, provider_location, provider_auth, provider_geometry, volume_type_id, source_volid, encryption_key_id, consistencygroup_id, deleted, bootable, replication_status, replication_extended_status, replication_driver_data) VALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s)' (datetime.datetime(2015, 3, 25, 9, 29, 55, 306816), None, None, '54fa12a2-b53a-4183-b1ef-1334e3f7b469', None, None, '5a4c8b6072fd4bc8bdbb42ea58fbdd00', '3c513580c125402daf7976a54faf9e10', None, None, 1, 'nova', None, None, None, None, 'creating', 'detached', None, None, None, None, None, None, None, None, None, None, None, None, None, 0, 0, 'disabled', None, None)' (in response to event 'executed') under completion units request during completion of node 'cinder.volume.flows.api.create_volume.EntryCreateTask;volume:create==1.0' (intention is to REVERT) from (pid=13734) analyze /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:181
2015-03-25 14:59:55.313 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'ANALYZING' in response to event 'schedule_next' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.314 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'SCHEDULING' in response to event 'schedule_next' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.315 WARNING cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.EntryCreateTask;volume:create' (8a0ce9cd-15db-4f6e-a987-49d46d7aeb96) transitioned into state 'REVERTING'
2015-03-25 14:59:55.316 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'SCHEDULING' in response to event 'wait_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.316 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'WAITING' in response to event 'wait_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.317 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'WAITING' in response to event 'examine_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.317 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'ANALYZING' in response to event 'examine_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.318 DEBUG cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.EntryCreateTask;volume:create' (8a0ce9cd-15db-4f6e-a987-49d46d7aeb96) transitioned into state 'REVERTED' from (pid=13734) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:131
2015-03-25 14:59:55.318 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'ANALYZING' in response to event 'schedule_next' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.319 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'SCHEDULING' in response to event 'schedule_next' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.320 WARNING cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.QuotaReserveTask;volume:create' (5023061f-f722-4141-9f6b-29da197463a6) transitioned into state 'REVERTING'
2015-03-25 14:59:55.346 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'SCHEDULING' in response to event 'wait_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.347 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'WAITING' in response to event 'wait_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.347 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'WAITING' in response to event 'examine_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.347 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'ANALYZING' in response to event 'examine_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.348 DEBUG cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.QuotaReserveTask;volume:create' (5023061f-f722-4141-9f6b-29da197463a6) transitioned into state 'REVERTED' from (pid=13734) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:131
2015-03-25 14:59:55.349 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'ANALYZING' in response to event 'schedule_next' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.349 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'SCHEDULING' in response to event 'schedule_next' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.350 WARNING cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.ExtractVolumeRequestTask;volume:create' (305945eb-cd20-4773-9e84-e768f43d0762) transitioned into state 'REVERTING'
2015-03-25 14:59:55.351 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'SCHEDULING' in response to event 'wait_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.352 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'WAITING' in response to event 'wait_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.352 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'WAITING' in response to event 'examine_finished' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.352 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'ANALYZING' in response to event 'examine_finished' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.353 DEBUG cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Task 'cinder.volume.flows.api.create_volume.ExtractVolumeRequestTask;volume:create' (305945eb-cd20-4773-9e84-e768f43d0762) transitioned into state 'REVERTED' from (pid=13734) _task_receiver /opt/stack/cinder/cinder/flow_utils.py:131
2015-03-25 14:59:55.353 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'ANALYZING' in response to event 'completed' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.354 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'GAME_OVER' in response to event 'completed' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.355 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Exiting old state 'GAME_OVER' in response to event 'reverted' from (pid=13734) on_exit /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:201
2015-03-25 14:59:55.355 DEBUG taskflow.engines.action_engine.runner [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Entering new state 'REVERTED' in response to event 'reverted' from (pid=13734) on_enter /usr/lib/python2.7/site-packages/taskflow/engines/action_engine/runner.py:205
2015-03-25 14:59:55.356 WARNING cinder.volume.api [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Flow 'volume_create_api' (a2d5d4ec-cd12-48ea-a427-e6ba3d04afef) transitioned into state 'REVERTED' from state 'RUNNING'
2015-03-25 14:59:55.356 ERROR cinder.api.middleware.fault [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] Caught error: (OperationalError) (1054, "Unknown column 'instance_uuid' in 'field list'") 'INSERT INTO volumes (created_at, updated_at, deleted_at, id, _name_id, ec2_id, user_id, project_id, snapshot_id, host, size, availability_zone, instance_uuid, attached_host, mountpoint, attach_time, status, attach_status, migration_status, scheduled_at, launched_at, terminated_at, display_name, display_description, provider_location, provider_auth, provider_geometry, volume_type_id, source_volid, encryption_key_id, consistencygroup_id, deleted, bootable, replication_status, replication_extended_status, replication_driver_data) VALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s)' (datetime.datetime(2015, 3, 25, 9, 29, 55, 306816), None, None, '54fa12a2-b53a-4183-b1ef-1334e3f7b469', None, None, '5a4c8b6072fd4bc8bdbb42ea58fbdd00', '3c513580c125402daf7976a54faf9e10', None, None, 1, 'nova', None, None, None, None, 'creating', 'detached', None, None, None, None, None, None, None, None, None, None, None, None, None, 0, 0, 'disabled', None, None)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault Traceback (most recent call last):
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/opt/stack/cinder/cinder/api/middleware/fault.py", line 76, in __call__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return req.get_response(self.application)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1320, in send
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     application, catch_exc_info=False)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1284, in call_application
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     app_iter = application(self.environ, start_response)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     resp = self.call_func(req, *args, **self.kwargs)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return self.func(req, *args, **kwargs)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/osprofiler/web.py", line 99, in __call__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return request.get_response(self.application)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1320, in send
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     application, catch_exc_info=False)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1284, in call_application
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     app_iter = application(self.environ, start_response)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 634, in __call__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return self._call_app(env, start_response)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 554, in _call_app
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return self._app(env, _fake_start_response)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     response = self.app(environ, start_response)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     resp = self.call_func(req, *args, **self.kwargs)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return self.func(req, *args, **kwargs)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/opt/stack/cinder/cinder/api/openstack/wsgi.py", line 897, in __call__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     content_type, body, accept)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/opt/stack/cinder/cinder/api/openstack/wsgi.py", line 945, in _process_stack
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     action_result = self.dispatch(meth, request, action_args)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/opt/stack/cinder/cinder/api/openstack/wsgi.py", line 1021, in dispatch
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return method(req=request, **action_args)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/opt/stack/cinder/cinder/api/v1/volumes.py", line 388, in create
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     **kwargs)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/opt/stack/cinder/cinder/volume/api.py", line 248, in create
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     flow_engine.run()
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/engine.py", line 96, in run
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     for _state in self.run_iter():
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/engine.py", line 153, in run_iter
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     failure.Failure.reraise_if_any(failures.values())
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/taskflow/types/failure.py", line 244, in reraise_if_any
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     failures[0].reraise()
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/taskflow/types/failure.py", line 251, in reraise
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     six.reraise(*self._exc_info)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/executor.py", line 67, in _execute_task
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     result = task.execute(**arguments)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/opt/stack/cinder/cinder/volume/flows/api/create_volume.py", line 502, in execute
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     volume = self.db.volume_create(context, volume_properties)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/opt/stack/cinder/cinder/db/api.py", line 178, in volume_create
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return IMPL.volume_create(context, values)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 172, in wrapper
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return f(*args, **kwargs)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 1056, in volume_create
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     session.add(volume_ref)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 470, in __exit__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     self.rollback()
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     compat.reraise(exc_type, exc_value, exc_tb)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 467, in __exit__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     self.commit()
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 377, in commit
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     self._prepare_impl()
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 357, in _prepare_impl
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     self.session.flush()
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 1919, in flush
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     self._flush(objects)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2037, in _flush
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     transaction.rollback(_capture_exception=True)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     compat.reraise(exc_type, exc_value, exc_tb)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2001, in _flush
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     flush_context.execute()
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 372, in execute
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     rec.execute(self)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 526, in execute
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     uow
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 65, in save_obj
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     mapper, table, insert)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 570, in _emit_insert_statements
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     execute(statement, multiparams)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 729, in execute
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return meth(self, multiparams, params)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 322, in _execute_on_connection
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     return connection._execute_clauseelement(self, multiparams, params)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 826, in _execute_clauseelement
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     compiled_sql, distilled_params
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 958, in _execute_context
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     context)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/compat/handle_error.py", line 261, in _handle_dbapi_exception
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     e, statement, parameters, cursor, context)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1155, in _handle_dbapi_exception
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     util.raise_from_cause(newraise, exc_info)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     reraise(type(exception), exception, tb=exc_tb)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 951, in _execute_context
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     context)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 436, in do_execute
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     cursor.execute(statement, parameters)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/MySQLdb/cursors.py", line 174, in execute
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     self.errorhandler(self, exc, value)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault   File "/usr/lib64/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault     raise errorclass, errorvalue
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault OperationalError: (OperationalError) (1054, "Unknown column 'instance_uuid' in 'field list'") 'INSERT INTO volumes (created_at, updated_at, deleted_at, id, _name_id, ec2_id, user_id, project_id, snapshot_id, host, size, availability_zone, instance_uuid, attached_host, mountpoint, attach_time, status, attach_status, migration_status, scheduled_at, launched_at, terminated_at, display_name, display_description, provider_location, provider_auth, provider_geometry, volume_type_id, source_volid, encryption_key_id, consistencygroup_id, deleted, bootable, replication_status, replication_extended_status, replication_driver_data) VALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s)' (datetime.datetime(2015, 3, 25, 9, 29, 55, 306816), None, None, '54fa12a2-b53a-4183-b1ef-1334e3f7b469', None, None, '5a4c8b6072fd4bc8bdbb42ea58fbdd00', '3c513580c125402daf7976a54faf9e10', None, None, 1, 'nova', None, None, None, None, 'creating', 'detached', None, None, None, None, None, None, None, None, None, None, None, None, None, 0, 0, 'disabled', None, None)
2015-03-25 14:59:55.356 TRACE cinder.api.middleware.fault 
2015-03-25 14:59:55.360 INFO cinder.api.middleware.fault [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] http://192.168.21.108:8776/v1/3c513580c125402daf7976a54faf9e10/volumes returned with HTTP 500
2015-03-25 14:59:55.361 INFO eventlet.wsgi.server [req-c98cb6a0-eda6-40f9-a60d-d8438159cf64 5a4c8b6072fd4bc8bdbb42ea58fbdd00 3c513580c125402daf7976a54faf9e10] 192.168.21.107 - - [25/Mar/2015 14:59:55] "POST /v1/3c513580c125402daf7976a54faf9e10/volumes HTTP/1.1" 500 425 0.39198