Mirantis OpenStack

Too many reconnects in logs

Series 5.0.x
Bug #1371723

Bug #1371723 reported by Serg Melikyan on 2014-09-19

336

This bug affects 15 people

	Status	Importance	Assigned to	Milestone
Mirantis OpenStack	Fix Committed	High	Ilya Pekelny	Mirantis OpenStack 5.1.1
5.0.x	Fix Committed	High	Ilya Pekelny	Mirantis OpenStack 5.0-updates
5.1.x	Fix Committed	High	Serg Melikyan	Mirantis OpenStack 5.1.1
6.0.x	Fix Committed	High	Ilya Pekelny	Mirantis OpenStack 6.0

Bug Description

We see too many reconnects in different components logs like:

2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit Traceback (most recent call last):
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/impl_rabbit.py", line 648, in ensure
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit return method(*args, **kwargs)
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/impl_rabbit.py", line 753, in _publish
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit publisher = cls(self.conf, self.channel, topic, **kwargs)
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/impl_rabbit.py", line 396, in __init__
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit **options)
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/impl_rabbit.py", line 339, in __init__
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit self.reconnect(channel)
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/impl_rabbit.py", line 347, in reconnect
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit routing_key=self.routing_key)
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/kombu/messaging.py", line 84, in __init__
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit self.revive(self._channel)
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/kombu/messaging.py", line 218, in revive
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit self.declare()
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/kombu/messaging.py", line 104, in declare
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit self.exchange.declare()
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/kombu/entity.py", line 166, in declare
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit nowait=nowait, passive=passive,
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/amqp/channel.py", line 613, in exchange_declare
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit self._send_method((40, 10), args)
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/amqp/abstract_channel.py", line 56, in _send_method
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit self.channel_id, method_sig, args, content,
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/amqp/method_framing.py", line 221, in write_method
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit write_frame(1, channel, payload)
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/amqp/transport.py", line 177, in write_frame
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit frame_type, channel, size, payload, 0xce,
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/eventlet/greenio.py", line 307, in sendall
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit tail = self.send(data, flags)
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/eventlet/greenio.py", line 293, in send
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit total_sent += fd.send(data[total_sent:], flags)
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit error: [Errno 32] Broken pipe
2014-09-19 15:58:42.807 29170 TRACE oslo.messaging._drivers.impl_rabbit
<182>Sep 19 15:58:42 node-5 nova-api 2014-09-19 15:58:42.819 29170 INFO oslo.messaging._drivers.impl_rabbit [req-408a15b9-532e-4748-a07e-770761bfedf5 ] Reconnecting to AMQP server on 192.168.0.5:5672
<182>Sep 19 15:58:42 node-5 nova-api 2014-09-19 15:58:42.821 29170 INFO oslo.messaging._drivers.impl_rabbit [req-408a15b9-532e-4748-a07e-770761bfedf5 ] Delaying reconnect for 1.0 seconds...
<182>Sep 19 15:58:46 node-5 nova-api 2014-09-19 15:58:46.763 29170 INFO oslo.messaging._drivers.impl_rabbit [req-408a15b9-532e-4748-a07e-770761bfedf5 ] Connected to AMQP server on 192.168.0.5:5672
<179>Sep 19 15:58:46 node-5 nova-api 2014-09-19 15:58:46.773 29170 ERROR oslo.messaging._drivers.impl_rabbit [req-408a15b9-532e-4748-a07e-770761bfedf5 ] Failed to consume message from queue: Socket closed
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit Traceback (most recent call last):
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/impl_rabbit.py", line 648, in ensure
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit return method(*args, **kwargs)
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/oslo/messaging/_drivers/impl_rabbit.py", line 737, in _consume
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit return self.connection.drain_events(timeout=timeout)
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/kombu/connection.py", line 279, in drain_events
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit return self.transport.drain_events(self.connection, **kwargs)
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/kombu/transport/pyamqp.py", line 91, in drain_events
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit return connection.drain_events(**kwargs)
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/amqp/connection.py", line 299, in drain_events
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit chanmap, None, timeout=timeout,
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/amqp/connection.py", line 362, in _wait_multiple
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit channel, method_sig, args, content = read_timeout(timeout)
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/amqp/connection.py", line 333, in read_timeout
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit return self.method_reader.read_method()
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit File "/usr/lib/python2.7/dist-packages/amqp/method_framing.py", line 189, in read_method
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit raise m
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit IOError: Socket closed
2014-09-19 15:58:46.773 29170 TRACE oslo.messaging._drivers.impl_rabbit
<182>Sep 19 15:58:46 node-5 nova-api 2014-09-19 15:58:46.778 29170 INFO oslo.messaging._drivers.impl_rabbit [req-408a15b9-532e-4748-a07e-770761bfedf5 ] Reconnecting to AMQP server on 192.168.0.5:5672
<182>Sep 19 15:58:46 node-5 nova-api 2014-09-19 15:58:46.780 29170 INFO oslo.messaging._drivers.impl_rabbit [req-408a15b9-532e-4748-a07e-770761bfedf5 ] Delaying reconnect for 1.0 seconds...
<182>Sep 19 15:58:49 node-5 nova-api 2014-09-19 15:58:49.519 29170 INFO oslo.messaging._drivers.impl_rabbit [req-408a15b9-532e-4748-a07e-770761bfedf5 ] Connected to AMQP server on 192.168.0.5:5672

