[DISPATCH-1956] log.c rewrite to reduce locking scope

• Type: Bug
• Status: Reopened
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 1.15.0
• Fix Version/s: 1.20.0
• Component/s: Router Node
• Labels: deadlock tsan
• Assignee: michael goulish
• Reporter: Ken Giusti
• Created: 11/Feb/21 15:43
• Updated: 15/Mar/22 21:54

Description

WARNING: ThreadSanitizer: lock-order-inversion (potential deadlock) (pid=1474955) 
 Cycle in lock order graph: M11 (0x7b10000002c0) => M9 (0x7b1000000240) => M11 
 
 Mutex M9 acquired here while holding mutex M11 in main thread: 
 #0 pthread_mutex_lock <null> (libtsan.so.0+0x528ac) 
 #1 sys_mutex_lock /home/kgiusti/work/dispatch/qpid-dispatch/src/posix/threading.c:57 (libqpid-dispatch.so+0x8cb7d) 
 #2 push_event /home/kgiusti/work/dispatch/qpid-dispatch/src/entity_cache.c:63 (libqpid-dispatch.so+0x6fa13) 
 #3 qd_entity_cache_add /home/kgiusti/work/dispatch/qpid-dispatch/src/entity_cache.c:69 (libqpid-dispatch.so+0x6fc26) 
 #4 qd_alloc_init /home/kgiusti/work/dispatch/qpid-dispatch/src/alloc_pool.c:302 (libqpid-dispatch.so+0x5878b) 
 #5 qd_alloc /home/kgiusti/work/dispatch/qpid-dispatch/src/alloc_pool.c:318 (libqpid-dispatch.so+0x5878b) 
 #6 new_qd_log_entry_t /home/kgiusti/work/dispatch/qpid-dispatch/src/log.c:61 (libqpid-dispatch.so+0x75891) 
 #7 qd_vlog_impl /home/kgiusti/work/dispatch/qpid-dispatch/src/log.c:426 (libqpid-dispatch.so+0x76205) 
 #8 qd_log_impl /home/kgiusti/work/dispatch/qpid-dispatch/src/log.c:453 (libqpid-dispatch.so+0x76580) 
 #9 qd_python_log /home/kgiusti/work/dispatch/qpid-dispatch/src/python_embedded.c:547 (libqpid-dispatch.so+0x8d1cb) 
 #10 <null> <null> (libpython3.8.so.1.0+0x12a23b) 
 #11 main_process /home/kgiusti/work/dispatch/qpid-dispatch/router/src/main.c:95 (qdrouterd+0x40281c) 
 #12 main /home/kgiusti/work/dispatch/qpid-dispatch/router/src/main.c:367 (qdrouterd+0x4024fc) 
 
 Hint: use TSAN_OPTIONS=second_deadlock_stack=1 to get more informative warning message 
 
 Mutex M11 acquired here while holding mutex M9 in main thread: 
 #0 pthread_mutex_lock <null> (libtsan.so.0+0x528ac) 
 #1 sys_mutex_lock /home/kgiusti/work/dispatch/qpid-dispatch/src/posix/threading.c:57 (libqpid-dispatch.so+0x8cb7d) 
 #2 qd_vlog_impl /home/kgiusti/work/dispatch/qpid-dispatch/src/log.c:425 (libqpid-dispatch.so+0x76200) 
 #3 qd_log_impl /home/kgiusti/work/dispatch/qpid-dispatch/src/log.c:453 (libqpid-dispatch.so+0x76580) 
 #4 qd_python_log /home/kgiusti/work/dispatch/qpid-dispatch/src/python_embedded.c:547 (libqpid-dispatch.so+0x8d1cb) 
 #5 <null> <null> (libpython3.8.so.1.0+0x12a23b) 
 #6 main_process /home/kgiusti/work/dispatch/qpid-dispatch/router/src/main.c:95 (qdrouterd+0x40281c) 
 #7 main /home/kgiusti/work/dispatch/qpid-dispatch/router/src/main.c:367 (qdrouterd+0x4024fc) 
 
SUMMARY: ThreadSanitizer: lock-order-inversion (potential deadlock) (/lib64/libtsan.so.0+0x528ac) in __interceptor_pthread_mutex_lock