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@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@lists.launchpad.net >> Unsubscribe : https://launchpad.net/~openstack >> More help : https://help.launchpad.net/ListHelp
_______________________________________________ Mailing list: https://launchpad.net/~openstack Post to : openstack@lists.launchpad.net Unsubscribe : https://launchpad.net/~openstack More help : https://help.launchpad.net/ListHelp