leaked threads run after test case teardown causing intermittent functional test failures

It seems it happens pretty frequently on the gate[1]. I run the whole functional suit locally for days with random ordering but I was not able to reproduce it. So it is really hard to figure out what happens.

The first exception nova.exception.UnexpectedResourceProviderNameForPCIRequest is expected that is part of the test case. The the logs shows that we reverted the allocation in placement as the VM creation is failed due to the first exception.

The I see the following from the stack trace

LOG.warning("Failed to revert task state for instance.

So we end up at[2]. Then the compute thread seems to end. Then the parallel conductor thread times out in self.conductor_compute_rpcapi.build_instances:

File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/_drivers/impl_fake.py", line 213, in _send
    raise oslo_messaging.MessagingTimeout(
oslo_messaging.exceptions.MessagingTimeout: No reply on topic conductor

But it seems that at that point DB was already deleted by the test env leading to errors like:

sqlite3.OperationalError: no such table: instance_faults

I don't see how this can be timing related, but other then having some kind of race condition between the compute and the conductor I have no other idea.

[1] https://paste.opendev.org/show/809926/
[2] https://github.com/openstack/nova/blob/fdfdba265833d237e22676f9a223ab8ca0fe1e03/nova/compute/manager.py#L183

On the timing:
The successful runs on the gate takes 3-7 seconds, the failed runs takes 4-6 seconds. So there is no big timing difference.

This is a reschedule in the stack trace[1]:

File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 2263, in _do_build_and_run_instance

Which does not happen in a successful test case run. So I have to figure out why and how we can hit re-schedule.

https://github.com/openstack/nova/blob/fdfdba265833d237e22676f9a223ab8ca0fe1e03/nova/compute/manager.py#L2263-L2268

looking at the logs we booted on host1 then sheleved and then shelve offloaded.

2021-10-08 01:20:33.107782 | ubuntu-focal | 2021-10-08 01:20:30,613 INFO [nova.scheduler.host_manager] Host filter only checking host host1 and node host1
2021-10-08 01:20:33.107801 | ubuntu-focal | 2021-10-08 01:20:30,628 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/06aab374-ae34-4223-b31d-ba1558efa2ac" status: 200 len: 19 microversion: 1.28
2021-10-08 01:20:33.107819 | ubuntu-focal | 2021-10-08 01:20:30,676 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/06aab374-ae34-4223-b31d-ba1558efa2ac" status: 204 len: 0 microversion: 1.36
2021-10-08 01:20:33.107837 | ubuntu-focal | 2021-10-08 01:20:30,873 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/e11c9de0-4624-49ef-835c-a56da97a5f68" status: 200 len: 890 microversion: 1.14
2021-10-08 01:20:33.107855 | ubuntu-focal | 2021-10-08 01:20:30,881 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/06aab374-ae34-4223-b31d-ba1558efa2ac" status: 200 len: 644 microversion: 1.28
2021-10-08 01:20:33.107886 | ubuntu-focal | 2021-10-08 01:20:30,885 INFO [nova.compute.claims] Claim successful on node host1
2021-10-08 01:20:33.107905 | ubuntu-focal | 2021-10-08 01:20:31,138 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/06aab374-ae34-4223-b31d-ba1558efa2ac" status: 200 len: 1942 microversion: 2.90 time: 0.146510
2021-10-08 01:20:33.107924 | ubuntu-focal | 2021-10-08 01:20:31,145 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor.
2021-10-08 01:20:33.107942 | ubuntu-focal | 2021-10-08 01:20:31,187 INFO [nova.compute.manager] Took 0.33 seconds to build instance.
2021-10-08 01:20:33.107960 | ubuntu-focal | 2021-10-08 01:20:31,231 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'host1'. Re-created its InstanceList.
2021-10-08 01:20:33.107979 | ubuntu-focal | 2021-10-08 01:20:31,677 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/06aab374-ae34-4223-b31d-ba1558efa2ac" status: 200 len: 2436 microversion: 2.90 time: 0.033292
2021-10-08 01:20:33.107997 | ubuntu-focal | 2021-10-08 01:20:31,688 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/06aab374-ae34-4223-b31d-ba1558efa2ac" status: 200 len: 548 microversion: 1.0
2021-10-08 01:20:33.108015 | ubuntu-focal | 2021-10-08 01:20:31,789 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/servers/06aab374-ae34-4223-b31d-ba1558efa2ac/action" status: 202 len: 0 microversion: 2.90 time: 0.097403
2021-10-08 01:20:33.108033 | ubuntu-focal | 2021-10-08 01:20:31,825 INFO [nova.compute.manager] Shelving
2021-10-08 01:20:33.108060 | ubuntu-focal | 2021-10-08 01:20:31,828 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/06aab374-ae34-4223-b31d-ba1558efa2ac" status: 200 len: 2442 microversion: 2.90 time: 0.034799
2021-10-08 01:20:33.108080 | ubuntu-focal | 2021-10-08 01:20:31,885 INFO [nova.compute.manager] Shelve offloading
2021-10-08 01:20:33.108098 | ubuntu-focal | 2021-10-08 01:20:31,911 INFO [placement.requestlog] 127.0.0.1 "DELETE /placement/allocations/06aab374-ae34-4223-b31d-ba1558efa...

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/nova/+/813674

I managed to create a stable reproduction locally. \o/

1) duplicate the failing tests

diff --git a/nova/tests/functional/test_servers_resource_request.py b/nova/tests/functional/test_servers_resource_request.py
index e2746b3669..d678067c18 100644
--- a/nova/tests/functional/test_servers_resource_request.py
+++ b/nova/tests/functional/test_servers_resource_request.py
@@ -2572,6 +2572,18 @@ class ServerMoveWithPortResourceRequestTest(
         self._delete_server_and_check_allocations(
             server, qos_normal_port, qos_sriov_port)

+ def test_unshelve_offloaded_server_with_qos_port_pci_update_fails0(self):
+ self.test_unshelve_offloaded_server_with_qos_port_pci_update_fails()
+
+ def test_unshelve_offloaded_server_with_qos_port_pci_update_fails1(self):
+ self.test_unshelve_offloaded_server_with_qos_port_pci_update_fails()
+
+ def test_unshelve_offloaded_server_with_qos_port_pci_update_fails2(self):
+ self.test_unshelve_offloaded_server_with_qos_port_pci_update_fails()
+
+ def test_unshelve_offloaded_server_with_qos_port_pci_update_fails3(self):
+ self.test_unshelve_offloaded_server_with_qos_port_pci_update_fails()
+

2) run tox with tox -e functional-py38 "test_description_errors|test_unshelve_offloaded_server_with_qos_port_pci_update_fails" -- --serial

This make one of the test_unshelve_offloaded_server_with_qos_port_pci_update_fails test case fail with the reported error.

What I know so far:
* nova.tests.functional.test_servers.ServersTestV219.test_description_errors() starts a new instance but does not wait for it to become ACTIVE. The test case passes and finishes.

* But the build_and_run_instance RPC call still runs in compute service in a greenlet building up the instance. The service.kill at the end of the test case does not kill the running / waiting greenlets. I proved this by dumping a gmr at the end of the test run after the service.kill was called by the Fixture.cleanup. The build_and_run_instance greenlet was visible there.

* Still other fixture cleanup drops the database from behind the compute service. This leads to ComputeNodeNotFound error. You can see this by simply adding a self.fail() at the end of test_description_errors test case and run it. There will be ComputeNodeNotFound in the logs.

* After test_description_errors passes the test executor runs the next test cases

* After ~60 seconds an RPC timeout happens in the original greenlet from test_description_errors() and it *somehow* interferes with the currently running test making that to fail.

What I don't know yet is what is the way of the interference.

I know now what it the global that facilitate the effect between the two test cases.

When a versioned notification is emitted the code in [1] calls the nova.rpc.get_versioned_notifier() which uses the global NOTIFIER[2] from the rpc module. This global is properly reset between tests, but still if the first testcase runs [1] 60 seconds after the testcase is finished, another testcase already re-initialized the NOTIFIER with a valid FakeVersionedNotifier that can be used to deliver notifications. In this case the first test case delivers a notification to the later testcase making that to fail.

[1] https://github.com/openstack/nova/blob/50fdbc752a9ca9c31488140ef2997ed59d861a41/nova/notifications/objects/base.py#L211
[2] https://github.com/openstack/nova/blob/50fdbc752a9ca9c31488140ef2997ed59d861a41/nova/rpc.py#L239

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/nova/+/814036

Change abandoned by "Balazs Gibizer <email address hidden>" on branch: master
Review: https://review.opendev.org/c/openstack/nova/+/813674
Reason: fix is up in https://review.opendev.org/c/openstack/nova/+/814036

Reviewed: https://review.opendev.org/c/openstack/nova/+/814036
Committed: https://opendev.org/openstack/nova/commit/61fc81a6761d34afdfc4a6d1c4c953802fd8a179
Submitter: "Zuul (22348)"
Branch: master

commit 61fc81a6761d34afdfc4a6d1c4c953802fd8a179
Author: Balazs Gibizer <email address hidden>
Date: Thu Oct 14 18:09:18 2021 +0200

    Prevent leaked eventlets to send notifications

    In out functional tests we run nova services as eventlets. Also those
    services can spawn there own eventlets for RPC or other parallel
    processing. The test case executor only sees and tracks the main
    eventlet where the code of the test case is running. When that is
    finishes the test executor considers the test case to be finished
    regardless of the other spawned eventlets. This could lead to leaked
    eventlets that are running in parallel with later test cases.

    One way that it can cause trouble is via the global variables in
    nova.rpc module. Those globals are re-initialized for each test case so
    they are not directly leaking information between test cases. However if
    a late eventlet calls nova.rpc.get_versioned_notifier() it will get a
    totally usable FakeVersionedNotifier object regardless of which test
    case this notifier is belongs to or which test case the eventlet belongs
    to. This way the late eventlet can send a notification to the currently
    running test case and therefore can make it fail.

    The current case we saw is the following:

    1) The test case
      nova.tests.functional.test_servers.ServersTestV219.test_description_errors
      creates a server but don't wait for it to reach terminal state (ACTIVE
      / ERROR). This test case finishes quickly but leaks running eventlets
      in the background waiting for some RPC call to return.
    2) As the test case finished the cleanup code deletes the test case
       specific setup, including the DB.
    3) The test executor moves forward and starts running another test case
    4) 60 seconds later the leaked eventlet times out waiting for the RPC
       call to return and tries doing things, but fails as the DB is already
       gone. Then it tries to report this as an error notification. It calls
       nova.rpc.get_versioned_notifier() and gets a fresh notifier that is
       connected to the currently running test case. Then emits the error
       notification there.
    5) The currently running test case also waits for an error notification
       to be triggered by the currently running test code. But it gets the
       notification form the late eventlet first. As the content of the
       notification does not match with the expectations the currently
       running test case fails. The late eventlet prints a lot of
       error about the DB being gone making the troubleshooting pretty hard.

    This patch proposes a way to fix this by marking each eventlet at spawn
    time with the id of the test case that was directly or indirectly
    started it.

    Then when the NotificationFixture gets a notification it compares the
    test case id stored in the calling eventlet with the id of the test case
    in...

