Uploaded image for project: 'Qpid Dispatch'
  1. Qpid Dispatch
  2. DISPATCH-2180

Race: timer freeing qd_message_t during cleanup conflict with I/O threads

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Open
    • Critical
    • Resolution: Unresolved
    • 1.17.0
    • 1.20.0
    • None

    Description

      This is a PR build, but I think it is unlikely the build changes in PR caused this.

      https://github.com/apache/qpid-dispatch/pull/1267/checks?check_run_id=2872865196#step:25:804

       26: Router EA1 output file:
26: >>>>
26: ==================
26: WARNING: ThreadSanitizer: data race (pid=1865)
26:   Read of size 8 at 0x7b480001b600 by thread T2:
26:     #0 qd_alloc_sequence /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/alloc_pool.c:525 (qdrouterd+0x44df98)
26:     #1 cleanup_link /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/container.c:359 (qdrouterd+0x462da3)
26:     #2 qd_link_free /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/container.c:1000 (qdrouterd+0x4632b5)
26:     #3 qd_link_free /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/container.c:991 (qdrouterd+0x463392)
26:     #4 AMQP_link_detach_handler /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_node.c:1142 (qdrouterd+0x4dc8f1)
26:     #5 AMQP_link_detach_handler /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_node.c:1095 (qdrouterd+0x4dc8f1)
26:     #6 close_links /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/container.c:336 (qdrouterd+0x463419)
26:     #7 qd_container_handle_event /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/container.c:528 (qdrouterd+0x4643f3)
26:     #8 handle /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:1096 (qdrouterd+0x4e1c51)
26:     #9 thread_run /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:1121 (qdrouterd+0x4e3f0b)
26:     #10 _thread_init /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/posix/threading.c:172 (qdrouterd+0x4868bd)
26: 
26:   Previous write of size 8 at 0x7b480001b600 by main thread:
26:     #0 qd_dealloc /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/alloc_pool.c:477 (qdrouterd+0x44d6d6)
26:     #1 free_qd_message_t /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/message.c:91 (qdrouterd+0x472a1b)
26:     #2 qd_message_free /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/message.c:1091 (qdrouterd+0x472a1b)
26:     #3 qdr_do_message_to_addr_free /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:102 (qdrouterd+0x4bcfa6)
26:     #4 qdr_general_handler /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core.c:942 (qdrouterd+0x4b5bc3)
26:     #5 qd_timer_visit /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/timer.c:316 (qdrouterd+0x4e6bb5)
26:     #6 handle /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:1006 (qdrouterd+0x4e1be6)
26:     #7 thread_run /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:1121 (qdrouterd+0x4e4005)
26:     #8 qd_server_run /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:1501 (qdrouterd+0x4e4c11)
26:     #9 main_process /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/router/src/main.c:115 (qdrouterd+0x426ccc)
26:     #10 main /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/router/src/main.c:369 (qdrouterd+0x42622c)
26: 
26:   Location is heap block of size 384 at 0x7b480001b600 allocated by thread T1:
26:     #0 posix_memalign <null> (libtsan.so.0+0x32a23)
26:     #1 qd_alloc /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/alloc_pool.c:396 (qdrouterd+0x44c6d4)
26:     #2 new_qd_message_t /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/message.c:91 (qdrouterd+0x475a3d)
26:     #3 qd_message_copy /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/message.c:1099 (qdrouterd+0x475a3d)
26:     #4 qdr_forward_on_message_CT /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/forwarder.c:401 (qdrouterd+0x4af41b)
26:     #5 qdr_forward_to_subscriber_CT /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/forwarder.c:451 (qdrouterd+0x4af6ef)
26:     #6 qdr_forward_closest_CT /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/forwarder.c:644 (qdrouterd+0x4b073b)
26:     #7 qdr_forward_message_CT /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/forwarder.c:1120 (qdrouterd+0x4b22a0)
26:     #8 qdr_link_forward_CT /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/transfer.c:572 (qdrouterd+0x4c5a43)
26:     #9 qdr_link_deliver_CT /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/transfer.c:862 (qdrouterd+0x4c6f52)
26:     #10 router_core_thread /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:239 (qdrouterd+0x4bdcc1)
26:     #11 _thread_init /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/posix/threading.c:172 (qdrouterd+0x4868bd)
26: 
26:   Thread T2 (tid=1868, running) created by main thread at:
26:     #0 pthread_create <null> (libtsan.so.0+0x5bf45)
26:     #1 sys_thread /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/posix/threading.c:181 (qdrouterd+0x486d4c)
26:     #2 qd_server_run /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:1499 (qdrouterd+0x4e4bec)
26:     #3 main_process /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/router/src/main.c:115 (qdrouterd+0x426ccc)
26:     #4 main /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/router/src/main.c:369 (qdrouterd+0x42622c)
26: 
26:   Thread T1 (tid=1867, running) created by main thread at:
26:     #0 pthread_create <null> (libtsan.so.0+0x5bf45)
26:     #1 sys_thread /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/posix/threading.c:181 (qdrouterd+0x486d4c)
26:     #2 qdr_core /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core.c:124 (qdrouterd+0x4b7170)
26:     #3 qd_router_setup_late /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_node.c:2124 (qdrouterd+0x4dce28)
26:     #4 ffi_call_unix64 <null> (libffi.so.6+0x6c03)
26:     #5 main_process /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/router/src/main.c:97 (qdrouterd+0x426c6c)
26:     #6 main /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/router/src/main.c:369 (qdrouterd+0x42622c)
26: 
26: SUMMARY: ThreadSanitizer: data race /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/alloc_pool.c:525 in qd_alloc_sequence
26: ==================
26: ThreadSanitizer: reported 1 warnings
26: 
26: <<<<
26: 
26: Router EA1 command file:
26: >>>>
26: qdrouterd -c EA1.conf -I /home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/python
26: pid=1865
26: 
26: <<<<
26: 
26: Router EA1 log file tail:
26: >>>>
26: 2021-06-21 07:29:07.882159 +0000 PROTOCOL (trace) [C1]:FRAME: 2 -> @disposition(21) [role=true, first=19, settled=true, state=@accepted(36) []] (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:111)
26: 2021-06-21 07:29:07.882322 +0000 PROTOCOL (trace) [C1]:FRAME: 0 -> @detach(22) [handle=2, closed=true] (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:111)
26: 2021-06-21 07:29:07.882607 +0000 PROTOCOL (trace) [C19]:FRAME:   -> EOS (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:111)
26: 2021-06-21 07:29:07.882774 +0000 POLICY (debug) [C19] Connection '127.0.0.1:58174' closed with resources n_sessions=1, n_senders=0, n_receivers=0, sessions_denied=0, senders_denied=0, receivers_denied=0, max_message_size_denied:4, nConnections= 1. (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/policy.c:318)
26: 2021-06-21 07:29:07.886179 +0000 ROUTER_CORE (trace) Core action 'connection_closed' (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:238)
26: 2021-06-21 07:29:07.886279 +0000 ROUTER_CORE (info) [C19][L40] Link closed due to connection loss: del=10 presett=0 psdrop=0 acc=10 rej=0 rel=0 mod=0 delay1=0 delay10=0 blocked=no (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/connections.c:1082)
26: 2021-06-21 07:29:07.886346 +0000 ROUTER_CORE (info) [C19] Connection Closed (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/connections.c:1565)
26: 2021-06-21 07:29:07.895274 +0000 PROTOCOL (trace) [C1]:FRAME: 0 <- @detach(22) [handle=2, closed=true] (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:111)
26: 2021-06-21 07:29:07.895512 +0000 ROUTER_CORE (trace) Core action 'link_detach' (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:238)
26: 2021-06-21 07:29:07.895595 +0000 ROUTER_CORE (info) [C1][L41] Link detached: del=0 presett=0 psdrop=0 acc=0 rej=0 rel=0 mod=0 delay1=0 delay10=0 blocked=no (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/connections.c:1082)
26: 2021-06-21 07:29:08.316474 +0000 ROUTER_CORE (trace) Core action 'process_tick' (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:238)
26: 2021-06-21 07:29:08.328086 +0000 PROTOCOL (trace) [C4]:FRAME: 0 <- @flow(19) [next-incoming-id=2, incoming-window=2147483647, next-outgoing-id=2, outgoing-window=2147483647, handle=1, delivery-count=2, link-credit=1, drain=false] (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:111)
26: 2021-06-21 07:29:08.328210 +0000 PROTOCOL (trace) [C4]:FRAME: 0 <- @close(24) [] (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:111)
26: 2021-06-21 07:29:08.328290 +0000 PROTOCOL (trace) [C4]:FRAME:   <- EOS (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:111)
26: 2021-06-21 07:29:08.328520 +0000 PROTOCOL (trace) [C4]:FRAME: 0 -> @close(24) [] (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:111)
26: 2021-06-21 07:29:08.328579 +0000 ROUTER_CORE (trace) Core action 'link_flow' (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:238)
26: 2021-06-21 07:29:08.328665 +0000 ROUTER_CORE (trace) Core action 'link_detach' (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:238)
26: 2021-06-21 07:29:08.328749 +0000 ROUTER_CORE (info) [C4][L9] Link lost: del=2 presett=0 psdrop=0 acc=2 rej=0 rel=0 mod=0 delay1=0 delay10=0 blocked=no (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/connections.c:1082)
26: 2021-06-21 07:29:08.328813 +0000 ROUTER_CORE (trace) Core action 'link_detach' (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:238)
26: 2021-06-21 07:29:08.328882 +0000 ROUTER_CORE (info) [C4][L10] Link lost: del=2 presett=2 psdrop=0 acc=0 rej=0 rel=0 mod=0 delay1=0 delay10=0 blocked=no (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/connections.c:1082)
26: 2021-06-21 07:29:08.329618 +0000 PROTOCOL (trace) [C4]:FRAME:   -> EOS (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:111)
26: 2021-06-21 07:29:08.329770 +0000 ROUTER_CORE (trace) Core action 'connection_closed' (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:238)
26: 2021-06-21 07:29:08.329846 +0000 POLICY (debug) [C4] Connection '127.0.0.1:57890' closed with resources n_sessions=1, n_senders=1, n_receivers=1, sessions_denied=0, senders_denied=0, receivers_denied=0, max_message_size_denied:4, nConnections= 0. (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/policy.c:318)
26: 2021-06-21 07:29:08.329914 +0000 ROUTER_CORE (info) [C4] Connection Closed (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/connections.c:1565)
26: 2021-06-21 07:29:08.330881 +0000 SERVER (notice) Shut Down (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:1508)
26: 2021-06-21 07:29:08.330983 +0000 HTTP (trace) lws_context_destroy: ctx 0x7b8c00000000 (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/http-libwebsockets.c:58)
26: 2021-06-21 07:29:08.331079 +0000 HTTP (trace) _lws_state_transition: system: changed 1 'CONTEXT_CREATED' -> 13 'POLICY_INVALID' (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/http-libwebsockets.c:58)
26: 2021-06-21 07:29:08.331143 +0000 HTTP (trace) lws_destroy_event_pipe (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/http-libwebsockets.c:58)
26: 2021-06-21 07:29:08.331208 +0000 HTTP (trace) lws_pt_destroy: pt destroyed (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/http-libwebsockets.c:58)
26: 2021-06-21 07:29:08.331261 +0000 HTTP (trace) lws_context_destroy2: ctx 0x7b8c00000000 (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/http-libwebsockets.c:58)
26: 2021-06-21 07:29:08.331310 +0000 HTTP (trace) 0x7f3883ade9e0: post vh listl (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/http-libwebsockets.c:58)
26: 2021-06-21 07:29:08.331358 +0000 HTTP (trace) 0x7f3883ade9e0: post pdl (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/http-libwebsockets.c:58)
26: 2021-06-21 07:29:08.334179 +0000 HTTP (trace) 0x7f3883ade9e0: baggage (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/http-libwebsockets.c:58)
26: 2021-06-21 07:29:08.334243 +0000 HTTP (trace) 0x7f3883ade9e0: post dc2 (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/http-libwebsockets.c:58)
26: 2021-06-21 07:29:08.337107 +0000 HTTP (trace) lws_context_destroy3: ctx 0x7b8c00000000 freed (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/http-libwebsockets.c:58)
26: 2021-06-21 07:29:08.337321 +0000 CONTAINER (trace) Default node removed (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/container.c:852)
26: 2021-06-21 07:29:08.337509 +0000 ROUTER_CORE (info) Router Core thread exited (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:259)
26: 2021-06-21 07:29:08.337713 +0000 TCP_ADAPTOR (info) Shutting down TCP protocol adaptor (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/adaptors/tcp_adaptor.c:1760)
26: 2021-06-21 07:29:08.338504 +0000 ROUTER_CORE (trace) Core client sender detached c=0x7b4800015e10 (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/core_client_api.c:581)
26: 2021-06-21 07:29:08.338573 +0000 ROUTER_CORE (trace) edge mgmt client state change: uc=(nil) down (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/modules/edge_router/edge_mgmt.c:139)
26: 2021-06-21 07:29:08.338642 +0000 ROUTER_CORE (trace) Core client receiver detached c=0x7b4800015e10 (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/core_client_api.c:614)
26: 2021-06-21 07:29:08.338701 +0000 ROUTER_CORE (trace) Core client sender detached c=0x7b4800015c90 (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/core_client_api.c:581)
26: 2021-06-21 07:29:08.338773 +0000 ROUTER_CORE (trace) Core client receiver detached c=0x7b4800015c90 (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/core_client_api.c:614)
26: 2021-06-21 07:29:08.338859 +0000 ROUTER_CORE (info) Finalizing core module: streaming_link_scrubber (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:138)
26: 2021-06-21 07:29:08.338919 +0000 ROUTER_CORE (info) Finalizing core module: stuck_delivery_detection (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:138)
26: 2021-06-21 07:29:08.338969 +0000 ROUTER_CORE (info) Finalizing core module: address_lookup_client (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:138)
26: 2021-06-21 07:29:08.339032 +0000 ROUTER_CORE (trace) Core client freed c=0x7b4800015c90 (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/core_client_api.c:224)
26: 2021-06-21 07:29:08.339101 +0000 ROUTER_CORE (info) Finalizing core module: edge_router (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/router_core_thread.c:138)
26: 2021-06-21 07:29:08.339161 +0000 ROUTER_CORE (trace) Core client freed c=0x7b4800015e10 (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/router_core/core_client_api.c:224)
26: 2021-06-21 07:29:08.339387 +0000 SERVER (info) [C1] Closing connection on shutdown (/home/runner/work/qpid-dispatch/qpid-dispatch/qpid-dispatch/src/server.c:1388)
26: 
26: <<<<
26: 
26: ::MaxMessageSizeBlockOversize::test_s32_allow_gt_signed_32bit_max ERROR

      Attachments

        Issue Links

          duplicates

          Bug - A problem which impairs or prevents the functions of the product. DISPATCH-2172 TSan data race from qd_message_free in system_tests_http1_adaptor

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. DISPATCH-2182 Data races in cleanup from system_tests_topology_disposition

          • Major - Major loss of function.
          • Closed
          is cloned by

          Bug - A problem which impairs or prevents the functions of the product. DISPATCH-2182 Data races in cleanup from system_tests_topology_disposition

          • Major - Major loss of function.
          • Closed

          Activity

            People

              Unassigned Unassigned
              jdanek Jiri Daněk
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated: