Open Stack

Vish, Jay,

OK, this looks promising.  A couple of questions…

I'm seeing this RPC timeout on the Essex 2012.1 packages released with Ubuntu 12.04.  I'm assuming these packages are affected by this bug?

Why would something this fundamental not show up during Essex RC.X testing?

How best to 'fix' this for our production environment (thank god it's only the research organization!)

My previous testing of Essex (running on Diablo) didn't exhibit this problem.  However during testing, I was configured using FlatDHCP networking versus our production cloud using VLAN networking.  This was what lead me to believe that it might be a network configuration issue.  Apparently not.

As it stands right now, we're dead in the water, so I hope some easy fix for the Ubuntu Essex release is possible.

Thanks for everyone looking this.  Hope to hear a resolution soon.

Regards,
Ross

On Jun 19, 2012, at 2:13 PM, Vishvananda Ishaya wrote:

Sorry, paste fail on the last message.

This seems like a likely culprit:

https://review.openstack.org/#/c/8339/

I'm guessing it only happens on concurrent builds?  We probably need a synchronized somewhere.

Vish

On Jun 19, 2012, at 12:03 PM, Jay Pipes wrote:

cc'ing Vish on this, as this is now occurring on every single devstack + Tempest run, for multiple servers.

Vish, I am seeing the exact same issue as shown below. Instances end up in ERROR state and looking into the nova-network log, I find *no* errors at all, and yet looking at the nova-compute log, I see multiple timeout errors -- all of them trying to RPC while in the allocate_network method. Always the same method, always the same error, and no errors in nova-network or nova-api (other than just reporting a failed build)

Any idea on something that may have crept in recently? This wasn't happening a week or so ago, AFAICT.

Best,
-jay

On 06/18/2012 06:03 PM, Lillie Ross-CDSR11 wrote:
I'm receiving RPC timeouts when trying to launch an instance. My
installation is the Essex release running on Ubuntu 12.04.

When I launch a test image, the launch fails. In my setup, Nova network
runs on a controller node, and all compute instances run on separate,
dedicated server nodes. The failure is repeatable. Upon examining the
various logs, I see the following (see below). Any insight would be welcome.

Regards,
Ross

>From 'nova show <instance name>' I read the following:

root at cirrus1:~# nova show test
+-------------------------------------+-----------------------------------------------------------------------------+
| Property | Value |
+-------------------------------------+-----------------------------------------------------------------------------+
| OS-DCF:diskConfig | MANUAL |
| OS-EXT-SRV-ATTR:host | nova8 |
| OS-EXT-SRV-ATTR:hypervisor_hostname | None |
| OS-EXT-SRV-ATTR:instance_name | instance-00000005 |
| OS-EXT-STS:power_state | 0 |
| OS-EXT-STS:task_state | networking |
| OS-EXT-STS:vm_state | error |
| accessIPv4 | |
| accessIPv6 | |
| config_drive | |
| created | 2012-06-18T20:42:56Z |
| fault | {u'message': u'Timeout', u'code': 500, u'created':
u'2012-06-18T20:43:58Z'} |
| flavor | m1.tiny |
| hostId | 50272989300483e2b5e5236cd572fef3f9149ae60faa5f5660f8da54 |
| id | d569b16f-10a8-4cb8-90a3-d5b664c2322d |
| image | tty-linux |
| key_name | admin |
| metadata | {} |
| name | test |
| private_0 network | |
| status | ERROR |
| tenant_id | 1 |
| updated | 2012-06-18T20:43:57Z |
| user_id | 1 |
+-------------------------------------+-----------------------------------------------------------------------------+

>From the nova-network.log I see the following:

2012-06-18 15:43:36 DEBUG nova.manager [-] Running periodic task
VlanManager._disassociate_stale_fixed_ips from (pid=1381) periodic_tasks
/usr/lib/python2.7/dist-packages
/nova/manager.py:152
2012-06-18 15:43:57 ERROR nova.rpc.common [-] Timed out waiting for RPC
response: timed out
2012-06-18 15:43:57 TRACE nova.rpc.common Traceback (most recent call last):
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 490, in
ensure
2012-06-18 15:43:57 TRACE nova.rpc.common return method(*args, **kwargs)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 567, in
_consume
2012-06-18 15:43:57 TRACE nova.rpc.common return
self.connection.drain_events(timeout=timeout)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/connection.py", line 175, in
drain_events
2012-06-18 15:43:57 TRACE nova.rpc.common return
self.transport.drain_events(self.connection, **kwargs)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line
238, in drain_events
2012-06-18 15:43:57 TRACE nova.rpc.common return
connection.drain_events(**kwargs)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line
57, in drain_events
2012-06-18 15:43:57 TRACE nova.rpc.common return
self.wait_multi(self.channels.values(), timeout=timeout)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line
63, in wait_multi
2012-06-18 15:43:57 TRACE nova.rpc.common chanmap.keys(),
allowed_methods, timeout=timeout)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line
120, in _wait_multiple
2012-06-18 15:43:57 TRACE nova.rpc.common channel, method_sig, args,
content = read_timeout(timeout)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line
94, in read_timeout
2012-06-18 15:43:57 TRACE nova.rpc.common return
self.method_reader.read_method()
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/amqplib/client_0_8/method_framing.py",
line 221, in read_method
2012-06-18 15:43:57 TRACE nova.rpc.common raise m
2012-06-18 15:43:57 TRACE nova.rpc.common timeout: timed out
2012-06-18 15:43:57 TRACE nova.rpc.common
2012-06-18 15:43:58 DEBUG nova.utils
[req-16158a6b-f3d6-49f3-977e-3ccfecc791ca 1 1] Attempting to grab
semaphore "get_dhcp" for method "_get_dhcp_ip"... from (pid=1381) i
nner /usr/lib/python2.7/dist-packages/nova/utils.py:927
2012-06-18 15:43:58 DEBUG nova.utils
[req-16158a6b-f3d6-49f3-977e-3ccfecc791ca 1 1] Got semaphore "get_dhcp"
for method "_get_dhcp_ip"... from (pid=1381) inner /usr/lib/p
ython2.7/dist-packages/nova/utils.py:931
2012-06-18 15:43:58 DEBUG nova.utils
[req-16158a6b-f3d6-49f3-977e-3ccfecc791ca 1 1] Attempting to grab
semaphore "get_dhcp" for method "_get_dhcp_ip"... from (pid=1381) i