Fix proposed to branch: stable/xena
Review: https://review.opendev.org/c/openstack/nova/+/816487

Reviewed: https://review.opendev.org/c/openstack/nova/+/816487
Committed: https://opendev.org/openstack/nova/commit/f24e0c1da2c099609388555091d987b8807b5f0d
Submitter: "Zuul (22348)"
Branch: stable/xena

commit f24e0c1da2c099609388555091d987b8807b5f0d
Author: Balazs Gibizer <email address hidden>
Date: Thu Oct 14 18:09:18 2021 +0200

    Prevent leaked eventlets to send notifications

    In out functional tests we run nova services as eventlets. Also those
    services can spawn there own eventlets for RPC or other parallel
    processing. The test case executor only sees and tracks the main
    eventlet where the code of the test case is running. When that is
    finishes the test executor considers the test case to be finished
    regardless of the other spawned eventlets. This could lead to leaked
    eventlets that are running in parallel with later test cases.

    One way that it can cause trouble is via the global variables in
    nova.rpc module. Those globals are re-initialized for each test case so
    they are not directly leaking information between test cases. However if
    a late eventlet calls nova.rpc.get_versioned_notifier() it will get a
    totally usable FakeVersionedNotifier object regardless of which test
    case this notifier is belongs to or which test case the eventlet belongs
    to. This way the late eventlet can send a notification to the currently
    running test case and therefore can make it fail.

    The current case we saw is the following:

    1) The test case
      nova.tests.functional.test_servers.ServersTestV219.test_description_errors
      creates a server but don't wait for it to reach terminal state (ACTIVE
      / ERROR). This test case finishes quickly but leaks running eventlets
      in the background waiting for some RPC call to return.
    2) As the test case finished the cleanup code deletes the test case
       specific setup, including the DB.
    3) The test executor moves forward and starts running another test case
    4) 60 seconds later the leaked eventlet times out waiting for the RPC
       call to return and tries doing things, but fails as the DB is already
       gone. Then it tries to report this as an error notification. It calls
       nova.rpc.get_versioned_notifier() and gets a fresh notifier that is
       connected to the currently running test case. Then emits the error
       notification there.
    5) The currently running test case also waits for an error notification
       to be triggered by the currently running test code. But it gets the
       notification form the late eventlet first. As the content of the
       notification does not match with the expectations the currently
       running test case fails. The late eventlet prints a lot of
       error about the DB being gone making the troubleshooting pretty hard.

    This patch proposes a way to fix this by marking each eventlet at spawn
    time with the id of the test case that was directly or indirectly
    started it.

    Then when the NotificationFixture gets a notification it compares the
    test case id stored in the calling eventlet with the id of the test case
 ...

