ASSERT memquery_linux.c:233 mi->newline != NULL
Running a medium-sized app I hit this assert:
<Application handler_test (59365). Internal Error: DynamoRIO debug check failure: core/unix/memquery_linux.c:233 mi->newline != NULL(gdb) info local
mi = 0x7fffe81b9039
perm = "8\241\234\000\000\000\000\000\n\000\000\000\005\000\000"
line = 0xa8d640 <buf_iter> "7ffff7fb7000-7ffff7fbf000 r-xp 00000000 00:1c 51504", ' ' <repeats 22 times>, "/somepath"
len = 0
prev_start = 0xffffffffff600000 "H\307\300`"
(gdb) p *mi
$2 = {
maps = 37,
newline = 0x0,
bufread = 165,
bufwant = 165,
buf = 0xa8d640 <buf_iter> "7ffff7fb7000-7ffff7fbf000 r-xp 00000000 00:1c 51504", ' ' <repeats 22 times>, "/somepath",
comment_buffer = 0xa8e650 <comment_buf_iter> "[vsyscall]"
}
7ffff7fb7000-7ffff7fbf000 r-xp 00000000 00:1c 51504 /somepath/libdrmgr.so
7ffff7fbf000-7ffff7fc0000 rw-p 00008000 00:1c 51504 /somepath/libdrmgr.so
(gdb) p mi->buf[252]
$14 = 46 '.'
(gdb) p mi->buf[253]
$13 = 115 's'
(gdb) p mi->buf[254]
$15 = 111 'o'
(gdb) p mi->buf[255]
$16 = 0 '\000'
(gdb) p mi->buf[256]
$17 = 55 '7'
(gdb) x/3s mi->buf
0xa8d640 <buf_iter>: "7ffff7fb7000-7ffff7fbf000 r-xp 00000000 00:1c 51504", ' ' <repeats 22 times>, "/somepath"
0xa8d6e6 <buf_iter+166>: "/libdrx.so"
0xa8d740 <buf_iter+256>: "7ffff7fb2000-7ffff7fb3000 rw-p 00000000 00:00 0 "It's really messed up: it has values from earlier in the file (drx.so) and nulls in several weird places. Is it due to races w/ the kernel updating the file? Or just bugs in the code that were somehow not seen on smaller maps files? The buffer size is 4096: maybe many maps files are smaller than that.
# wc /proc/59542/maps
2400 13842 504739 /proc/59542/mapsThe end of the file:
7ffffffdd000-7ffffffff000 rw-p 00000000 00:00 0 [stack]
ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0 [vsyscall]Breakpoint 1, memquery_iterator_next (iter=0x7fffeb409008) at core/unix/memquery_linux.c:219
219 ASSERT(mi->bufread <= mi->bufwant);
$521 = {
maps = 37,
newline = 0x0,
bufread = 3722,
bufwant = 3722,
buf = 0xa8d640 <buf_iter> "7ffff7fb1000-7ffff7fb2000 rw-p 00006000 00:1c 52894", ' ' <repeats 22 times>, "/somepath"...,
comment_buffer = 0xa8e650 <comment_buf_iter> "/somepath/libdrx.so"
}
mi = 0x7fffeb409039
perm = "\202\241\234\000\000\000\000\000\236\316\000\001\005\000\000"
line = 0xa8e4ca <buf_iter+3722> ' ' <repeats 11 times>, "lib64/ld-2.19.so\n7ffffffdd000-7ffffffff000 rw-p 00000000 00:00 "
len = 190
prev_start = 0x7ffff7faa000 "\177ELF\002\001\001"
$522 = 32 ' '
$523 = 32 ' '
$524 = 32 ' '
Breakpoint 1, memquery_iterator_next (iter=0x7fffeb409008) at core/unix/memquery_linux.c:219
219 ASSERT(mi->bufread <= mi->bufwant);
$525 = {
maps = 37,
newline = 0x0,
bufread = 119,
bufwant = 3866,
buf = 0xa8d640 <buf_iter> "7ffffffdd000-7ffffffff000 rw-p 00000000 00:00 0", ' ' <repeats 26 times>, "[stack]\nffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0", ' ' <repeats 18 times>, "[vsyscall]\n"...,
comment_buffer = 0xa8e650 <comment_buf_iter> "lib64/ld-2.19.so"
}
mi = 0x7fffeb409039
perm = "\202\241\234\000\000\000\000\000\000 \000\001\003\000\000"
line = 0xa8e55a <buf_iter+3866> "7ffffffdd000-7ffffffff000 rw-p 00000000 00:00 "
len = 46
prev_start = 0x7ffff7ffd000 "`^\""
$526 = 0 '\000'
$527 = 55 '7'
$528 = 102 'f'
Breakpoint 1, memquery_iterator_next (iter=0x7fffeb409008) at core/unix/memquery_linux.c:219
219 ASSERT(mi->bufread <= mi->bufwant);
$529 = {
maps = 37,
newline = 0x0,
bufread = 165,
bufwant = 165,
buf = 0xa8d640 <buf_iter> "7ffff7fb7000-7ffff7fbf000 r-xp 00000000 00:1c 51504", ' ' <repeats 22 times>, "/somepath",
comment_buffer = 0xa8e650 <comment_buf_iter> "[vsyscall]"
}
mi = 0x7fffeb409039
perm = "8\241\234\000\000\000\000\000\n\000\000\000\005\000\000"
line = 0xa8d6e5 <buf_iter+165> ""
len = 0
prev_start = 0xffffffffff600000 "H\307\300`"
$530 = 47 '/'
$531 = 0 '\000'
$532 = 108 'l'119+46=165, so it has the full final 2 lines there.
For the further os_read to succeed and read that much, the file must change underneath it? Maybe DR mmaps some memory or sthg. That's handled later, after this assert. But if it only reads 165 more bytes (strange that the 165 there matches the prior 165 for the final 2 lines) why does it read so far back in the final file? If it's that far back why doesn't it read the whole end?
Stepping through: the maps file does not change! "wc" returns identical data throughout the final few reads.
The filepos makes no sense. After reading the final 2 lines, instead of being 504739, it's inexplicably 738 bytes earlier:
# wc /proc/`pgrep handler_test`/maps
2400 13842 504739 /proc/80331/maps
ASSERT(mi->bufread <= mi->bufwant);
(gdb) p os_tell(mi->maps)
$1 = 504001After the bogus extra read it advances the 165 that it read:
(gdb) p os_tell(mi->maps)
$7 = 504166Yet the bogus data that's read is earlier than that in the file! My only theory is that the kernel just has some issues reading a long procfs file and gets the position messed up?