Could not acquire exclusive lock to access _open_log_files

[pevogam]

Hi @luckyh, @YongxueHong, @smitterl, @bgartzi some recent changes in Avocado VT are causing this:

[stdlog] 2025-06-21 01:59:11,650 avocado.virttest.qemu_vm qemu_vm          L4194 DEBUG| Destroying VM vm1 (PID 2752)                                                                                                                       │
[stdlog] 2025-06-21 01:59:11,650 avocado.virttest.qemu_vm qemu_vm          L4084 DEBUG| Shutting down VM vm1 (shell)                                                                                                                       │
[stderr] Exception in thread                                                                                                                                                                                                               │
[stderr] tail_thread_Pc24l9Zg_ssh  -o Us                                                                                                                                                                                                   │
[stderr] :                                                                                                                                                                                                                                 │
[stderr] Traceback (most recent call last):                                                                                                                                                                                                │
[stderr]   File "/usr/lib64/python3.13/threading.py", line 1041, in _bootstrap_inner                                                                                                                                                       │
[stderr]     self.run()                                                                                                                                                                                                                    │
[stderr]     ~~~~~~~~^^                                                                                                                                                                                                                    │
[stderr]   File "/usr/lib64/python3.13/threading.py", line 992, in run                                                                                                                                                                     │
[stderr]     self._target(*self._args, **self._kwargs)                                                                                                                                                                                     │
[stderr]     ~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^                                                                                                                                                                                     │
[stderr]   File "/usr/lib/python3.13/site-packages/aexpect/client.py", line 776, in _tail                                                                                                                                                  │
[stderr]     _print_line(f"(Process terminated with status {status})")                                                                                                                                                                     │
[stderr]     ~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^                                                                                                                                                                     │
[stderr]   File "/usr/lib/python3.13/site-packages/aexpect/client.py", line 720, in _print_line                                                                                                                                            │
[stderr]     self.output_func(*self.output_params + (text,))                                                                                                                                                                               │
[stderr]     ~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^                                                                                                                                                                               │
[stderr]   File "/usr/lib/python3.13/site-packages/virttest/utils_logfile.py", line 67, in log_line                                                                                                                                        │
[stderr]     raise LogLockError(                                                                                                                                                                                                           │
[stderr]         "Could not acquire exclusive lock to access" " _open_log_files"                                                                                                                                                           │
[stderr]     )                                                                                                                                                                                                                             │
[stderr] virttest.utils_logfile.LogLockError: Could not acquire exclusive lock to access _open_log_files                                                                                                                                   │
[stdlog] 2025-06-21 02:00:18,832 avocado.virttest.ip_sniffing ip_sniffing      L0177 WARNI| Can't log ip sniffer output: 'Could not acquire exclusive lock to access _open_log_files'                                                      │
[stdlog] 2025-06-21 02:00:28,271 avocado.virttest.qemu_vm client           L0722 INFO | [qemu output] (Process terminated with status 0)                                                                                                   │
[stdlog] 2025-06-21 02:00:28,854 avocado.virttest.ip_sniffing ip_sniffing      L0177 WARNI| Can't log ip sniffer output: 'Could not acquire exclusive lock to access _open_log_files'                                                      │
[stdlog] 2025-06-21 02:00:38,048 avocado.virttest.utils_net utils_net        L1229 DEBUG| Host does not support OpenVSwitch: Command 'ovs-vswitchd' could not be found in any of the PATH dirs: ['/bin', '/sbin', '/usr/bin', '/usr/lib64/c│
[stdlog] 2025-06-21 02:00:38,062 avocado.virttest.utils_net utils_net        L1229 DEBUG| Host does not support OpenVSwitch: Command 'ovs-vswitchd' could not be found in any of the PATH dirs: ['/bin', '/sbin', '/usr/bin', '/usr/lib64/c│
[stdlog] 2025-06-21 02:00:38,203 avocado.virttest.utils_net utils_net        L1229 DEBUG| Host does not support OpenVSwitch: Command 'ovs-vswitchd' could not be found in any of the PATH dirs: ['/bin', '/sbin', '/usr/bin', '/usr/lib64/c│
[stdlog] 2025-06-21 02:00:38,324 avocado.virttest.env_process env_process      L1360 ERROR| Could not acquire exclusive lock to access _open_log_files                                                                                     ┤
[stdlog] 2025-06-21 02:00:38,566 avocado.job.avocado_i2n.states.setup setup            L0403 DEBUG| Skip setting states of types nets/vms, nets/vms/images                                                                                 │
[stdlog] 2025-06-21 02:00:38,567 avocado.job.avocado_i2n.states.setup setup            L0403 DEBUG| Skip setting states of types nets/vms, nets/vms/images                                                                                 │
[stdlog] 2025-06-21 02:00:38,568 avocado.job.avocado_i2n.states.setup setup            L0418 DEBUG| Skip setting any nets state for net5                                                                                                   │
[stdlog] 2025-06-21 02:00:38,915 avocado.test stacktrace       L0041 ERROR|                                                                                                                                                                │
[stdlog] 2025-06-21 02:00:38,915 avocado.test stacktrace       L0043 ERROR| Reproduced traceback from: /usr/lib/python3.13/site-packages/avocado_vt/test.py:329                                                                            ┤
[stdlog] 2025-06-21 02:00:38,917 avocado.test stacktrace       L0050 ERROR| Traceback (most recent call last):                                                                                                                             │
[stdlog] 2025-06-21 02:00:38,917 avocado.test stacktrace       L0050 ERROR|   File "/usr/lib/python3.13/site-packages/virttest/error_context.py", line 141, in new_fn                                                                      │
[stdlog] 2025-06-21 02:00:38,917 avocado.test stacktrace       L0050 ERROR|     return fn(*args, **kwargs)                                                                                                                                 │
[stdlog] 2025-06-21 02:00:38,917 avocado.test stacktrace       L0050 ERROR|   File "/usr/lib/python3.13/site-packages/virttest/env_process.py", line 1551, in postprocess                                                                  │
[stdlog] 2025-06-21 02:00:38,918 avocado.test stacktrace       L0050 ERROR|     raise RuntimeError("Failures occurred while postprocess:\n%s" % err)                                                                                       │
[stdlog] 2025-06-21 02:00:38,918 avocado.test stacktrace       L0050 ERROR| RuntimeError: Failures occurred while postprocess:                                                                                                             │
[stdlog] 2025-06-21 02:00:38,918 avocado.test stacktrace       L0050 ERROR|                                                                                                                                                                │
[stdlog] 2025-06-21 02:00:38,918 avocado.test stacktrace       L0050 ERROR| Postprocess: Could not acquire exclusive lock to access _open_log_files                                                                                        │
[stdlog] 2025-06-21 02:00:38,918 avocado.test stacktrace       L0051 ERROR|                                                                                                                                                                │
[stderr] Traceback (most recent call last):                                                                                                                                                                                                │
[stderr]   File "/usr/lib/python3.13/site-packages/avocado_vt/plugins/vt_runner.py", line 74, in runTest                                                                                                                                   ┤
[stderr]     raise self.__status  # pylint: disable-msg=E0702                                                                                                                                                                              │
[stderr]     ^^^^^^^^^^^^^^^^^^^                                                                                                                                                                                                           │
[stderr]   File "/usr/lib/python3.13/site-packages/avocado_vt/test.py", line 146, in setUp                                                                                                                                                 │
[stderr]     self._runTest()                                                                                                                                                                                                               │
[stderr]     ~~~~~~~~~~~~~^^                                                                                                                                                                                                               ┤
[stderr]   File "/usr/lib/python3.13/site-packages/avocado_vt/test.py", line 322, in _runTest                                                                                                                                              │
[stderr]     env_process.postprocess(self, params, env)                                                                                                                                                                                    │
[stderr]     ~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^                                                                                                                                                                                    │
[stderr]   File "/usr/lib/python3.13/site-packages/virttest/error_context.py", line 141, in new_fn                                                                                                                                         │
[stderr]     return fn(*args, **kwargs)                                                                                                                                                                                                    │
[stderr]   File "/usr/lib/python3.13/site-packages/virttest/env_process.py", line 1551, in postprocess                                                                                                                                     │
[stderr]     raise RuntimeError("Failures occurred while postprocess:\n%s" % err)                                                                                                                                                          │
[stderr] RuntimeError: Failures occurred while postprocess:                                                                                                                                                                                │
[stderr]                                                                                                                                                                                                                                   ┤
[stderr] Postprocess: Could not acquire exclusive lock to access _open_log_files      

[YongxueHong]

Hi @pevogam
I have not encountered such an issue on my end recently.
The following is the related version of my test environment:

Avocado: 
    Branch: 111.0
    Git commit: 53f6136d9330b574eb684a8d367beb3d59d7154f
Avocado-VT: 
    Branch: master
    Git commit: 4318f9030331724df417b3e600e405aba84f8ac5
Aexpect: 
    Branch: main
    Git commit: 5e615fc24c604cd268ff33551ad71757920c4157

May I know which version of your issue?
Thanks.

[pevogam]

Hi @YongxueHong,

This is the environment I am using:

Python 3.13
Aexpect:
    Branch: main
    Git commit: 5e615fc24c604cd268ff33551ad71757920c4157
Avocado:
    Branch: master
    Git commit: 9ef471c980028844fa523b8fb5a27acdd3574468
Avocado-VT:
    Branch: master
    Git commit: 4318f9030331724df417b3e600e405aba84f8ac5

In particular, have you tried this with Python 3.13?

[YongxueHong]

Hi @pevogam
Thanks for your information.
No, I have not tried it with Python 3.13, I was using Python 3.9.21.
I will try it with Python 3.13.

[pevogam]

It seems is also only triggers (but 100% reproducibly) on a particular guest OS variant like Linux.Fedora.40.64 but not on Windows.Win10.x86_64 and Linux.CentOS.8.0.

Another interesting observation - if I check out the 109.0 tag of Avocado I2N the error no longer happens for any OS variant despite me using Python 3.13.

[YongxueHong]

Hi @pevogam
Maybe it was fixed by the latest version, and we mainly focus on the Windows and RHEL guests, not the Fedora guest.
I suggest using the latest version of the framework for your testing if you do not have any concerns, since it will be compatible with the latest Python as well.
Thanks.

[pevogam]

The versions I reported are already the most recent ones from avocado/vt/aexpect from what I can gather but I made another finding - it seems the above is a race condition and doesn't happen 100% of the time. So it may not be restricted solely to the Fedora vm and worse yet, git history bisection might not be as trivial as I have hoped. Will check if I can reproduce this with the most recent Avocado VT tag 109.0 which I have used just fine for a while now but not yet on Python 3.13.

[YongxueHong]

Hi @pevogam
Please consider the aexpect version as well.
Thanks.

[pevogam]

Hi @pevogam Please consider the aexpect version as well. Thanks.

Yes, precisely your aexpect version as you can see in the commit hash:

[pevogam]

@ldoktor Do you think that any of this could be related to the merged avocado-framework/aexpect#147? After all, the utils_logfile uses thread-related _log_lock = threading.RLock() and could now be outdated w.r.t. to aexpect's recent fixes.

[ldoktor]

@ldoktor Do you think that any of this could be related to the merged avocado-framework/aexpect#147? After all, the utils_logfile uses thread-related _log_lock = threading.RLock() and could now be outdated w.r.t. to aexpect's recent fixes.

Hello folks, sorry for the delay, I was on a vacation. This shouldn't be related to aexpect at all, aexpect is listed in the traceback only because it was given avocado-vt function to be called in output_function.

Even if it was this code complains about threading.RLock which is per-thread reentrant object that can be locked (not file-based) while in aexpect we use file-based lock (we're locking files and not python objects).

I haven't played avocado-vt for quite some time but my rough estimate would be some change/hardening in python3.13 (there were quite a few deprecations and changes in that release) so you might need to revisit how the locking is being performed in avocado-vt's log files.

Another suspect could be good old overutilized system. Would increasing the default 10 timeout help? It might sound like generous but if eg. swapping comes in, flushing a file after long log might actually take longer. Or even starvation as we don't prioritize in acquire_lock (you might try decreasing the time.sleep() value based on how long the _acquire_lock will wait.

[pevogam]

Thanks for @ldoktor for adding your valuable knowledge here - in fact I tried increasing the timeout and so far have collected the following observations:

1. Small increases still led to the lock acquisition timeout so in order to completely rule this out I tried an unacceptably large timeout of 600 seconds and have not obtained the problem any longer -> maybe we would have to fine-tune such timeout parameter.
2. The timeout happens consistently with Python 3.13 but not with previous python version so it is very likely that some of the hardening and changes you mentioned indirectly affect this by modifying the duration of certain operations behind the scenes.

So all in all so far I can say it is likely a mix of both of the things you mentioned and the best we can do right now is fine-tune this timeout some more. Will push a pull request once I have found a better parameter value and verified it is consistently better.

[pevogam]

Pull request to close this issue is available now at #4227.