Tags:

Roman Podoliaka (rpodolyaka) on 2014-09-20

Changed in mos:
status:	New → Triaged
importance:	Medium → Critical
importance:	Critical → High

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-09-20:

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/28770
DEB Repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-5.1-stable-28770/ubuntu

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-09-20:

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/28770
RPM Repository URL: http://osci-obs.vm.mirantis.net:82/centos-fuel-5.1-stable-28770/centos

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-09-20:

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/28770
DEB Repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-5.1-stable-28770/ubuntu

Revision history for this message

Vasilios Tzanoudakis (vtzanoudakis) wrote on 2014-09-22:

The problem still exists on the latest nightly iso. is there any fix yet?

Revision history for this message

Serg Melikyan (smelikyan) wrote on 2014-09-22:

There is a fix for this issue, we are working on testing that fix, should be release soon.

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-09-22:

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/28770
RPM Repository URL: http://osci-obs.vm.mirantis.net:82/centos-fuel-5.1-stable-28770/centos

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-09-22:

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/28770
DEB Repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-5.1-stable-28770/ubuntu

Revision history for this message

Vasilios Tzanoudakis (vtzanoudakis) wrote on 2014-09-22:

Is this pushed to nightly iso?

Revision history for this message

Serg Melikyan (smelikyan) wrote on 2014-09-23:

Unfortunately no, this will be pushed once commit will be tested and merged.

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-09-23:

#10

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/28770
DEB Repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-5.1-stable-28770/ubuntu

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-09-23:

#11

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/28770
RPM Repository URL: http://osci-obs.vm.mirantis.net:82/centos-fuel-5.1-stable/centos

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-09-23:

#12

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/28770
DEB Repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-5.1-stable/ubuntu

Revision history for this message

Tyler Wilson (loth) wrote on 2014-09-30:

#13

Is this scheduled to be commited to http://fuel-repository.mirantis.com/fwm/5.1.1/ubuntu/pool/main/ ?

Revision history for this message

Serg Melikyan (smelikyan) wrote on 2014-10-06:

#14

Tyler, it is already available in repository that you've mentioned

Revision history for this message

Dmitry Borodaenko (angdraug) wrote on 2014-10-10:

#15

Does 5.0.2 include AMQP heartbeat? If not, is this bug valid for 5.0.x?

Revision history for this message

Serg Melikyan (smelikyan) wrote on 2014-10-10:

#16

Dmitry, unfortunately no, this is not ported for 5.0.2

Revision history for this message

Serg Melikyan (smelikyan) wrote on 2014-10-10:

#17

Dmitry, we are working on porting fix for this issue to 5.0.3 and 6.0

Alexander Ignatov (aignatov) on 2014-10-13

tags:

added: scale

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-10-15:

#18

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/29966
DEB Repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-6.0-stable-29966/ubuntu

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-10-15:

#19

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/29966
RPM Repository URL: http://osci-obs.vm.mirantis.net:82/centos-fuel-6.0-stable-29966/centos

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-10-15:

#20

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/29965
RPM Repository URL: http://osci-obs.vm.mirantis.net:82/centos-fuel-5.0.3-stable-29965/centos

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-10-15:

#21

Package oslo.messaging has been built from changeset: http://gerrit.mirantis.com/29965
DEB Repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-5.0.3-stable-29965/ubuntu

Revision history for this message

OSCI Robot (oscirobot) wrote on 2014-10-20:

#22

Package oslo.messaging has been built from changeset: https://review.fuel-infra.org/120
DEB Repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-6.0-stable-120/ubuntu

