Can't log from within tpool.execute

[smerritt]

If you try to log from within a function called by tpool.execute, there is a chance that the tpool thread never returns, and you see a stack trace like this one:

Traceback (most recent call last):
  File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 458, in fire_timers
    timer()
  File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/timer.py", line 58, in __call__
    cb(*args, **kw)
  File "/usr/local/lib/python2.7/dist-packages/eventlet/semaphore.py", line 147, in _do_acquire
    waiter.switch()
error: cannot switch to a different thread

This is because many logging handlers have mutexes that are threading._RLock objects, and Eventlet's replacement for thread.allocate_lock returns an eventlet.semaphore.Semaphore object, which does not work across different hubs in different pthreads.

Here's a small script to reproduce the issue:

#!/usr/bin/env python
#
# Demonstrates the crash with logging across pthreads
import eventlet.patcher
import eventlet.tpool
import logging
import random
import sys
import time

eventlet.patcher.monkey_patch()

logger = logging.getLogger("logger-test")
# This handler's .lock is a threading._RLock
logger.addHandler(logging.StreamHandler(sys.stdout))
logger.setLevel(logging.DEBUG)


def log_n_times(me, n):
    for x in range(n):
        logger.info("%s %d", me, x)
        time.sleep(random.random() * 0.01)


logger.info("starting")

greenthread = eventlet.spawn(log_n_times, 'greenthread', 50)
eventlet.tpool.execute(log_n_times, 'pthread', 50)
greenthread.wait()

logger.info("done")

The bug was originally found in Openstack Swift, and there's a better writeup at https://bugs.launchpad.net/swift/+bug/1710328 and a commit at openstack/swift@6d16079 that fixes the problem, but only for Swift, and not in a general way.

I'd like to figure out how to fix this in general, but I'm not sure how to proceed. Using a pipe-based mutex for all _RLock objects would work, but would be a very expensive fix. Perhaps just the locks in logging handlers, because those are global?

[temoto]

@smerritt thank you for this sad information.

Please try to replace your custom PipeMutex with eventlet.patcher.original('threading').Lock. If that works, I think we could include a custom green version of logging before actual problem is fixed.

Actual problem is, of course, green locks not working across OS threads.

[smerritt]

@temoto That produces correct results, but the performance is not good. My usual process is a WSGI server, so a bunch of greenthreads on the main OS thread, and a few other OS threads hidden inside eventlet.tpool. When a tpool thread has the lock and a main-OS-thread greenthread tries to get it, the whole main OS thread is blocked. The pipe gives me a file descriptor to wait on, so in this case, other greenthreads in the main OS thread can keep working.

[temoto]

Sorry, I didn't think enough before saying. Of course it will block all other greenthreads.

You know the tpool itself was using pipe for some time and then switched to local socket connection. I think with a little ugly creativity you could leverage that synchronisation.

lock = eventlet.tpool.Proxy(original_threading.Lock())

It's still slow as pipe, but at least you don't have to add a crutch pipemutex to code base.

[smerritt]

The proxied lock only works as long as you never run out of tpool threads.

Imagine you've got only two tpool threads, A and B, plus the main thread.

Thread A calls .acquire(), which goes into the tpool, and thread B picks it up, locks the lock, and goes back in the pool to do more work.

The next work item also needs the lock, so thread B calls .acquire(), the work item goes in the queue, and B blocks.

Thread A finishes with the lock, calls .release(), the work item goes in the queue, and A blocks.

[temoto]

Yes it's wasting tpool threads, but they're cheap and easy to increase.

[smerritt]

True, but you can exhaust any finite tpool.

Thread A has the lock. B wants it, calls acquire. Now A has it, B waits on C, C waits on the lock. Then D wants it: A has it, B waits on C, C waits on the lock, D waits on E, E waits on the lock.

You can fill up the tpool with these pretty quickly. All it takes is one thread to hold the lock for a long time.

[temoto]

@smerritt dear Sam, I'm confused, I would imagine A eventually release the lock and whole thing continues. It seems only harmful as starvation against other usages of tpool. But considering that tpool proxied lock was a dirty workaround in the first place, this hardly deserves our time?

Real solution is to make eventlet work across OS threads. Today I was thinking how to implement it, and probably general greenlet multiplexing on OS threads is a bit too complex for now. But special treatment of synchronisation primitives seems doable.

