[DISPATCH-2130] python lock inversion deadlock

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 1.16.0
• Fix Version/s: 1.20.0
• Component/s: Router Node
• Labels: deadlock tsan
• Assignee: Ken Giusti
• Reporter: Ken Giusti
• Created: 18/May/21 19:01
• Updated: 15/Mar/22 21:54

Description

The python lock is a top-level lock: no other locks should be held when taking the python lock.

The python lock is held for as long as the thread is running in python.  The python code often calls back into C, which takes locks as necessary (timers, server lock, whatever).

Debug code should be added to enforce this.

TSAN deadlock trace:

21: Mutex M253 acquired here while holding mutex M13 in main thread:
21: #0 pthread_mutex_lock <null> (libtsan.so.0+0x528ac)
<M253 == timer lock == qd_server->lock>
21: #1 sys_mutex_lock /home/kgiusti/work/dispatch/qpid-dispatch/src/posix/threading.c:57 (libqpid-dispatch.so+0xacee5)
21: #2 qd_timer_schedule /home/kgiusti/work/dispatch/qpid-dispatch/src/timer.c:216 (libqpid-dispatch.so+0x1350fe)
21: #3 qd_router_setup_late /home/kgiusti/work/dispatch/qpid-dispatch/src/router_node.c:2144 (libqpid-dispatch.so+0x128656)
21: #4 ffi_call_unix64 <null> (libffi.so.6+0x6aef)
21: #5 main_process /home/kgiusti/work/dispatch/qpid-dispatch/router/src/main.c:97 (qdrouterd+0x402697)
21: #6 main /home/kgiusti/work/dispatch/qpid-dispatch/router/src/main.c:369 (qdrouterd+0x403557)
21:
21: Mutex M13 previously acquired by the same thread here:
21: #0 pthread_mutex_lock <null> (libtsan.so.0+0x528ac)
<M13 == python ilock>
21: #1 sys_mutex_lock /home/kgiusti/work/dispatch/qpid-dispatch/src/posix/threading.c:57 (libqpid-dispatch.so+0xacee5)
21: #2 qd_python_lock /home/kgiusti/work/dispatch/qpid-dispatch/src/python_embedded.c:902 (libqpid-dispatch.so+0xb070e)
21: #3 qd_dispatch_load_config /home/kgiusti/work/dispatch/qpid-dispatch/src/dispatch.c:129 (libqpid-dispatch.so+0x80ad2)
21: #4 main_process /home/kgiusti/work/dispatch/qpid-dispatch/router/src/main.c:97 (qdrouterd+0x402697)
21: #5 main /home/kgiusti/work/dispatch/qpid-dispatch/router/src/main.c:369 (qdrouterd+0x403557)

---------------------------

21: Mutex M13 acquired here while holding mutex M253 in thread T4:
21: #0 pthread_mutex_lock <null> (libtsan.so.0+0x528ac)
<M13 == python ilock>
21: #1 sys_mutex_lock /home/kgiusti/work/dispatch/qpid-dispatch/src/posix/threading.c:57 (libqpid-dispatch.so+0xacee5)
21: #2 qd_python_lock /home/kgiusti/work/dispatch/qpid-dispatch/src/python_embedded.c:902 (libqpid-dispatch.so+0xb070e)
21: #3 qd_policy_socket_close /home/kgiusti/work/dispatch/qpid-dispatch/src/policy.c:296 (libqpid-dispatch.so+0xa3a8e)
21: #4 qd_connection_free /home/kgiusti/work/dispatch/qpid-dispatch/src/server.c:925 (libqpid-dispatch.so+0x12f703)
21: #5 thread_run /home/kgiusti/work/dispatch/qpid-dispatch/src/server.c:1127 (libqpid-dispatch.so+0x13069e)
21: #6 _thread_init /home/kgiusti/work/dispatch/qpid-dispatch/src/posix/threading.c:172 (libqpid-dispatch.so+0xad37a)
21: #7 <null> <null> (libtsan.so.0+0x2d33f)
21:
21: Mutex M253 previously acquired by the same thread here:
21: #0 pthread_mutex_lock <null> (libtsan.so.0+0x528ac)
<M253 == qd_server->lock>
21: #1 sys_mutex_lock /home/kgiusti/work/dispatch/qpid-dispatch/src/posix/threading.c:57 (libqpid-dispatch.so+0xacee5)
21: #2 qd_connection_free /home/kgiusti/work/dispatch/qpid-dispatch/src/server.c:920 (libqpid-dispatch.so+0x12f48f)
21: #3 thread_run /home/kgiusti/work/dispatch/qpid-dispatch/src/server.c:1127 (libqpid-dispatch.so+0x13069e)
21: #4 _thread_init /home/kgiusti/work/dispatch/qpid-dispatch/src/posix/threading.c:172 (libqpid-dispatch.so+0xad37a)
21: #5 <null> <null> (libtsan.so.0+0x2d33f)