yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1416269] [NEW] boot vm failed with --block-device set as attach volume failed during boot

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Jerry Cai <caimin@xxxxxxxxxx>
Date: Fri, 30 Jan 2015 07:08:54 -0000
Reply-to: Bug 1416269 <1416269@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

When attach a existing vm during booting vm by following cmd:
nova boot --flavor small --image c7e8738b-c2c6-4365-a305-040bfbd1b514 --nic net-id=abfe3157-d23c-4d15-a7ff-80429a7d9b27 --block-device source=volume,dest=volume,bootindex=1,shutdown=remove,id=ca383135-d619-43c2-8826-95ae4d475581 test11

It failed in "block device mapping" phase, error from nova is:
2015-01-30 01:59:14.030 28957 ERROR nova.compute.manager [-] [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] Instance failed block device setup
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] Traceback (most recent call last):
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1856, in _prep_block_device
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     do_check_attach=do_check_attach) +
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 407, in attach_block_devices
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     map(_log_and_attach, block_device_mapping)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 405, in _log_and_attach
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     bdm.attach(*attach_args, **attach_kwargs)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 48, in wrapped
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     ret_val = method(obj, context, *args, **kwargs)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 272, in attach
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     self['mount_device'], mode=mode)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 213, in wrapper
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     res = method(self, ctx, volume_id, *args, **kwargs)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 359, in attach
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     mountpoint, mode=mode)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 326, in attach
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     'mode': mode})
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 311, in _action
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return self.api.client.post(url, body=body)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 91, in post
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return self._cs_request(url, 'POST', **kwargs)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 85, in _cs_request
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return self.request(url, method, **kwargs)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 80, in request
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return super(SessionClient, self).request(*args, **kwargs)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 158, in request
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     resp = super(LegacyJsonAdapter, self).request(*args, **kwargs)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 88, in request
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return self.session.request(url, method, **kwargs)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return func(*args, **kwargs)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 354, in request
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     raise exceptions.from_response(resp, method, url)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] InternalServerError: Internal Server Error (HTTP 500) (Request-ID: req-5247adeb-1053-4b62-972a-84b40c66c455)
2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]
2015-01-30 01:59:14.053 28957 ERROR nova.compute.manager [-] [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] Failure prepping block device
2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] Traceback (most recent call last):
2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2324, in _build_resources
2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     block_device_mapping)
2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1884, in _prep_block_device
2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     raise exception.InvalidBDM()
2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] InvalidBDM: Block Device Mapping is Invalid.

>From cinder is:
2015-01-30 01:39:23.456 17583 ERROR cinder.api.middleware.fault [req-5247adeb-1053-4b62-972a-84b40c66c455 039935838396418e9182b3e48360f6df 952d9c8024594f48baca9b24cb2562a6 - - -] Caught error: Timed out waiting for a reply to message ID 68416fdbc88e4ccf894ee6f3c5d2ad5b
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault Traceback (most recent call last):
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/middleware/fault.py", line 76, in __call__
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return req.get_response(self.application)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     application, catch_exc_info=False)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     app_iter = application(self.environ, start_response)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token.py", line 748, in __call__
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return self._call_app(env, start_response)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token.py", line 684, in _call_app
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return self._app(env, _fake_start_response)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     response = self.app(environ, start_response)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     resp = self.call_func(req, *args, **self.kwargs)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return self.func(req, *args, **kwargs)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/openstack/wsgi.py", line 978, in __call__
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     content_type, body, accept)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/openstack/wsgi.py", line 1026, in _process_stack
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     action_result = self.dispatch(meth, request, action_args)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/openstack/wsgi.py", line 1106, in dispatch
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/openstack/wsgi.py", line 978, in __call__
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return method(req=request, **action_args)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/contrib/volume_actions.py", line 118, in _attach
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     instance_uuid, host_name, mountpoint, mode)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/volume/api.py", line 87, in wrapped
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return func(self, context, target_obj, *args, **kwargs)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/volume/api.py", line 500, in attach
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     mode)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/volume/rpcapi.py", line 147, in attach_volume
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     mode=mode)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/client.py", line 152, in call
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     retry=self.retry)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/transport.py", line 90, in _send
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     timeout=timeout, retry=retry)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/amqpdriver.py", line 404, in send
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     retry=retry)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/amqpdriver.py", line 393, in _send
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     result = self._waiter.wait(msg_id, timeout)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/amqpdriver.py", line 281, in wait
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     reply, ending = self._poll_connection(msg_id, timeout)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/amqpdriver.py", line 231, in _poll_connection
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     % msg_id)
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault MessagingTimeout: Timed out waiting for a reply to message ID 68416fdbc88e4ccf894ee6f3c5d2ad5b
2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault
2015-01-30 01:39:23.460 17583 INFO cinder.api.middleware.fault [req-5247adeb-1053-4b62-972a-84b40c66c455 039935838396418e9182b3e48360f6df 952d9c8024594f48baca9b24cb2562a6 - - -] http://9.114.192.160:8776/v2/952d9c8024594f48baca9b24cb2562a6/volumes/ca383135-d619-43c2-8826-95ae4d475581/action returned with HTTP 500

