Using the asyncio hub on Openstack lead to threading errors

[4383]

On Openstack we recently made integration tests with the asyncio hub on Openstack devstask.
Those tests showed us threading issues when the asyncio hub is the hub in use in the stack:

https://review.opendev.org/c/openstack/devstack/+/914108

A living example of the observed error: https://zuul.opendev.org/t/openstack/build/ff9694b77a7943569f39cc850fad28f1/log/job-output.txt#11709

Here is an extract of the observed error, among other occurrences:

2024-03-25 16:04:04.521 | �[00;36mINFO keystone.common.fernet_utils [�[00;36m-�[00;36m] �[01;35m�[00;36mBecome a valid new key: /etc/keystone/fernet-keys/0�[00m�[00m
2024-03-25 16:04:04.699 | Exception ignored in: <function _removeHandlerRef at 0x7fc8ae830040>
2024-03-25 16:04:04.700 | Traceback (most recent call last):
2024-03-25 16:04:04.700 | File "/usr/lib/python3.10/logging/init.py", line 846, in _removeHandlerRef
2024-03-25 16:04:04.700 | File "/usr/lib/python3.10/logging/init.py", line 226, in _acquireLock
2024-03-25 16:04:04.700 | File "/usr/lib/python3.10/threading.py", line 164, in acquire
2024-03-25 16:04:04.700 | File "/opt/stack/data/venv/lib/python3.10/site-packages/eventlet/green/thread.py", line 36, in get_ident

We should notice that the eventlet version in use in this context is the version 0.35.1, which is the one currently defined in the Openstack upper-constraints https://opendev.org/openstack/requirements/src/branch/master/upper-constraints.txt#L165.

We are currently in a requirement freeze period. We will be able to upgrade to 0.35.2 or 0.36.0 in few days, and then rerun the test to see if one of recent patches merged on the eventlet side could fix the problem we observed.

I opened this github issue to track the problem.

[SeanMooney]

i can use depend on to pull in the latest 0.36.0 version so ill do that now

i will point out that there appears to be other unintended behavior

keystone does not use eventlet but defining EVENTLET_HUB=asyncio seams to have enabled it.

i would expect EVENTLET_HUB=asyncio to just set the default hub to use if the application then tried to use eventlet.

the fact that we are seeing /opt/stack/data/venv/lib/python3.10/site-packages/eventlet/green/thread.py in the trace is concerning because keystone is not monkypatching

i belive this is coming form oslo.cotext or oslo.log where its trying to get the current thread id for logging reasons.

[itamarst]

Setting a random environment variable on its own cannot make Python code be imported unless there's something like a .pth file, which eventlet does not have. So "does not use eventlet" must be inaccurate; perhaps a dependency is importing eventlet.

For example:

(py39) ~/devel/eventlet$ EVENTLET_HUB=asyncio python
Python 3.9.18 (main, Aug 25 2023, 13:20:14) 
[GCC 11.4.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import sys
>>> "eventlet" in sys.modules
False

[itamarst]

That being said, I do wonder how this is happening, given there does not appear to be monkey patching directly in this package. Not great if a library is monkeypatching :/

[4383]

I think we should look at https://opendev.org/openstack/oslo.log/commit/94b9dc32ec1f52a582adbd97fe2847f7c87d6c17

In this patch oslo.log import eventlet... so even if services are not using eventlet, eventlet is somehow imported, by a library...

[4383]

And this same patch tweak the logging module to use greenthreads. So the env is not directly monkey patched, but partially reshuffled at the oslo.log level, with the aim to use gthreads.

[4383]

An other patch has been submitted to make these changes optional https://opendev.org/openstack/oslo.log/commit/de615d9370681a2834cebe88acfa81b919da340c

But AFAICS, this feature is turned on by default.

[4383]

I'm not sure how we can disable that feature by using config file in a devstack environment.

@SeanMooney: Any idea? I'd suggest to disable this feature and then reran the devstack jobs of your DNM patch.

[4383]

Wait, in my previous analyze, I missed the condition based on eventlet = sys.modules.get('eventlet'). So yeah, something else seems to import eventlet before we reach that oslo.log point.

[4383]

May be imported at some point by oslo.utils's eventletutils module... and then the condition of oslo.log would then be fulfilled

https://opendev.org/openstack/oslo.utils/src/branch/master/oslo_utils/eventletutils.py
https://docs.openstack.org/oslo.utils/latest/reference/importutils.html#oslo_utils.importutils.try_import

[4383]

Apparently some people may have already faced this problem.
They proposed a related patch early today https://review.opendev.org/c/openstack/oslo.log/+/914190

Needs to re-review this proposed patch more carrefully.

[SeanMooney]

oh i also jsut created https://review.opendev.org/c/openstack/oslo.log/+/914246/1/oslo_log/log.py

but we coudl go with the other one both do the same thing

[4383]

FYI, Sean rebased the devstack env over the proposed oslo.log fix https://review.opendev.org/c/openstack/oslo.log/+/914190

https://review.opendev.org/c/openstack/devstack/+/914108/1..2

Related jobs who were previously broken have been retriggered, we will see if this oslo.log patch fix the error.
IMO this is not an eventlet bug but a bad usage of eventlet in the Openstack side.

I'll close this github issue and remove the asyncio and bug labels if the devstack is repaired by the oslo.log patch.

[4383]

The Openstack issue have been managed and seems now fixed

https://review.opendev.org/c/openstack/devstack/+/914108

I think we are now able to close this github issue.

Thanks everyone for your investigations.

[4383]

related to #432