yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1296972] Re: RPC code in Havana doesn't handle connection errors

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Chris Friesen <chris.friesen@xxxxxxxxxxxxx>
Date: Tue, 25 Mar 2014 03:41:57 -0000
Reply-to: Bug 1296972 <1296972@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Looks like I misread that patch below, it's adding back the channel
error check, not the connection error check.

This may be due to a bad patch on our end, sorry for the noise.

** Changed in: nova
       Status: New => Invalid

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1296972

Title:
  RPC code in Havana doesn't handle connection errors

Status in OpenStack Compute (Nova):
  Invalid

Bug description:
  We've got an HA controller setup using pacemaker and were stress-
  testing it by doing multiple controlled switchovers while doing other
  activity.  Generally this works okay, but last night we ran into a
  problem where nova-compute got into a state where it was unable to
  reconnect with the AMQP server.  Logs are at the bottom, they repeat
  every minute and did this for 7+ hours until the system was manually
  cleaned up.

  
  I've found something in the code that looks a bit suspicious.  The  "Unexpected exception occurred 61 time(s)... retrying." message comes from forever_retry_uncaught_exceptions() in excutils.py.  It looks like we're raising

  RecoverableConnectionError: connection already closed

  down in /usr/lib64/python2.7/site-packages/amqp/abstract_channel.py,
  but nothing handles it.

  It looks like the most likely place that should be handling it is
  nova.openstack.common.rpc.impl_kombu.Connection.ensure().

  In the current oslo.messaging code the ensure() routine explicitly
  handles connection errors (which RecoverableConnectionError is) and
  socket timeouts--the ensure() routine in Havana doesn't do this.

  Maybe we should look at porting
  https://github.com/openstack/oslo.messaging/commit/0400cbf4f83cf8d58076c7e65e08a156ec3508a8
  to the Havana RPC code?


  Logs showing the start of the problem and the first few iterations of
  the repeating issue:

  
  2014-03-24 09:24:33.566 6620 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
  2014-03-24 09:24:34.126 6620 INFO nova.compute.resource_tracker [-] DETAIL: instance: name=u'sgw-4', vm_state=u'active', task_state=None, vcpus=2, cpuset=0x180, cpulist=[7, 8] pinned, nodelist=[0], node=0 
  2014-03-24 09:24:34.126 6620 INFO nova.compute.resource_tracker [-] DETAIL: instance: name=u'sgw-1', vm_state=u'active', task_state=None, vcpus=2, cpuset=0x60, cpulist=[5, 6] pinned, nodelist=[0], node=0 
  2014-03-24 09:24:34.126 6620 INFO nova.compute.resource_tracker [-] DETAIL: instance: name=u'load_balancer', vm_state=u'active', task_state=None, vcpus=3, cpuset=0x1c00, cpulist=[10, 11, 12] pinned, nodelist=[1], node=1 
  2014-03-24 09:24:34.182 6620 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 111290, per-node: [52286, 59304], numa nodes:2
  2014-03-24 09:24:34.183 6620 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 29
  2014-03-24 09:24:34.183 6620 AUDIT nova.compute.resource_tracker [-] Free vcpus: 170, free per-node float vcpus: [48, 112], free per-node pinned vcpus: [3, 7]
  2014-03-24 09:24:34.183 6620 INFO nova.compute.resource_tracker [-] DETAIL: vcpus:20, Free vcpus:170, 16.0x overcommit, per-cpu float cpulist: [3, 4, 9, 13, 14, 15, 16, 17, 18, 19]
  2014-03-24 09:24:34.244 6620 INFO nova.compute.resource_tracker [-] Compute_service record updated for compute-0:compute-0
  2014-03-24 09:25:36.564 6620 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
  2014-03-24 09:25:37.122 6620 INFO nova.compute.resource_tracker [-] DETAIL: instance: name=u'sgw-4', vm_state=u'active', task_state=None, vcpus=2, cpuset=0x180, cpulist=[7, 8] pinned, nodelist=[0], node=0 
  2014-03-24 09:25:37.122 6620 INFO nova.compute.resource_tracker [-] DETAIL: instance: name=u'sgw-1', vm_state=u'active', task_state=None, vcpus=2, cpuset=0x60, cpulist=[5, 6] pinned, nodelist=[0], node=0 
  2014-03-24 09:25:37.122 6620 INFO nova.compute.resource_tracker [-] DETAIL: instance: name=u'load_balancer', vm_state=u'active', task_state=None, vcpus=3, cpuset=0x1c00, cpulist=[10, 11, 12] pinned, nodelist=[1], node=1 
  2014-03-24 09:25:37.182 6620 AUDIT nova.compute.resource_tracker [-] Free ram (MB): 111290, per-node: [52286, 59304], numa nodes:2
  2014-03-24 09:25:37.182 6620 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 29
  2014-03-24 09:25:37.183 6620 AUDIT nova.compute.resource_tracker [-] Free vcpus: 170, free per-node float vcpus: [48, 112], free per-node pinned vcpus: [3, 7]
  2014-03-24 09:25:37.183 6620 INFO nova.compute.resource_tracker [-] DETAIL: vcpus:20, Free vcpus:170, 16.0x overcommit, per-cpu float cpulist: [3, 4, 9, 13, 14, 15, 16, 17, 18, 19]
  2014-03-24 09:25:37.245 6620 INFO nova.compute.resource_tracker [-] Compute_service record updated for compute-0:compute-0
  2014-03-24 09:26:47.324 6620 ERROR root [-] Unexpected exception occurred 1 time(s)... retrying.
  2014-03-24 09:26:47.324 6620 TRACE root Traceback (most recent call last):
  2014-03-24 09:26:47.324 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/excutils.py", line 78, in inner_func
  2014-03-24 09:26:47.324 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 745, in _consumer_thread
  2014-03-24 09:26:47.324 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 736, in consume
  2014-03-24 09:26:47.324 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 663, in iterconsume
  2014-03-24 09:26:47.324 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 578, in ensure
  2014-03-24 09:26:47.324 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 658, in _consume
  2014-03-24 09:26:47.324 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/kombu/connection.py", line 279, in drain_events
  2014-03-24 09:26:47.324 6620 TRACE root     return self.transport.drain_events(self.connection, **kwargs)
  2014-03-24 09:26:47.324 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/kombu/transport/pyamqp.py", line 90, in drain_events
  2014-03-24 09:26:47.324 6620 TRACE root     return connection.drain_events(**kwargs)
  2014-03-24 09:26:47.324 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/amqp/connection.py", line 303, in drain_events
  2014-03-24 09:26:47.324 6620 TRACE root     return amqp_method(channel, args)
  2014-03-24 09:26:47.324 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/amqp/connection.py", line 509, in _close
  2014-03-24 09:26:47.324 6620 TRACE root     (class_id, method_id), ConnectionError)
  2014-03-24 09:26:47.324 6620 TRACE root ConnectionForced: (0, 0): (320) CONNECTION_FORCED - broker forced connection closure with reason 'shutdown'
  2014-03-24 09:26:47.324 6620 TRACE root 
  2014-03-24 09:26:47.366 6620 ERROR nova.openstack.common.rpc.common [-] Failed to consume message from queue: [Errno 104] Connection reset by peer
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common Traceback (most recent call last):
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 578, in ensure
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 658, in _consume
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/kombu/connection.py", line 279, in drain_events
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common     return self.transport.drain_events(self.connection, **kwargs)
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/kombu/transport/pyamqp.py", line 90, in drain_events
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common     return connection.drain_events(**kwargs)
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/amqp/connection.py", line 303, in drain_events
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common     return amqp_method(channel, args)
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/amqp/connection.py", line 506, in _close
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common     self._x_close_ok()
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/amqp/connection.py", line 534, in _x_close_ok
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common     self._send_method((10, 51))
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/amqp/abstract_channel.py", line 62, in _send_method
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common     self.channel_id, method_sig, args, content,
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/amqp/method_framing.py", line 227, in write_method
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common     write_frame(1, channel, payload)
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/amqp/transport.py", line 183, in write_frame
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common     frame_type, channel, size, payload, 0xce,
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/eventlet/greenio.py", line 309, in sendall
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common     tail = self.send(data, flags)
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/eventlet/greenio.py", line 295, in send
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common     total_sent += fd.send(data[total_sent:], flags)
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common error: [Errno 104] Connection reset by peer
  2014-03-24 09:26:47.366 6620 TRACE nova.openstack.common.rpc.common 
  2014-03-24 09:26:47.368 6620 INFO nova.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
  2014-03-24 09:26:47.378 6620 ERROR nova.openstack.common.rpc.common [-] AMQP server on 192.168.204.2:5672 is unreachable: [Errno 111] ECONNREFUSED. Trying again in 1 seconds.
  2014-03-24 09:26:48.103 6620 ERROR nova.openstack.common.rpc.common [-] Failed to publish message to topic 'conductor': [Errno 104] Connection reset by peer
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common Traceback (most recent call last):
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 578, in ensure
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 689, in _publish
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 369, in __init__
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 316, in __init__
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 324, in reconnect
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/kombu/messaging.py", line 82, in __init__
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common     self.revive(self._channel)
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/kombu/messaging.py", line 216, in revive
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common     self.declare()
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/kombu/messaging.py", line 102, in declare
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common     self.exchange.declare()
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/kombu/entity.py", line 166, in declare
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common     nowait=nowait, passive=passive,
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/amqp/channel.py", line 604, in exchange_declare
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common     self._send_method((40, 10), args)
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/amqp/abstract_channel.py", line 62, in _send_method
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common     self.channel_id, method_sig, args, content,
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/amqp/method_framing.py", line 227, in write_method
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common     write_frame(1, channel, payload)
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/amqp/transport.py", line 183, in write_frame
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common     frame_type, channel, size, payload, 0xce,
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/eventlet/greenio.py", line 309, in sendall
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common     tail = self.send(data, flags)
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common   File "/usr/lib64/python2.7/site-packages/eventlet/greenio.py", line 295, in send
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common     total_sent += fd.send(data[total_sent:], flags)
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common error: [Errno 104] Connection reset by peer
  2014-03-24 09:26:48.103 6620 TRACE nova.openstack.common.rpc.common 
  2014-03-24 09:26:48.105 6620 INFO nova.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
  2014-03-24 09:26:48.112 6620 ERROR nova.openstack.common.rpc.common [-] AMQP server on 192.168.204.2:5672 is unreachable: [Errno 111] ECONNREFUSED. Trying again in 1 seconds.
  2014-03-24 09:26:48.327 6620 ERROR root [-] Unexpected exception occurred 1 time(s)... retrying.
  2014-03-24 09:26:48.327 6620 TRACE root Traceback (most recent call last):
  2014-03-24 09:26:48.327 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/excutils.py", line 78, in inner_func
  2014-03-24 09:26:48.327 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 745, in _consumer_thread
  2014-03-24 09:26:48.327 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 736, in consume
  2014-03-24 09:26:48.327 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 663, in iterconsume
  2014-03-24 09:26:48.327 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 578, in ensure
  2014-03-24 09:26:48.327 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 656, in _consume
  2014-03-24 09:26:48.327 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 191, in consume
  2014-03-24 09:26:48.327 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/kombu/entity.py", line 609, in consume
  2014-03-24 09:26:48.327 6620 TRACE root     nowait=nowait)
  2014-03-24 09:26:48.327 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/amqp/channel.py", line 1775, in basic_consume
  2014-03-24 09:26:48.327 6620 TRACE root     self._send_method((60, 20), args)
  2014-03-24 09:26:48.327 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/amqp/abstract_channel.py", line 56, in _send_method
  2014-03-24 09:26:48.327 6620 TRACE root     raise RecoverableConnectionError('connection already closed')
  2014-03-24 09:26:48.327 6620 TRACE root RecoverableConnectionError: connection already closed
  2014-03-24 09:26:48.327 6620 TRACE root 
  2014-03-24 09:26:48.379 6620 INFO nova.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
  2014-03-24 09:26:48.386 6620 ERROR nova.openstack.common.rpc.common [-] AMQP server on 192.168.204.2:5672 is unreachable: [Errno 111] ECONNREFUSED. Trying again in 3 seconds.
  2014-03-24 09:26:49.112 6620 INFO nova.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
  2014-03-24 09:26:49.120 6620 ERROR nova.openstack.common.rpc.common [-] AMQP server on 192.168.204.2:5672 is unreachable: [Errno 111] ECONNREFUSED. Trying again in 3 seconds.
  2014-03-24 09:26:51.386 6620 INFO nova.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
  2014-03-24 09:26:51.402 6620 ERROR nova.openstack.common.rpc.common [-] AMQP server on 192.168.204.2:5672 is unreachable: [Errno 111] ECONNREFUSED. Trying again in 5 seconds.
  2014-03-24 09:26:52.120 6620 INFO nova.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
  2014-03-24 09:26:52.127 6620 ERROR nova.openstack.common.rpc.common [-] AMQP server on 192.168.204.2:5672 is unreachable: [Errno 111] ECONNREFUSED. Trying again in 5 seconds.
  2014-03-24 09:26:56.408 6620 INFO nova.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
  2014-03-24 09:26:56.454 6620 INFO nova.openstack.common.rpc.common [-] Connected to AMQP server on 192.168.204.2:5672
  2014-03-24 09:26:57.128 6620 INFO nova.openstack.common.rpc.common [-] Reconnecting to AMQP server on 192.168.204.2:5672
  2014-03-24 09:26:57.137 6620 INFO nova.openstack.common.rpc.common [-] Connected to AMQP server on 192.168.204.2:5672
  2014-03-24 09:27:39.807 6620 ERROR nova.openstack.common.periodic_task [-] Error during ComputeManager._instance_usage_audit: Timeout while waiting on RPC response - topic: "conductor", RPC method: "task_log_get" info: "<unknown>"
  2014-03-24 09:27:39.807 6620 TRACE nova.openstack.common.periodic_task Traceback (most recent call last):
  2014-03-24 09:27:39.807 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/periodic_task.py", line 180, in run_periodic_tasks
  2014-03-24 09:27:39.807 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/compute/manager.py", line 4623, in _instance_usage_audit
  2014-03-24 09:27:39.807 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/compute/utils.py", line 363, in has_audit_been_run
  2014-03-24 09:27:39.807 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/conductor/api.py", line 273, in task_log_get
  2014-03-24 09:27:39.807 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/conductor/rpcapi.py", line 403, in task_log_get
  2014-03-24 09:27:39.807 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/rpcclient.py", line 85, in call
  2014-03-24 09:27:39.807 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/rpcclient.py", line 63, in _invoke
  2014-03-24 09:27:39.807 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/proxy.py", line 130, in call
  2014-03-24 09:27:39.807 6620 TRACE nova.openstack.common.periodic_task Timeout: Timeout while waiting on RPC response - topic: "conductor", RPC method: "task_log_get" info: "<unknown>"
  2014-03-24 09:27:39.807 6620 TRACE nova.openstack.common.periodic_task 
  2014-03-24 09:27:39.809 6620 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
  2014-03-24 09:27:49.335 6620 ERROR root [-] Unexpected exception occurred 61 time(s)... retrying.
  2014-03-24 09:27:49.335 6620 TRACE root Traceback (most recent call last):
  2014-03-24 09:27:49.335 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/excutils.py", line 78, in inner_func
  2014-03-24 09:27:49.335 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 745, in _consumer_thread
  2014-03-24 09:27:49.335 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 736, in consume
  2014-03-24 09:27:49.335 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 663, in iterconsume
  2014-03-24 09:27:49.335 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 578, in ensure
  2014-03-24 09:27:49.335 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 656, in _consume
  2014-03-24 09:27:49.335 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 191, in consume
  2014-03-24 09:27:49.335 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/kombu/entity.py", line 609, in consume
  2014-03-24 09:27:49.335 6620 TRACE root     nowait=nowait)
  2014-03-24 09:27:49.335 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/amqp/channel.py", line 1775, in basic_consume
  2014-03-24 09:27:49.335 6620 TRACE root     self._send_method((60, 20), args)
  2014-03-24 09:27:49.335 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/amqp/abstract_channel.py", line 56, in _send_method
  2014-03-24 09:27:49.335 6620 TRACE root     raise RecoverableConnectionError('connection already closed')
  2014-03-24 09:27:49.335 6620 TRACE root RecoverableConnectionError: connection already closed
  2014-03-24 09:27:49.335 6620 TRACE root 
  2014-03-24 09:27:57.139 6620 ERROR nova.servicegroup.drivers.db [-] model server went away
  2014-03-24 09:27:57.139 6620 TRACE nova.servicegroup.drivers.db Traceback (most recent call last):
  2014-03-24 09:27:57.139 6620 TRACE nova.servicegroup.drivers.db   File "./usr/lib64/python2.7/site-packages/nova/servicegroup/drivers/db.py", line 98, in _report_state
  2014-03-24 09:27:57.139 6620 TRACE nova.servicegroup.drivers.db   File "./usr/lib64/python2.7/site-packages/nova/conductor/api.py", line 269, in service_update
  2014-03-24 09:27:57.139 6620 TRACE nova.servicegroup.drivers.db   File "./usr/lib64/python2.7/site-packages/nova/conductor/rpcapi.py", line 397, in service_update
  2014-03-24 09:27:57.139 6620 TRACE nova.servicegroup.drivers.db   File "./usr/lib64/python2.7/site-packages/nova/rpcclient.py", line 85, in call
  2014-03-24 09:27:57.139 6620 TRACE nova.servicegroup.drivers.db   File "./usr/lib64/python2.7/site-packages/nova/rpcclient.py", line 63, in _invoke
  2014-03-24 09:27:57.139 6620 TRACE nova.servicegroup.drivers.db   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/proxy.py", line 130, in call
  2014-03-24 09:27:57.139 6620 TRACE nova.servicegroup.drivers.db Timeout: Timeout while waiting on RPC response - topic: "conductor", RPC method: "service_update" info: "<unknown>"
  2014-03-24 09:27:57.139 6620 TRACE nova.servicegroup.drivers.db 
  2014-03-24 09:27:57.141 6620 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 59.038519 sec
  2014-03-24 09:28:40.346 6620 ERROR nova.openstack.common.periodic_task [-] Error during ComputeManager.update_available_resource: Timeout while waiting on RPC response - topic: "conductor", RPC method: "object_class_action" info: "<unknown>"
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task Traceback (most recent call last):
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/periodic_task.py", line 180, in run_periodic_tasks
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/compute/manager.py", line 5024, in update_available_resource
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/lockutils.py", line 246, in inner
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/compute/resource_tracker.py", line 495, in update_available_resource
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/objects/base.py", line 106, in wrapper
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/conductor/rpcapi.py", line 492, in object_class_action
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/rpcclient.py", line 85, in call
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/rpcclient.py", line 63, in _invoke
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/proxy.py", line 130, in call
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task Timeout: Timeout while waiting on RPC response - topic: "conductor", RPC method: "object_class_action" info: "<unknown>"
  2014-03-24 09:28:40.346 6620 TRACE nova.openstack.common.periodic_task 
  2014-03-24 09:28:50.342 6620 ERROR root [-] Unexpected exception occurred 61 time(s)... retrying.
  2014-03-24 09:28:50.342 6620 TRACE root Traceback (most recent call last):
  2014-03-24 09:28:50.342 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/excutils.py", line 78, in inner_func
  2014-03-24 09:28:50.342 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 745, in _consumer_thread
  2014-03-24 09:28:50.342 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 736, in consume
  2014-03-24 09:28:50.342 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 663, in iterconsume
  2014-03-24 09:28:50.342 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 578, in ensure
  2014-03-24 09:28:50.342 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 656, in _consume
  2014-03-24 09:28:50.342 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 191, in consume
  2014-03-24 09:28:50.342 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/kombu/entity.py", line 609, in consume
  2014-03-24 09:28:50.342 6620 TRACE root     nowait=nowait)
  2014-03-24 09:28:50.342 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/amqp/channel.py", line 1775, in basic_consume
  2014-03-24 09:28:50.342 6620 TRACE root     self._send_method((60, 20), args)
  2014-03-24 09:28:50.342 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/amqp/abstract_channel.py", line 56, in _send_method
  2014-03-24 09:28:50.342 6620 TRACE root     raise RecoverableConnectionError('connection already closed')
  2014-03-24 09:28:50.342 6620 TRACE root RecoverableConnectionError: connection already closed
  2014-03-24 09:28:50.342 6620 TRACE root 
  2014-03-24 09:28:57.144 6620 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 50.00323 sec
  2014-03-24 09:29:40.351 6620 ERROR nova.openstack.common.periodic_task [-] Error during ComputeManager._run_pending_deletes: Timeout while waiting on RPC response - topic: "conductor", RPC method: "object_class_action" info: "<unknown>"
  2014-03-24 09:29:40.351 6620 TRACE nova.openstack.common.periodic_task Traceback (most recent call last):
  2014-03-24 09:29:40.351 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/periodic_task.py", line 180, in run_periodic_tasks
  2014-03-24 09:29:40.351 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/compute/manager.py", line 5239, in _run_pending_deletes
  2014-03-24 09:29:40.351 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/objects/base.py", line 106, in wrapper
  2014-03-24 09:29:40.351 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/conductor/rpcapi.py", line 492, in object_class_action
  2014-03-24 09:29:40.351 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/rpcclient.py", line 85, in call
  2014-03-24 09:29:40.351 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/rpcclient.py", line 63, in _invoke
  2014-03-24 09:29:40.351 6620 TRACE nova.openstack.common.periodic_task   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/proxy.py", line 130, in call
  2014-03-24 09:29:40.351 6620 TRACE nova.openstack.common.periodic_task Timeout: Timeout while waiting on RPC response - topic: "conductor", RPC method: "object_class_action" info: "<unknown>"
  2014-03-24 09:29:40.351 6620 TRACE nova.openstack.common.periodic_task 
  2014-03-24 09:29:51.349 6620 ERROR root [-] Unexpected exception occurred 61 time(s)... retrying.
  2014-03-24 09:29:51.349 6620 TRACE root Traceback (most recent call last):
  2014-03-24 09:29:51.349 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/excutils.py", line 78, in inner_func
  2014-03-24 09:29:51.349 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 745, in _consumer_thread
  2014-03-24 09:29:51.349 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 736, in consume
  2014-03-24 09:29:51.349 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 663, in iterconsume
  2014-03-24 09:29:51.349 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 578, in ensure
  2014-03-24 09:29:51.349 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 656, in _consume
  2014-03-24 09:29:51.349 6620 TRACE root   File "./usr/lib64/python2.7/site-packages/nova/openstack/common/rpc/impl_kombu.py", line 191, in consume
  2014-03-24 09:29:51.349 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/kombu/entity.py", line 609, in consume
  2014-03-24 09:29:51.349 6620 TRACE root     nowait=nowait)
  2014-03-24 09:29:51.349 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/amqp/channel.py", line 1775, in basic_consume
  2014-03-24 09:29:51.349 6620 TRACE root     self._send_method((60, 20), args)
  2014-03-24 09:29:51.349 6620 TRACE root   File "/usr/lib64/python2.7/site-packages/amqp/abstract_channel.py", line 56, in _send_method
  2014-03-24 09:29:51.349 6620 TRACE root     raise RecoverableConnectionError('connection already closed')
  2014-03-24 09:29:51.349 6620 TRACE root RecoverableConnectionError: connection already closed
  2014-03-24 09:29:51.349 6620 TRACE root 
  2014-03-24 09:29:57.147 6620 WARNING nova.openstack.common.loopingcall [-] task run outlasted interval by 50.002704 sec

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1296972/+subscriptions
References

[Bug 1296972] [NEW] RPC code in Havana doesn't handle connection errors
From: Chris Friesen, 2014-03-24