$ pytest --benchmark-skip -vv
========================================================================== test session starts ===========================================================================
platform cygwin -- Python 3.9.10, pytest-7.2.0, pluggy-1.0.0 -- /home/admin/w/borg-env/bin/python
cachedir: .pytest_cache
benchmark: 4.0.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)
Tests enabled: root, symlinks, hardlinks, atime/mtime, modes
Tests disabled: BSD flags, fuse2, fuse3
rootdir: /home/admin/w/borg, configfile: setup.cfg
plugins: benchmark-4.0.0, cov-4.0.0, forked-1.4.0, xdist-3.0.2
collected 1559 items
...
================================================================================ FAILURES ================================================================================
_________________________________________________________________ TestExclusiveLock.test_race_condition __________________________________________________________________
self = <borg.testsuite.locking.TestExclusiveLock object at 0x6ffffd4fa220>, lockpath = '/tmp/pytest-of-admin/pytest-32/test_race_condition0/lock'
def test_race_condition(self, lockpath):
class SynchronizedCounter:
def __init__(self, count=0):
self.lock = ThreadingLock()
self.count = count
self.maxcount = count
def value(self):
with self.lock:
return self.count
def maxvalue(self):
with self.lock:
return self.maxcount
def incr(self):
with self.lock:
self.count += 1
if self.count > self.maxcount:
self.maxcount = self.count
return self.count
def decr(self):
with self.lock:
self.count -= 1
return self.count
def print_locked(msg):
with print_lock:
print(msg)
def acquire_release_loop(
id, timeout, thread_id, lock_owner_counter, exception_counter, print_lock, last_thread=None
):
print_locked(
"Thread %2d: Starting acquire_release_loop(id=%s, timeout=%d); lockpath=%s"
% (thread_id, id, timeout, lockpath)
)
timer = TimeoutTimer(timeout, -1).start()
cycle = 0
while not timer.timed_out():
cycle += 1
try:
with ExclusiveLock(
lockpath, id=id, timeout=timeout / 20, sleep=-1
): # This timeout is only for not exceeding the given timeout by more than 5%. With sleep<0 it's constantly polling anyway.
lock_owner_count = lock_owner_counter.incr()
print_locked(
"Thread %2d: Acquired the lock. It's my %d. loop cycle. I am the %d. who has the lock concurrently."
% (thread_id, cycle, lock_owner_count)
)
time.sleep(0.005)
lock_owner_count = lock_owner_counter.decr()
print_locked(
"Thread %2d: Releasing the lock, finishing my %d. loop cycle. Currently, %d colleagues still have the lock."
% (thread_id, cycle, lock_owner_count)
)
except LockTimeout:
print_locked("Thread %2d: Got LockTimeout, finishing my %d. loop cycle." % (thread_id, cycle))
except:
exception_count = exception_counter.incr()
e = format_exc()
print_locked(
"Thread %2d: Exception thrown, finishing my %d. loop cycle. It's the %d. exception seen until now: %s"
% (thread_id, cycle, exception_count, e)
)
print_locked("Thread %2d: Loop timed out--terminating after %d loop cycles." % (thread_id, cycle))
if last_thread is not None: # joining its predecessor, if any
last_thread.join()
print("")
lock_owner_counter = SynchronizedCounter()
exception_counter = SynchronizedCounter()
print_lock = ThreadingLock()
thread = None
for thread_id in range(RACE_TEST_NUM_THREADS):
thread = Thread(
target=acquire_release_loop,
args=(
("foo", thread_id, 0),
RACE_TEST_DURATION,
thread_id,
lock_owner_counter,
exception_counter,
print_lock,
thread,
),
)
thread.start()
thread.join() # joining the last thread
assert lock_owner_counter.maxvalue() > 0, "Never gained the lock? Something went wrong here..."
> assert (
lock_owner_counter.maxvalue() <= 1
), "Maximal number of concurrent lock holders was %d. So exclusivity is broken." % (
lock_owner_counter.maxvalue()
)
E AssertionError: Maximal number of concurrent lock holders was 4. So exclusivity is broken.
E assert 4 <= 1
E + where 4 = <bound method TestExclusiveLock.test_race_condition.<locals>.SynchronizedCounter.maxvalue of <borg.testsuite.locking.TestExclusiveLock.test_race_condition.<locals>.SynchronizedCounter object at 0x6ffffce78490>>()
E + where <bound method TestExclusiveLock.test_race_condition.<locals>.SynchronizedCounter.maxvalue of <borg.testsuite.locking.TestExclusiveLock.test_race_condition.<locals>.SynchronizedCounter object at 0x6ffffce78490>> = <borg.testsuite.locking.TestExclusiveLock.test_race_condition.<locals>.SynchronizedCounter object at 0x6ffffce78490>.maxvalue
src/borg/testsuite/locking.py:201: AssertionError
-------------------------------------------------------------------------- Captured stdout call --------------------------------------------------------------------------
...
Thread 16: Acquired the lock. It's my 1. loop cycle. I am the 2. who has the lock concurrently.
Thread 4: Acquired the lock. It's my 2. loop cycle. I am the 4. who has the lock concurrently.
...
Thread 8: Releasing the lock, finishing my 2. loop cycle. Currently, 3 colleagues still have the lock.
...
...
Thread 33: Got LockTimeout, finishing my 1. loop cycle.
Thread 16: Exception thrown, finishing my 1. loop cycle. It's the 2. exception seen until now: Traceback (most recent call last):
File "/home/admin/w/borg/src/borg/testsuite/locking.py", line 161, in acquire_release_loop
print_locked(
File "/home/admin/w/borg/src/borg/locking.py", line 120, in __exit__
self.release()
File "/home/admin/w/borg/src/borg/locking.py", line 171, in release
raise NotMyLock(self.path)
borg.locking.NotMyLock: Failed to release the lock /tmp/pytest-of-admin/pytest-32/test_race_condition0/lock (was/is locked, but not by me).
Thread 8: Exception thrown, finishing my 2. loop cycle. It's the 1. exception seen until now: Traceback (most recent call last):
File "/home/admin/w/borg/src/borg/testsuite/locking.py", line 161, in acquire_release_loop
print_locked(
File "/home/admin/w/borg/src/borg/locking.py", line 120, in __exit__
self.release()
File "/home/admin/w/borg/src/borg/locking.py", line 171, in release
raise NotMyLock(self.path)
borg.locking.NotMyLock: Failed to release the lock /tmp/pytest-of-admin/pytest-32/test_race_condition0/lock (was/is locked, but not by me).
Thread 4: Exception thrown, finishing my 2. loop cycle. It's the 3. exception seen until now: Traceback (most recent call last):
File "/home/admin/w/borg/src/borg/testsuite/locking.py", line 161, in acquire_release_loop
print_locked(
File "/home/admin/w/borg/src/borg/locking.py", line 120, in __exit__
self.release()
File "/home/admin/w/borg/src/borg/locking.py", line 171, in release
raise NotMyLock(self.path)
borg.locking.NotMyLock: Failed to release the lock /tmp/pytest-of-admin/pytest-32/test_race_condition0/lock (was/is locked, but not by me).
...
Thread 26: Got LockTimeout, finishing my 3. loop cycle.
Thread 23: Exception thrown, finishing my 3. loop cycle. It's the 4. exception seen until now: Traceback (most recent call last):
File "/home/admin/w/borg/src/borg/testsuite/locking.py", line 161, in acquire_release_loop
print_locked(
File "/home/admin/w/borg/src/borg/locking.py", line 120, in __exit__
self.release()
File "/home/admin/w/borg/src/borg/locking.py", line 178, in release
raise err
File "/home/admin/w/borg/src/borg/locking.py", line 174, in release
os.rmdir(self.path)
PermissionError: [Errno 13] Permission denied: '/tmp/pytest-of-admin/pytest-32/test_race_condition0/lock'
...
Thread 8: Releasing the lock, finishing my 5. loop cycle. Currently, 0 colleagues still have the lock.
Thread 36: Exception thrown, finishing my 5. loop cycle. It's the 5. exception seen until now: Traceback (most recent call last):
File "/home/admin/w/borg/src/borg/testsuite/locking.py", line 161, in acquire_release_loop
print_locked(
File "/home/admin/w/borg/src/borg/locking.py", line 120, in __exit__
self.release()
File "/home/admin/w/borg/src/borg/locking.py", line 171, in release
raise NotMyLock(self.path)
borg.locking.NotMyLock: Failed to release the lock /tmp/pytest-of-admin/pytest-32/test_race_condition0/lock (was/is locked, but not by me).
...
Thread 36: Exception thrown, finishing my 7. loop cycle. It's the 6. exception seen until now: Traceback (most recent call last):
File "/home/admin/w/borg/src/borg/testsuite/locking.py", line 161, in acquire_release_loop
print_locked(
File "/home/admin/w/borg/src/borg/locking.py", line 120, in __exit__
self.release()
File "/home/admin/w/borg/src/borg/locking.py", line 172, in release
os.unlink(self.unique_name)
FileNotFoundError: [Errno 2] No such file or directory: '/tmp/pytest-of-admin/pytest-32/test_race_condition0/lock/foo.36-0'
...
Thread 9: Exception thrown, finishing my 8. loop cycle. It's the 7. exception seen until now: Traceback (most recent call last):
File "/home/admin/w/borg/src/borg/locking.py", line 144, in acquire
os.rename(temp_path, self.path)
OSError: [Errno 90] Directory not empty: '/tmp/pytest-of-admin/pytest-32/test_race_condition0/lock.bc71_db8.tmp' -> '/tmp/pytest-of-admin/pytest-32/test_race_condition0/lock'
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/home/admin/w/borg/src/borg/testsuite/locking.py", line 151, in acquire_release_loop
with ExclusiveLock(
File "/home/admin/w/borg/src/borg/locking.py", line 117, in __enter__
return self.acquire()
File "/home/admin/w/borg/src/borg/locking.py", line 148, in acquire
self.kill_stale_lock()
File "/home/admin/w/borg/src/borg/locking.py", line 191, in kill_stale_lock
names = os.listdir(self.path)
PermissionError: [Errno 13] Permission denied: '/tmp/pytest-of-admin/pytest-32/test_race_condition0/lock'
...
______________________________________________________________________ ArchiverTestCase.test_atime _______________________________________________________________________
self = <borg.testsuite.archiver.extract_cmd.ArchiverTestCase testMethod=test_atime>
@pytest.mark.skipif(not is_utime_fully_supported(), reason="cannot properly setup and execute test without utime")
def test_atime(self):
def has_noatime(some_file):
atime_before = os.stat(some_file).st_atime_ns
try:
with open(os.open(some_file, flags_noatime)) as file:
file.read()
except PermissionError:
return False
else:
atime_after = os.stat(some_file).st_atime_ns
noatime_used = flags_noatime != flags_normal
return noatime_used and atime_before == atime_after
self.create_test_files()
atime, mtime = 123456780, 234567890
have_noatime = has_noatime("input/file1")
os.utime("input/file1", (atime, mtime))
self.cmd(f"--repo={self.repository_location}", "rcreate", RK_ENCRYPTION)
self.cmd(f"--repo={self.repository_location}", "create", "--atime", "test", "input")
with changedir("output"):
self.cmd(f"--repo={self.repository_location}", "extract", "test")
sti = os.stat("input/file1")
sto = os.stat("output/input/file1")
assert sti.st_mtime_ns == sto.st_mtime_ns == mtime * 1e9
if have_noatime:
assert sti.st_atime_ns == sto.st_atime_ns == atime * 1e9
else:
# it touched the input file's atime while backing it up
> assert sto.st_atime_ns == atime * 1e9
E assert 1671377299453455500 == (123456780 * 1000000000.0)
E + where 1671377299453455500 = os.stat_result(st_mode=35309, st_ino=1688849860568944, st_dev=2550678920, st_nlink=2, st_uid=197609, st_gid=197121, st_size=81920, st_atime=1671377299, st_mtime=234567890, st_ctime=1671377299).st_atime_ns
src/borg/testsuite/archiver/extract_cmd.py:91: AssertionError
___________________________________________________________________ RemoteArchiverTestCase.test_atime ____________________________________________________________________
self = <borg.testsuite.archiver.extract_cmd.RemoteArchiverTestCase testMethod=test_atime>
@pytest.mark.skipif(not is_utime_fully_supported(), reason="cannot properly setup and execute test without utime")
def test_atime(self):
def has_noatime(some_file):
atime_before = os.stat(some_file).st_atime_ns
try:
with open(os.open(some_file, flags_noatime)) as file:
file.read()
except PermissionError:
return False
else:
atime_after = os.stat(some_file).st_atime_ns
noatime_used = flags_noatime != flags_normal
return noatime_used and atime_before == atime_after
self.create_test_files()
atime, mtime = 123456780, 234567890
have_noatime = has_noatime("input/file1")
os.utime("input/file1", (atime, mtime))
self.cmd(f"--repo={self.repository_location}", "rcreate", RK_ENCRYPTION)
self.cmd(f"--repo={self.repository_location}", "create", "--atime", "test", "input")
with changedir("output"):
self.cmd(f"--repo={self.repository_location}", "extract", "test")
sti = os.stat("input/file1")
sto = os.stat("output/input/file1")
assert sti.st_mtime_ns == sto.st_mtime_ns == mtime * 1e9
if have_noatime:
assert sti.st_atime_ns == sto.st_atime_ns == atime * 1e9
else:
# it touched the input file's atime while backing it up
> assert sto.st_atime_ns == atime * 1e9
E assert 1671377311454228200 == (123456780 * 1000000000.0)
E + where 1671377311454228200 = os.stat_result(st_mode=35309, st_ino=3096224744287459, st_dev=2550678920, st_nlink=2, st_uid=197609, st_gid=197121, st_size=81920, st_atime=1671377311, st_mtime=234567890, st_ctime=1671377311).st_atime_ns
src/borg/testsuite/archiver/extract_cmd.py:91: AssertionError