[smerritt]

If all the tpool threads are occupied, then the proxied call to release() will never happen, or at least that's what I thought. Perhaps if acquire() is proxied but release() is not, then it would all work.

You are, of course, correct that the answer is to make eventlet semaphores work across OS threads. I'm afraid I don't currently have any useful ideas to offer up in that domain.

[hemna]

This is still an open issue?

[temoto]

Reproduction script still fails, yes.

[ebolam]

Still an issue. Running across this issue with loguru when running flask in eventlet.

[frittentheke]

This is still an open issue?

Reproduction script still fails, yes.

We are regularly running into this issue with different OpenStack components:

nova-compute[6888]: Traceback (most recent call last):
nova-compute[6888]:   File "/usr/lib/python3/dist-packages/eventlet/hubs/hub.py", line 476, in fire_timers
nova-compute[6888]:     timer()
nova-compute[6888]:   File "/usr/lib/python3/dist-packages/eventlet/hubs/timer.py", line 59, in __call__
nova-compute[6888]:     cb(*args, **kw)
nova-compute[6888]:   File "/usr/lib/python3/dist-packages/eventlet/semaphore.py", line 152, in _do_acquire
nova-compute[6888]:     waiter.switch()
nova-compute[6888]: greenlet.error: cannot switch to a different thread