I guess the problem may go here:
/usr/lib/python2.7/site-packages/nova/virt/block_device.py line 270:
        if volume['attach_status'] == "detached":
            volume_api.attach(context, volume_id, instance.uuid,
                              self['mount_device'], mode=mode)


I also tried prepare a vm and a volume, and attach by using nova volume-attach cmd, this code worked but it failed when attach during booting by nova boot --block-device cmd.
Please to help check on this case.

** Affects: nova
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1416269

Title:
  boot vm failed with --block-device set as attach volume failed during
  boot

Status in OpenStack Compute (Nova):
  New

Bug description:
  When attach a existing vm during booting vm by following cmd:
  nova boot --flavor small --image c7e8738b-c2c6-4365-a305-040bfbd1b514 --nic net-id=abfe3157-d23c-4d15-a7ff-80429a7d9b27 --block-device source=volume,dest=volume,bootindex=1,shutdown=remove,id=ca383135-d619-43c2-8826-95ae4d475581 test11

  It failed in "block device mapping" phase, error from nova is:
  2015-01-30 01:59:14.030 28957 ERROR nova.compute.manager [-] [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] Instance failed block device setup
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] Traceback (most recent call last):
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1856, in _prep_block_device
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     do_check_attach=do_check_attach) +
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 407, in attach_block_devices
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     map(_log_and_attach, block_device_mapping)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 405, in _log_and_attach
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     bdm.attach(*attach_args, **attach_kwargs)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 48, in wrapped
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     ret_val = method(obj, context, *args, **kwargs)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/virt/block_device.py", line 272, in attach
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     self['mount_device'], mode=mode)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 213, in wrapper
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     res = method(self, ctx, volume_id, *args, **kwargs)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/volume/cinder.py", line 359, in attach
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     mountpoint, mode=mode)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 326, in attach
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     'mode': mode})
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/cinderclient/v2/volumes.py", line 311, in _action
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return self.api.client.post(url, body=body)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 91, in post
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return self._cs_request(url, 'POST', **kwargs)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 85, in _cs_request
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return self.request(url, method, **kwargs)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/cinderclient/client.py", line 80, in request
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return super(SessionClient, self).request(*args, **kwargs)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 158, in request
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     resp = super(LegacyJsonAdapter, self).request(*args, **kwargs)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/keystoneclient/adapter.py", line 88, in request
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return self.session.request(url, method, **kwargs)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     return func(*args, **kwargs)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/keystoneclient/session.py", line 354, in request
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     raise exceptions.from_response(resp, method, url)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] InternalServerError: Internal Server Error (HTTP 500) (Request-ID: req-5247adeb-1053-4b62-972a-84b40c66c455)
  2015-01-30 01:59:14.030 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]
  2015-01-30 01:59:14.053 28957 ERROR nova.compute.manager [-] [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] Failure prepping block device
  2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] Traceback (most recent call last):
  2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2324, in _build_resources
  2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     block_device_mapping)
  2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1884, in _prep_block_device
  2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c]     raise exception.InvalidBDM()
  2015-01-30 01:59:14.053 28957 TRACE nova.compute.manager [instance: 5456c257-9dda-4ce3-b16d-112ac55e498c] InvalidBDM: Block Device Mapping is Invalid.

  From cinder is:
  2015-01-30 01:39:23.456 17583 ERROR cinder.api.middleware.fault [req-5247adeb-1053-4b62-972a-84b40c66c455 039935838396418e9182b3e48360f6df 952d9c8024594f48baca9b24cb2562a6 - - -] Caught error: Timed out waiting for a reply to message ID 68416fdbc88e4ccf894ee6f3c5d2ad5b
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault Traceback (most recent call last):
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/middleware/fault.py", line 76, in __call__
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return req.get_response(self.application)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1296, in send
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     application, catch_exc_info=False)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/request.py", line 1260, in call_application
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     app_iter = application(self.environ, start_response)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token.py", line 748, in __call__
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return self._call_app(env, start_response)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token.py", line 684, in _call_app
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return self._app(env, _fake_start_response)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/routes/middleware.py", line 131, in __call__
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     response = self.app(environ, start_response)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 144, in __call__
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return resp(environ, start_response)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 130, in __call__
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     resp = self.call_func(req, *args, **self.kwargs)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/webob/dec.py", line 195, in call_func
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return self.func(req, *args, **kwargs)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/openstack/wsgi.py", line 978, in __call__
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     content_type, body, accept)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/openstack/wsgi.py", line 1026, in _process_stack
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     action_result = self.dispatch(meth, request, action_args)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/openstack/wsgi.py", line 1106, in dispatch
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/openstack/wsgi.py", line 978, in __call__
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return method(req=request, **action_args)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/api/contrib/volume_actions.py", line 118, in _attach
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     instance_uuid, host_name, mountpoint, mode)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/volume/api.py", line 87, in wrapped
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     return func(self, context, target_obj, *args, **kwargs)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/volume/api.py", line 500, in attach
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     mode)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/cinder/volume/rpcapi.py", line 147, in attach_volume
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     mode=mode)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/client.py", line 152, in call
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     retry=self.retry)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/transport.py", line 90, in _send
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     timeout=timeout, retry=retry)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/amqpdriver.py", line 404, in send
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     retry=retry)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/amqpdriver.py", line 393, in _send
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     result = self._waiter.wait(msg_id, timeout)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/amqpdriver.py", line 281, in wait
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     reply, ending = self._poll_connection(msg_id, timeout)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault   File "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/amqpdriver.py", line 231, in _poll_connection
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault     % msg_id)
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault MessagingTimeout: Timed out waiting for a reply to message ID 68416fdbc88e4ccf894ee6f3c5d2ad5b
  2015-01-30 01:39:23.456 17583 TRACE cinder.api.middleware.fault
  2015-01-30 01:39:23.460 17583 INFO cinder.api.middleware.fault [req-5247adeb-1053-4b62-972a-84b40c66c455 039935838396418e9182b3e48360f6df 952d9c8024594f48baca9b24cb2562a6 - - -] http://9.114.192.160:8776/v2/952d9c8024594f48baca9b24cb2562a6/volumes/ca383135-d619-43c2-8826-95ae4d475581/action returned with HTTP 500

  I guess the problem may go here:
  /usr/lib/python2.7/site-packages/nova/virt/block_device.py line 270:
          if volume['attach_status'] == "detached":
              volume_api.attach(context, volume_id, instance.uuid,
                                self['mount_device'], mode=mode)

  
  I also tried prepare a vm and a volume, and attach by using nova volume-attach cmd, this code worked but it failed when attach during booting by nova boot --block-device cmd.
  Please to help check on this case.

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1416269/+subscriptions
Follow ups

[Bug 1416269] Re: boot vm failed with --block-device set as attach volume failed during boot
From: Sujitha, 2016-07-08
[Bug 1416269] [NEW] boot vm failed with --block-device set as attach volume failed during boot
From: Jerry Cai, 2015-01-30
References

[Bug 1416269] [NEW] boot vm failed with --block-device set as attach volume failed during boot
From: Jerry Cai, 2015-01-30