[
https://issues.apache.org/jira/browse/DISPATCH-1989?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17298260#comment-17298260
]
Alex Ward commented on DISPATCH-1989:
-------------------------------------
OK this doesn;t seem right.
Normally when I dump the loop's handle_queue in uv__finish_close I see a happy
linked list.
The trace lines below show "handle_address [next, previous]", in a good case
below we see all the previous pointers pointing up the list in the reverse
direction from the next pointers. The first entry previous points to the list
head and the last entry next points to the list head. All seems well.
{{[19846] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__finish_close(uv_handle_t *) before QUEUE_REMOVE handle_queue
0x61a0000c4f98,0x61d000590e48" ../../../../distro/src/unix/core.c:367}}
{{[19847] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [--I] signal 0x61a0000c51b0
[0x61a0000c5038,0x61a0000c4f98]" ../../../../distro/src/un}}
{{ix/core.c:293}}
{{[19848] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [-AI] async 0x61a0000c5018
[0x61a0000c4ea0,0x61a0000c51d0]" ../../../../distro/src/un}}
{{ix/core.c:293}}
{{[19849] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] async 0x61a0000c4e80
[0x61a0000c4f20,0x61a0000c5038]" ../../../../distro/src/un}}
{{ix/core.c:293}}
{{[19850] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] async 0x61a0000c4f00
[0x61a0000c5270,0x61a0000c4ea0]" ../../../../distro/src/un}}
{{ix/core.c:293}}
{{[19851] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] timer 0x61a0000c5250
[0x612000030370,0x61a0000c4f20]" ../../../../distro/src/un}}
{{ix/core.c:293}}
{{[19852] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] tcp 0x612000030350
[0x61d00058fce8,0x61a0000c5270]" ../../../../distro/src/un}}
{{ix/core.c:293}}
{{[19853] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [R--] tcp 0x61d00058fcc8
[0x61d000590448,0x612000030370]" ../../../../distro/src/un}}
{{ix/core.c:293}}
{{[19854] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [R--] timer 0x61d000590428
[0x61d0005906e8,0x61d00058fce8]" ../../../../distro/src/un}}
{{ix/core.c:293}}
{{[19855] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [R--] tcp 0x61d0005906c8
[0x61d000590e48,0x61d000590448]" ../../../../distro/src/un}}
{{ix/core.c:293}}
{{[19856] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [R--] timer 0x61d000590e28
[0x61d000594a48,0x61d0005906e8]" ../../../../distro/src/un}}
{{ix/core.c:293}}
{{[19857] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [---] timer 0x61d000594a28
[0x61a0000c4f98,0x61d000590e48]" ../../../../distro/src/un}}
{{ix/core.c:293}}
At some point the starts to look malformed.
Here we see on line [20398] the previous pointer is {{0x61d000590e48}} not the
{{0x612000030370}} you would expect.
In face, both entry on [20398] and [20399] have the same previous pointer of
{{0x61d000590e48 which does not represent an entry on the list. }}{{[20400]
points back to [20399] correctly.}}{{}}
{{The entry being removed from the list is 0x61d000590428, the timer handle
listed on line [20399]. This time around seems to complete but the next time
uv__finish_close is called I get a use after free in the list traversal around
about the entry 0x612000030350.}}
{{This looks wroong, right?}}
{{[20390] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__finish_close(uv_handle_t *) handle 0x61d000590428 data 0x61d00058fc80 flags
9 type 13" ../../../../distro/src/unix/core.c:303}}
{{[20391] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__finish_close(uv_handle_t *) before QUEUE_REMOVE handle_queue
0x61d0005a5ae8,0x61d000590e48" ../../../../distro/src/unix/core.c:367}}
{{[20392] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [--I] signal 0x61a0000c51b0
[0x61a0000c5038,0x61a0000c4f98]" ../../../../distro/src/unix/core.c:293}}
{{[20393] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [-AI] async 0x61a0000c5018
[0x61a0000c4ea0,0x61a0000c51d0]" ../../../../distro/src/unix/core.c:293}}
{{[20394] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] async 0x61a0000c4e80
[0x61a0000c4f20,0x61a0000c5038]" ../../../../distro/src/unix/core.c:293}}
{{[20395] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] async 0x61a0000c4f00
[0x61a0000c5270,0x61a0000c4ea0]" ../../../../distro/src/unix/core.c:293}}
{{[20396] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] timer 0x61a0000c5250
[0x612000030370,0x61a0000c4f20]" ../../../../distro/src/unix/core.c:293}}
{{[20397] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] tcp 0x612000030350
[0x61d00058fce8,0x61a0000c5270]" ../../../../distro/src/unix/core.c:293}}
{{[20398] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [---] tcp 0x61d00058fcc8
[0x61d000590448,0x61d000590e48]" ../../../../distro/src/unix/core.c:293}}
{{[20399] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [---] timer 0x61d000590428
[0x61d0005a5ae8,0x61d000590e48]" ../../../../distro/src/unix/core.c:293}}
{{[20400] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] tcp 0x61d0005a5ac8
[0x61d0005a6248,0x61d000590448]" ../../../../distro/src/unix/core.c:293}}
{{[20401] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] timer 0x61d0005a6228
[0x61d0005a64e8,0x61d0005a5ae8]" ../../../../distro/src/unix/core.c:293}}
{{[20402] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] tcp 0x61d0005a64c8
[0x61d0005a6c48,0x61d0005a6248]" ../../../../distro/src/unix/core.c:293}}
{{[20403] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] timer 0x61d0005a6c28
[0x61a0000c4f98,0x61d0005a64e8]" ../../../../distro/src/unix/core.c:293}}
{{[}}
> ASAN use after free in connection close
> ---------------------------------------
>
> Key: DISPATCH-1989
> URL: https://issues.apache.org/jira/browse/DISPATCH-1989
> Project: Qpid Dispatch
> Issue Type: Bug
> Components: Router Node, Routing Engine
> Affects Versions: 1.13.0, 1.14.0
> Reporter: Alex Ward
> Priority: Minor
> Attachments: mtrace.txt, qdrouterd.txt
>
>
> While we dig into the issue below I thought it worth reaching out to see if
> this is a familiar issue or in code that has changed much since 1.13 so may
> have likely already been fixed.
> We have a freebsd product that is using qdrouterd. We have had some crashes
> during closing of connections to a broker so built a qdrouterd with asan on.
> This is hitting the use-after-free issue in uv__run_closing_handles below
> fairly reliably.
> It appears from first inspection that uv__finish_close is trying to remove a
> handle from the handle_queue at line 300 but the handle_queue has reference
> into a pconnection_t that has already been freed.
> Is this an area of code that has had issues in the past? Is this likely to
> have been fixed in the latest release? Any suggestions on where to add
> printfs etc to identify the culprit?
>
>
> {{243static void uv__finish_close(uv_handle_t* handle) {}}
> {{244 uv_signal_t* sh;}}
> {{245}}
> {{246 /* Note: while the handle is in the UV_HANDLE_CLOSING state now, it's
> still}}
> {{247 * possible for it to be active in the sense that uv__is_active()
> returns}}
> {{248 * true.}}
> {{249 *}}
> {{250 * A good example is when the user calls uv_shutdown(), immediately
> followed}}
> {{251 * by uv_close(). The handle is considered active at this point because
> the}}
> {{252 * completion of the shutdown req is still pending.}}
> {{253 */}}
> {{254 assert(handle->flags & UV_HANDLE_CLOSING);}}
> {{255 assert(!(handle->flags & UV_HANDLE_CLOSED));}}
> {{256 handle->flags |= UV_HANDLE_CLOSED;}}
> {{257}}
> {{258 switch (handle->type) {}}
> {{259 case UV_PREPARE:}}
> {{260 case UV_CHECK:}}
> {{261 case UV_IDLE:}}
> {{262 case UV_ASYNC:}}
> {{263 case UV_TIMER:}}
> {{264 case UV_PROCESS:}}
> {{265 case UV_FS_EVENT:}}
> {{266 case UV_FS_POLL:}}
> {{267 case UV_POLL:}}
> {{268 break;}}
> {{269}}
> {{270 case UV_SIGNAL:}}
> {{271 /* If there are any caught signals "trapped" in the signal pipe,}}
> {{272 * we can't call the close callback yet. Reinserting the handle}}
> {{273 * into the closing queue makes the event loop spin but that's}}
> {{274 * okay because we only need to deliver the pending events.}}
> {{275 */}}
> {{276 sh = (uv_signal_t*) handle;}}
> {{277 if (sh->caught_signals > sh->dispatched_signals) {}}
> {{278 handle->flags ^= UV_HANDLE_CLOSED;}}
> {{279 uv__make_close_pending(handle); /* Back into the queue. */}}
> {{280 return;}}
> {{281 }}}
> {{282 break;}}
> {{283}}
> {{284 case UV_NAMED_PIPE:}}
> {{285 case UV_TCP:}}
> {{286 case UV_TTY:}}
> {{287 uv__stream_destroy((uv_stream_t*)handle);}}
> {{288 break;}}
> {{289}}
> {{290 case UV_UDP:}}
> {{291 uv__udp_finish_close((uv_udp_t*)handle);}}
> {{292 break;}}
> {{293}}
> {{294 default:}}
> {{295 assert(0);}}
> {{296 break;}}
> {{297 }}}
> {{298}}
> {{299 uv__handle_unref(handle);}}
> {{300 QUEUE_REMOVE(&handle->handle_queue);}}
> {{301}}
> {{302 if (handle->close_cb) {}}
> {{303 handle->close_cb(handle);}}
> {{304 }}}
> {{305}}}
>
> Here's the asan report
> {{10 ==13358==ERROR: AddressSanitizer: heap-use-after-free on address
> 0x61d0002ec048 at pc 0x0008006a7f84 bp 0x7fffffffe8c0 sp 0x7fffffffe8b8}}
> {{11 WRITE of size 8 at 0x61d0002ec048 thread T0}}
> {{12 #0 0x8006a7f83 in uv__finish_close
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/libuv/bedrock/internal/x86_64.asan.sim/build_configure/../../../../distro/src/unix/core.c:300:3}}
> {{13 #1 0x8006a38db in uv__run_closing_handles
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/libuv/bedrock/internal/x86_64.asan.sim/build_configure/../../../../distro/src/unix/core.c:317:5}}
> {{14 #2 0x8006a3463 in uv_run
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/libuv/bedrock/internal/x86_64.asan.sim/build_configure/../../../../distro/src/unix/core.c:387:5}}
> {{15 #3 0x800b378b5 in leader_lead_lh
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-proton/distro/c/src/proactor/libuv.c:1039:5}}
> {{16 #4 0x800b37a5c in pn_proactor_wait
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-proton/distro/c/src/proactor/libuv.c:1072:15}}
> {{17 #5 0x8005b55c0 in thread_run
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-dispatch/distro/src/server.c:1051:36}}
> {{18 #6 0x8005b524b in qd_server_run
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-dispatch/distro/src/server.c:1453:5}}
> {{19 #7 0x2b8e20 in main_process
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-dispatch/distro/router/src/main.c:130:5}}
> {{20 #8 0x2b7ef2 in main
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-dispatch/distro/router/src/main.c:384:9}}
> {{21 #9 0x2b780a in _start
> /x/eng/bbrtp2/daemon/DOT/dev/daemon_base/bsd99/bedrock/private/x86_64/bsd_libcrt_files/lib/csu/amd64/../../../../../../../src/lib/csu/amd64/crt1.c:74:7}}
> {{22 #10 0x8002e4fff (<unknown module>)}}
> {{23 }}
> {{24 0x61d0002ec048 is located 1992 bytes inside of 2408-byte region
> [0x61d0002eb880,0x61d0002ec1e8)}}
> {{25 freed by thread T5 here:}}
> {{26 #0 0x28ca2d in free
> /x/eng/bbrtp2/daemon/DOT/dev/daemon_base/third_party/open_source/llvm/distro/compiler-rt/lib/asan/asan_malloc_linux.cpp:123:3}}
> {{27 #1 0x800b3aec7 in pconnection_free
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-proton/distro/c/src/proactor/libuv.c:363:3}}
> {{28 #2 0x800b3ae05 in on_close_pconnection_final
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-proton/distro/c/src/proactor/libuv.c:421:3}}
> {{29 #3 0x8006a7e28 in uv__finish_close
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/libuv/bedrock/internal/x86_64.asan.sim/build_configure/../../../../distro/src/unix/core.c:303:5}}
> {{30 #4 0x8006a38db in uv__run_closing_handles
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/libuv/bedrock/internal/x86_64.asan.sim/build_configure/../../../../distro/src/unix/core.c:317:5}}
> {{31 #5 0x8006a3463 in uv_run
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/libuv/bedrock/internal/x86_64.asan.sim/build_configure/../../../../distro/src/unix/core.c:387:5}}
> {{32 #6 0x800b378b5 in leader_lead_lh
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-proton/distro/c/src/proactor/libuv.c:1039:5}}
> {{33 #7 0x800b37a5c in pn_proactor_wait
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-proton/distro/c/src/proactor/libuv.c:1072:15}}
> {{34 #8 0x8005b55c0 in thread_run
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-dispatch/distro/src/server.c:1051:36}}
> {{35 #9 0x8005be392 in _thread_init
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-dispatch/distro/src/posix/threading.c:172:12}}
> {{36 #10 0x800eb20f4 in thread_start
> /x/eng/bbrtp2/daemon/DOT/dev/daemon_base/bsd99/bedrock/private/x86_64/bsd_libthr/lib/libthr/../../../../../../src/lib/libthr/thread/thr_create.c:300:16}}
> {{37 }}
> {{38 previously allocated by thread T5 here:}}
> {{39 #0 0x28cd12 in calloc
> /x/eng/bbrtp2/daemon/DOT/dev/daemon_base/third_party/open_source/llvm/distro/compiler-rt/lib/asan/asan_malloc_linux.cpp:154:3}}
> {{40 #1 0x800b38288 in pconnection
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-proton/distro/c/src/proactor/libuv.c:339:39}}
> {{41 #2 0x800b381e0 in pn_proactor_connect2
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-proton/distro/c/src/proactor/libuv.c:1168:23}}
> {{42 #3 0x800b4658d in pn_proactor_connect
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-proton/distro/c/src/proactor/proactor-internal.c:97:3}}
> {{43 #4 0x8005b8156 in try_open_lh
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-dispatch/distro/src/server.c:1169:5}}
> {{44 #5 0x8005b641e in try_open_cb
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-dispatch/distro/src/server.c:1278:14}}
> {{45 #6 0x8005bf6ad in qd_timer_visit
> /x/eng/bbrtp3/users/alward/resilasan_5930910_2102181129/third_party/open_source/qpid-dispatch/distro/src/timer.c:201:9}}
> {{46 #7 0x8005b6ef8 (/usr/lib/libqpid-dispatch.so
> (distro/router/src/main.c:43)}}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
