Login | Register For Free | Help
Search for: (Advanced)

Mailing List Archive: OpenStack: Dev

Timeout during image build (task Networking)

 

 

OpenStack dev RSS feed   Index | Next | Previous | View Threaded


Ross.Lillie at motorolasolutions

Jun 18, 2012, 3:03 PM

Post #1 of 11 (362 views)
Permalink
Timeout during image build (task Networking)

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] cirrus:~# 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


jaypipes at gmail

Jun 19, 2012, 10:00 AM

Post #2 of 11 (328 views)
Permalink
Re: Timeout during image build (task Networking) [In reply to]

Hi Ross,

In the process of diagnosing this, but I'm seeing this sporadically when
running Tempest against a devstack install. I'll try to pinpoint the
issue later today and post back my findings.

Best,
-jay

p.s. Sorry for top-posting.

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

_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


jaypipes at gmail

Jun 19, 2012, 12:03 PM

Post #3 of 11 (324 views)
Permalink
Re: Timeout during image build (task Networking) [In reply to]

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

_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


vishvananda at gmail

Jun 19, 2012, 12:12 PM

Post #4 of 11 (324 views)
Permalink
Re: Timeout during image build (task Networking) [In reply to]

This seems like a likely culprit.

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


_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


vishvananda at gmail

Jun 19, 2012, 12:13 PM

Post #5 of 11 (323 views)
Permalink
Re: Timeout during image build (task Networking) [In reply to]

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


Ross.Lillie at motorolasolutions

Jun 19, 2012, 1:34 PM

Post #6 of 11 (324 views)
Permalink
Re: Timeout during image build (task Networking) [In reply to]

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] cirrus:~# 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<mailto:openstack [at] lists>
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp

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


jaypipes at gmail

Jun 19, 2012, 1:57 PM

Post #7 of 11 (331 views)
Permalink
Re: Timeout during image build (task Networking) [In reply to]

On 06/19/2012 03: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.

I notice the the RPC calls to the network topic were changed from cast
to call. Would this make any difference that would manifest itself in
the way we are seeing?

-jay

_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


jaypipes at gmail

Jun 20, 2012, 12:23 PM

Post #8 of 11 (320 views)
Permalink
Re: Timeout during image build (task Networking) [In reply to]

Turns out my issue was a borked run of Tempest that left a
nova-ensure_bridge.lock file around. After manually destroying this lock
file, Tempest is running cleanly again.

I'll look into adding a forcible removal of this lockfile to the
unstack.sh script (which I personally use to reset my Devstack envs)

Thanks,
-jay

On 06/19/2012 03: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] cirrus:~# 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
>>> <mailto:openstack [at] lists>
>>> Unsubscribe : https://launchpad.net/~openstack
>>> More help : https://help.launchpad.net/ListHelp
>

_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


yunmao at gmail

Jun 20, 2012, 12:32 PM

Post #9 of 11 (317 views)
Permalink
Re: Timeout during image build (task Networking) [In reply to]

Jay,

there is a tools/clean_file_locks.py that you might be able to take
advantage of.

Yun

On Wed, Jun 20, 2012 at 3:23 PM, Jay Pipes <jaypipes [at] gmail> wrote:
> Turns out my issue was a borked run of Tempest that left a
> nova-ensure_bridge.lock file around. After manually destroying this lock
> file, Tempest is running cleanly again.
>
> I'll look into adding a forcible removal of this lockfile to the unstack.sh
> script (which I personally use to reset my Devstack envs)
>
> Thanks,
> -jay
>
>
> On 06/19/2012 03: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] cirrus:~# 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
>>>> <mailto:openstack [at] lists>
>>>>
>>>> Unsubscribe : https://launchpad.net/~openstack
>>>> More help : https://help.launchpad.net/ListHelp
>>
>>
>
> _______________________________________________
> Mailing list: https://launchpad.net/~openstack
> Post to     : openstack [at] lists
> Unsubscribe : https://launchpad.net/~openstack
> More help   : https://help.launchpad.net/ListHelp

_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


jaypipes at gmail

Jun 20, 2012, 12:39 PM

Post #10 of 11 (322 views)
Permalink
Re: Timeout during image build (task Networking) [In reply to]

Ah, good to know. Thanks Yun!
-jay

On 06/20/2012 03:32 PM, Yun Mao wrote:
> Jay,
>
> there is a tools/clean_file_locks.py that you might be able to take
> advantage of.
>
> Yun
>
> On Wed, Jun 20, 2012 at 3:23 PM, Jay Pipes<jaypipes [at] gmail> wrote:
>> Turns out my issue was a borked run of Tempest that left a
>> nova-ensure_bridge.lock file around. After manually destroying this lock
>> file, Tempest is running cleanly again.
>>
>> I'll look into adding a forcible removal of this lockfile to the unstack.sh
>> script (which I personally use to reset my Devstack envs)
>>
>> Thanks,
>> -jay
>>
>>
>> On 06/19/2012 03: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] cirrus:~# 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
>>>>> <mailto:openstack [at] lists>
>>>>>
>>>>> Unsubscribe : https://launchpad.net/~openstack
>>>>> More help : https://help.launchpad.net/ListHelp
>>>
>>>
>>
>> _______________________________________________
>> Mailing list: https://launchpad.net/~openstack
>> Post to : openstack [at] lists
>> Unsubscribe : https://launchpad.net/~openstack
>> More help : https://help.launchpad.net/ListHelp

_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp


vishvananda at gmail

Jun 20, 2012, 2:59 PM

Post #11 of 11 (319 views)
Permalink
Re: Timeout during image build (task Networking) [In reply to]

Might be nice to figure out why the code to clean unused locks on worker startup is not working. It should detect orphaned locks and delete them but it sounds like it isn't working. Maybe because the pid has been reused by another process? Maybe we can improve it to make sure the process represented by the pid actually has the lockfile open with lsof?

Vish

On Jun 20, 2012, at 12:23 PM, Jay Pipes wrote:

> Turns out my issue was a borked run of Tempest that left a nova-ensure_bridge.lock file around. After manually destroying this lock file, Tempest is running cleanly again.
>
> I'll look into adding a forcible removal of this lockfile to the unstack.sh script (which I personally use to reset my Devstack envs)
>
> Thanks,
> -jay
>
> On 06/19/2012 03: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] cirrus:~# 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
>>>> <mailto:openstack [at] lists>
>>>> Unsubscribe : https://launchpad.net/~openstack
>>>> More help : https://help.launchpad.net/ListHelp
>>


_______________________________________________
Mailing list: https://launchpad.net/~openstack
Post to : openstack [at] lists
Unsubscribe : https://launchpad.net/~openstack
More help : https://help.launchpad.net/ListHelp

OpenStack dev RSS feed   Index | Next | Previous | View Threaded
 
 


Interested in having your list archived? Contact Gossamer Threads
 
  Web Applications & Managed Hosting Powered by Gossamer Threads Inc.