and from nova-compute.log I read:

2012-06-18 15:43:57 ERROR nova.rpc.common
[req-16158a6b-f3d6-49f3-977e-3ccfecc791ca 1 1] Timed out waiting for RPC
response: timed out
2012-06-18 15:43:57 TRACE nova.rpc.common Traceback (most recent call last):
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 490, in
ensure
2012-06-18 15:43:57 TRACE nova.rpc.common return method(*args, **kwargs)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 567, in
_consume
2012-06-18 15:43:57 TRACE nova.rpc.common return
self.connection.drain_events(timeout=timeout)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/connection.py", line 175, in
drain_events
2012-06-18 15:43:57 TRACE nova.rpc.common return
self.transport.drain_events(self.connection, **kwargs)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line
238, in drain_events
2012-06-18 15:43:57 TRACE nova.rpc.common return
connection.drain_events(**kwargs)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line
57, in drain_events
2012-06-18 15:43:57 TRACE nova.rpc.common return
self.wait_multi(self.channels.values(), timeout=timeout)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line
63, in wait_multi
2012-06-18 15:43:57 TRACE nova.rpc.common chanmap.keys(),
allowed_methods, timeout=timeout)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line
120, in _wait_multiple
2012-06-18 15:43:57 TRACE nova.rpc.common channel, method_sig, args,
content = read_timeout(timeout)
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line
94, in read_timeout
2012-06-18 15:43:57 TRACE nova.rpc.common return
self.method_reader.read_method()
2012-06-18 15:43:57 TRACE nova.rpc.common File
"/usr/lib/python2.7/dist-packages/amqplib/client_0_8/method_framing.py",
line 221, in read_method
2012-06-18 15:43:57 TRACE nova.rpc.common raise m
2012-06-18 15:43:57 TRACE nova.rpc.common timeout: timed out
2012-06-18 15:43:57 TRACE nova.rpc.common
2012-06-18 15:43:57 ERROR nova.compute.manager
[req-16158a6b-f3d6-49f3-977e-3ccfecc791ca 1 1] [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] Instance failed network setup
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] Traceback (most recent call last):
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] File
"/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 559, in
_allocate_network
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] requested_networks=requested_networks)
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] File
"/usr/lib/python2.7/dist-packages/nova/network/api.py", line 170, in
allocate_for_instance
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] 'args': args})
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] File
"/usr/lib/python2.7/dist-packages/nova/rpc/__init__.py", line 68, in call
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] return _get_impl().call(context,
topic, msg, timeout)
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 674, in call
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] return rpc_amqp.call(context,
topic, msg, timeout, Connection.pool)
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] File
"/usr/lib/python2.7/dist-packages/nova/rpc/amqp.py", line 338, in call
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] rv = list(rv)
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] File
"/usr/lib/python2.7/dist-packages/nova/rpc/amqp.py", line 299, in __iter__
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] self._iterator.next()
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 572, in
iterconsume
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] yield self.ensure(_error_callback,
_consume)
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 503, in
ensure
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] error_callback(e)
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 553, in
_error_callback
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] raise rpc_common.Timeout()
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d] Timeout: Timeout while waiting on
RPC response.
2012-06-18 15:43:57 TRACE nova.compute.manager [instance:
d569b16f-10a8-4cb8-90a3-d5b664c2322d]
2012-06-18 15:43:58 ERROR nova.rpc.amqp
[req-16158a6b-f3d6-49f3-977e-3ccfecc791ca 1 1] Exception during message
handling
2012-06-18 15:43:58 TRACE nova.rpc.amqp Traceback (most recent call last):
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/rpc/amqp.py", line 252, in
_process_data
2012-06-18 15:43:58 TRACE nova.rpc.amqp rval = node_func(context=ctxt,
**node_args)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/exception.py", line 114, in wrapped
2012-06-18 15:43:58 TRACE nova.rpc.amqp return f(*args, **kw)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 177, in
decorated_function
2012-06-18 15:43:58 TRACE nova.rpc.amqp sys.exc_info())
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-06-18 15:43:58 TRACE nova.rpc.amqp self.gen.next()
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 171, in
decorated_function
2012-06-18 15:43:58 TRACE nova.rpc.amqp return function(self, context,
instance_uuid, *args, **kwargs)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 651, in
run_instance
2012-06-18 15:43:58 TRACE nova.rpc.amqp do_run_instance()
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/utils.py", line 945, in inner
2012-06-18 15:43:58 TRACE nova.rpc.amqp retval = f(*args, **kwargs)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 650, in
do_run_instance
2012-06-18 15:43:58 TRACE nova.rpc.amqp self._run_instance(context,
instance_uuid, **kwargs)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 451, in
_run_instance
2012-06-18 15:43:58 TRACE nova.rpc.amqp
self._set_instance_error_state(context, instance_uuid)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-06-18 15:43:58 TRACE nova.rpc.amqp self.gen.next()
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 424, in
_run_instance
2012-06-18 15:43:58 TRACE nova.rpc.amqp requested_networks)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/compute/manager.py", line 559, in
_allocate_network
2012-06-18 15:43:58 TRACE nova.rpc.amqp
requested_networks=requested_networks)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/network/api.py", line 170, in
allocate_for_instance
2012-06-18 15:43:58 TRACE nova.rpc.amqp 'args': args})
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/rpc/__init__.py", line 68, in call
2012-06-18 15:43:58 TRACE nova.rpc.amqp return _get_impl().call(context,
topic, msg, timeout)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 674, in call
2012-06-18 15:43:58 TRACE nova.rpc.amqp return rpc_amqp.call(context,
topic, msg, timeout, Connection.pool)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/rpc/amqp.py", line 338, in call
2012-06-18 15:43:58 TRACE nova.rpc.amqp rv = list(rv)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/rpc/amqp.py", line 299, in __iter__
2012-06-18 15:43:58 TRACE nova.rpc.amqp self._iterator.next()
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 572, in
iterconsume
2012-06-18 15:43:58 TRACE nova.rpc.amqp yield
self.ensure(_error_callback, _consume)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 503, in
ensure
2012-06-18 15:43:58 TRACE nova.rpc.amqp error_callback(e)
2012-06-18 15:43:58 TRACE nova.rpc.amqp File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 553, in
_error_callback
2012-06-18 15:43:58 TRACE nova.rpc.amqp raise rpc_common.Timeout()
2012-06-18 15:43:58 TRACE nova.rpc.amqp Timeout: Timeout while waiting
on RPC response.
2012-06-18 15:43:58 TRACE nova.rpc.amqp
2012-06-18 15:44:05 DEBUG nova.manager [-] Running periodic task
ComputeManager._publish_service_capabilities from (pid=13262)
periodic_tasks /usr/lib/python2.7/dist-packages/nova/manager.py:152
2012-06-18 15:44:05 DEBUG nova.manager [-] Notifying Schedulers of
capabilities ... from (pid=13262) _publish_service_capabilities
/usr/lib/python2.7/dist-packages/nova/manager.py:203
2012-06-18 15:44:05 DEBUG nova.rpc.amqp [-] Making asynchronous fanout
cast... from (pid=13262) fanout_cast
/usr/lib/python2.7/dist-packages/nova/rpc/amqp.py:354
2012-06-18 15:44:05 DEBUG nova.manager [-] Running periodic task
ComputeManager._poll_rescued_instances from (pid=13262) periodic_tasks
/usr/lib/python2.7/dist-packages/nova/manager.py:152
2012-06-18 15:44:05 DEBUG nova.manager [-] Skipping
ComputeManager._sync_power_states, 1 ticks left until next run from


_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to     : openstack at lists.launchpad.net<mailto:openstack at lists.launchpad.net>
Unsubscribe : https://launchpad.net/~openstack
More help   : https://help.launchpad.net/ListHelp

_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to     : openstack at lists.launchpad.net<mailto:openstack at lists.launchpad.net>
Unsubscribe : https://launchpad.net/~openstack
More help   : https://help.launchpad.net/ListHelp

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openstack.org/pipermail/openstack/attachments/20120619/b945c104/attachment.html>