v5.0.1 is breaking Neutron functional job

[Rodolfo Alonso]

The Neutron functional job that uses oslo master versions is not working now. Reviewing the logs [0], what I suspect is that the problem is in oslo.log v5.0.1 is breaking the CI.

Error: https://paste.opendev.org/show/b9ly4v3mv84xnIKkbARH/

I've tested using the upper version limited by "requirements" (v5.0.0) and it's working. The only patch between both versions is [1]. It seems that this patch is opening files but not closing them. Eventually, the host reaches the limit of open files.

[0]https://ba79a5854b7bb6f2b1df-25f8dcd5db154e1632e2236aa5a8224a.ssl.cf1.rackcdn.com/863315/1/check/neutron-functional-with-oslo-master/e7b4d34/job-output.txt
[1]https://github.com/openstack/oslo.log/commit/94b9dc32ec1f52a582adbd97fe2847f7c87d6c17

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

I manually executed the tests in my env. What I found is this [1]. In particular I would like to focus on this:
ResourceWarning: Enable tracemalloc to get the object allocation traceback
Exception ignored in: <function PipeMutex.__del__ at 0x7f88df98c8b0>
Traceback (most recent call last):
  File "/opt/stack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/oslo_log/pipe_mutex.py", line 137, in __del__
    self.close()
  File "/opt/stack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/oslo_log/pipe_mutex.py", line 116, in close
    if self.wfd is not None:
AttributeError: 'PipeMutex' object has no attribute 'wfd'

This is another log captured during the execution of the Neutron functional jobs:
    Traceback (most recent call last):

      File "/opt/stack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/fixtures/fixture.py", line 196, in setUp
    self._setUp()

      File "/opt/stack/neutron/.tox/dsvm-functional/lib/python3.8/site-packages/fixtures/_fixtures/logger.py", line 107, in _setUp

      File "/usr/lib/python3.8/logging/__init__.py", line 1057, in __init__
                                                                                                                                                                                                                               ...

[Gorka Eguileor (gorka)]

Looks like the problem may be that my patch in oslo.logging didn't expect consumers of the library to call the setup method multiple times.

Neutron functional tests seem to do it: In BaseLoggingTestCase's setup it calls [1] base.setup_test_logging which in turn calls config.setup_logging() [2] which in turn calls logging.setup [3].

I think this may be fixed by modifying the `if eventlet` condition [4] to also check if the change has not already been made:

  if eventlet and logging.Handler.createLock != pipe_mutex.pipe_createLock:

I'm assuming the problem is that Python is not running the Garbage Collector fast enough to trigger the closing of the pipes [5].

[1]: https://github.com/openstack/neutron/blob/9e2a0ac058305dd16d6dedb883d305cd162f5fe4/neutron/tests/functional/base.py#L82

[2]: https://github.com/openstack/neutron/blob/9e2a0ac058305dd16d6dedb883d305cd162f5fe4/neutron/tests/base.py#L94

[3]: https://github.com/openstack/neutron/blob/9e2a0ac058305dd16d6dedb883d305cd162f5fe4/neutron/common/config.py#L118

[4]: https://github.com/openstack/oslo.log/blob/94b9dc32ec1f52a582adbd97fe2847f7c87d6c17/oslo_log/log.py#L276

[5]: https://github.com/openstack/oslo.log/blob/94b9dc32ec1f52a582adbd97fe2847f7c87d6c17/oslo_log/pipe_mutex.py#L125-L137

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Hi Gorka:

I'll try what you are suggesting for [4] and I'll test it in the Neutron patch.

Thanks.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/oslo.log/+/864018

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/oslo.log/+/864252

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/oslo.privsep/+/864254

[OpenStack Infra (hudson-openstack)]

Change abandoned by "Rodolfo Alonso <email address hidden>" on branch: master
Review: https://review.opendev.org/c/openstack/oslo.privsep/+/864209

[OpenStack Infra (hudson-openstack)]

Change abandoned by "Rodolfo Alonso <email address hidden>" on branch: master
Review: https://review.opendev.org/c/openstack/oslo.log/+/864018

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/oslo.log/+/864252
Committed: https://opendev.org/openstack/oslo.log/commit/de615d9370681a2834cebe88acfa81b919da340c
Submitter: "Zuul (22348)"
Branch: master

commit de615d9370681a2834cebe88acfa81b919da340c
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Nov 11 10:15:58 2022 +0100

    Make the eventlet logging fix execution conditional

    This patch changes the ``log.setup()`` signature to allow a kwarg
    that makes the eventlet logging fix conditional.

    Some libraries that import oslo.log, replace the logging locking
    handling with its own implementation. For example oslo.privsep
    replaces the logging handler with its own one [1], that allows the
    communication between the privileged daemon process and the service
    importing the library. This local handler clashes with the
    evenlet logging fix implemented in [2].

    [1]https://github.com/openstack/oslo.privsep/blob/1020c6fbf54f93cad9fa36b97bcd9cf75549984a/oslo_privsep/daemon.py#L579
    [2]https://review.opendev.org/c/openstack/oslo.log/+/852443

    Partial-Bug: #1995514
    Related-Bug: #1995091
    Change-Id: I4bbcfe7db6d75188e61b9084cb02b2dd2aaa0c76

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/oslo.privsep/+/864254
Committed: https://opendev.org/openstack/oslo.privsep/commit/c2b6df05e0c8bd2a34b2b7db1935ea605062e22c
Submitter: "Zuul (22348)"
Branch: master

commit c2b6df05e0c8bd2a34b2b7db1935ea605062e22c
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Nov 11 10:30:24 2022 +0100

    Setup logging without fixing evenlet logging

    Since [1], ``oslo_log.log.setup`` can be called without applying the
    fix for eventlet in native threads [2]. This fix clashes with the
    oslo.privsep logging handler that replaces the original one. This
    handler is implemented to allow the sync between the daemon process
    and the process making the privileged call.

    Once the oslo.log library version is bumped to 5.0.2, the try clause
    can be removed.

    [1]https://review.opendev.org/c/openstack/oslo.log/+/864252
    [2]https://review.opendev.org/c/openstack/oslo.log/+/852443

    Closes-Bug: #1995514
    Related-Bug: #1995091
    Change-Id: I7a4c55228064cb2dd4f4a359cdd81fd288baaf68

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.privsep 3.1.0 release.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/oslo.log/+/914790

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/oslo.log/+/914790
Committed: https://opendev.org/openstack/oslo.log/commit/142fde8224c8994b94518803fe5005cdeec6a37e
Submitter: "Zuul (22348)"
Branch: master

commit 142fde8224c8994b94518803fe5005cdeec6a37e
Author: Takashi Kajinami <email address hidden>
Date: Sun Mar 31 01:23:21 2024 +0900

    Apply eventlet workaround only once

    ... to avoid issues caused by setup method called multiple times.

    Closes-Bug: #1995514
    Change-Id: I125f7a8fa12f4d17af70987c20e5dedb14232d7b

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/2024.1
Review: https://review.opendev.org/c/openstack/oslo.log/+/915802