openstack team mailing list archive

Thread
Date
Re: can not launch an instance + RPC timeout + nova-network does not start dnsmasq

To: Afef MDHAFFAR <afef.mdhaffar@xxxxxxxxx>, "openstack@xxxxxxxxxxxxxxxxxxx" <openstack@xxxxxxxxxxxxxxxxxxx>
From: John Garbutt <John.Garbutt@xxxxxxxxxx>
Date: Mon, 10 Dec 2012 17:34:34 +0000
Accept-language: en-US
Acceptlanguage: en-US
In-reply-to: <CAEufa6B3-nCTspob_v=64DruwCUug31TixtwS0Dvet9gTWtuEQ@mail.gmail.com>
Thread-index: Ac3W9/YFr4eyNowsQ8qn/vPTMZJ9YAAA/spQ
Thread-topic: [Openstack] can not launch an instance + RPC timeout + nova-network does not start dnsmasq
>From this line:
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common timeout: timed out

It is worth checking to see if you have all your services running, and that they all have the correct Rabbit server configured. Try "nova-manage service list" and make sure you can see all the services you expect to see.

I don't see any logs form nova-network, it might be that nova-network is failing in a way that means it never replies the RPC call. Can you get hold of the logs from that component?

I hope that helps,
John

From: openstack-bounces+john.garbutt=citrix.com@xxxxxxxxxxxxxxxxxxx [mailto:openstack-bounces+john.garbutt=citrix.com@xxxxxxxxxxxxxxxxxxx] On Behalf Of Afef MDHAFFAR
Sent: 10 December 2012 16:59
To: openstack@xxxxxxxxxxxxxxxxxxx
Subject: [Openstack] can not launch an instance + RPC timeout + nova-network does not start dnsmasq

Hi all,

