[DISPATCH-2070] Data race when incrementing severity_histogram from logging calls

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: 1.16.0
• Fix Version/s: Backlog
• Labels: race-condition tsan
• Assignee: Michael Goulish
• Reporter: Jiri Daněk
• Created: 21/Apr/21 09:26
• Updated: 02/Nov/21 19:24

Description

% TSAN_OPTIONS=second_deadlock_stack=1 router/qdrouterd -c ./tests/system_test.dir/system_tests_policy/LoadPolicyFromFolder/setUpClass/conn-limit-router.conf -I /home/jdanek/repos/qpid/qpid-dispatch/python
==================
WARNING: ThreadSanitizer: data race (pid=14373)
  Read of size 8 at 0x7b1c000006d0 by thread T1:
    #0 qd_vlog_impl ../src/log.c:420 (libqpid-dispatch.so+0x791c4)
    #1 qd_log_impl ../src/log.c:456 (libqpid-dispatch.so+0x795e8)
    #2 qdr_subscribe_CT ../src/router_core/route_tables.c:633 (libqpid-dispatch.so+0xc5d7e)
    #3 router_core_thread ../src/router_core/router_core_thread.c:239 (libqpid-dispatch.so+0xc40d7)
    #4 _thread_init ../src/posix/threading.c:172 (libqpid-dispatch.so+0x8f3cf)
    #5 <null> <null> (libtsan.so.0+0x30f0f)

  Previous write of size 8 at 0x7b1c000006d0 by main thread (mutexes: write M14):
    #0 qd_vlog_impl ../src/log.c:420 (libqpid-dispatch.so+0x791d4)
    #1 qd_log_impl ../src/log.c:456 (libqpid-dispatch.so+0x795e8)
    #2 qdr_protocol_adaptor ../src/router_core/router_core.c:1050 (libqpid-dispatch.so+0xc2f81)
    #3 qd_router_setup_late ../src/router_node.c:2121 (libqpid-dispatch.so+0xe3b03)
    #4 ffi_call_unix64 <null> (libffi.so.7+0x7abc)
    #5 main_process ../router/src/main.c:97 (qdrouterd+0x4025ae)
    #6 main ../router/src/main.c:369 (qdrouterd+0x4032ae)

  Location is heap block of size 104 at 0x7b1c00000690 allocated by main thread:
    #0 malloc <null> (libtsan.so.0+0x33dc1)
    #1 qd_malloc ../include/qpid/dispatch/ctools.h:229 (libqpid-dispatch.so+0x78763)
    #2 qd_log_source_lh ../src/log.c:367 (libqpid-dispatch.so+0x78763)
    #3 qd_log_entity ../src/log.c:545 (libqpid-dispatch.so+0x79c7e)
    #4 ffi_call_unix64 <null> (libffi.so.7+0x7abc)
    #5 main_process ../router/src/main.c:97 (qdrouterd+0x4025ae)
    #6 main ../router/src/main.c:369 (qdrouterd+0x4032ae)

  Mutex M14 (0x7b1000000300) created at:
    #0 pthread_mutex_init <null> (libtsan.so.0+0x4a764)
    #1 sys_mutex ../src/posix/threading.c:43 (libqpid-dispatch.so+0x8f447)
    #2 qd_python_initialize ../src/python_embedded.c:54 (libqpid-dispatch.so+0x91ea4)
    #3 qd_dispatch ../src/dispatch.c:111 (libqpid-dispatch.so+0x71595)
    #4 main_process ../router/src/main.c:92 (qdrouterd+0x40254d)
    #5 main ../router/src/main.c:369 (qdrouterd+0x4032ae)

  Thread T1 (tid=14376, running) created by main thread at:
    #0 pthread_create <null> (libtsan.so.0+0x5cba2)
    #1 sys_thread ../src/posix/threading.c:181 (libqpid-dispatch.so+0x8f89b)
    #2 qdr_core ../src/router_core/router_core.c:122 (libqpid-dispatch.so+0xbd91b)
    #3 qd_router_setup_late ../src/router_node.c:2119 (libqpid-dispatch.so+0xe3a56)
    #4 ffi_call_unix64 <null> (libffi.so.7+0x7abc)
    #5 main_process ../router/src/main.c:97 (qdrouterd+0x4025ae)
    #6 main ../router/src/main.c:369 (qdrouterd+0x4032ae)

SUMMARY: ThreadSanitizer: data race ../src/log.c:420 in qd_vlog_impl

The racy operation is

source->severity_histogram[level_index]++;