[
https://issues.apache.org/jira/browse/DISPATCH-1989?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17299677#comment-17299677
]
Alex Ward commented on DISPATCH-1989:
-------------------------------------
A little more data, it seems the use after free I'm seeing is being introduced
when a handle is added to the handle_queue that is already in it.
See attached file mtrace.3.9.txt
The loop handle_queue looks good here, all next pointers and previous pointers
in the uv__trace_handles look good.
[19840] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void uv_close(uv_handle_t *,
uv_close_cb) handle 0x61d000594a28 type 13 data 0x61d000594280 is_closing 0
flags 8" ../../../../distro/src/unix/core.c:123
[19841] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__timer_close(uv_timer_t *) handle 0x61d000594a28"
../../../../distro/src/timer.c:191
[19842] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__make_close_pending(uv_handle_t *) handle 0x61d000594a28 data 0x61d000594280
current 0x0" ../../../../distro/src/unix/core.c:232
[19843] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__run_closing_handles(uv_loop_t *) loop 0x61a0000c4f88"
../../../../distro/src/unix/core.c:393
[19844] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "p 0x61d000594a28 conn
0x61d000594280" ../../../../distro/src/unix/core.c:394
[19845] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__finish_close(uv_handle_t *) handle 0x61d000594a28 data 0x61d000594280 flags
9 type 13" ../../../../distro/src/unix/core.c:303
[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/unix/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/unix/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/unix/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/unix/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/unix/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/unix/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/unix/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/unix/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/unix/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/unix/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/unix/core.c:293
[19858] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
uv__finish_close(uv_handle_t *) before close_cb 0x61d000594a28 3"
../../../../distro/src/unix/core.c:378
[19859] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "void
on_close_pconnection_final(uv_handle_t *) handle 0x61d000594a28 pc
0x61d000594280" distro/c/src/proactor/libuv.c:431
[19860] (2021-03-09 10:17:49) tid:0x61a0000c9c80 "pconnection_free() pc
0x61d000594280" distro/c/src/proactor/libuv.c:364
Between this and the next time a handle is removed from the handle_queue, the
following handles streams are created, and will have been added to list
[19872] (2021-03-09 10:17:51) tid:0x61a0000c9c80 "void
uv__stream_init(uv_loop_t *, uv_stream_t *, uv_handle_type) h 0x61d0005a3cc8
data 0x0 type 12 &hq 0x61d0005a3ce8 hq[0x61a0000c4f98,0x61d000590e48]"
../../../../distro/src/unix/stream.c:90
[19873] (2021-03-09 10:17:51) tid:0x61a0000c9c80 "int uv_timer_init(uv_loop_t
*, uv_timer_t *) h 0x61d0005a4428 data 0x0 type 13 &hq 0x61d0005a4448
hq[0x61a0000c4f98,0x61d0005a3ce8]" ../../../../distro/src/timer.c:66
[19967] (2021-03-09 10:17:51) tid:0x2d2310 <alloc_memory_for_dlsym> "void
uv__stream_init(uv_loop_t *, uv_stream_t *, uv_handle_type) h 0x61d0005906c8
data 0x61d000590680 type 12 &hq 0x61d0005906e8
hq[0x61a0000c4f98,0x61d0005a4448]" ../../../../distro/src/unix/stream.c:90
[19968] (2021-03-09 10:17:51) tid:0x2d2310 <alloc_memory_for_dlsym> "int
uv_timer_init(uv_loop_t *, uv_timer_t *) h 0x61d000590e28 data 0x61d000590680
type 13 &hq 0x61d000590e48 hq[0x61a0000c4f98,0x61d0005906e8]"
../../../../distro/src/timer.c:66
[20007] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__stream_init(uv_loop_t *, uv_stream_t *, uv_handle_type) h 0x61d00058fcc8
data 0x61d00058fc80 type 12 &hq 0x61d00058fce8
hq[0x61a0000c4f98,0x61d000590e48]" ../../../../distro/src/unix/stream.c:90
[20008] (2021-03-09 10:17:51) tid:0x61a0000ca280 "int uv_timer_init(uv_loop_t
*, uv_timer_t *) h 0x61d000590428 data 0x61d00058fc80 type 13 &hq
0x61d000590448 hq[0x61a0000c4f98,0x61d00058fce8]"
../../../../distro/src/timer.c:66
[20057] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__stream_init(uv_loop_t *, uv_stream_t *, uv_handle_type) h 0x61d0005a5ac8
data 0x0 type 12 &hq 0x61d0005a5ae8 hq[0x61a0000c4f98,0x61d000590448]"
../../../../distro/src/unix/stream.c:90
[20058] (2021-03-09 10:17:51) tid:0x61a0000ca280 "int uv_timer_init(uv_loop_t
*, uv_timer_t *) h 0x61d0005a6228 data 0x0 type 13 &hq 0x61d0005a6248
hq[0x61a0000c4f98,0x61d0005a5ae8]" ../../../../distro/src/timer.c:66
[20125] (2021-03-09 10:17:51) tid:0x2d2310 <alloc_memory_for_dlsym> "void
uv__stream_init(uv_loop_t *, uv_stream_t *, uv_handle_type) h 0x61d0005a64c8
data 0x0 type 12 &hq 0x61d0005a64e8 hq[0x61a0000c4f98,0x61d0005a6248]"
../../../../distro/src/unix/stream.c:90
[20126] (2021-03-09 10:17:51) tid:0x2d2310 <alloc_memory_for_dlsym> "int
uv_timer_init(uv_loop_t *, uv_timer_t *) h 0x61d0005a6c28 data 0x0 type 13 &hq
0x61d0005a6c48 hq[0x61a0000c4f98,0x61d0005a64e8]"
../../../../distro/src/timer.c:66
* 10 new handles are below, two of them look like they were already in the
queue
0x61d0005a3cc8
0x61d0005a4428
0x61d0005906c8
0x61d000590e28
0x61d00058fcc8 <=== this is already in list
0x61d000590428 <=== this is already in list
0x61d0005a5ac8
0x61d0005a6228
0x61d0005a64c8
0x61d0005a6c28
[20176] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv_safe_close(uv_handle_t *, uv_close_cb) handle 0x61d0005a3cc8 is_closing 0"
distro/c/src/proactor/libuv.c:440
[20177] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv_safe_close(uv_handle_t *, uv_close_cb) handle 0x61d0005a3cc8 before
uv_close" distro/c/src/proactor/libuv.c:446
[20178] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void uv_close(uv_handle_t *,
uv_close_cb) handle 0x61d0005a3cc8 type 12 data 0x61d0005a3c80 is_closing 0
flags e408" ../../../../distro/src/unix/core.c:123
[20179] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void uv__tcp_close(uv_tcp_t
*) handle 0x61d0005a3cc8" ../../../../distro/src/unix/tcp.c:469
[20180] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__make_close_pending(uv_handle_t *) handle 0x61d0005a3cc8 data 0x61d0005a3c80
current 0x0" ../../../../distro/src/unix/core.c:232
[20181] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__run_closing_handles(uv_loop_t *) loop 0x61a0000c4f88"
../../../../distro/src/unix/core.c:393
[20182] (2021-03-09 10:17:51) tid:0x61a0000ca280 "p 0x61d0005a3cc8 conn
0x61d0005a3c80" ../../../../distro/src/unix/core.c:394
[20183] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__finish_close(uv_handle_t *) handle 0x61d0005a3cc8 data 0x61d0005a3c80 flags
2409 type 12" ../../../../distro/src/unix/core.c:303
[20184] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__finish_close(uv_handle_t *) before QUEUE_REMOVE handle_queue
0x61d0005a4448,0x61d000590e48" ../../../../distro/src/unix/core.c:367
[20185] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [--I] signal 0x61a0000c51b0
[0x61a0000c5038,0x61a0000c4f98]" ../../../../distro/src/unix/core.c:293
[20186] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [-AI] async 0x61a0000c5018
[0x61a0000c4ea0,0x61a0000c51d0]" ../../../../distro/src/unix/core.c:293
[20187] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] async 0x61a0000c4e80
[0x61a0000c4f20,0x61a0000c5038]" ../../../../distro/src/unix/core.c:293
[20188] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] async 0x61a0000c4f00
[0x61a0000c5270,0x61a0000c4ea0]" ../../../../distro/src/unix/core.c:293
[20189] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] timer 0x61a0000c5250
[0x612000030370,0x61a0000c4f20]" ../../../../distro/src/unix/core.c:293
[20190] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] tcp 0x612000030350
[0x61d00058fce8,0x61a0000c5270]" ../../../../distro/src/unix/core.c:293
[20191] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [R--] tcp 0x61d00058fcc8
[0x61d000590448,{color:#FF0000}0x61d000590e48{color}]"
../../../../distro/src/unix/core.c:293
[20192] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [R--] timer 0x61d000590428
[0x61d0005a5ae8,0x61d00058fce8]" ../../../../distro/src/unix/core.c:293
[20193] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] tcp 0x61d0005a5ac8
[0x61d0005a6248,0x61d000590448]" ../../../../distro/src/unix/core.c:293
[20194] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] timer 0x61d0005a6228
[0x61d0005a64e8,0x61d0005a5ae8]" ../../../../distro/src/unix/core.c:293
[20195] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] tcp 0x61d0005a64c8
[0x61d0005a6c48,0x61d0005a6248]" ../../../../distro/src/unix/core.c:293
[20196] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [RA-] timer 0x61d0005a6c28
[0x61a0000c4f98,0x61d0005a64e8]" ../../../../distro/src/unix/core.c:293
[20197] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv__finish_close(uv_handle_t *) before close_cb 0x61d0005a3cc8 2403"
../../../../distro/src/unix/core.c:378
[20198] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
on_close_pconnection(uv_handle_t *) handle 0x61d0005a3cc8 pc 0x61d0005a3c80
timer due 15999" distro/c/src/proactor/libuv.c:467
[20199] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
on_close_pconnection(uv_handle_t *) last timer now 2360161 next 2376161 pc
0x61d0005a3c80 now 2360162" distro/c/src/proactor/libuv.c:470
[20200] (2021-03-09 10:17:51) tid:0x61a0000ca280 "void
uv_safe_close(uv_handle_t *, uv_close_cb) handle 0x61d0005a4428 is_closing 0"
distro/c/src/proactor/libuv.c:440
We can see that the entry for handle 0x61d00058fcc8 is bad, the prev pointer no
longer points back to the entry before it. It should be 0x612000030370.
All seems well for quite a while until the bad handle 0x61d00058fcc8 is removed
from the list. It can be seen that the entry removal did not work as the
pointers are messed up so it remains in the list. The memory it is in is freed
when the pconnection associated is freed.
Next time the queue is traversed there is a pointer into the freed memory and
we get an asan issue.
[20359] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv_safe_close(uv_handle_t *, uv_close_cb) handle 0x61d00058fcc8 is_closing 0"
distro/c/src/proactor/libuv.c:440
[20360] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv_safe_close(uv_handle_t *, uv_close_cb) handle 0x61d00058fcc8 before
uv_close" distro/c/src/proactor/libuv.c:446
[20361] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void uv_close(uv_handle_t *,
uv_close_cb) handle 0x61d00058fcc8 type 12 data 0x61d00058fc80 is_closing 0
flags c008" ../../../../distro/src/unix/core.c:123
[20362] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void uv__tcp_close(uv_tcp_t
*) handle 0x61d00058fcc8" ../../../../distro/src/unix/tcp.c:469
[20363] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__make_close_pending(uv_handle_t *) handle 0x61d00058fcc8 data 0x61d00058fc80
current 0x0" ../../../../distro/src/unix/core.c:232
[20364] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__run_closing_handles(uv_loop_t *) loop 0x61a0000c4f88"
../../../../distro/src/unix/core.c:393
[20365] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "p 0x61d00058fcc8 conn
0x61d00058fc80" ../../../../distro/src/unix/core.c:394
[20366] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__finish_close(uv_handle_t *) handle 0x61d00058fcc8 data 0x61d00058fc80 flags
9 type 12" ../../../../distro/src/unix/core.c:303
[20367] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__finish_close(uv_handle_t *) before QUEUE_REMOVE handle_queue
0x61d000590448,0x61d000590e48" ../../../../distro/src/unix/core.c:367
[20368] (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
[20369] (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
[20370] (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
[20371] (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
[20372] (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
[20373] (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
[20374] (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
[20375] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__trace_handles(uv_loop_t *) loop 0x61a0000c4f88 [R--] timer 0x61d000590428
[0x61d0005a5ae8,0x61d00058fce8]" ../../../../distro/src/unix/core.c:293
[20376] (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
[20377] (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
[20378] (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
[20379] (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
[20380] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__finish_close(uv_handle_t *) before close_cb 0x61d00058fcc8 3"
../../../../distro/src/unix/core.c:378
[20381] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
on_close_pconnection(uv_handle_t *) handle 0x61d00058fcc8 pc 0x61d00058fc80
timer due 0" distro/c/src/proactor/libuv.c:467
[20382] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
on_close_pconnection(uv_handle_t *) last timer now 2365905 next 0 pc
0x61d000590680 now 2365907" distro/c/src/proactor/libuv.c:470
[20383] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv_safe_close(uv_handle_t *, uv_close_cb) handle 0x61d000590428 is_closing 0"
distro/c/src/proactor/libuv.c:440
[20384] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv_safe_close(uv_handle_t *, uv_close_cb) handle 0x61d000590428 before
uv_close" distro/c/src/proactor/libuv.c:446
[20385] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void uv_close(uv_handle_t *,
uv_close_cb) handle 0x61d000590428 type 13 data 0x61d00058fc80 is_closing 0
flags 8" ../../../../distro/src/unix/core.c:123
[20386] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__timer_close(uv_timer_t *) handle 0x61d000590428"
../../../../distro/src/timer.c:191
[20387] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__make_close_pending(uv_handle_t *) handle 0x61d000590428 data 0x61d00058fc80
current 0x0" ../../../../distro/src/unix/core.c:232
[20388] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__run_closing_handles(uv_loop_t *) loop 0x61a0000c4f88"
../../../../distro/src/unix/core.c:393
[20389] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "p 0x61d000590428 conn
0x61d00058fc80" ../../../../distro/src/unix/core.c:394
[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
[20404] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__finish_close(uv_handle_t *) before close_cb 0x61d000590428 3"
../../../../distro/src/unix/core.c:378
[20405] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
on_close_pconnection_final(uv_handle_t *) handle 0x61d000590428 pc
0x61d00058fc80" distro/c/src/proactor/libuv.c:431
[20406] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "pconnection_free() pc
0x61d00058fc80" distro/c/src/proactor/libuv.c:364
[20407] (2021-03-09 10:17:57) tid:0x61a0000ca280 "_Bool handle(qd_server_t *,
pn_event_t *, pn_connection_t *, qd_connection_t *) pn_conn 0x612000096950 ctx
0x61e0000ca910 event PN_TRANSPORT_CLOSED" distro/src/server.c:982
[20408] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv_safe_close(uv_handle_t *, uv_close_cb) handle 0x61d0005906c8 is_closing 0"
distro/c/src/proactor/libuv.c:440
[20409] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv_safe_close(uv_handle_t *, uv_close_cb) handle 0x61d0005906c8 before
uv_close" distro/c/src/proactor/libuv.c:446
[20410] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void uv_close(uv_handle_t *,
uv_close_cb) handle 0x61d0005906c8 type 12 data 0x61d000590680 is_closing 0
flags c008" ../../../../distro/src/unix/core.c:123
[20411] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void uv__tcp_close(uv_tcp_t
*) handle 0x61d0005906c8" ../../../../distro/src/unix/tcp.c:469
[20412] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__make_close_pending(uv_handle_t *) handle 0x61d0005906c8 data 0x61d000590680
current 0x0" ../../../../distro/src/unix/core.c:232
[20413] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__run_closing_handles(uv_loop_t *) loop 0x61a0000c4f88"
../../../../distro/src/unix/core.c:393
[20414] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "p 0x61d0005906c8 conn
0x61d000590680" ../../../../distro/src/unix/core.c:394
[20415] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__finish_close(uv_handle_t *) handle 0x61d0005906c8 data 0x61d000590680 flags
9 type 12" ../../../../distro/src/unix/core.c:303
[20416] (2021-03-09 10:17:57) tid:0x61a0000c9c80 "void
uv__finish_close(uv_handle_t *) before QUEUE_REMOVE handle_queue
0x61d000590e48,0x61d000590e48" ../../../../distro/src/unix/core.c:367
[20417] (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
[20418] (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
[20419] (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
[20420] (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
[20421] (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
[20422] (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
(ugdb-x86_64-7.11-261) quit
In our system we have been seeing a bunch of spurious corruptions and crashes,
this issue might be that cause as it could be causing corruptions due to writes
to freed memory.
So it looks like we are searching for a reason why a handle would not have been
closed (and removed from the list) and is re-added later.
Perhaps this could be
* pconnection is freed without closing its stream handle and later that memory
is reused and so the same handle address is reinited and added to list
* pconnection streams are reinited without having been properly closed.
Anyone know a way that a close could not be done propperly for a connection?
I'll be digging into that logic next.
> 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: dev-unsubscr...@qpid.apache.org
For additional commands, e-mail: dev-h...@qpid.apache.org
