api servers hang with 100% CPU if syslog restarted

[George Shuklin]

Affected:

glance-api
glance-registry
neutron-server
nova-api

If service was configured to use rsyslog and rsyslog was restarted after API server started, it hangs on next log line with 100% CPU. If server have few workers, each worker will eat own 100% CPU share.

Steps to reproduce:
1. Configure syslog:
use_syslog=true
syslog_log_facility=LOG_LOCAL4
2. restart api service
3. restart rsyslog

Execute some command to force logging. F.e.: neutron net-create foo, nova boot, etc.

Expected result: normal operation

Actual result:
with some chance (about 30-50%) api server will hung with 100% CPU usage and will not reply to request.

Strace on hung service:

gettimeofday({1432827199, 745141}, NULL) = 0
poll([{fd=3, events=POLLOUT|POLLERR|POLLHUP}, {fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 2, 60000) = 1 ([{fd=3, revents=POLLOUT}])
sendto(3, "<151>keystonemiddleware.auth_token[12502]: DEBUG Authenticating user token __call__ /usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py:650\0", 154, 0, NULL, 0) = -1 ENOTCONN (Transport endpoint is not connected)
gettimeofday({1432827199, 745226}, NULL) = 0
poll([{fd=3, events=POLLOUT|POLLERR|POLLHUP}, {fd=5, events=POLLIN|POLLPRI|POLLERR|POLLHUP}], 2, 60000) = 1 ([{fd=3, revents=POLLOUT}])
sendto(3, "<151>keystonemiddleware.auth_token[12502]: DEBUG Authenticating user token __call__ /usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py:650\0", 154, 0, NULL, 0) = -1 ENOTCONN (Transport endpoint is not connected)
gettimeofday({1432827199, 745325}, NULL) = 0

Tested on:
nova, glance, neutron: 1:2014.2.3, Ubuntu version.

[Nobuto Murata (nobuto)]

It sounds similar with:
https://bugs.launchpad.net/ubuntu/+source/python-eventlet/+bug/1452312
https://github.com/eventlet/eventlet/issues/192

[George Shuklin (george-shuklin)]

May be. But it affects not glance only, but all other components of OS too.

[Nobuto Murata (nobuto)]

To be clear, python-eventlet is a library depended by nova, neutron, glance, cinder, etc. Proposed fix is available for testing/verification in Ubuntu 14.04 or later in bug #1452312.

[Stuart McLaren (stuart-mclaren)]

I think this is a duplicate of https://bugs.launchpad.net/bugs/1459726

[Stuart McLaren (stuart-mclaren)]

Oops, wrong link: https://bugs.launchpad.net/oslo.log/+bug/1076466

[Vil Surkin (vill-srk)]

Stuart, no, its new bug.

[Stuart McLaren (stuart-mclaren)]

@vill-srk

What is the difference between the two bugs? (One of the signatures of bug 1076466 was the cpu spinning at 100%).

Thanks.

[Vil Surkin (vill-srk)]

@stuart-mclaren, bug #1076466 was fixed (in oslo logging module). Now it's new problem with logging, but looks like it in python-eventlet library. We have installation on Juno and Trusty, code already have patches from #1076466, but it hang CPU anyway.

[Doug Hellmann (doug-hellmann)]

Bug #1076466 doesn't appear to have been fixed. The patch against the old incubated version of the code was abandoned, and I don't see a related fix in the oslo.log library version of the code.

[George Shuklin (george-shuklin)]

Yes, I think this is not a duplicate - #1076466 has been fixed already.

[George Shuklin (george-shuklin)]

I've just tried to use https://launchpad.net/ubuntu/+archive/primary/+files/python-eventlet_0.13.0-1ubuntu3.3_all.deb (proposed) and it helped.

We have two API servers, I've done experiment: one is trusty/juno-cloud-archive. One got update, second not.

Working:
python-eventlet 0.13.0-1ubuntu3.3

Broken:
python-eventlet 0.13.0-1ubuntu3.2~cloud0

After syslog restart few iteration of neutron net-create hang neutron-server with 100% CPU on broken node and works fine on the working. Same for glance-api/registry.

[Simon Pasquier (simon-pasquier)]

This looks similar to https://bugs.launchpad.net/oslo.log/+bug/1101404 also, isn't it?

[George Shuklin (george-shuklin)]

May be. I'm not sure. Anyway, this is not nova/glance/neutron bug, but python-eventlet, and it is mostly concerns for distributions, not for developers.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.