wandk (wandk000) on 2014-11-06

information type:

Public → Public Security

Revision history for this message

Pavel Vaylov (pvaylov) wrote on 2014-12-11:

#24

Guys, do we have a manual how to fix existed 5.1 environment and direct download links for updated oslo messaging package ?

Revision history for this message

Igor Marnat (imarnat) wrote on 2014-12-11:

#25

Pavel, you can find this information in release notes for 5.1:
http://docs.mirantis.com/openstack/fuel/fuel-5.1/pdf/Mirantis-OpenStack-5.1-RelNotes.pdf

Just look for topic "OpenStack services report multiple AMQP reconnects in the logs" in known issues.

Revision history for this message

Alexander Bozhenko (alexbozhenko) wrote on 2014-12-17:

#26

Igor, version of document that you mentioned contains this text about the bug:

============
OpenStack services report multiple AMQP reconnects in the logs
nova-api and other services may call fork() soon after the process starts. This may lead to a situation when the
AMQP heartbeat sending thread is initialized and run in the context of the parent process, while the reply waiters
are added to the list in the child process. When this happens, the thread won't send any heartbeats and RabbitMQ
will close AMQP connections after timeout.
This problem is addressed in oslo.messaging packages from MOS 5.1.1 package repositories (CentOS, Ubuntu).
After installing these packages, restart the affected services. See LP1371723.
============

