You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Ganesh Murthy (Jira)" <ji...@apache.org> on 2021/11/02 19:34:00 UTC
[jira] [Updated] (DISPATCH-2180) Race: timer freeing qd_message_t
during cleanup conflict with I/O threads
[ https://issues.apache.org/jira/browse/DISPATCH-2180?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ganesh Murthy updated DISPATCH-2180:
------------------------------------
Fix Version/s: (was: 1.18.0)
1.19.0
> Race: timer freeing qd_message_t during cleanup conflict with I/O threads
> -------------------------------------------------------------------------
>
> Key: DISPATCH-2180
> URL: https://issues.apache.org/jira/browse/DISPATCH-2180
> Project: Qpid Dispatch
> Issue Type: Bug
> Affects Versions: 1.17.0
> Reporter: Jiri Daněk
> Priority: Critical
> Labels: race-condition, tsan
> Fix For: 1.19.0
>
>
> 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
> {noformat}
> 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
> {noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org