yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1282841] [NEW] Cannot spawn VMs when using ML2 ODL

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Venkata Siva Vijayendra Bhamidipati <vijayendrabvs@xxxxxxxxx>
Date: Fri, 21 Feb 2014 01:19:53 -0000
Reply-to: Bug 1282841 <1282841@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

When testing out the latest ODL (Opendaylight) and Openstack
integration, I'm not able to spawn VMs. I see different traces when I
attempt to spawn VMs on different compute nodes. The traces are pasted
below:


When trying to create a VM on the controller node doubling up as a compute node:


2014-02-19 09:19:24.892 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 6ede9d9d237447c3b5fe0007d1237497. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
2014-02-19 09:19:24.894 ERROR nova.compute.manager [req-764e4d40-902f-42ff-995e-548c9ce7c96c admin demo] [instance: 36df418b-699b-4d94-a6a5-fa138399845f] Error: 500-{u'NeutronError': {u'message': u'create
_port_postcommit failed.', u'type': u'MechanismDriverError', u'detail': u''}}
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f] Traceback (most recent call last):
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/compute/manager.py", line 1070, in _build_instance
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     set_access_ip=set_access_ip)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/compute/manager.py", line 357, in decorated_function
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     return function(self, context, *args, **kwargs)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/compute/manager.py", line 1478, in _spawn
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     LOG.exception(_('Instance failed to spawn'), instance=instance)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/openstack/common/excutils.py", line 68, in __exit__
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     six.reraise(self.type_, self.value, self.tb)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/compute/manager.py", line 1475, in _spawn
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     block_device_info)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2207, in spawn
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     admin_pass=admin_password)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2572, in _create_image
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     content=files, extra_md=extra_md, network_info=network_info)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/api/metadata/base.py", line 163, in __init__
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     ec2utils.get_ip_info_for_instance_from_nw_info(network_info)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/api/ec2/ec2utils.py", line 147, in get_ip_info_for_instance_from_nw_info
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     fixed_ips = nw_info.fixed_ips()
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/network/model.py", line 366, in _sync_wrapper
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     self.wait()
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/network/model.py", line 398, in wait
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     self[:] = self._gt.wait()
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 168, in wait
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     return self._exit_event.wait()
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 120, in wait
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     current.throw(*self._exc)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 194, in main
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     result = function(*args, **kwargs)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/compute/manager.py", line 1256, in _allocate_network_async
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     dhcp_options=dhcp_options)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/network/neutronv2/api.py", line 342, in allocate_for_instance
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     LOG.exception(msg, port_id)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/openstack/common/excutils.py", line 68, in __exit__
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     six.reraise(self.type_, self.value, self.tb)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/network/neutronv2/api.py", line 319, in allocate_for_instance
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     security_group_ids, available_macs, dhcp_opts))
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/network/neutronv2/api.py", line 170, in _create_port
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     port_id = port_client.create_port(port_req_body)['port']['id']
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 111, in with_params
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     ret = self.function(instance, *args, **kwargs)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 316, in create_port
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     return self.post(self.ports_path, body=body)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 1241, in post
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     headers=headers, params=params)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 1164, in do_request
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     self._handle_fault_response(status_code, replybody)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 1134, in _handle_fault_response
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     exception_handler_v20(status_code, des_error_body)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 96, in exception_handler_v20
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     message=msg)
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f] NeutronClientException: 500-{u'NeutronError': {u'message': u'create_port_postcommit failed.', u'type': u'MechanismDriverError', u'detail': u''}}
2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]
2014-02-19 09:19:24.896 DEBUG nova.openstack.common.lockutils [req-764e4d40-902f-42ff-995e-548c9ce7c96c admin demo] Semaphore / lock released "do_run_instance" inner /opt/stack/nova/nova/openstack/common/lockutils.py:252
2014-02-19 09:19:24.896 39653 DEBUG oslo.messaging._drivers.amqpdriver [-] MSG_ID is 81630975aa834823ac19106ac8af13e0 _send /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqpdriver.py:361
2014-02-19 09:19:24.896 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 0661781a14f6487ab8c5aa8fb515653e. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
2014-02-19 09:19:24.908 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 36c5e21ec5224728b62b4f28865f7a58. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
2014-02-19 09:19:24.908 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 4aa99e4317d94c549f1c97a4548c0423. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
2014-02-19 09:19:34.422 39653 DEBUG oslo.messaging._drivers.amqpdriver [-] MSG_ID is 40369d4d8e2c4c4b8edf3334146528ae _send /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqpdriver.py:361
2014-02-19 09:19:34.422 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 36c130e867a14953a0e25106e0b958bb. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
2014-02-19 09:19:44.422 39653 DEBUG oslo.messaging._drivers.amqpdriver [-] MSG_ID is 110ee0a95904403b934c17873332df46 _send /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqpdriver.py:361
2014-02-19 09:19:44.422 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 8174211ed6b54175b74423e2f550c872. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
2014-02-19 09:19:44.480 39653 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /opt/stack/nova/nova/openstack/common/periodic_task.py:178


