openstack team mailing list archive

[Vishvananda Ishaya <vishvananda@xxxxxxxxx>]

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@xxxxxxxxxxxxxxxxxxx
>> Unsubscribe : https://launchpad.net/~openstack
>> More help   : https://help.launchpad.net/ListHelp