But current version of docs, updated for 5.1.1 (docs.mirantis.com/openstack/fuel/fuel-5.1/release-notes.html#openstack-bugs-are-fixed) has only this:
============
The Oslo messaging service had a bug that affected MOS HA environments. The bug could make OpenStack unstable; the problem got worse as the load increased. A large number of broken AMQP connections caused Oslo-related errors appear in different logs. See LP1371723.
============

So, instructions for those, who still use 5.1.0 is gone...

Revision history for this message

OSCI Robot (oscirobot) wrote on 2015-03-18:

#27

RPM package oslo.messaging has been built for project openstack/oslo.messaging
Package version == 1.8.0, package release == fuel6.1.mira10.git.873c247.acb3abf

Changeset: https://review.fuel-infra.org/4736
project: openstack/oslo.messaging
branch: master
author: Pekelny Ilya
committer: Pekelny Ilya
subject: rabbit: heartbeat implementation
status: patchset-created

Files placed on repository:
python-oslo-messaging-1.8.0-fuel6.1.mira10.git.873c247.acb3abf.noarch.rpm
python-oslo-messaging-doc-1.8.0-fuel6.1.mira10.git.873c247.acb3abf.noarch.rpm

NOTE: Changeset is not merged, created temporary package repository.
RPM repository URL: http://osci-obs.vm.mirantis.net:82/centos-fuel-master-4736/centos

Revision history for this message

OSCI Robot (oscirobot) wrote on 2015-03-18:

#28

DEB package oslo.messaging has been built for project openstack/oslo.messaging
Package version == 1.8.0, package release == fuel6.1~mira10+git.873c247.acb3abf

Files placed on repository:
python-oslo.messaging_1.8.0-fuel6.1~mira10+git.873c247.acb3abf_all.deb

NOTE: Changeset is not merged, created temporary package repository.
DEB repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-master-4736/ubuntu

Revision history for this message

OSCI Robot (oscirobot) wrote on 2015-03-18:

#29

RPM package oslo.messaging has been built for project openstack/oslo.messaging
Package version == 1.8.0, package release == fuel6.1.mira10.git.689b558.acb3abf

Files placed on repository:
python-oslo-messaging-1.8.0-fuel6.1.mira10.git.689b558.acb3abf.noarch.rpm
python-oslo-messaging-doc-1.8.0-fuel6.1.mira10.git.689b558.acb3abf.noarch.rpm

NOTE: Changeset is not merged, created temporary package repository.
RPM repository URL: http://osci-obs.vm.mirantis.net:82/centos-fuel-master-4736/centos

Revision history for this message

OSCI Robot (oscirobot) wrote on 2015-03-18:

#30

DEB package oslo.messaging has been built for project openstack/oslo.messaging
Package version == 1.8.0, package release == fuel6.1~mira10+git.689b558.acb3abf

Files placed on repository:
python-oslo.messaging_1.8.0-fuel6.1~mira10+git.689b558.acb3abf_all.deb

NOTE: Changeset is not merged, created temporary package repository.
DEB repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-master-4736/ubuntu

Revision history for this message

Vasilios Tzanoudakis (vtzanoudakis) wrote on 2015-03-18:

#31

Dear Team,

It is possible for those packages to be backported for MOS 5.1.1 too?

Thank you.

Revision history for this message

OSCI Robot (oscirobot) wrote on 2015-03-18:

#32

RPM package oslo.messaging has been built for project openstack/oslo.messaging
Package version == 1.8.0, package release == fuel6.1.mira10.git.b9e134d.acb3abf

Changeset: https://review.fuel-infra.org/4736
project: openstack/oslo.messaging
branch: master
author: Pekelny Ilya
committer: openstack-ci-mirrorer-jenkins
subject: rabbit: heartbeat implementation
status: patchset-created

Files placed on repository:
python-oslo-messaging-1.8.0-fuel6.1.mira10.git.b9e134d.acb3abf.noarch.rpm
python-oslo-messaging-doc-1.8.0-fuel6.1.mira10.git.b9e134d.acb3abf.noarch.rpm

NOTE: Changeset is not merged, created temporary package repository.
RPM repository URL: http://osci-obs.vm.mirantis.net:82/centos-fuel-master-4736/centos

Revision history for this message

OSCI Robot (oscirobot) wrote on 2015-03-18:

#33

RPM package oslo.messaging has been built for project openstack/oslo.messaging
Package version == 1.8.0, package release == fuel6.1.mira10

Files placed on repository:
python-oslo-messaging-1.8.0-fuel6.1.mira10.noarch.rpm
python-oslo-messaging-doc-1.8.0-fuel6.1.mira10.noarch.rpm

Changeset merged. Package placed on primary repository
RPM repository URL: http://osci-obs.vm.mirantis.net:82/centos-fuel-master/centos

Revision history for this message

OSCI Robot (oscirobot) wrote on 2015-03-18:

#34

DEB package oslo.messaging has been built for project openstack/oslo.messaging
Package version == 1.8.0, package release == fuel6.1~mira10

Files placed on repository:
python-oslo.messaging_1.8.0-fuel6.1~mira10_all.deb

Changeset merged. Package placed on primary repository
DEB repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-master/ubuntu

Revision history for this message

OSCI Robot (oscirobot) wrote on 2015-03-18:

#35

DEB package oslo.messaging has been built for project openstack/oslo.messaging
Package version == 1.8.0, package release == fuel6.1~mira10+git.b9e134d.acb3abf

Files placed on repository:
python-oslo.messaging_1.8.0-fuel6.1~mira10+git.b9e134d.acb3abf_all.deb

NOTE: Changeset is not merged, created temporary package repository.
DEB repository URL: http://osci-obs.vm.mirantis.net:82/ubuntu-fuel-master-4736/ubuntu

Revision history for this message

Dmitry Mescheryakov (dmitrymex) wrote on 2015-04-01:

#36

Vasilios, sorry, I've just noticed your comment. The fix is already included into 5.1.1. If you still see a similar issue, please file a bug for it.

Revision history for this message

Vasilios Tzanoudakis (vtzanoudakis) wrote on 2015-04-02:

#37

Dear Dmitry, just to check that i run the latest packages. Could you please verify which packages correct this bug?
It would be very helpful. thank you

Revision history for this message

Sean Murphy (murp) wrote on 2015-05-01:

#38

We have MOS 5.1.1 installed but we still see some behaviour as described here. Here are the relevant packages on our controller:

root@node-1:~# dpkg -l | grep nova-api
ii nova-api 1:2014.1.3-fuel5.1.1~mira3 OpenStack Compute - API frontend

root@node-1:~# dpkg -l | grep rabbit
ii rabbitmq-server 3.3.5-ubuntu3 AMQP server written in Erlang

We see issues that the rabbit closes connections to many of the processes (it seems many of the
nova-api processes); when there is new request to nova-api, it often has a broken pipe and then
it started a new connection to rabbitmq. So we have this sequence:

- rabbit kills connection to many nova-api processes due to heartbeat timeouts
- nova-api receives request
- nova-api tries to talk to rabbit but experiences broken pipe
- (many) nova-api processes restart communications with rabbit
- nova-api is able to then communicate

It does not have much of an impact in userland, but it's suboptimal from pov of keeping
clean logs.

We have MOS 5.1.1 installed but we still see some behaviour as described here. Here are the relevant packages on our controller:

root@node-1:~# dpkg -l | grep nova-api
ii  nova-api                            1:2014.1.3-fuel5.1.1~mira3                          OpenStack Compute - API frontend

root@node-1:~# dpkg -l | grep oslo
ii  python-oslo.config                  1:1.2.1-0ubuntu1~cloud0                             Common code for Openstack Projects (configuration API)
ii  python-oslo.i18n                    1.0.0-fuel5.1.1~mira1                               Oslo Internationalization Utilities - Python 2.x
ii  python-oslo.messaging               1.3.1-fuel5.1.1~mira0                               oslo messaging library
ii  python-oslo.rootwrap                1.0.0-0ubuntu2                                      Fine filtering of shell commands as 'root'
ii  python-oslo.serialization           1.0.0-fuel5.1.1~mira0                               utilities for serialization , especially JSON - Python 2.x
ii  python-oslo.utils                   1.0.0-fuel5.1.1~mira0                               set of utility functions for OpenStack - Python 2.x
ii  python-oslo.vmware                  0.2-0ubuntu1                                        oslo vmware library

root@node-1:~# dpkg -l | grep rabbit
ii  rabbitmq-server                     3.3.5-ubuntu3                                       AMQP server written in Erlang

It does not have much of an impact in userland, but it's suboptimal from pov of keeping
clean logs.

Revision history for this message

Alexander Bozhenko (alexbozhenko) wrote on 2015-05-01:

#39

@Sean, please teke a look at the following bug:
https://bugs.launchpad.net/fuel/+bug/1440018

You probably may want to backport scripts using that docs.

Revision history for this message

Sean Murphy (murp) wrote on 2015-05-04:

#40

@Alexander - thanks for that.

Revision history for this message

Sean Murphy (murp) wrote on 2015-05-04:

#41

@Alexander - it looks like that is more targetted at the HA context - we see the problem in a basic single controller context. Do you know of any processes/instructions for the non-HA context?

Thanks,
Seán.

Revision history for this message

Alexander Bozhenko (alexbozhenko) wrote on 2015-05-04:

#42

Probably Ilya Pekelny can comment on this...

Revision history for this message

JohnsonYi (yichengli) wrote on 2015-07-22:

#43

We faced the same issue on our MOS 6.0 environment, even I replaced the newest oslo.messaging 1.4.1 from MOS 6.1 to my MOS 6.0 environment, this issue came up some times, not only during reboot one controller node, but also when I try to create a new instance from horizon. The reconnect will be finished after 6~8 mins.

Does this issue also impact mos 6.1? Or any fix for oslo.messaging 1.4.1? Thanks in advance.

Revision history for this message

JohnsonYi (yichengli) wrote on 2015-07-22:

#44

I can reproduce the error by create new instance fron horizon, during instance "spawning", the error will come out until spawning finished. F.Y.I

lk (1415511065-f) on 2015-10-01

Changed in mos:
status:	Fix Committed → New
status:	New → Fix Committed

Revision history for this message

Jeremy Huylebroeck (jeremy-huylebroeck) wrote on 2015-11-07:

#45

Is there a work around without patching anything (restarting services/cleaning up database, disabling HA etc...)?

Revision history for this message

tangjinli (767844151-t) wrote on 2016-05-31:

#46

Revision history for this message

tangjinli (767844151-t) wrote on 2016-05-31:

#47

Download full text (27.9 KiB)

part of the log:
2016-05-20 09:27:44.163 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:27:59.164 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:28:14.165 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:28:17.235 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:28:17.637 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:28:17.638 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:28:19.290 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:28:29.166 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:28:32.564 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:28:44.167 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:28:59.168 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:29:14.169 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:29:18.236 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:29:18.627 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:29:18.628 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:29:20.310 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:29:29.170 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:29:32.563 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:29:44.171 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:29:59.172 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:30:14.173 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:30:19.236 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:30:19.642 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:30:19.643 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:30:21.282 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:30:29.174 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:30:34.507 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:30:44.175 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:30:59.176 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:31:14.178 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:31:21.234 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:31:21.622 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:31:21.623 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:31:23.311 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:31:29.179 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:31:35.509 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:31:44.180 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:31:59.181 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:32:14.182 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:32:23.230 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:32:23.619 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:32:23.620 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:32:25.233 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:32:29.183 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:32:37.524 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:32:44.184 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:32:59.185 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:33:14.186 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:33:24.231 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:33:24.642 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:33:24.643 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:33:26.480 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:33:29.187 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:33:38.579 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:33:44.188 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:33:59.190 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:34:14.191 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:34:26.230 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:34:26.633 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:34:26.633 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:34:28.101 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:34:29.192 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:34:38.512 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:34:44.193 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:34:59.194 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:35:14.195 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:35:27.236 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:35:27.629 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:35:27.629 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:35:29.161 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:35:29.195 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:35:38.526 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:35:44.196 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:35:59.197 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:36:14.199 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:36:27.233 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:36:27.628 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:36:27.629 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:36:29.074 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:36:29.200 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:36:39.517 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:36:44.200 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:36:59.201 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:37:14.202 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:37:27.241 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:37:27.637 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:37:27.638 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:37:29.203 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:37:29.293 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:37:41.511 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:37:44.204 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:37:59.205 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:38:14.206 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:38:28.235 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:38:28.625 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:38:28.626 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:38:29.207 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:38:30.051 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:38:42.510 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:38:44.208 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:38:59.209 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:39:14.210 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:39:29.211 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:39:30.236 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:39:30.642 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:39:30.642 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:39:32.312 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:39:43.516 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:39:44.212 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:39:59.213 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:40:14.214 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:40:29.215 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:40:31.229 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:40:31.630 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:40:31.630 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:40:33.317 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:40:44.216 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:40:45.508 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:40:59.217 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:41:14.218 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:41:29.219 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:41:31.231 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:41:31.595 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:41:31.596 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:41:32.983 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:41:44.220 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:41:45.513 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:41:59.221 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:42:14.222 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:42:29.223 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:42:32.230 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:42:32.624 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:42:32.625 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:42:34.409 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11
2016-05-20 09:42:44.224 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:42:46.516 5576 WARNING nova.compute.manager [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] While synchronizing instance power states, found 7 instances in the database and 2 instances on the hypervisor.
2016-05-20 09:42:59.225 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:43:14.226 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:43:29.227 5576 INFO oslo.messaging._drivers.impl_rabbit [-] A recoverable connection/channel error occurred, trying to reconnect: [Errno 32] Broken pipe
2016-05-20 09:43:34.229 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Auditing locally available compute resources for node vdi11
2016-05-20 09:43:34.695 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Total usable vcpus: 24, total allocated vcpus: 0
2016-05-20 09:43:34.696 5576 INFO nova.compute.resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Final resource view: name=vdi11 phys_ram=64389MB used_ram=12800MB phys_disk=199GB used_disk=70GB total_vcpus=24 used_vcpus=0 pci_stats=None
2016-05-20 09:43:36.428 5576 INFO nova.compute.cloudos_resource_tracker [req-73b5a98e-226a-4592-890a-e6e6f76f0090 - - - - -] Compute_service record updated for vdi11:vdi11

the code that the error occur:
   def _heartbeat_thread_job(self):
        """Thread that maintains inactive connections
        """
        while not self._heartbeat_exit_event.is_set():
            with self._connection_lock.for_heartbeat():

recoverable_errors = (
                    self.connection.recoverable_channel_errors +
                    self.connection.recoverable_connection_errors)

try:
                    try:
                        self._heartbeat_check()
                        # NOTE(sileht): We need to drain event to receive
                        # heartbeat from the broker but don't hold the
                        # connection too much times. In amqpdriver a connection
                        # is used exclusively for read or for write, so we have
                        # to do this for connection used for write drain_events
                        # already do that for other connection
                        try:
                            self.connection.drain_events(timeout=0.001)
                        except socket.timeout:
                            pass
                    except recoverable_errors as exc:
                        LOG.info(_LI("A recoverable connection/channel error "
                                     "occurred, trying to reconnect: %s"), exc)
                        self.ensure_connection()
                except Exception:
                    LOG.warning(_LW("Unexpected error during heartbeart "
                                    "thread processing, retrying..."))
                    LOG.debug('Exception', exc_info=True)

self._heartbeat_exit_event.wait(
                timeout=self._heartbeat_wait_timeout)
        self._heartbeat_exit_event.clear()

hello,
I meet one issue;this is strange.
The connecttion is ok, but the error occur when the rpc client sent the heartbeat. So it will reconnect.But the result is the same. The error do not occur at reconnection, and occur at checking the heartbeat when have ensured the connection.
The issue is frequent before we update the version, and now the issue still occur but not frequent
I do not the reason, Can I get some help from you?

Pooja Ghumre (pooja-9) on 2017-07-10

summary:

- To many reconnects in logs
+ Too many reconnects in logs

Report a bug

This report contains Public Security information

Everyone can see this security related information.

Duplicates of this bug

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

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