nova-oslo.messaging._drivers.impl_rabbit ERROR: Failed to consume message from queue: Socket closed

Bug #1378672 reported by Ruslan Usichenko
16
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Mirantis OpenStack
Invalid
Undecided
Unassigned

Bug Description

Fuel 5.0.1
Icehouse
Ubuntu 12.04
MultiNode HA installation

3xControllers
3xCompute nodes
Network: Neutron + ovs plugin with bonding

nova.api log

<182>Oct 7 10:12:40 node-1 nova-urllib3.connectionpool INFO: Starting new HTTP connection (1): 192.168.0.2
<180>Oct 7 10:12:40 node-1 nova-nova.api.openstack.compute.contrib.attach_interfaces AUDIT: Attach interface
<179>Oct 7 10:12:40 node-1 nova-oslo.messaging._drivers.impl_rabbit ERROR: Failed to consume message from queue: Socket closed
Traceback (most recent call last):
File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/impl_rabbit.py", line 648, in ensure
return method(*args, **kwargs)
File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/impl_rabbit.py", line 737, in _consume
return self.connection.drain_events(timeout=timeout)
File "/usr/lib/python2.7/dist-packages/kombu/connection.py", line 279, in drain_events
return self.transport.drain_events(self.connection, **kwargs)
File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqp.py", line 91, in drain_events
return connection.drain_events(**kwargs)
File "/usr/lib/python2.7/dist-packages/amqp/connection.py", line 299, in drain_events
chanmap, None, timeout=timeout,
File "/usr/lib/python2.7/dist-packages/amqp/connection.py", line 362, in _wait_multiple
channel, method_sig, args, content = read_timeout(timeout)
File "/usr/lib/python2.7/dist-packages/amqp/connection.py", line 333, in read_timeout
return self.method_reader.read_method()
File "/usr/lib/python2.7/dist-packages/amqp/method_framing.py", line 189, in read_method
raise m
IOError: Socket closed
<182>Oct 7 10:12:40 node-1 nova-oslo.messaging._drivers.impl_rabbit INFO: Reconnecting to AMQP server on 192.168.0.3:5673
<182>Oct 7 10:12:40 node-1 nova-oslo.messaging._drivers.impl_rabbit INFO: Delaying reconnect for 5.0 seconds...
<180>Oct 7 10:12:43 node-1 nova-keystoneclient.middleware.auth_token WARNING: Unable to find authentication token in headers
<182>Oct 7 10:12:43 node-1 nova-keystoneclient.middleware.auth_token INFO: Invalid user token - rejecting request
<182>Oct 7 10:12:43 node-1 nova-nova.osapi_compute.wsgi.server INFO: 192.168.0.2 "POST /v2/d07aaf45f175487eafc6bee0728090e5/os-server-external-events HTTP/1.1" status: 401 len: 194 time: 0.0015540
<182>Oct 7 10:12:45 node-1 nova-oslo.messaging._drivers.impl_rabbit INFO: Connected to AMQP server on 192.168.0.3:5673
<179>Oct 7 10:13:41 node-1 nova-nova.api.openstack ERROR: Caught error: Timed out waiting for a reply to message ID afe846be62464fb8a8ef6a8051e78245
Traceback (most recent call last):
File "/usr/lib/python2.7/dist-packages/nova/api/openstack/_init.py", line 125, in __call_
return req.get_response(self.application)
File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1296, in send
application, catch_exc_info=False)
File "/usr/lib/python2.7/dist-packages/webob/request.py", line 1260, in call_application
app_iter = application(self.environ, start_response)
File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in _call_
return resp(environ, start_response)
File "/usr/lib/python2.7/dist-packages/keystoneclient/middleware/auth_token.py", line 582, in _call_
return self.app(env, start_response)
File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in _call_
return resp(environ, start_response)
File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in _call_
return resp(environ, start_response)
File "/usr/lib/python2.7/dist-packages/routes/middleware.py", line 131, in _call_
response = self.app(environ, start_response)
File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 144, in _call_
return resp(environ, start_response)
File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 130, in _call_
resp = self.call_func(req, *args, **self.kwargs)
File "/usr/lib/python2.7/dist-packages/webob/dec.py", line 195, in call_func
return self.func(req, *args, **kwargs)
File "/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line 917, in _call_
content_type, body, accept)
File "/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line 983, in _process_stack
action_result = self.dispatch(meth, request, action_args)
File "/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line 1070, in dispatch
return method(req=request, **action_args)
File "/usr/lib/python2.7/dist-packages/nova/api/openstack/compute/contrib/attach_interfaces.py", line 106, in create
instance, network_id, port_id, req_ip)
File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 201, in wrapped
return func(self, context, target, *args, **kwargs)
File "/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 2864, in attach_interface
requested_ip=requested_ip)
File "/usr/lib/python2.7/dist-packages/nova/compute/rpcapi.py", line 322, in attach_interface
port_id=port_id, requested_ip=requested_ip)
File "/usr/lib/python2.7/dist-packages/oslo/messaging/rpc/client.py", line 150, in call
wait_for_reply=True, timeout=timeout)
File "/usr/lib/python2.7/dist-packages/oslo/messaging/transport.py", line 90, in _send
timeout=timeout)
File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 430, in send
return self._send(target, ctxt, message, wait_for_reply, timeout)
File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 421, in _send
result = self._waiter.wait(msg_id, timeout)
File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 267, in wait
reply, ending = self._poll_connection(msg_id, timeout)
File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/amqpdriver.py", line 217, in _poll_connection
% msg_id)
MessagingTimeout: Timed out waiting for a reply to message ID afe846be62464fb8a8ef6a8051e78245
<182>Oct 7 10:13:41 node-1 nova-nova.api.openstack INFO: http://172.16.0.2:8774/v2/3d0e067fc60a45b2af980681895501c6/servers/84bff0c1-b85e-4056-9fbc-c1d56b2de15c/os-interface returned with HTTP 500
<182>Oct 7 10:13:41 node-1 nova-nova.osapi_compute.wsgi.server INFO: 192.168.0.2 "POST /v2/3d0e067fc60a45b2af980681895501c6/servers/84bff0c1-b85e-4056-9fbc-c1d56b2de15c/os-interface HTTP/1.1" status: 500 len: 359 time: 60.1963000
<182>Oct 7 11:25:12 node-1 nova-nova.osapi_compute.wsgi.server INFO: 192.168.0.2 "GET /v2/3d0e067fc60a45b2af980681895501c6/servers/detail?limit=21&project_id=3d0e067fc60a45b2af980681895501c6 HTTP/1.1" status: 200 len: 31168 time: 0.3820059
<182>Oct 7 11:25:12 node-1 nova-nova.osapi_compute.wsgi.server INFO: 192.168.0.2 "GET /v2/3d0e067fc60a45b2af980681895501c6/flavors/detail HTTP/1.1" status: 200 len: 2545 time: 0.0209150
<182>Oct 7 11:25:13 node-1 nova-nova.osapi_compute.wsgi.server INFO: 192.168.0.2 "GET /v2/3d0e067fc60a45b2af980681895501c6/limits?reserved=1 HTTP/1.1" status: 200 len: 601 time: 0.0063190
<182>Oct 7 11:25:13 node-1 nova-nova.osapi_compute.wsgi.server INFO: 192.168.0.2 "GET /v2/3d0e067fc60a45b2af980681895501c6/extensions HTTP/1.1" status: 200 len: 20697 time: 0.0066860
<182>Oct 7 11:25:13 node-1 nova-nova.osapi_compute.wsgi.server INFO: 192.168.0.2 "GET /v2/3d0e067fc60a45b2af980681895501c6/limits?reserved=1 HTTP/1.1" status: 200 len: 601 time: 0.0057850