This issue was fixed in the openstack/nova 24.1.0 release.

This issue was fixed in the openstack/nova 25.0.0.0rc1 release candidate.

I'm not totally sure but I think I might have seen this again today in the nova-tox-functional-py38 job[1]:

2022-03-24 05:08:04,163 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/0606b03e-f05f-407c-9fd8-33a8d673e2f4" status: 200 len: 2147 microversion: 2.90 time: 0.028787
2022-03-24 05:08:04,193 ERROR [root] Original exception being dropped: ['Traceback (most recent call last):\n', ' File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/_drivers/impl_fake.py", line 207, in _send\n reply, failure = reply_q.get(timeout=timeout)\n', ' File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/eventlet/queue.py", line 322, in get\n return waiter.wait()\n', ' File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/eventlet/queue.py", line 141, in wait\n return get_hub().switch()\n', ' File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/eventlet/hubs/hub.py", line 313, in switch\n return self.greenlet.switch()\n', '_queue.Empty\n', '\nDuring handling of the above exception, another exception occurred:\n\n', 'Traceback (most recent call last):\n', ' File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 201, in decorated_function\n return function(self, context, *args, **kwargs)\n', ' File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 8969, in _post_live_migration\n self._update_scheduler_instance_info(ctxt, instance)\n', ' File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 2109, in _update_scheduler_instance_info\n self.query_client.update_instance_info(context, self.host,\n', ' File "/home/zuul/src/opendev.org/openstack/nova/nova/scheduler/client/query.py", line 69, in update_instance_info\n self.scheduler_rpcapi.update_instance_info(context, host_name,\n', ' File "/home/zuul/src/opendev.org/openstack/nova/nova/scheduler/rpcapi.py", line 174, in update_instance_info\n return cctxt.cast(ctxt, \'update_instance_info\', host_name=host_name,\n', ' File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/fixtures/_fixtures/monkeypatch.py", line 89, in avoid_get\n return captured_method(*args, **kwargs)\n', ' File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/rpc/client.py", line 189, in call\n result = self.transport._send(\n', ' File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/transport.py", line 123, in _send\n return self._driver.send(target, ctxt, message,\n', ' File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/_drivers/impl_fake.py", line 222, in send\n return self._send(target, ctxt, message, wait_for_reply, timeout,\n', ' File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/_drivers/impl_fake.py", line 213, in _send\n raise oslo_messa...

@Melanie: nice catch. It is similar as it seems a long(er) running thread, the _live_migration_monitor, keeps running after the actual test that started it has already finished. Then when the monitor awakes and try to record an instance fault that fails as the test cleanup already removed the DB under it. At least I was able to decode that much so far from the stack trace. I will keep digging this...

I managed to reproduce the issue once (in ~20 runs) locally with some extra print statements but no breakthrough so far.

[1] run log https://paste.ubuntu.com/p/rf3mpgXhtc/
[2] test case list used in the run https://paste.opendev.org/show/bITh68wTY3XNq3jdLy3h/

one more reproduction: https://paste.ubuntu.com/p/svZTwCWT25/ It shows that the test_case_id propagation does not work in this case so the original fix is not effective in this case https://review.opendev.org/c/openstack/nova/+/814036/1/nova/tests/fixtures/nova.py#1527

Another hit in https://review.opendev.org/c/openstack/nova/+/823229 with logs: https://zuul.opendev.org/t/openstack/build/956bd217bbf04d97bfed9479ee7bbc75/log/job-output.txt#3497

The common thing in the new hits is that the libvirt monitoring thread is leaked. Unfortunately I have no time at the moment to dig more. So I made a TODO to look back later.

I looked at this for awhile trying to find if there's some way we could reduce the number of leaked threads, since killing them (naked greenlet) is not always possible as evidenced by gibi's abandoned patch [1] and some similar things I have tried locally since.

I noticed that when the nova-compute service is stopped by calling stop(), the part that cleans up live migrations in the thread pool uses wait=False [2]:

    def cleanup_host(self):
        self.driver.register_event_listener(None)
        self.instance_events.cancel_all_events()
        self.driver.cleanup_host(host=self.host)
        self._cleanup_live_migrations_in_pool()

    def _cleanup_live_migrations_in_pool(self):
        # Shutdown the pool so we don't get new requests.
        self._live_migration_executor.shutdown(wait=False)

which "If True then shutdown will not return until all running futures have finished executing and the resources used by the executor have been reclaimed." [3]. So wait=False will move on even while running futures are still executing.

I wondered if a patch like the following might reduce the chances of a leaked greenlet from a previous test running during a new test:

diff --git a/nova/test.py b/nova/test.py
index a6449c01f0..69b9d06cdc 100644
--- a/nova/test.py
+++ b/nova/test.py
@@ -37,6 +37,7 @@ import pprint
 import sys

 import fixtures
+import futurist
 import mock
 from oslo_cache import core as cache
 from oslo_concurrency import lockutils
@@ -290,6 +291,15 @@ class TestCase(base.BaseTestCase):
         # instead of only once initialized for test worker
         wsgi_app.init_global_data.reset()

+ orig_shutdown = futurist.GreenThreadPoolExecutor.shutdown
+
+ def wrap_shutdown(*a, **kw):
+ kw['wait'] = True
+ return orig_shutdown(*a, **kw)
+
+ self.useFixture(fixtures.MonkeyPatch(
+ 'futurist.GreenThreadPoolExecutor.shutdown', wrap_shutdown))
+

but I haven't been able to reproduce the failure to tell if it might help.

[1] https://review.opendev.org/c/openstack/nova/+/815017
[2] https://github.com/openstack/nova/blob/b8cc5704558d3c08fda9db2f1bb7fecb2bcd985d/nova/compute/manager.py#L1627
[3] https://docs.openstack.org/futurist/latest/reference/index.html#futurist.GreenThreadPoolExecutor.shutdown

Reopening this because (1) we're still seeing it the gate (albeit less often since the notifications related workaround) and (2) when the bug is closed it won't show up in the gate bug list: https://bugs.launchpad.net/nova/+bugs?field.tag=gate-failure for easy finding for recheck comments.

This looks very much like the the problem discussed above https://7ffaea22ff93fca2f0ea-bf433abff5f8b85f7f80257b72ac6f67.ssl.cf5.rackcdn.com/869900/7/gate/nova-tox-functional-py38/3b10d8a/testr_results.html

This issue seems to become more and more problematic over time.

Opensearch query :
https://opensearch.logs.openstack.org/_dashboards/app/discover?security_tenant=global#/?_g=(filters:!(),refreshInterval:(pause:!t,value:0),time:(from:now-7d,to:now))&_a=(columns:!(_source),filters:!(('$state':(store:appState),meta:(alias:!n,disabled:!f,index:'94869730-aea8-11ec-9e6a-83741af3fdcd',key:project,negate:!f,params:(query:openstack%2Fnova),type:phrase),query:(match_phrase:(project:openstack%2Fnova)))),index:'94869730-aea8-11ec-9e6a-83741af3fdcd',interval:auto,query:(language:kuery,query:'%22sqlite3.OperationalError:%20no%20such%20table:%20instance_faults%22'),sort:!())

I can read 1525 hits on the last 7 days (if my query is correct and doesn't include false positives)

FWIW, I'm in favor of changing the bug report title to make it broader. There are evidences that this problem isn't related to a single test but spans across our func tests (and not being dependent on a single python version)

OK, let me wrap here a few findings.
First, the number of occurences is way lower than what I said in c#25 (fortunately).
Something around 19 occurrences around the last 20 days (which is still pretty big tho)

Secondly, I think I identified the real exception leading to a failed test condition :

2023-01-24 18:29:03.537384 | ubuntu-jammy | During handling of the above exception, another exception occurred:
2023-01-24 18:29:03.537389 | ubuntu-jammy |
2023-01-24 18:29:03.537394 | ubuntu-jammy | Traceback (most recent call last):
2023-01-24 18:29:03.537400 | ubuntu-jammy | File "/home/zuul/src/opendev.org/openstack/nova/nova/virt/libvirt/driver.py", line 10619, in _live_migration
2023-01-24 18:29:03.537405 | ubuntu-jammy | self.live_migration_abort(instance)
2023-01-24 18:29:03.537411 | ubuntu-jammy | File "/home/zuul/src/opendev.org/openstack/nova/nova/virt/libvirt/driver.py", line 10087, in live_migration_abort
2023-01-24 18:29:03.537416 | ubuntu-jammy | guest = self._host.get_guest(instance)
2023-01-24 18:29:03.537422 | ubuntu-jammy | File "/home/zuul/src/opendev.org/openstack/nova/nova/virt/libvirt/host.py", line 673, in get_guest
2023-01-24 18:29:03.537427 | ubuntu-jammy | return libvirt_guest.Guest(self._get_domain(instance))
2023-01-24 18:29:03.537432 | ubuntu-jammy | File "/home/zuul/src/opendev.org/openstack/nova/nova/virt/libvirt/guest.py", line 112, in __init__
2023-01-24 18:29:03.537438 | ubuntu-jammy | libvirt = importutils.import_module('libvirt')
2023-01-24 18:29:03.537482 | ubuntu-jammy | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py310/lib/python3.10/site-packages/oslo_utils/importutils.py", line 73, in import_module
2023-01-24 18:29:03.537494 | ubuntu-jammy | __import__(import_str)
2023-01-24 18:29:03.537500 | ubuntu-jammy | File
2023-01-24 18:29:03.537505 | ubuntu-jammy | "/home/zuul/src/opendev.org/openstack/nova/nova/tests/fixtures/nova.py", line 1829, in find_spec
2023-01-24 18:29:03.537511 | ubuntu-jammy | raise ImportError(fullname)
2023-01-24 18:29:03.537516 | ubuntu-jammy | ImportError: libvirt
2023-01-24 18:29:03.537521 | ubuntu-jammy |
2023-01-24 18:29:03.537527 | ubuntu-jammy | During handling of the above exception, another exception occurred:
2023-01-24 18:29:03.537532 | ubuntu-jammy |
2023-01-24 18:29:03.537537 | ubuntu-jammy | Traceback (most recent call last):
2023-01-24 18:29:03.537543 | ubuntu-jammy | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 8854, in _do_live_migration
2023-01-24 18:29:03.537548 | ubuntu-jammy | self.driver.live_migration(context, instance, dest,
2023-01-24 18:29:03.537553 | ubuntu-jammy | File "/home/zuul/src/opendev.org/openstack/nova/nova/virt/libvirt/driver.py", line 10076, in live_migration
2023-01-24 18:29:03.537559 | ubuntu-jammy | self._live_migration(context, instance, dest,
2023-01-24 18:29:03.537564 | ubuntu-jammy | File "/home/zuul/src/opendev.org/openstack/nova/nova/virt/libvirt/driver.py", line 10620, in _live_migration
2023-01-24 18:29:03.537569 | ubuntu-jammy | except libvirt.libvirtError:
2023-01-24 18:29:03.537575 | ubuntu-jammy | AttributeError: 'NoneType' o...

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/nova/+/872975

Reviewed: https://review.opendev.org/c/openstack/nova/+/872975
Committed: https://opendev.org/openstack/nova/commit/1778a9c589cf24e17b44f556680b17af9577df11
Submitter: "Zuul (22348)"
Branch: master

commit 1778a9c589cf24e17b44f556680b17af9577df11
Author: Sylvain Bauza <email address hidden>
Date: Tue Feb 7 16:30:59 2023 +0100

    Add logging to find test cases leaking libvirt threads

    We see functional test failures due to leaked libvirt event handling
    thread weaking up after its original test finished and importing
    libvirt. If it happens when the libvirt package import is poisoned then
    the currently executing test will fail. This patch logs the name of the
    test case that leaked the libvirt event handling thread.

    We will revert his before RC1.

    Change-Id: I3146e9afb411056d004fc118ccfa31126a3c6b15
    Related-Bug: #1946339

After a week, here is the paste of the added logging :

https://paste.opendev.org/show/bfvZX0XeKsELzY54EGb8/

Looks like each of the failures we got was done by a different functest.

New paste :

Search call is "logsearch log --job-group nova-functional --result FAILURE --branch master '!!!---!!!' --days 7"
https://paste.opendev.org/show/bzFdND2j4YbJRK1JLfcY/

Looks like actually most of the failing tests inherit from nova.tests.functional.libvirt base except from that failing test :
https://github.com/openstack/nova/blob/00299dcaad9a42c7f81be62a3966c59b299dff1d/nova/tests/functional/test_cross_az_attach.py#L69

More to come, investigating.

I see an uptick of this issue again in the gate. For example:
https://zuul.opendev.org/t/openstack/build/4eb17ff20e2d4525854cb11969baca97
https://zuul.opendev.org/t/openstack/build/24507ed59d7a4c2b95e1ea119c3e61d3

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/nova/+/883317

Reviewed: https://review.opendev.org/c/openstack/nova/+/883317
Committed: https://opendev.org/openstack/nova/commit/c095cfe04e2c71efcfbfdd95948af080a98065e6
Submitter: "Zuul (22348)"
Branch: master

commit c095cfe04e2c71efcfbfdd95948af080a98065e6
Author: melanie witt <email address hidden>
Date: Thu May 11 19:23:52 2023 +0000

    tests: Use GreenThreadPoolExecutor.shutdown(wait=True)

    We are still having some issues in the gate where greenlets from
    previous tests continue to run while the next test starts, causing
    false negative failures in unit or functional test jobs.

    This adds a new fixture that will ensure
    GreenThreadPoolExecutor.shutdown() is called with wait=True, to wait
    for greenlets in the pool to finish running before moving on.

    In local testing, doing this does not appear to adversely affect test
    run times, which was my primary concern.

    As a baseline, I ran a subset of functional tests in a loop
    until failure without the patch and after 11 hours, I got a failure
    reproducing the bug. With the patch, running the same subset of
    functional tests in a loop has been running for 24 hours and has not
    failed yet.

    Based on this, I think it may be worth trying this out to see if it
    will help stability of our unit and functional test jobs. And if it
    ends up impacting test run times or causes other issues, we can
    revert it.

    Partial-Bug: #1946339

    Change-Id: Ia916310522b007061660172fa4d63d0fde9a55ac

Fix proposed to branch: stable/2023.1
Review: https://review.opendev.org/c/openstack/nova/+/908806

Change abandoned by "Balazs Gibizer <email address hidden>" on branch: stable/2023.1
Review: https://review.opendev.org/c/openstack/nova/+/908806

Reviewed: https://review.opendev.org/c/openstack/nova/+/908806
Committed: https://opendev.org/openstack/nova/commit/22cccb9bd9b5e1eb27f7e94855e734ed3863ab8a
Submitter: "Zuul (22348)"
Branch: stable/2023.1

commit 22cccb9bd9b5e1eb27f7e94855e734ed3863ab8a
Author: melanie witt <email address hidden>
Date: Thu May 11 19:23:52 2023 +0000

    tests: Use GreenThreadPoolExecutor.shutdown(wait=True)

    We are still having some issues in the gate where greenlets from
    previous tests continue to run while the next test starts, causing
    false negative failures in unit or functional test jobs.

    This adds a new fixture that will ensure
    GreenThreadPoolExecutor.shutdown() is called with wait=True, to wait
    for greenlets in the pool to finish running before moving on.

    In local testing, doing this does not appear to adversely affect test
    run times, which was my primary concern.

    As a baseline, I ran a subset of functional tests in a loop
    until failure without the patch and after 11 hours, I got a failure
    reproducing the bug. With the patch, running the same subset of
    functional tests in a loop has been running for 24 hours and has not
    failed yet.

    Based on this, I think it may be worth trying this out to see if it
    will help stability of our unit and functional test jobs. And if it
    ends up impacting test run times or causes other issues, we can
    revert it.

    Partial-Bug: #1946339

    Change-Id: Ia916310522b007061660172fa4d63d0fde9a55ac
    (cherry picked from commit c095cfe04e2c71efcfbfdd95948af080a98065e6)