test_with_lock sometimes failing

[ThomasWaldmann]

    openbsd7: ________________________________ test_with_lock ________________________________
    openbsd7: [gw0] openbsd7 -- Python 3.10.13 /vagrant/borg/borg/.tox/py310-none/bin/python
    openbsd7: 
    openbsd7: tmp_path = PosixPath('/tmp/pytest-of-vagrant/pytest-0/popen-gw0/test_with_lock0')
    openbsd7: 
    openbsd7:     def test_with_lock(tmp_path):
    openbsd7:         repo_path = tmp_path / "repo"
    openbsd7:         env = os.environ.copy()
    openbsd7:         env["BORG_REPO"] = "file://" + str(repo_path)
    openbsd7:         command0 = "python3", "-m", "borg", "repo-create", "--encryption=none"
    openbsd7:         # timings must be adjusted so that command1 keeps running while command2 tries to get the lock,
    openbsd7:         # so that lock acquisition for command2 fails as the test expects it.
    openbsd7:         lock_wait, execution_time, startup_wait = 2, 4, 1
    openbsd7:         assert lock_wait < execution_time - startup_wait
    openbsd7:         command1 = "python3", "-c", f'import time; print("first command - acquires the lock"); time.sleep({execution_time})'
    openbsd7:         command2 = "python3", "-c", 'print("second command - should never get executed")'
    openbsd7:         borgwl = "python3", "-m", "borg", "with-lock", f"--lock-wait={lock_wait}"
    openbsd7:         popen_options = dict(stdout=subprocess.PIPE, stderr=subprocess.PIPE, text=True, env=env)
    openbsd7:         subprocess.run(command0, env=env, check=True, text=True, capture_output=True)
    openbsd7:         assert repo_path.exists()
    openbsd7:         with subprocess.Popen([*borgwl, *command1], **popen_options) as p1:
    openbsd7:             time.sleep(startup_wait)  # wait until p1 is running
    openbsd7:             # now try to get another lock on the same repository:
    openbsd7:             with subprocess.Popen([*borgwl, *command2], **popen_options) as p2:
    openbsd7:                 out, err_out = p2.communicate()
    openbsd7: >               assert "second command" not in out  # command2 is "locked out"
    openbsd7: E               AssertionError: assert 'second command' not in 'second comm...t executed\n'
    openbsd7: E
    openbsd7: E                 'second command' is contained here:
    openbsd7: E                   second command - should never get executed
    openbsd7: E                 ? ++++++++++++++
    openbsd7: 
    openbsd7: src/borg/testsuite/archiver/lock_cmds_test.py:38: AssertionError

[ThomasWaldmann]

it's in a VM and there maybe was quite some load due to other VMs, so maybe startup_wait is too short?

[ThomasWaldmann]

Doesn't always reproduce:

(borg-env) [vagrant@openbsd7 borg]$ pytest -vk test_with_lock
====================================================== test session starts ======================================================
platform openbsd7 -- Python 3.10.13, pytest-8.3.5, pluggy-1.5.0 -- /vagrant/borg/borg-env/bin/python
cachedir: .pytest_cache
benchmark: 5.1.0 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000)
rootdir: /vagrant/borg/borg
configfile: pyproject.toml
plugins: xdist-3.6.1, cov-6.0.0, benchmark-5.1.0
collected 1817 items / 1813 deselected / 4 selected                                                                             

src/borg/testsuite/archiver/lock_cmds_test.py::test_with_lock PASSED                                                      [ 25%]
src/borg/testsuite/archiver/lock_cmds_test.py::test_with_lock_non_existent_command[archiver] PASSED                       [ 50%]
src/borg/testsuite/archiver/lock_cmds_test.py::test_with_lock_non_existent_command[remote_archiver] PASSED                [ 75%]
src/borg/testsuite/archiver/lock_cmds_test.py::test_with_lock_non_existent_command[binary_archiver] SKIPPED (No borg....) [100%]

======================================== 3 passed, 1 skipped, 1813 deselected in 21.55s =========================================