rabbitmq.log

=ERROR REPORT==== 7-Oct-2014::10:14:58 ===
closing AMQP connection <0.1676.328> (192.168.0.3:41621 -> 192.168.0.3:5673):
{heartbeat_timeout,running}

=ERROR REPORT==== 7-Oct-2014::10:15:06 ===
closing AMQP connection <0.1972.328> (192.168.0.6:59283 -> 192.168.0.3:5673):{heartbeat_timeout,running}
=ERROR REPORT==== 7-Oct-2014::10:15:10 ===
closing AMQP connection <0.2020.328> (192.168.0.4:49212 -> 192.168.0.3:5673):
{heartbeat_timeout,running}

=ERROR REPORT==== 7-Oct-2014::10:15:24 ===
closing AMQP connection <0.2497.328> (192.168.0.3:42529 -> 192.168.0.3:5673):{heartbeat_timeout,running}
=ERROR REPORT==== 7-Oct-2014::10:15:45 ===
closing AMQP connection <0.2823.328> (192.168.0.3:43155 -> 192.168.0.3:5673):
{heartbeat_timeout,running}

=ERROR REPORT==== 7-Oct-2014::10:15:48 ===
closing AMQP connection <0.2865.328> (192.168.0.4:49344 -> 192.168.0.3:5673):{heartbeat_timeout,running}

tags: added: customer-found
description: updated
description: updated
affects: fuel → mos
Revision history for this message
Dmitry Mescheryakov (dmitrymex) wrote :

Guys, please specify, what was actually broken. Also a diagnostic snapshot would help.

Changed in mos:
status: New → Incomplete
Changed in mos:
milestone: none → 5.0.3
Revision history for this message
Dmitry Mescheryakov (dmitrymex) wrote :

The issue is hanging in incomplete state for too long. Hence moving to invalid state.

Changed in mos:
status: Incomplete → Invalid
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.