I installed openstack (folsom release) on ubuntu 12.04 + XCP.
All services seem to be running.
However nova-network does not start dnsmasq -- and the interface xapi0 is missing.
I can not launch an instance , and I got the following logs on nova-compute.
Please try to help to fix this issue.
Thank you,
Afef
------
2012-12-10 16:51:14 DEBUG nova.virt.xenapi.host [-] Updating host stats from (pid=28401) update_status /opt/stack/nova/nova/virt/xenapi/host.py:150
2012-12-10 16:51:15 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_unconfirmed_resizes from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:51:37 ERROR nova.openstack.common.rpc.common [req-2c7c1df0-e6f7-4a13-83d6-c51e23d0fcbb admin admin] Timed out waiting for RPC response: timed out
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common Traceback (most recent call last):
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 552, in ensure
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common     return method(*args, **kwargs)
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 630, in _consume
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common     return self.connection.drain_events(timeout=timeout)
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/connection.py", line 110, in drain_events
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common     return self.transport.drain_events(self.connection, **kwargs)
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 200, in drain_events
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common     return connection.drain_events(**kwargs)
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 50, in drain_events
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common     return self.wait_multi(self.channels.values(), timeout=timeout)
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 56, in wait_multi
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common     chanmap.keys(), allowed_methods, timeout=timeout)
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 104, in _wait_multiple
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common     channel, method_sig, args, content = self.read_timeout(timeout)
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 86, in read_timeout
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common     return self.method_reader.read_method()
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common   File "/usr/local/lib/python2.7/dist-packages/amqplib/client_0_8/method_framing.py", line 215, in read_method
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common     raise m
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common timeout: timed out
2012-12-10 16:51:37 TRACE nova.openstack.common.rpc.common
2012-12-10 16:51:37 DEBUG nova.openstack.common.rpc.amqp [req-2c7c1df0-e6f7-4a13-83d6-c51e23d0fcbb admin admin] Making asynchronous call on conductor ... from (pid=28401) multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:359
2012-12-10 16:51:37 DEBUG nova.openstack.common.rpc.amqp [req-2c7c1df0-e6f7-4a13-83d6-c51e23d0fcbb admin admin] MSG_ID is 806e29cdea2640b9a03a6990d793c57b from (pid=28401) multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
2012-12-10 16:52:15 DEBUG nova.manager [-] Running periodic task ComputeManager.publish_service_capabilities from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:15 DEBUG nova.manager [-] Notifying Schedulers of capabilities ... from (pid=28401) publish_service_capabilities /opt/stack/nova/nova/manager.py:257
2012-12-10 16:52:15 DEBUG nova.openstack.common.rpc.amqp [-] Making asynchronous fanout cast... from (pid=28401) fanout_cast /opt/stack/nova/nova/openstack/common/rpc/amqp.py:392
2012-12-10 16:52:15 DEBUG nova.manager [-] Running periodic task ComputeManager._heal_instance_info_cache from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:15 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_rescued_instances from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:15 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_volume_usage from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:15 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_bandwidth_usage from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:15 DEBUG nova.manager [-] Skipping ComputeManager._sync_power_states, 7 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
2012-12-10 16:52:15 DEBUG nova.manager [-] Running periodic task ComputeManager._instance_usage_audit from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:15 DEBUG nova.manager [-] Running periodic task ComputeManager.update_available_resource from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:15 DEBUG nova.virt.xenapi.host [-] Updating host stats from (pid=28401) update_status /opt/stack/nova/nova/virt/xenapi/host.py:150
2012-12-10 16:52:15 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" for method "update_available_resource"... from (pid=28401) inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
2012-12-10 16:52:15 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
2012-12-10 16:52:15 DEBUG nova.virt.xenapi.host [-] Updating host stats from (pid=28401) update_status /opt/stack/nova/nova/virt/xenapi/host.py:150
2012-12-10 16:52:16 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 4938 from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:322
2012-12-10 16:52:16 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 218 from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:323
2012-12-10 16:52:16 DEBUG nova.compute.resource_tracker [-] Hypervisor: VCPU information unavailable from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:330
2012-12-10 16:52:16 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 7679
2012-12-10 16:52:16 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 225
2012-12-10 16:52:16 AUDIT nova.compute.resource_tracker [-] Free VCPU information unavailable
2012-12-10 16:52:16 INFO nova.compute.resource_tracker [-] Compute_service record updated for openstackDomU
2012-12-10 16:52:16 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_rebooting_instances from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:16 DEBUG nova.manager [-] Skipping ComputeManager._cleanup_running_deleted_instances, 27 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
2012-12-10 16:52:16 DEBUG nova.manager [-] Running periodic task ComputeManager._check_instance_build_time from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:16 DEBUG nova.manager [-] Skipping ComputeManager._run_image_cache_manager_pass, 37 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
2012-12-10 16:52:16 DEBUG nova.manager [-] Running periodic task ComputeManager._reclaim_queued_deletes from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:16 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... from (pid=28401) _reclaim_queued_deletes /opt/stack/nova/nova/compute/manager.py:3215
2012-12-10 16:52:16 DEBUG nova.manager [-] Running periodic task ComputeManager._report_driver_status from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:16 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_unconfirmed_resizes from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
2012-12-10 16:52:37 ERROR nova.openstack.common.rpc.common [req-2c7c1df0-e6f7-4a13-83d6-c51e23d0fcbb admin admin] Timed out waiting for RPC response: timed out
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common Traceback (most recent call last):
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 552, in ensure
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common     return method(*args, **kwargs)
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 630, in _consume
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common     return self.connection.drain_events(timeout=timeout)
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/connection.py", line 110, in drain_events
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common     return self.transport.drain_events(self.connection, **kwargs)
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 200, in drain_events
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common     return connection.drain_events(**kwargs)
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 50, in drain_events
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common     return self.wait_multi(self.channels.values(), timeout=timeout)
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 56, in wait_multi
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common     chanmap.keys(), allowed_methods, timeout=timeout)
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 104, in _wait_multiple
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common     channel, method_sig, args, content = self.read_timeout(timeout)
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 86, in read_timeout
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common     return self.method_reader.read_method()
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common   File "/usr/local/lib/python2.7/dist-packages/amqplib/client_0_8/method_framing.py", line 215, in read_method
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common     raise m
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common timeout: timed out
2012-12-10 16:52:37 TRACE nova.openstack.common.rpc.common
ERROR:root:Original exception being dropped: ['Traceback (most recent call last):\n', '  File "/opt/stack/nova/nova/compute/manager.py", line 605, in _run_instance\n    self._start_building(context, instance)\n', '  File "/opt/stack/nova/nova/compute/manager.py", line 835, in _start_building\n    None))\n', '  File "/opt/stack/nova/nova/compute/manager.py", line 349, in _instance_update\n    **kwargs)\n', '  File "/opt/stack/nova/nova/conductor/api.py", line 78, in instance_update\n    updates)\n', '  File "/opt/stack/nova/nova/conductor/rpcapi.py", line 48, in instance_update\n    updates=updates_p))\n', '  File "/opt/stack/nova/nova/openstack/common/rpc/proxy.py", line 80, in call\n    return rpc.call(context, self._get_topic(topic), msg, timeout)\n', '  File "/opt/stack/nova/nova/openstack/common/rpc/__init__.py", line 108, in call\n    return _get_impl().call(cfg.CONF, context, topic, msg, timeout)\n', '  File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 754, in call\n    rpc_amqp.get_connection_pool(conf, Connection))\n', '  File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 376, in call\n    rv = list(rv)\n', '  File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 337, in __iter__\n    self.done()\n', '  File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__\n    self.gen.next()\n', '  File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 334, in __iter__\n    self._iterator.next()\n', '  File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 635, in iterconsume\n    yield self.ensure(_error_callback, _consume)\n', '  File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 555, in ensure\n    error_callback(e)\n', '  File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 616, in _error_callback\n    raise rpc_common.Timeout()\n', 'Timeout: Timeout while waiting on RPC response.\n']
2012-12-10 16:52:37 DEBUG nova.openstack.common.rpc.amqp [req-2c7c1df0-e6f7-4a13-83d6-c51e23d0fcbb admin admin] Making asynchronous call on conductor ... from (pid=28401) multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:359
DEBUG:nova.openstack.common.rpc.amqp:Making asynchronous call on conductor ...
2012-12-10 16:52:37 DEBUG nova.openstack.common.rpc.amqp [req-2c7c1df0-e6f7-4a13-83d6-c51e23d0fcbb admin admin] MSG_ID is bca57b2f78434b58beac25467d23177c from (pid=28401) multicall /opt/stack/nova/nova/openstack/common/rpc/amqp.py:362
DEBUG:nova.openstack.common.rpc.amqp:MSG_ID is bca57b2f78434b58beac25467d23177c
2012-12-10 16:53:16 DEBUG nova.manager [-] Running periodic task ComputeManager.publish_service_capabilities from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager.publish_service_capabilities
2012-12-10 16:53:16 DEBUG nova.manager [-] Notifying Schedulers of capabilities ... from (pid=28401) publish_service_capabilities /opt/stack/nova/nova/manager.py:257
DEBUG:nova.manager:Notifying Schedulers of capabilities ...
2012-12-10 16:53:16 DEBUG nova.openstack.common.rpc.amqp [-] Making asynchronous fanout cast... from (pid=28401) fanout_cast /opt/stack/nova/nova/openstack/common/rpc/amqp.py:392
DEBUG:nova.openstack.common.rpc.amqp:Making asynchronous fanout cast...
2012-12-10 16:53:16 DEBUG nova.manager [-] Running periodic task ComputeManager._heal_instance_info_cache from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._heal_instance_info_cache
2012-12-10 16:53:16 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_rescued_instances from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_rescued_instances
2012-12-10 16:53:16 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_volume_usage from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_volume_usage
2012-12-10 16:53:16 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_bandwidth_usage from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_bandwidth_usage
2012-12-10 16:53:16 DEBUG nova.manager [-] Skipping ComputeManager._sync_power_states, 6 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
DEBUG:nova.manager:Skipping ComputeManager._sync_power_states, 6 ticks left until next run
2012-12-10 16:53:16 DEBUG nova.manager [-] Running periodic task ComputeManager._instance_usage_audit from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._instance_usage_audit
2012-12-10 16:53:16 DEBUG nova.manager [-] Running periodic task ComputeManager.update_available_resource from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager.update_available_resource
2012-12-10 16:53:16 DEBUG nova.virt.xenapi.host [-] Updating host stats from (pid=28401) update_status /opt/stack/nova/nova/virt/xenapi/host.py:150
DEBUG:nova.virt.xenapi.host:Updating host stats
2012-12-10 16:53:17 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" for method "update_available_resource"... from (pid=28401) inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
DEBUG:nova.openstack.common.lockutils:Got semaphore "compute_resources" for method "update_available_resource"...
2012-12-10 16:53:17 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
AUDIT:nova.compute.resource_tracker:Auditing locally available compute resources
2012-12-10 16:53:17 DEBUG nova.virt.xenapi.host [-] Updating host stats from (pid=28401) update_status /opt/stack/nova/nova/virt/xenapi/host.py:150
DEBUG:nova.virt.xenapi.host:Updating host stats
2012-12-10 16:53:17 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 4938 from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:322
DEBUG:nova.compute.resource_tracker:Hypervisor: free ram (MB): 4938
2012-12-10 16:53:17 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 218 from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:323
DEBUG:nova.compute.resource_tracker:Hypervisor: free disk (GB): 218
2012-12-10 16:53:17 DEBUG nova.compute.resource_tracker [-] Hypervisor: VCPU information unavailable from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:330
DEBUG:nova.compute.resource_tracker:Hypervisor: VCPU information unavailable
2012-12-10 16:53:17 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 7679
AUDIT:nova.compute.resource_tracker:Free ram (MB): 7679
2012-12-10 16:53:17 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 225
AUDIT:nova.compute.resource_tracker:Free disk (GB): 225
2012-12-10 16:53:17 AUDIT nova.compute.resource_tracker [-] Free VCPU information unavailable
AUDIT:nova.compute.resource_tracker:Free VCPU information unavailable
2012-12-10 16:53:18 INFO nova.compute.resource_tracker [-] Compute_service record updated for openstackDomU
INFO:nova.compute.resource_tracker:Compute_service record updated for openstackDomU
2012-12-10 16:53:18 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_rebooting_instances from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_rebooting_instances
2012-12-10 16:53:18 DEBUG nova.manager [-] Skipping ComputeManager._cleanup_running_deleted_instances, 26 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
DEBUG:nova.manager:Skipping ComputeManager._cleanup_running_deleted_instances, 26 ticks left until next run
2012-12-10 16:53:18 DEBUG nova.manager [-] Running periodic task ComputeManager._check_instance_build_time from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._check_instance_build_time
2012-12-10 16:53:18 DEBUG nova.manager [-] Skipping ComputeManager._run_image_cache_manager_pass, 36 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
DEBUG:nova.manager:Skipping ComputeManager._run_image_cache_manager_pass, 36 ticks left until next run
2012-12-10 16:53:18 DEBUG nova.manager [-] Running periodic task ComputeManager._reclaim_queued_deletes from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._reclaim_queued_deletes
2012-12-10 16:53:18 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... from (pid=28401) _reclaim_queued_deletes /opt/stack/nova/nova/compute/manager.py:3215
DEBUG:nova.compute.manager:CONF.reclaim_instance_interval <= 0, skipping...
2012-12-10 16:53:18 DEBUG nova.manager [-] Running periodic task ComputeManager._report_driver_status from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._report_driver_status
2012-12-10 16:53:18 INFO nova.compute.manager [-] Updating host status
INFO:nova.compute.manager:Updating host status
2012-12-10 16:53:18 DEBUG nova.virt.xenapi.host [-] Updating host stats from (pid=28401) update_status /opt/stack/nova/nova/virt/xenapi/host.py:150
DEBUG:nova.virt.xenapi.host:Updating host stats
2012-12-10 16:53:18 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_unconfirmed_resizes from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_unconfirmed_resizes
2012-12-10 16:53:37 ERROR nova.openstack.common.rpc.common [req-2c7c1df0-e6f7-4a13-83d6-c51e23d0fcbb admin admin] Timed out waiting for RPC response: timed out
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common Traceback (most recent call last):
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 552, in ensure
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return method(*args, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 630, in _consume
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return self.connection.drain_events(timeout=timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/connection.py", line 110, in drain_events
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return self.transport.drain_events(self.connection, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 200, in drain_events
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return connection.drain_events(**kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 50, in drain_events
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return self.wait_multi(self.channels.values(), timeout=timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 56, in wait_multi
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     chanmap.keys(), allowed_methods, timeout=timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 104, in _wait_multiple
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     channel, method_sig, args, content = self.read_timeout(timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 86, in read_timeout
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return self.method_reader.read_method()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/local/lib/python2.7/dist-packages/amqplib/client_0_8/method_framing.py", line 215, in read_method
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     raise m
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common timeout: timed out
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common
ERROR:nova.openstack.common.rpc.common:Timed out waiting for RPC response: timed out
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common Traceback (most recent call last):
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 552, in ensure
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return method(*args, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 630, in _consume
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return self.connection.drain_events(timeout=timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/connection.py", line 110, in drain_events
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return self.transport.drain_events(self.connection, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 200, in drain_events
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return connection.drain_events(**kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 50, in drain_events
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return self.wait_multi(self.channels.values(), timeout=timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 56, in wait_multi
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     chanmap.keys(), allowed_methods, timeout=timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 104, in _wait_multiple
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     channel, method_sig, args, content = self.read_timeout(timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 86, in read_timeout
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     return self.method_reader.read_method()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common   File "/usr/local/lib/python2.7/dist-packages/amqplib/client_0_8/method_framing.py", line 215, in read_method
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common     raise m
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common timeout: timed out
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.common
2012-12-10 16:53:37 ERROR nova.openstack.common.rpc.amqp [req-2c7c1df0-e6f7-4a13-83d6-c51e23d0fcbb admin admin] Exception during message handling
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 277, in _process_data
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 147, in dispatch
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return getattr(proxyobj, method)(ctxt, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/exception.py", line 115, in wrapped
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     temp_level, payload)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self.gen.next()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/exception.py", line 90, in wrapped
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return f(*args, **kw)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 212, in decorated_function
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     pass
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self.gen.next()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 198, in decorated_function
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return function(self, context, *args, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 239, in decorated_function
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     kwargs['instance']['uuid'], e, sys.exc_info())
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self.gen.next()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 227, in decorated_function
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return function(self, context, *args, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 976, in run_instance
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     do_run_instance()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/lockutils.py", line 228, in inner
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     retval = f(*args, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 975, in do_run_instance
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     admin_password, is_first_time, node, instance)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 649, in _run_instance
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self._set_instance_error_state(context, instance['uuid'])
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 361, in _set_instance_error_state
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     vm_state=vm_states.ERROR)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 349, in _instance_update
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/conductor/api.py", line 78, in instance_update
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     updates)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/conductor/rpcapi.py", line 48, in instance_update
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     updates=updates_p))
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/proxy.py", line 80, in call
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return rpc.call(context, self._get_topic(topic), msg, timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/__init__.py", line 108, in call
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return _get_impl().call(cfg.CONF, context, topic, msg, timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 754, in call
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     rpc_amqp.get_connection_pool(conf, Connection))
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 376, in call
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     rv = list(rv)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 337, in __iter__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self.done()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self.gen.next()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 334, in __iter__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self._iterator.next()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 635, in iterconsume
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     yield self.ensure(_error_callback, _consume)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 555, in ensure
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     error_callback(e)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 616, in _error_callback
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     raise rpc_common.Timeout()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp Timeout: Timeout while waiting on RPC response.
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp
ERROR:nova.openstack.common.rpc.amqp:Exception during message handling
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp Traceback (most recent call last):
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 277, in _process_data
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     rval = self.proxy.dispatch(ctxt, version, method, **args)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/dispatcher.py", line 147, in dispatch
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return getattr(proxyobj, method)(ctxt, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/exception.py", line 115, in wrapped
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     temp_level, payload)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self.gen.next()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/exception.py", line 90, in wrapped
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return f(*args, **kw)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 212, in decorated_function
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     pass
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self.gen.next()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 198, in decorated_function
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return function(self, context, *args, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 239, in decorated_function
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     kwargs['instance']['uuid'], e, sys.exc_info())
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self.gen.next()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 227, in decorated_function
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return function(self, context, *args, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 976, in run_instance
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     do_run_instance()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/lockutils.py", line 228, in inner
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     retval = f(*args, **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 975, in do_run_instance
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     admin_password, is_first_time, node, instance)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 649, in _run_instance
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self._set_instance_error_state(context, instance['uuid'])
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 361, in _set_instance_error_state
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     vm_state=vm_states.ERROR)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/compute/manager.py", line 349, in _instance_update
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     **kwargs)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/conductor/api.py", line 78, in instance_update
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     updates)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/conductor/rpcapi.py", line 48, in instance_update
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     updates=updates_p))
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/proxy.py", line 80, in call
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return rpc.call(context, self._get_topic(topic), msg, timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/__init__.py", line 108, in call
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     return _get_impl().call(cfg.CONF, context, topic, msg, timeout)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 754, in call
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     rpc_amqp.get_connection_pool(conf, Connection))
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 376, in call
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     rv = list(rv)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 337, in __iter__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self.done()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self.gen.next()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/amqp.py", line 334, in __iter__
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     self._iterator.next()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 635, in iterconsume
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     yield self.ensure(_error_callback, _consume)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 555, in ensure
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     error_callback(e)
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp   File "/opt/stack/nova/nova/openstack/common/rpc/impl_kombu.py", line 616, in _error_callback
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp     raise rpc_common.Timeout()
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp Timeout: Timeout while waiting on RPC response.
2012-12-10 16:53:37 TRACE nova.openstack.common.rpc.amqp
2012-12-10 16:54:18 DEBUG nova.manager [-] Running periodic task ComputeManager.publish_service_capabilities from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager.publish_service_capabilities
2012-12-10 16:54:18 DEBUG nova.manager [-] Notifying Schedulers of capabilities ... from (pid=28401) publish_service_capabilities /opt/stack/nova/nova/manager.py:257
DEBUG:nova.manager:Notifying Schedulers of capabilities ...
2012-12-10 16:54:18 DEBUG nova.openstack.common.rpc.amqp [-] Making asynchronous fanout cast... from (pid=28401) fanout_cast /opt/stack/nova/nova/openstack/common/rpc/amqp.py:392
DEBUG:nova.openstack.common.rpc.amqp:Making asynchronous fanout cast...
2012-12-10 16:54:18 DEBUG nova.manager [-] Running periodic task ComputeManager._heal_instance_info_cache from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._heal_instance_info_cache
2012-12-10 16:54:18 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_rescued_instances from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_rescued_instances
2012-12-10 16:54:18 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_volume_usage from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_volume_usage
2012-12-10 16:54:18 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_bandwidth_usage from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_bandwidth_usage
2012-12-10 16:54:18 DEBUG nova.manager [-] Skipping ComputeManager._sync_power_states, 5 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
DEBUG:nova.manager:Skipping ComputeManager._sync_power_states, 5 ticks left until next run
2012-12-10 16:54:18 DEBUG nova.manager [-] Running periodic task ComputeManager._instance_usage_audit from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._instance_usage_audit
2012-12-10 16:54:18 DEBUG nova.manager [-] Running periodic task ComputeManager.update_available_resource from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager.update_available_resource
2012-12-10 16:54:18 DEBUG nova.virt.xenapi.host [-] Updating host stats from (pid=28401) update_status /opt/stack/nova/nova/virt/xenapi/host.py:150
DEBUG:nova.virt.xenapi.host:Updating host stats
2012-12-10 16:54:19 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" for method "update_available_resource"... from (pid=28401) inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
DEBUG:nova.openstack.common.lockutils:Got semaphore "compute_resources" for method "update_available_resource"...
2012-12-10 16:54:19 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
AUDIT:nova.compute.resource_tracker:Auditing locally available compute resources
2012-12-10 16:54:19 DEBUG nova.virt.xenapi.host [-] Updating host stats from (pid=28401) update_status /opt/stack/nova/nova/virt/xenapi/host.py:150
DEBUG:nova.virt.xenapi.host:Updating host stats
2012-12-10 16:54:19 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 4938 from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:322
DEBUG:nova.compute.resource_tracker:Hypervisor: free ram (MB): 4938
2012-12-10 16:54:19 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 218 from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:323
DEBUG:nova.compute.resource_tracker:Hypervisor: free disk (GB): 218
2012-12-10 16:54:19 DEBUG nova.compute.resource_tracker [-] Hypervisor: VCPU information unavailable from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:330
DEBUG:nova.compute.resource_tracker:Hypervisor: VCPU information unavailable
2012-12-10 16:54:19 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 7679
AUDIT:nova.compute.resource_tracker:Free ram (MB): 7679
2012-12-10 16:54:19 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 225
AUDIT:nova.compute.resource_tracker:Free disk (GB): 225
2012-12-10 16:54:19 AUDIT nova.compute.resource_tracker [-] Free VCPU information unavailable
AUDIT:nova.compute.resource_tracker:Free VCPU information unavailable
2012-12-10 16:54:19 INFO nova.compute.resource_tracker [-] Compute_service record updated for openstackDomU
INFO:nova.compute.resource_tracker:Compute_service record updated for openstackDomU
2012-12-10 16:54:19 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_rebooting_instances from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_rebooting_instances
2012-12-10 16:54:19 DEBUG nova.manager [-] Skipping ComputeManager._cleanup_running_deleted_instances, 25 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
DEBUG:nova.manager:Skipping ComputeManager._cleanup_running_deleted_instances, 25 ticks left until next run
2012-12-10 16:54:19 DEBUG nova.manager [-] Running periodic task ComputeManager._check_instance_build_time from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._check_instance_build_time
2012-12-10 16:54:19 DEBUG nova.manager [-] Skipping ComputeManager._run_image_cache_manager_pass, 35 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
DEBUG:nova.manager:Skipping ComputeManager._run_image_cache_manager_pass, 35 ticks left until next run
2012-12-10 16:54:19 DEBUG nova.manager [-] Running periodic task ComputeManager._reclaim_queued_deletes from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._reclaim_queued_deletes
2012-12-10 16:54:19 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... from (pid=28401) _reclaim_queued_deletes /opt/stack/nova/nova/compute/manager.py:3215
DEBUG:nova.compute.manager:CONF.reclaim_instance_interval <= 0, skipping...
2012-12-10 16:54:19 DEBUG nova.manager [-] Running periodic task ComputeManager._report_driver_status from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._report_driver_status
2012-12-10 16:54:19 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_unconfirmed_resizes from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_unconfirmed_resizes
2012-12-10 16:55:19 DEBUG nova.manager [-] Running periodic task ComputeManager.publish_service_capabilities from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager.publish_service_capabilities
2012-12-10 16:55:19 DEBUG nova.manager [-] Notifying Schedulers of capabilities ... from (pid=28401) publish_service_capabilities /opt/stack/nova/nova/manager.py:257
DEBUG:nova.manager:Notifying Schedulers of capabilities ...
2012-12-10 16:55:19 DEBUG nova.openstack.common.rpc.amqp [-] Making asynchronous fanout cast... from (pid=28401) fanout_cast /opt/stack/nova/nova/openstack/common/rpc/amqp.py:392
DEBUG:nova.openstack.common.rpc.amqp:Making asynchronous fanout cast...
2012-12-10 16:55:19 DEBUG nova.manager [-] Running periodic task ComputeManager._heal_instance_info_cache from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._heal_instance_info_cache
2012-12-10 16:55:19 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_rescued_instances from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_rescued_instances
2012-12-10 16:55:19 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_volume_usage from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_volume_usage
2012-12-10 16:55:19 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_bandwidth_usage from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_bandwidth_usage
2012-12-10 16:55:19 DEBUG nova.manager [-] Skipping ComputeManager._sync_power_states, 4 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
DEBUG:nova.manager:Skipping ComputeManager._sync_power_states, 4 ticks left until next run
2012-12-10 16:55:19 DEBUG nova.manager [-] Running periodic task ComputeManager._instance_usage_audit from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._instance_usage_audit
2012-12-10 16:55:19 DEBUG nova.manager [-] Running periodic task ComputeManager.update_available_resource from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager.update_available_resource
2012-12-10 16:55:19 DEBUG nova.virt.xenapi.host [-] Updating host stats from (pid=28401) update_status /opt/stack/nova/nova/virt/xenapi/host.py:150
DEBUG:nova.virt.xenapi.host:Updating host stats
2012-12-10 16:55:20 DEBUG nova.openstack.common.lockutils [-] Got semaphore "compute_resources" for method "update_available_resource"... from (pid=28401) inner /opt/stack/nova/nova/openstack/common/lockutils.py:185
DEBUG:nova.openstack.common.lockutils:Got semaphore "compute_resources" for method "update_available_resource"...
2012-12-10 16:55:20 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
AUDIT:nova.compute.resource_tracker:Auditing locally available compute resources
2012-12-10 16:55:20 DEBUG nova.virt.xenapi.host [-] Updating host stats from (pid=28401) update_status /opt/stack/nova/nova/virt/xenapi/host.py:150
DEBUG:nova.virt.xenapi.host:Updating host stats
2012-12-10 16:55:20 DEBUG nova.compute.resource_tracker [-] Hypervisor: free ram (MB): 4938 from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:322
DEBUG:nova.compute.resource_tracker:Hypervisor: free ram (MB): 4938
2012-12-10 16:55:20 DEBUG nova.compute.resource_tracker [-] Hypervisor: free disk (GB): 218 from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:323
DEBUG:nova.compute.resource_tracker:Hypervisor: free disk (GB): 218
2012-12-10 16:55:20 DEBUG nova.compute.resource_tracker [-] Hypervisor: VCPU information unavailable from (pid=28401) _report_hypervisor_resource_view /opt/stack/nova/nova/compute/resource_tracker.py:330
DEBUG:nova.compute.resource_tracker:Hypervisor: VCPU information unavailable
2012-12-10 16:55:21 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 7679
AUDIT:nova.compute.resource_tracker:Free ram (MB): 7679
2012-12-10 16:55:21 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 225
AUDIT:nova.compute.resource_tracker:Free disk (GB): 225
2012-12-10 16:55:21 AUDIT nova.compute.resource_tracker [-] Free VCPU information unavailable
AUDIT:nova.compute.resource_tracker:Free VCPU information unavailable
2012-12-10 16:55:21 INFO nova.compute.resource_tracker [-] Compute_service record updated for openstackDomU
INFO:nova.compute.resource_tracker:Compute_service record updated for openstackDomU
2012-12-10 16:55:21 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_rebooting_instances from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_rebooting_instances
2012-12-10 16:55:21 DEBUG nova.manager [-] Skipping ComputeManager._cleanup_running_deleted_instances, 24 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
DEBUG:nova.manager:Skipping ComputeManager._cleanup_running_deleted_instances, 24 ticks left until next run
2012-12-10 16:55:21 DEBUG nova.manager [-] Running periodic task ComputeManager._check_instance_build_time from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._check_instance_build_time
2012-12-10 16:55:21 DEBUG nova.manager [-] Skipping ComputeManager._run_image_cache_manager_pass, 34 ticks left until next run from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:167
DEBUG:nova.manager:Skipping ComputeManager._run_image_cache_manager_pass, 34 ticks left until next run
2012-12-10 16:55:21 DEBUG nova.manager [-] Running periodic task ComputeManager._reclaim_queued_deletes from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._reclaim_queued_deletes
2012-12-10 16:55:21 DEBUG nova.compute.manager [-] CONF.reclaim_instance_interval <= 0, skipping... from (pid=28401) _reclaim_queued_deletes /opt/stack/nova/nova/compute/manager.py:3215
DEBUG:nova.compute.manager:CONF.reclaim_instance_interval <= 0, skipping...
2012-12-10 16:55:21 DEBUG nova.manager [-] Running periodic task ComputeManager._report_driver_status from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._report_driver_status
2012-12-10 16:55:21 INFO nova.compute.manager [-] Updating host status
INFO:nova.compute.manager:Updating host status
2012-12-10 16:55:21 DEBUG nova.virt.xenapi.host [-] Updating host stats from (pid=28401) update_status /opt/stack/nova/nova/virt/xenapi/host.py:150
DEBUG:nova.virt.xenapi.host:Updating host stats
2012-12-10 16:55:21 DEBUG nova.manager [-] Running periodic task ComputeManager._poll_unconfirmed_resizes from (pid=28401) periodic_tasks /opt/stack/nova/nova/manager.py:172
DEBUG:nova.manager:Running periodic task ComputeManager._poll_unconfirmed_resizes
References

can not launch an instance + RPC timeout + nova-network does not start dnsmasq
From: Afef MDHAFFAR, 2012-12-10