Examined the MirrorSnapshotScheduleHandler's run thread using gdb (with python extensions `sudo dnf debuginfo-install python3`) in vstart environment:
$ gdb attach <ceph-mgr-pid>
...
(gdb) thread apply all py-bt
# identified that thread 91 was the MirrorSnapshotScheduleHandler's run thread from the python backtraces
(gdb) thread 91
[Switching to thread 91 (Thread 0x7f50b8100640 (LWP 166305))]
#0 __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x5619cd688380) at futex-internal.c:57
57 return INTERNAL_SYSCALL_CANCEL (futex_time64, futex_word, op, expected,
(gdb) py-list
47 def __del__(self) -> None:
48 self.log.debug("{} CreateSnapshotRequests.wait_for_pending: __del__".format(repr(self)))
49 self.wait_for_pending()
50
51 def wait_for_pending(self) -> None:
>52 with self.lock:
53 self.log.debug("CreateSnapshotRequests.wait_for_pending: acquired lock")
54 while self.pending:
55 self.log.debug(
56 "CreateSnapshotRequests.wait_for_pending: "
57 "{} images".format(len(self.pending)))
(gdb) py-bt
Traceback (most recent call first):
<built-in method __enter__ of _thread.lock object at remote 0x7f50d21c0d00>
File "/home/rraja/git/ceph/src/pybind/mgr/rbd_support/mirror_snapshot_schedule.py", line 52, in wait_for_pending
with self.lock:
File "/home/rraja/git/ceph/src/pybind/mgr/rbd_support/mirror_snapshot_schedule.py", line 49, in __del__
self.wait_for_pending()
Garbage-collecting
File "/usr/lib64/python3.10/logging/__init__.py", line 819, in filter
for f in self.filters:
File "/usr/lib64/python3.10/logging/__init__.py", line 964, in handle
rv = self.filter(record)
File "/usr/lib64/python3.10/logging/__init__.py", line 1696, in callHandlers
hdlr.handle(record)
File "/usr/lib64/python3.10/logging/__init__.py", line 1634, in handle
self.callHandlers(record)
File "/usr/lib64/python3.10/logging/__init__.py", line 1624, in _log
self.handle(record)
File "/usr/lib64/python3.10/logging/__init__.py", line 1465, in debug
self._log(DEBUG, msg, args, **kwargs)
File "/home/rraja/git/ceph/src/pybind/mgr/rbd_support/mirror_snapshot_schedule.py", line 328, in get_ioctx
self.log.debug("{} CreateSnapshotRequests.get_ioctx acquired lock: {}/{}/{}".format(
File "/home/rraja/git/ceph/src/pybind/mgr/rbd_support/mirror_snapshot_schedule.py", line 98, in open_image
ioctx = self.get_ioctx(image_spec)
File "/home/rraja/git/ceph/src/pybind/mgr/rbd_support/mirror_snapshot_schedule.py", line 87, in add
self.open_image(image_spec)
File "/home/rraja/git/ceph/src/pybind/mgr/rbd_support/mirror_snapshot_schedule.py", line 407, in run
self.create_snapshot_requests.add(pool_id, namespace, image_id)
File "/usr/lib64/python3.10/threading.py", line 953, in run
self._target(*self._args, **self._kwargs)
File "/usr/lib64/python3.10/threading.py", line 1016, in _bootstrap_inner
self.run()
File "/usr/lib64/python3.10/threading.py", line 973, in _bootstrap
self._bootstrap_inner()
Observed a recursive deadlock in the MirrorSnapshotSchedulerHandler's run thread. Ilya identified the root cause of the deadlock. The thread acquired a CreateSnapshotRequests's class variable lock (shared across all CreateSnapshotRequests instances) in CreateSnapshotRequests.get_ioctx(), and then attempted to garbage collect another CreateSnapshotRequest instance. When garbage collecting, CreateSnapshotRequests.__del__() was called, which in turn called CreateSnapshotRequests.wait_for_pending(). Here the thread expectedly failed to acquire the CreateSnapshotRequests's class variable lock that the thread already acquired when it called the other CreateSnapshotRequests's get_ioctx() earlier.
2023-10-26T17:54:00.002-0400 7f50b8100640 0 [rbd_support DEBUG root] CreateSnapshotRequests.open_image: 3//15032b4e30aa
...
2023-10-26T17:54:00.002-0400 7f50b8100640 0 [rbd_support DEBUG root] <rbd_support.mirror_snapshot_schedule.CreateSnapshotRequests object at 0x7f50b89f0d30> entering CreateSnapshotRequests.get_ioctx: 3//15032b4e30aa
...
2023-10-26T17:54:00.003-0400 7f50b8100640 0 [rbd_support DEBUG root] <rbd_support.mirror_snapshot_schedule.CreateSnapshotRequests object at 0x7f50b89f3370> CreateSnapshotRequests.wait_for_pending: __del__
...
2023-10-26T17:54:00.006-0400 7f50a68dd640 0 [rbd_support DEBUG root] CreateSnapshotRequests.handle_open_image 3//14fdd5b36d44: r=-108
2023-10-26T17:54:00.006-0400 7f50a68dd640 0 [rbd_support ERROR root] error when opening 3//14fdd5b36d44: -108
2023-10-26T17:54:00.006-0400 7f50a68dd640 0 [rbd_support DEBUG root] CreateSnapshotRequests.finish: 3//14fdd5b36d44
2023-10-26T17:54:00.006-0400 7f50a68dd640 0 [rbd_support DEBUG root] <rbd_support.mirror_snapshot_schedule.CreateSnapshotRequests object at 0x7f50b89f0d30> entering CreateSnapshotRequests.put_ioctx: 3//14fdd5b36d44
The above ceph-mgr log excerpt shows that in the MirrorSnapshotScheduleHandler's run thread, the get_ioctx() and the subsequent del() belong to different CreateSnapshotRequests instances. Please note that extra logging was added in mirror_snapshot_schedule.py to generate these logs.
diff --git a/src/pybind/mgr/rbd_support/mirror_snapshot_schedule.py b/src/pybind/mgr/rbd_support/mirror_snapshot_schedule.py
index 13242388282..f7567a03be3 100644
--- a/src/pybind/mgr/rbd_support/mirror_snapshot_schedule.py
+++ b/src/pybind/mgr/rbd_support/mirror_snapshot_schedule.py
@@ -45,6 +45,7 @@ class CreateSnapshotRequests:
self.ioctxs: Dict[Tuple[str, str], Tuple[rados.Ioctx, Set[ImageSpec]]] = {}
def __del__(self) -> None:
+ self.log.debug("{} CreateSnapshotRequests.wait_for_pending: __del__".format(repr(self)))
self.wait_for_pending()
def wait_for_pending(self) -> None:
@@ -320,44 +321,44 @@ class CreateSnapshotRequests:
def get_ioctx(self, image_spec: ImageSpec) -> rados.Ioctx:
pool_id, namespace, image_id = image_spec
nspec = (pool_id, namespace)
- self.log.debug("entering CreateSnapshotRequests.get_ioctx: {}/{}/{}".format(
- pool_id, namespace, image_id))
+ self.log.debug("{} entering CreateSnapshotRequests.get_ioctx: {}/{}/{}".format(
+ repr(self), pool_id, namespace, image_id))