When trying to create a VM on a second compute node:


2014-02-19 09:25:17.770 28205 DEBUG oslo.messaging._drivers.amqp [-] unpacked context: {'project_name': u'admin', 'user_id': u'0ffe610c7eda490e997d37cd46c77f6c', 'roles': [u'admin'], 'timestamp': u'2014-02-19T17:25:17.499844', 'auth_token': '<SANITIZED>', 'remote_address': u'192.168.216.50', 'quota_class': None, 'is_admin': True, 'tenant': u'414e5c7207374f8ca180bd88d97c06c6', 'service_catalog': [{u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://192.168.216.50:8776/v1/414e5c7207374f8ca180bd88d97c06c6', u'region': u'RegionOne', u'publicURL': u'http://192.168.216.50:8776/v1/414e5c7207374f8ca180bd88d97c06c6', u'internalURL': u'http://192.168.216.50:8776/v1/414e5c7207374f8ca180bd88d97c06c6', u'id': u'1ddd4e4de0184f76b1b12a3a317658b4'}], u'type': u'volume', u'name': u'cinder'}], 'request_id': u'req
-d3cd0692-0871-40f4-9117-b2f5ca17c042', 'instance_lock_checked': False, 'project_id': u'414e5c7207374f8ca180bd88d97c06c6', 'user_name': u'admin', 'read_deleted': u'no', 'user': u'0ffe610c7eda490e997d37cd46c77f6c'} _safe_log /opt/stack/oslo.messaging/oslo/messaging/_drivers/common.py:289
2014-02-19 09:25:17.772 AUDIT nova.compute.manager [req-d3cd0692-0871-40f4-9117-b2f5ca17c042 admin admin] [instance: 5eb053ec-03f0-4aa7-8fc7-e678ed262bc2] Get console output
2014-02-19 09:25:17.773 28205 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: Instance instance-00000003 could not be found.
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/oslo.messaging/oslo/messaging/rpc/server.py", line 139, in inner
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     return func(*args, **kwargs)
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/exception.py", line 88, in wrapped
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     payload)
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/openstack/common/excutils.py", line 68, in __exit__
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/exception.py", line 71, in wrapped
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 256, in decorated_function
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 3670, in get_console_output
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     output = self.driver.get_console_output(context, instance)
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2245, in get_console_output
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     virt_dom = self._lookup_by_name(instance.name)
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 3369, in _lookup_by_name
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     raise exception.InstanceNotFound(instance_id=instance_name)
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher InstanceNotFound: Instance instance-00000003 could not be found.
2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher
2014-02-19 09:25:17.776 28205 ERROR oslo.messaging._drivers.common [-] Returning exception Instance instance-00000003 could not be found. to caller
2014-02-19 09:25:17.776 28205 ERROR oslo.messaging._drivers.common [-] ['Traceback (most recent call last):\n', '  File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n    incoming.message))\n', '  File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n    return self._do_dispatch(endpoint, method, ctxt, args)\n', '  File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n    result = getattr(endpoint, method)(ctxt, **new_args)\n', '  File "/opt/stack/oslo.messaging/oslo/messaging/rpc/server.py", line 139, in inner\n    return func(*args, **kwargs)\n', '  File "/opt/stack/nova/nova/exception.py", line 88, in wrapped\n    payload)\n', '  File "/opt/stack/nova/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/opt/stack/nova/nova/exception.py", line 71, in wrapped\n    return f(self, context, *args, **kw)\n', '  File "/opt/stack/nova/nova/compute/manager.py", line 256, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/opt/stack/nova/nova/compute/manager.py", line 3670, in get_console_output\n    output = self.driver.get_console_output(context, instance)\n', '  File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2245, in get_console_output\n    virt_dom = self._lookup_by_name(
instance.name)\n', '  File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 3369, in _lookup_by_name\n    raise exception.InstanceNotFound(instance_id=instance_name)\n', 'InstanceNotFound: Instance ins
tance-00000003 could not be found.\n']


For the steps to reproduce this, do the following:

1. Install Ubuntu 13.10, install git/maven/openvswitch-switch/pip related packages and so on, whatever is required for devstack and ODL. Do *not* install mysql-server - allow devstack to do that for you, else you will run into a lot of issues with mysql. Create two such VMs, one intended to run as ctrl and the other as compute.
2. Install and run ODL with Openflow 1.3 as per the instructions given on the ODL wiki.
3. Run devstack to bring up both control and compute nodes. Attempt to spawn VMs, and see if you hit the above exception.

For instructions on setting up devstack with ODL, look at Kyle's
blogpost:

http://www.siliconloons.com/?p=523

** Affects: neutron
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1282841

Title:
  Cannot spawn VMs when using ML2 ODL

Status in OpenStack Neutron (virtual network service):
  New

Bug description:
  When testing out the latest ODL (Opendaylight) and Openstack
  integration, I'm not able to spawn VMs. I see different traces when I
  attempt to spawn VMs on different compute nodes. The traces are pasted
  below:

  
  When trying to create a VM on the controller node doubling up as a compute node:

  
  2014-02-19 09:19:24.892 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 6ede9d9d237447c3b5fe0007d1237497. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
  2014-02-19 09:19:24.894 ERROR nova.compute.manager [req-764e4d40-902f-42ff-995e-548c9ce7c96c admin demo] [instance: 36df418b-699b-4d94-a6a5-fa138399845f] Error: 500-{u'NeutronError': {u'message': u'create
  _port_postcommit failed.', u'type': u'MechanismDriverError', u'detail': u''}}
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f] Traceback (most recent call last):
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/compute/manager.py", line 1070, in _build_instance
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     set_access_ip=set_access_ip)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/compute/manager.py", line 357, in decorated_function
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     return function(self, context, *args, **kwargs)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/compute/manager.py", line 1478, in _spawn
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     LOG.exception(_('Instance failed to spawn'), instance=instance)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/openstack/common/excutils.py", line 68, in __exit__
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     six.reraise(self.type_, self.value, self.tb)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/compute/manager.py", line 1475, in _spawn
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     block_device_info)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2207, in spawn
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     admin_pass=admin_password)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2572, in _create_image
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     content=files, extra_md=extra_md, network_info=network_info)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/api/metadata/base.py", line 163, in __init__
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     ec2utils.get_ip_info_for_instance_from_nw_info(network_info)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/api/ec2/ec2utils.py", line 147, in get_ip_info_for_instance_from_nw_info
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     fixed_ips = nw_info.fixed_ips()
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/network/model.py", line 366, in _sync_wrapper
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     self.wait()
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/network/model.py", line 398, in wait
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     self[:] = self._gt.wait()
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 168, in wait
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     return self._exit_event.wait()
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/usr/lib/python2.7/dist-packages/eventlet/event.py", line 120, in wait
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     current.throw(*self._exc)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 194, in main
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     result = function(*args, **kwargs)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/compute/manager.py", line 1256, in _allocate_network_async
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     dhcp_options=dhcp_options)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/network/neutronv2/api.py", line 342, in allocate_for_instance
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     LOG.exception(msg, port_id)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/openstack/common/excutils.py", line 68, in __exit__
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     six.reraise(self.type_, self.value, self.tb)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/network/neutronv2/api.py", line 319, in allocate_for_instance
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     security_group_ids, available_macs, dhcp_opts))
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/nova/nova/network/neutronv2/api.py", line 170, in _create_port
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     port_id = port_client.create_port(port_req_body)['port']['id']
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 111, in with_params
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     ret = self.function(instance, *args, **kwargs)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 316, in create_port
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     return self.post(self.ports_path, body=body)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 1241, in post
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     headers=headers, params=params)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 1164, in do_request
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     self._handle_fault_response(status_code, replybody)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 1134, in _handle_fault_response
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     exception_handler_v20(status_code, des_error_body)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]   File "/opt/stack/python-neutronclient/neutronclient/v2_0/client.py", line 96, in exception_handler_v20
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]     message=msg)
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f] NeutronClientException: 500-{u'NeutronError': {u'message': u'create_port_postcommit failed.', u'type': u'MechanismDriverError', u'detail': u''}}
  2014-02-19 09:19:24.894 39653 TRACE nova.compute.manager [instance: 36df418b-699b-4d94-a6a5-fa138399845f]
  2014-02-19 09:19:24.896 DEBUG nova.openstack.common.lockutils [req-764e4d40-902f-42ff-995e-548c9ce7c96c admin demo] Semaphore / lock released "do_run_instance" inner /opt/stack/nova/nova/openstack/common/lockutils.py:252
  2014-02-19 09:19:24.896 39653 DEBUG oslo.messaging._drivers.amqpdriver [-] MSG_ID is 81630975aa834823ac19106ac8af13e0 _send /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqpdriver.py:361
  2014-02-19 09:19:24.896 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 0661781a14f6487ab8c5aa8fb515653e. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
  2014-02-19 09:19:24.908 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 36c5e21ec5224728b62b4f28865f7a58. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
  2014-02-19 09:19:24.908 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 4aa99e4317d94c549f1c97a4548c0423. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
  2014-02-19 09:19:34.422 39653 DEBUG oslo.messaging._drivers.amqpdriver [-] MSG_ID is 40369d4d8e2c4c4b8edf3334146528ae _send /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqpdriver.py:361
  2014-02-19 09:19:34.422 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 36c130e867a14953a0e25106e0b958bb. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
  2014-02-19 09:19:44.422 39653 DEBUG oslo.messaging._drivers.amqpdriver [-] MSG_ID is 110ee0a95904403b934c17873332df46 _send /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqpdriver.py:361
  2014-02-19 09:19:44.422 39653 DEBUG oslo.messaging._drivers.amqp [-] UNIQUE_ID is 8174211ed6b54175b74423e2f550c872. _add_unique_id /opt/stack/oslo.messaging/oslo/messaging/_drivers/amqp.py:333
  2014-02-19 09:19:44.480 39653 DEBUG nova.openstack.common.periodic_task [-] Running periodic task ComputeManager._poll_volume_usage run_periodic_tasks /opt/stack/nova/nova/openstack/common/periodic_task.py:178


  When trying to create a VM on a second compute node:


  
  2014-02-19 09:25:17.770 28205 DEBUG oslo.messaging._drivers.amqp [-] unpacked context: {'project_name': u'admin', 'user_id': u'0ffe610c7eda490e997d37cd46c77f6c', 'roles': [u'admin'], 'timestamp': u'2014-02-19T17:25:17.499844', 'auth_token': '<SANITIZED>', 'remote_address': u'192.168.216.50', 'quota_class': None, 'is_admin': True, 'tenant': u'414e5c7207374f8ca180bd88d97c06c6', 'service_catalog': [{u'endpoints_links': [], u'endpoints': [{u'adminURL': u'http://192.168.216.50:8776/v1/414e5c7207374f8ca180bd88d97c06c6', u'region': u'RegionOne', u'publicURL': u'http://192.168.216.50:8776/v1/414e5c7207374f8ca180bd88d97c06c6', u'internalURL': u'http://192.168.216.50:8776/v1/414e5c7207374f8ca180bd88d97c06c6', u'id': u'1ddd4e4de0184f76b1b12a3a317658b4'}], u'type': u'volume', u'name': u'cinder'}], 'request_id': u'req
  -d3cd0692-0871-40f4-9117-b2f5ca17c042', 'instance_lock_checked': False, 'project_id': u'414e5c7207374f8ca180bd88d97c06c6', 'user_name': u'admin', 'read_deleted': u'no', 'user': u'0ffe610c7eda490e997d37cd46c77f6c'} _safe_log /opt/stack/oslo.messaging/oslo/messaging/_drivers/common.py:289
  2014-02-19 09:25:17.772 AUDIT nova.compute.manager [req-d3cd0692-0871-40f4-9117-b2f5ca17c042 admin admin] [instance: 5eb053ec-03f0-4aa7-8fc7-e678ed262bc2] Get console output
  2014-02-19 09:25:17.773 28205 ERROR oslo.messaging.rpc.dispatcher [-] Exception during message handling: Instance instance-00000003 could not be found.
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/oslo.messaging/oslo/messaging/rpc/server.py", line 139, in inner
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     return func(*args, **kwargs)
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/exception.py", line 88, in wrapped
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     payload)
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/openstack/common/excutils.py", line 68, in __exit__
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/exception.py", line 71, in wrapped
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 256, in decorated_function
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/compute/manager.py", line 3670, in get_console_output
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     output = self.driver.get_console_output(context, instance)
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2245, in get_console_output
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     virt_dom = self._lookup_by_name(instance.name)
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 3369, in _lookup_by_name
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher     raise exception.InstanceNotFound(instance_id=instance_name)
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher InstanceNotFound: Instance instance-00000003 could not be found.
  2014-02-19 09:25:17.773 28205 TRACE oslo.messaging.rpc.dispatcher
  2014-02-19 09:25:17.776 28205 ERROR oslo.messaging._drivers.common [-] Returning exception Instance instance-00000003 could not be found. to caller
  2014-02-19 09:25:17.776 28205 ERROR oslo.messaging._drivers.common [-] ['Traceback (most recent call last):\n', '  File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply\n    incoming.message))\n', '  File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch\n    return self._do_dispatch(endpoint, method, ctxt, args)\n', '  File "/opt/stack/oslo.messaging/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch\n    result = getattr(endpoint, method)(ctxt, **new_args)\n', '  File "/opt/stack/oslo.messaging/oslo/messaging/rpc/server.py", line 139, in inner\n    return func(*args, **kwargs)\n', '  File "/opt/stack/nova/nova/exception.py", line 88, in wrapped\n    payload)\n', '  File "/opt/stack/nova/nova/openstack/common/excutils.py", line 68, in __exit__\n    six.reraise(self.type_, self.value, self.tb)\n', '  File "/opt/stack/nova/nova/exception.py", line 71, in wrapped\n    return f(self, context, *args, **kw)\n', '  File "/opt/stack/nova/nova/compute/manager.py", line 256, in decorated_function\n    return function(self, context, *args, **kwargs)\n', '  File "/opt/stack/nova/nova/compute/manager.py", line 3670, in get_console_output\n    output = self.driver.get_console_output(context, instance)\n', '  File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2245, in get_console_output\n    virt_dom = self._lookup_by_name(
  instance.name)\n', '  File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 3369, in _lookup_by_name\n    raise exception.InstanceNotFound(instance_id=instance_name)\n', 'InstanceNotFound: Instance ins
  tance-00000003 could not be found.\n']


  For the steps to reproduce this, do the following:

  1. Install Ubuntu 13.10, install git/maven/openvswitch-switch/pip related packages and so on, whatever is required for devstack and ODL. Do *not* install mysql-server - allow devstack to do that for you, else you will run into a lot of issues with mysql. Create two such VMs, one intended to run as ctrl and the other as compute.
  2. Install and run ODL with Openflow 1.3 as per the instructions given on the ODL wiki.
  3. Run devstack to bring up both control and compute nodes. Attempt to spawn VMs, and see if you hit the above exception.

  For instructions on setting up devstack with ODL, look at Kyle's
  blogpost:

  http://www.siliconloons.com/?p=523

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

[Bug 1282841] Re: Cannot spawn VMs when using ML2 ODL
From: Launchpad Bug Tracker, 2014-04-22
[Bug 1282841] [NEW] Cannot spawn VMs when using ML2 ODL
From: Venkata Siva Vijayendra Bhamidipati, 2014-02-21
References

[Bug 1282841] [NEW] Cannot spawn VMs when using ML2 ODL
From: Venkata Siva Vijayendra Bhamidipati, 2014-02-21