cinder-backup[3262663]: /usr/lib/python3/dist-packages/cinder/db/sqlalchemy/models.py:152: SAWarning: implicitly coercing SELECT object to scalar subquery; please use the .scalar_subquery() method to produce a scalar sub>
cinder-backup[3262663]:   last_heartbeat = column_property(
cinder-backup[3262663]: /usr/lib/python3/dist-packages/cinder/db/sqlalchemy/models.py:160: SAWarning: implicitly coercing SELECT object to scalar subquery; please use the .scalar_subquery() method to produce a scalar sub>
cinder-backup[3262663]:   num_hosts = column_property(
cinder-backup[3262663]: /usr/lib/python3/dist-packages/cinder/db/sqlalchemy/models.py:169: SAWarning: implicitly coercing SELECT object to scalar subquery; please use the .scalar_subquery() method to produce a scalar sub>
cinder-backup[3262663]:   num_down_hosts = column_property(
cinder-backup[3262663]: Traceback (most recent call last):
cinder-backup[3262663]:   File "/usr/lib/python3/dist-packages/eventlet/hubs/hub.py", line 476, in fire_timers
cinder-backup[3262663]:     timer()
cinder-backup[3262663]:   File "/usr/lib/python3/dist-packages/eventlet/hubs/timer.py", line 59, in __call__
cinder-backup[3262663]:     cb(*args, **kw)
cinder-backup[3262663]:   File "/usr/lib/python3/dist-packages/eventlet/semaphore.py", line 152, in _do_acquire
cinder-backup[3262663]:     waiter.switch()
cinder-backup[3262663]: greenlet.error: cannot switch to a different thread

I understand that there was a fix done at least to the oslo.log https://review.opendev.org/c/openstack/oslo.log/+/852443 which is available with >5.3.x so the Bobcat release, which avoids running into this issue when logging.

Apart from fixing the root cause (if even possible or attempted) in eventlet or OpenStack migrating to asyncio (https://review.opendev.org/c/openstack/governance/+/902585) I was simply wondering if

a) Can the python process be made to crash / exit properly. Currently a process that runs into this issue becomes somewhat of a zombie. This makes recognizing this condition and triggering a restart (systemd, container runtime, ...) much more difficult.

b) If there is any more details / log that could be produced with this traceback to allow finding and fixing the calls that lead to the greenlet.error in the first place. I suppose there are more reasons this can happen than the one in oslo.log?

[4383]

Hello @frittentheke,

Concerning "b", in short term perspective, I think a way to retrieve this kind of details could be to use the debug module of eventlet (https://eventlet.readthedocs.io/en/latest/modules/debug.html) and even maybe, when my patch will be merged and released (#926), to start an eventlet interactive backdoor on the process in trouble, and see what happens in the hub.

As this problem feels like a race condition issue, another short term option would be to use the ebpf/bcc deadlock module to identify where the deadlock is located. https://github.com/iovisor/bcc/blob/master/tools/deadlock_example.txt

Concerning "a" for now I've no response. I'll back later if I've things to share with you concerning that point.

[frittentheke]

Concerning "b", in short term perspective, I think a way to retrieve this kind of details could be to use the debug module of eventlet (https://eventlet.readthedocs.io/en/latest/modules/debug.html) and even maybe, when my patch will be merged and released (#926), to start an eventlet interactive backdoor on the process in trouble, and see what happens in the hub.
As this problem feels like a race condition issue, another short term option would be to use the ebpf/bcc deadlock module to identify where the deadlock is located. https://github.com/iovisor/bcc/blob/master/tools/deadlock_example.txt

Thanks @4383 for those ideas. While I understand the goal is to replace eventlet, it's still somewhat important to have it produce more debug information out of the box when reading this "deadlock" state. How else would someone be able to fix certain usage pattern if there is no indication which code paths caused it.

Concerning "a" for now I've no response. I'll back later if I've things to share with you concerning that point.

That would be awesome. Having processes or whole components not fail cleanly is the worst in distributed systems :-)

[4383]

See if you can start an eventlet backdoor https://eventlet.readthedocs.io/en/latest/modules/backdoor.html

It would require a process restart, unfortunately I think you will loose the context of the bug, but you can wait to see if you reproduce it, and, then, jump into that backdoor for further investigations.

Our new maintenance policy is not against adding some debug capabilities. If you find useful info and new debug opportunities, then do not hesitate to propose a patch to share it with the community. We will be happy to review it and to propose it "out of the box".

On my side I'll try to find some spare time to play with the inital reproducer and see if it is possible to increase debug details to help developer catch up this kind of bug. But I should admit that's not my top priority for now.

[frittentheke]

@4383 thanks again for your time and help!

Our new maintenance policy is not against adding some debug capabilities. If you find useful info and new debug opportunities, then do not hesitate to propose a patch to share it with the community. We will be happy to review it and to propose it "out of the box".

I would if I knew more about how eventlet works.

On my side I'll try to find some spare time to play with the inital reproducer and see if it is possible to increase debug details to help developer catch up this kind of bug. But I should admit that's not my top priority for now.

That would be awesome. If you kindly have a look at my comment https://bugs.launchpad.net/octavia/+bug/2039346/comments/14 about all the Openstack daemons we have throwing these greenlet.error: cannot switch to a different thread errors.

That launchpad bug is about an issue in oslo.log which apparently should not even exist in our Yoga release installation.
So we are again clueless what could be the cause.

[4383]

@frittentheke: oh ok. So I didn't make the link between this oslo.log problem and your gthread problem. I don't know why oslo.log is not fixed on zed.

Just to be sure, you observed this behavior on yoga, exact?

[4383]

Well, I think Openstack have many problems here:

1. oslo.log lack of the original fix on zed, yoga https://opendev.org/openstack/oslo.log/commit/94b9dc32ec1f52a582adbd97fe2847f7c87d6c17 Hence, leading you to observe the cannot switch non sense.
2. if this fix is applied to these stable branches, then, it should be followed by an other backport of https://review.opendev.org/c/openstack/oslo.log/+/914190 on these stable branches too.

In other words, you actually suffers from incomplete backports.

[4383]

@frittentheke: I'd suggest to you to reach Daniel (damani), or Takashi (tkajinam) on the openstack oslo channel. I think they would be happy to help you to finalize these incomplete backports.

[frittentheke]

Just to be sure, you observed this behavior on yoga, exact?

Yes @4383, we run Yoga using Ubuntu Cloud Archive packages on 22.04 LTS.

But according to Takashi in https://bugs.launchpad.net/octavia/+bug/2039346/comments/10 the issue should not exist on Zed? Or is he mistaken and these fixed actually have be backported further?

[4383]

I think the problem is that zed and yoga do not contains (at least) https://opendev.org/openstack/oslo.log/commit/94b9dc32ec1f52a582adbd97fe2847f7c87d6c17

The other patch is the fix to solve an other issue introduced by https://opendev.org/openstack/oslo.log/commit/94b9dc32ec1f52a582adbd97fe2847f7c87d6c17 (the same patch). But in all case IMO I think we need this fix and its parent fixes (the childrens).

[4383]

So, in order, I think we these patches should be backported to zed and yoga:

1. https://opendev.org/openstack/oslo.log/commit/94b9dc32ec1f52a582adbd97fe2847f7c87d6c17
2. https://opendev.org/openstack/oslo.log/commit/de615d9370681a2834cebe88acfa81b919da340c
3. https://review.opendev.org/c/openstack/oslo.log/+/914190

[SeanMooney]

while that will work on the epolls hub it wont work on the asyncio hub as
this is not supported https://review.opendev.org/c/openstack/oslo.log/+/852443/1/oslo_log/pipe_mutex.py#60

calling eventlet.debug.hub_prevent_multiple_readers(False) raises

RuntimeError("Multiple readers are not yet supported by asyncio hub")

so while a backport could be useful for older release like zed and yoga

the pipemutext impplenation in oslo log is going to need to be updated for the new asyncio hub.

you can see an example of the failure message you will get if you try to use both together

https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_130/914108/5/check/tempest-full-py3/130576a/controller/logs/screen-n-api.txt

[4383]

From an eventlet perspective we won't support that "multiple readers" nonsense (in the Asyncio hub):

#874

Openstack deliverables may have to consider using dup() with file descriptor (https://www.man7.org/linux/man-pages/man2/dup.2.html).

[4383]

IMO this "multiple readers" feature comes from a bad design.
If Openstack deliverables are migrated to asyncio, the design will differ and I don't think we will have to rely on such functionality.

If oslo.log is migrated is async design would be refactored:

• https://docs.python.org/3/library/asyncio-dev.html#logging
• https://docs.python.org/3/howto/logging-cookbook.html#blocking-handlers

Surely would allowing us to bypass this "multiple readers" things.

[4383]

I'd rather suggest that we rely on socket.fromfd and os.dup to move away from the "multiple readers" on Openstack:

• https://docs.python.org/3/library/socket.html#socket.fromfd
• https://docs.python.org/3/library/os.html#os.dup

Or something like that.

[SeanMooney]

Just keep in mind that migration to asynscio will take 3-4 release and druing that time we will need to support running with either hub. There has not been a community agreement to move to explicit async yet either.

If using dup and socket.fromfd can be hidden within oslo.log that is fine but if that would require change to the projects that use oslo.log that's problematic

[frittentheke]

There has not been a community agreement to move to explicit async yet either.

Discussion about this is at https://review.opendev.org/c/openstack/governance/+/902585

[SeanMooney]

Yep but that has not been approved and it may be rejected. There is a lot of work that needs to be done to socialise that proposal and get buy in from all the project that currently use eventlets. It's unlikely that projects like nova will invest time in adopting explicit async in 2024.2 until we have time to consider the detailed implementation aspect for our project. I may do some pocs, but one of the theme for this cycles ptg is likely to be completing ongoing work form last cycle and focusing on maintenance and tech debt. Changing the threading model does not fit with that theme.
With that said I'm looking forward to discussing this at the ptg.

[4383]

Just keep in mind that migration to asynscio will take 3-4 release and druing that time we will need to support running with either hub. There has not been a community agreement to move to explicit async yet either.

If using dup and socket.fromfd can be hidden within oslo.log that is fine but if that would require change to the projects that use oslo.log that's problematic

I think we are all aware that the migration will take a couple of Openstack release, even possibly more than 4 releases...

If "multiple readers" hack come from libs, like oslo.log, then, I think it should be also possible to remove that hack at the lib level. It would be also possible to implement a kind of log feeder threads as Dan suggested on irc. Hence allowing top layers to enable the asyncio hub. This is the oslo.log use case.

Else, if the "multiple readers" hack is located at the service level, then this service could remains to use the epolls hub giving time to solve this problem at the service level. This is the swift use case.

[4383]

Concerning the PTG, I won't be around during this period, so if a discussion happen I won't join that discussion. Feel free to trigger one. I could follow them asynchronously...

Concerning myself, I'm not convinced that a face to face discussion would allow to have a better and efficient discussion than the one made through write up and proposal. Written exchange leave more rooms for better understanding and thinking. That's my point of view.

[4383]

The writings remain, the words fly away...