Bug 1144157 - Repeated socket closed
Summary: Repeated socket closed
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: python-oslo-messaging
Version: 5.0 (RHEL 7)
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
: 5.0 (RHEL 7)
Assignee: Pádraig Brady
QA Contact: yeylon@redhat.com
URL:
Whiteboard:
: 1134570 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-09-18 19:44 UTC by Keith Schincke
Modified: 2016-11-04 15:37 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-12-16 15:24:08 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)

Description Keith Schincke 2014-09-18 19:44:53 UTC
Description of problem:
In the /var/log/nova/nova-compute.log file are mutple errors of messenging failing to consume a message due to a socket closed. 

Version-Release number of selected component (if applicable):
python-oslo-rootwrap-1.0.0-2.el7ost.noarch
openstack-nova-common-2014.1.2-1.el7ost.noarch
openstack-nova-api-2014.1.2-1.el7ost.noarch


How reproducible:
100%


Steps to Reproduce:
1. Configure OSP controller and compute
2. Monitor the nova-compute.log file
3.

Actual results:
2014-09-18 15:28:35.198 2317 ERROR oslo.messaging._drivers.impl_rabbit [-] Failed to consume message from queue: Socket closed
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit Traceback (most recent call last):
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit   File "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/impl_rabbit.py", line 622, in ensure
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit     return method(*args, **kwargs)
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit   File "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/impl_rabbit.py", line 702, in _consume
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit     return self.connection.drain_events(timeout=timeout)
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit   File "/usr/lib/python2.7/site-packages/kombu/connection.py", line 281, in drain_events
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit     return self.transport.drain_events(self.connection, **kwargs)
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit   File "/usr/lib/python2.7/site-packages/kombu/transport/pyamqp.py", line 94, in drain_events
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit     return connection.drain_events(**kwargs)
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit   File "/usr/lib/python2.7/site-packages/amqp/connection.py", line 266, in drain_events
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit     chanmap, None, timeout=timeout,
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit   File "/usr/lib/python2.7/site-packages/amqp/connection.py", line 328, in _wait_multiple
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit     channel, method_sig, args, content = read_timeout(timeout)
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit   File "/usr/lib/python2.7/site-packages/amqp/connection.py", line 292, in read_timeout
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit     return self.method_reader.read_method()
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit   File "/usr/lib/python2.7/site-packages/amqp/method_framing.py", line 192, in read_method
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit     raise m
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit 
2014-09-18 15:28:35.200 2317 INFO oslo.messaging._drivers.impl_rabbit [-] Reconnecting to AMQP server on 10.19.139.77:5672
2014-09-18 15:28:35.200 2317 INFO oslo.messaging._drivers.impl_rabbit [-] Delaying reconnect for 1.0 seconds...

The message repeates approx every 2 mins

2014-09-18 14:47:25.141 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 14:49:26.206 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 14:51:27.266 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 14:53:28.331 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 14:55:29.392 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 14:57:30.454 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 14:59:31.514 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:01:32.575 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:03:33.632 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:05:34.699 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:06:21.394 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:08:18.714 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:10:19.776 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:12:03.377 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:14:02.854 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:16:03.915 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:18:04.981 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:20:06.047 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:20:37.793 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:22:32.017 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:24:33.076 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:25:31.859 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:26:34.141 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:28:35.198 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:30:36.258 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:32:37.316 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:34:38.378 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:36:39.435 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:38:40.494 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-18 15:40:41.557 2317 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed



Expected results:
No errors. 

Additional info:

Comment 2 Pádraig Brady 2014-09-19 10:15:03 UTC
This isn't causing a functional issue due to retries I presume?
Is keepalived in the equation? Is the rabbitmqd service being restarted somehow?

Comment 3 Keith Schincke 2014-09-19 12:15:51 UTC
The process is not dieing. Rabbitmqd has a long running pid with a start time of the last reboot. 

The follwoing message is repeated in the rabbitmqd error log

=WARNING REPORT==== 19-Sep-2014::08:12:51 ===
closing AMQP connection <0.7417.0> (10.19.139.72:45492 -> 10.19.139.72:5672):
connection_closed_abruptly

Comment 4 Pádraig Brady 2014-09-22 10:49:18 UTC
That suggests that it's nova-compute killing the connection, not rabbitmqd.

My guess it that this is an exception due to a timeout from nova communicating with an unavailable service which results in the messy log spew

Comment 5 Jure Pečar 2015-10-22 08:40:37 UTC
It looks like patch is available here:
https://bugs.launchpad.net/cloud-archive/+bug/1338732

When can we expect updated packages for RDO6?

Comment 6 Peter Lemenkov 2015-11-12 13:55:19 UTC
*** Bug 1134570 has been marked as a duplicate of this bug. ***

Comment 7 Peter Lemenkov 2015-11-12 13:55:58 UTC
(In reply to Jure Pečar from comment #5)
> It looks like patch is available here:
> https://bugs.launchpad.net/cloud-archive/+bug/1338732
> 
> When can we expect updated packages for RDO6?

This is more likely candidate:

* https://bugs.launchpad.net/nova/+bug/856764

Fix is available in upstream since 1.3.0a9 version. We ship 1.3.1 for RHOS-5, so I believe it's safe to close this ticket.

Comment 9 Peter Lemenkov 2016-11-04 15:37:48 UTC
Unfortunately, "Failed to consume message from queue: Socket closed" indicates another one known issue in python-oslo-messaging which was fixed in the following builds:

* python-oslo-messaging-2.5.0-7.el7ost (OSP8)
* python-oslo-messaging-4.5.0-2.el7ost (OSP9)


Note You need to log in before you can comment on or make changes to this bug.