ThreadSanitizer: heap-use-after-free lib/dns/dispatch.c:494:2 in udp_recv
I was only able to trigger this on the !6763 (merged), but the early detach seems to be unrelated to any timer work, so I am reporting this separately. I think this is timing related, but perhaps this could be triggered by right combination of delays on the remote server, so I am marking this as confidential for the time being.
WARNING: ThreadSanitizer: heap-use-after-free (pid=3573303)
Read of size 4 at 0x7b5000021a00 by thread T4:
#0 udp_recv /home/ondrej/Projects/bind9/lib/dns/dispatch.c:494:2 (libdns-9.19.6-dev.so+0x7cce7) (BuildId: 75b25a5d7028880573ec25f433699b08af563a19)
#1 isc__nm_async_readcb /home/ondrej/Projects/bind9/lib/isc/netmgr/netmgr.c:2217:2 (libisc-9.19.6-dev.so+0x2a93f) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#2 isc__nm_readcb /home/ondrej/Projects/bind9/lib/isc/netmgr/netmgr.c:2190:3 (libisc-9.19.6-dev.so+0x27d3d) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#3 udp_recv_cb /home/ondrej/Projects/bind9/lib/isc/netmgr/udp.c:609:2 (libisc-9.19.6-dev.so+0x4a509) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#4 isc__nm_udp_read_cb /home/ondrej/Projects/bind9/lib/isc/netmgr/udp.c:892:2 (libisc-9.19.6-dev.so+0x4bcd8) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#5 uv__udp_recvmsg /home/ondrej/Projects/tsan/libuv/src/unix/udp.c (libuv.so.1+0x2b996) (BuildId: c99889fa13b668b594de36fc6ddc9685346ae47c)
#6 uv__udp_io /home/ondrej/Projects/tsan/libuv/src/unix/udp.c:178:5 (libuv.so.1+0x2b996)
#7 uv__io_poll /home/ondrej/Projects/tsan/libuv/src/unix/epoll.c:374:11 (libuv.so.1+0x31256) (BuildId: c99889fa13b668b594de36fc6ddc9685346ae47c)
#8 uv_run /home/ondrej/Projects/tsan/libuv/src/unix/core.c:406:5 (libuv.so.1+0x12eba) (BuildId: c99889fa13b668b594de36fc6ddc9685346ae47c)
#9 loop_run /home/ondrej/Projects/bind9/lib/isc/loop.c:266:6 (libisc-9.19.6-dev.so+0x7e31f) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#10 loop_thread /home/ondrej/Projects/bind9/lib/isc/loop.c:293:2 (libisc-9.19.6-dev.so+0x7bb10) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#11 isc__trampoline_run /home/ondrej/Projects/bind9/lib/isc/trampoline.c:189:11 (libisc-9.19.6-dev.so+0xb1de9) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
Previous write of size 8 at 0x7b5000021a00 by thread T4:
#0 free <null> (named+0x462125) (BuildId: 69e77619d28d9f58d0a86fddf377fe767a42a488)
#1 sdallocx /home/ondrej/Projects/bind9/lib/isc/./jemalloc_shim.h:43:2 (libisc-9.19.6-dev.so+0x886ca) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#2 mem_put /home/ondrej/Projects/bind9/lib/isc/mem.c:365:2 (libisc-9.19.6-dev.so+0x81026) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#3 isc__mem_put /home/ondrej/Projects/bind9/lib/isc/mem.c:779:2 (libisc-9.19.6-dev.so+0x82209) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#4 dispentry_destroy /home/ondrej/Projects/bind9/lib/dns/dispatch.c:420:2 (libdns-9.19.6-dev.so+0x85494) (BuildId: 75b25a5d7028880573ec25f433699b08af563a19)
#5 dispentry__detach /home/ondrej/Projects/bind9/lib/dns/dispatch.c:445:3 (libdns-9.19.6-dev.so+0x7ef79) (BuildId: 75b25a5d7028880573ec25f433699b08af563a19)
#6 udp_recv /home/ondrej/Projects/bind9/lib/dns/dispatch.c:612:2 (libdns-9.19.6-dev.so+0x7d511) (BuildId: 75b25a5d7028880573ec25f433699b08af563a19)
#7 isc__nm_async_readcb /home/ondrej/Projects/bind9/lib/isc/netmgr/netmgr.c:2217:2 (libisc-9.19.6-dev.so+0x2a93f) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#8 isc__nm_readcb /home/ondrej/Projects/bind9/lib/isc/netmgr/netmgr.c:2190:3 (libisc-9.19.6-dev.so+0x27d3d) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#9 udp_recv_cb /home/ondrej/Projects/bind9/lib/isc/netmgr/udp.c:609:2 (libisc-9.19.6-dev.so+0x4a509) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#10 isc__nm_udp_read_cb /home/ondrej/Projects/bind9/lib/isc/netmgr/udp.c:892:2 (libisc-9.19.6-dev.so+0x4bcd8) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#11 uv__udp_recvmsg /home/ondrej/Projects/tsan/libuv/src/unix/udp.c (libuv.so.1+0x2b996) (BuildId: c99889fa13b668b594de36fc6ddc9685346ae47c)
#12 uv__udp_io /home/ondrej/Projects/tsan/libuv/src/unix/udp.c:178:5 (libuv.so.1+0x2b996)
#13 uv__io_poll /home/ondrej/Projects/tsan/libuv/src/unix/epoll.c:374:11 (libuv.so.1+0x31256) (BuildId: c99889fa13b668b594de36fc6ddc9685346ae47c)
#14 uv_run /home/ondrej/Projects/tsan/libuv/src/unix/core.c:406:5 (libuv.so.1+0x12eba) (BuildId: c99889fa13b668b594de36fc6ddc9685346ae47c)
#15 loop_run /home/ondrej/Projects/bind9/lib/isc/loop.c:266:6 (libisc-9.19.6-dev.so+0x7e31f) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#16 loop_thread /home/ondrej/Projects/bind9/lib/isc/loop.c:293:2 (libisc-9.19.6-dev.so+0x7bb10) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#17 isc__trampoline_run /home/ondrej/Projects/bind9/lib/isc/trampoline.c:189:11 (libisc-9.19.6-dev.so+0xb1de9) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
Thread T4 'isc-loop-0004' (tid=3573321, running) created by main thread at:
#0 pthread_create <null> (named+0x46327b) (BuildId: 69e77619d28d9f58d0a86fddf377fe767a42a488)
#1 isc_thread_create /home/ondrej/Projects/bind9/lib/isc/thread.c:70:8 (libisc-9.19.6-dev.so+0xa6422) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#2 isc_loopmgr_run /home/ondrej/Projects/bind9/lib/isc/loop.c:467:3 (libisc-9.19.6-dev.so+0x7b91f) (BuildId: b6e3e5fefeba479efb90918b590dbb38234c793b)
#3 main /home/ondrej/Projects/bind9/bin/named/main.c:1441:2 (named+0x4f79c3) (BuildId: 69e77619d28d9f58d0a86fddf377fe767a42a488)
SUMMARY: ThreadSanitizer: heap-use-after-free /home/ondrej/Projects/bind9/lib/dns/dispatch.c:494:2 in udp_recvThere's an associated coredump:
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:49
set = {__val = {0, 140661556525872, 0, 0, 0, 140661556363264, 3258688776053076018, 3834034666501059633, 14415912475178298, 140661556673440, 140661550866096, 140661544714240, 0, 140661544714240, 3258688776053076018, 3834034657911125041}}
pid = <optimized out>
tid = <optimized out>
ret = <optimized out>
#1 0x00007fee5110d546 in __GI_abort () at abort.c:79
save_stage = 1
act = {__sigaction_handler = {sa_handler = 0x7fee51453970, sa_sigaction = 0x7fee51453970}, sa_mask = {__val = {5209597, 140661413048488, 494, 17, 140661413064448, 140661413048488, 4721842, 16, 4722126, 140661413064448, 140661413064448, 140661413052416, 494, 135738146882704, 140661540759008, 140661540742432}}, sa_flags = 1360375714, sa_restorer = 0xfffffffffffff8c0}
sigs = {__val = {32, 494, 140661413048488, 135738146882760, 140661413042496, 140661556841761, 140661413042432, 135875585386496, 6166224, 6163792, 18446744052234715136, 5853094, 1868, 140661413041616, 135720966627328, 17}}
#2 0x000000000046895b in abort ()
No symbol table info available.
#3 0x00000000004f7ed9 in assertion_failed (file=0x7fee5213a420 "dispatch.c", line=494, type=isc_assertiontype_require, cond=0x7fee5213a98d "(((resp)) != ((void*)0) && ((const isc__magic_t *)((resp)))->magic == ((('D') << 24 | ('r') << 16 | ('s') << 8 | ('p'))))") at main.c:237
tracebuf = {0x7fee521e9fb3 <isc_backtrace+83>, 0x4f7bef <assertion_failed+143>, 0x7fee521e90fe <isc_assertion_failed+94>, 0x7fee51dccd15 <udp_recv+229>, 0x7fee521c6940 <isc__nm_async_readcb+896>, 0x7fee521c3d3e <isc__nm_readcb+526>, 0x7fee521e650a <udp_recv_cb+1162>, 0x7fee521e7cd9 <isc__nm_udp_read_cb+313>, 0x7fee516ab997<error reading variable>, 0x7fee516b1257 <uv__io_poll+1911>, 0x7fee51692ebb<error reading variable>, 0x7fee5221a320 <loop_run+1168>, 0x7fee52217b11 <loop_thread+81>, 0x7fee5224ddea <isc__trampoline_run+106>, 0x4631de <__tsan_thread_start_func+174>, 0x7fee5145bd80 <start_thread+224>, 0x7fee511e576f <clone+63>, 0x7fee511e576f <clone+63>, 0x0, 0x1ee, 0x7fee5213a420, 0x5e1940 <__sanitizer::internal_alloc_placeholder>, 0x6, 0x4438d0 <__sanitizer::Printf(char const*, ...)+144>, 0x3000000010, 0x7fee498edba0, 0x7fee498edae0, 0xffff00001f80, 0x64, 0x7fee4e442000, 0x6e, 0x0, 0xf00, 0x73, 0x7fee51dccce8 <udp_recv+184>, 0x1000, 0x1000, 0x0, 0x7fee4e442000, 0x4438d0 <__sanitizer::Printf(char const*, ...)+144>, 0x3000000008, 0x7fee498edc20, 0x7fee498edb60, 0x7fee44501578, 0x0, 0x0, 0x1, 0x7fee4da02670, 0x58ab79, 0x58ab60, 0x0, 0x0, 0xffffffff, 0x0, 0xffffffffffffffff, 0x0, 0xffffffff, 0xffffffffffffffff, 0x0, 0x0, 0xff000000ff, 0xff000000ff, 0xffffffff, 0x0, 0xffffffffffffffff, 0xffffffffffffffff, 0x3fff00003fff0000, 0x3fff00003fff0000, 0xff000000ff00, 0xff000000ff00, 0x7fffffff7fffffff, 0x7fffffff7fffffff, 0x0, 0x0, 0x0, 0x0, 0x5960b3, 0x58c8c1, 0x7fee4da096f0, 0x0, 0x7fee447029f0, 0xfffff0000000000, 0x7fee4cb00100, 0x4000000000000000, 0x2000000000000000, 0x436044 <__sanitizer::InternalFree(void*, __sanitizer::SizeClassAllocator32LocalCache<__sanitizer::SizeClassAllocator32<__sanitizer::AP32> >*)+84>, 0x7fee498edd01, 0xfffff0000000000, 0x2, 0x800000000000000e, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xffffff0000000000, 0x4dd7e2 <__tsan::VarSizeStackTrace::~VarSizeStackTrace()+18>, 0x7fee498edd01, 0x4db58f <__tsan::ReportRace(__tsan::ThreadState*, __tsan::RawShadow*, __tsan::Shadow, __tsan::Shadow, unsigned long)+3727>, 0x7fee44902250, 0x12, 0x7fee45303d40, 0x7fee498edda8, 0x2, 0x8, 0x1938c00 <__tsan::ctx_placeholder+10493696>, 0x34ec3a810006fe00, 0x8, 0x34ec3a00000002, 0x1, 0x400000004, 0x7b5000021a00, 0x0, 0x7b6c0000fc00, 0x76dc3a0f000034ec, 0x0, 0x0, 0x193ee88 <__tsan::ctx_placeholder+10518920>, 0x1936da8 <__tsan::ctx_placeholder+10485928>, 0x1938c08 <__tsan::ctx_placeholder+10493704>, 0x7fee45303d40, 0x7fee498f2f00, 0x0, 0x0, 0x0, 0x0, 0x0}
nframes = 17
#4 0x00007fee521e90fe in isc_assertion_failed (file=0x7fee5213a420 "dispatch.c", line=494, type=isc_assertiontype_require, cond=0x7fee5213a98d "(((resp)) != ((void*)0) && ((const isc__magic_t *)((resp)))->magic == ((('D') << 24 | ('r') << 16 | ('s') << 8 | ('p'))))") at assertions.c:49
No locals.
#5 0x00007fee51dccd15 in udp_recv (handle=0x7b4800030000, eresult=ISC_R_SUCCESS, region=0x7fee498ee430, arg=0x7b5000021a00) at dispatch.c:494
resp = 0x7b5000021a00
disp = 0x0
id = 0
dres = 4829950
source = {magic = 1234118144, base = 0x7fee498f2e40, length = 1234120448, used = 32750, current = 459920, active = 31604, link = {prev = 0x20, next = 0x7fee498f2e40}, mctx = 0x7fee5228fee8, autore = 96}
flags = 32750
peer = {type = {sa = {sa_family = 0, sa_data = '\000' <repeats 13 times>}, sin = {sin_family = 0, sin_port = 0, sin_addr = {s_addr = 0}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 0, sin6_port = 0, sin6_flowinfo = 0, sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}, ss = {ss_family = 0, __ss_padding = '\000' <repeats 117 times>, __ss_align = 0}, sunix = {sun_family = 0, sun_path = '\000' <repeats 107 times>}}, length = 0, link = {prev = 0x0, next = 0x0}}
netaddr = {family = 0, type = {in = {s_addr = 0}, in6 = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, un = '\000' <repeats 107 times>}, zone = 0}
match = 0
timeout = 0
response = 0x0
#6 0x00007fee521c6940 in isc__nm_async_readcb (worker=0x0, ev0=0x7fee498ee4f0) at netmgr/netmgr.c:2217
ievent = 0x7fee498ee4f0
sock = 0x7b740006fe00
uvreq = 0x7b6c0000fc00
eresult = ISC_R_SUCCESS
region = {base = 0x7fee4bcbc000 "3\251\204", length = 166}
#7 0x00007fee521c3d3e in isc__nm_readcb (sock=0x7b740006fe00, uvreq=0x7b6c0000fc00, eresult=ISC_R_SUCCESS) at netmgr/netmgr.c:2190
ievent = {type = netievent_readcb, link = {prev = 0x0, next = 0x0}, worker = 0x0, sock = 0x7b740006fe00, file = 0x0, line = 0, func = 0x0, req = 0x7b6c0000fc00, result = ISC_R_SUCCESS}
#8 0x00007fee521e650a in udp_recv_cb (handle=0x7b7400070418, nrecv=166, buf=0x7fee498ef130, addr=0x7fee498eeee0, flags=0) at netmgr/udp.c:609
sock = 0x7b740006fe00
req = 0x7b6c0000fc00
maxudp = 0
result = ISC_R_SUCCESS
sockaddr = {type = {sa = {sa_family = 2, sa_data = "\024\264\n5\000\002\000\000\000\000\000\000\000"}, sin = {sin_family = 2, sin_port = 46100, sin_addr = {s_addr = 33568010}, sin_zero = "\000\000\000\000\000\000\000"}, sin6 = {sin6_family = 2, sin6_port = 46100, sin6_flowinfo = 33568010, sin6_addr = {__in6_u = {__u6_addr8 = '\000' <repeats 15 times>, __u6_addr16 = {0, 0, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {0, 0, 0, 0}}}, sin6_scope_id = 0}, ss = {ss_family = 2, __ss_padding = "\024\264\n5\000\002", '\000' <repeats 111 times>, __ss_align = 0}, sunix = {sun_family = 2, sun_path = "\024\264\n5\000\002", '\000' <repeats 101 times>}}, length = 16, link = {prev = 0x0, next = 0x0}}
sa = 0x7fee498ee648I've added some extra tracing, so here's the attach/detach log:
dns_dispatch_connect:dispatch.c:1816:dispentry__attach(0x7b5000021a00)->references = 2
startrecv:dispatch.c:1707:dispentry__attach(0x7b5000021a00)->references = 3
dns_dispatch_send:dispatch.c:1928:dispentry__attach(0x7b5000021a00)->references = 4
udp_connected:dispatch.c:1803:dispentry__detach(0x7b5000021a00)->references = 3
send_done:dispatch.c:1884:dispentry__detach(0x7b5000021a00)->references = 2
dispatch_getnext:dispatch.c:1543:dispentry__attach(0x7b5000021a00)->references = 3
dns_dispatch_send:dispatch.c:1928:dispentry__attach(0x7b5000021a00)->references = 4
udp_recv:dispatch.c:612:dispentry__detach(0x7b5000021a00)->references = 3
send_done:dispatch.c:1884:dispentry__detach(0x7b5000021a00)->references = 2
dns_dispatch_done:dispatch.c:1693:dispentry__detach(0x7b5000021a00)->references = 1
udp_recv:dispatch.c:612:dispentry__detach(0x7b5000021a00)->references = 0And here's the normal log related to the dispatch:
14-Sep-2022 17:55:51.113 dispatch 0x7b5000021800: UDP connected (0x7b5000021a00): success
14-Sep-2022 17:55:51.417 dispatch 0x7b5000021800: UDP response 0x7b5000021a00:timed out:requests 1
14-Sep-2022 17:55:51.469 dispatch 0x7b5000021800: UDP response 0x7b5000021a00:success:requests 1