search

DynamoRIO / dynamorio

Dynamic Instrumentation Tool Platform
Other
2.67k stars 562 forks source link

Add high loglevel regression testing by running tiny pure-asm apps #4736

Closed derekbruening closed 3 years ago

derekbruening commented 3 years ago

It is not uncommon for new users to run at -loglevel 5 or higher: but regular developers rarely go that high and we have no tests that high, meaning that such verbosity often bitrots and hits asserts or whatnot. This is a proposal to add some high-loglevel regression tests and keeping them reasonably short and with reasonable disk space by running tiny pure-asm apps (we already have some of those in the suite).

derekbruening commented 3 years ago

This issue also covers fixing the handful of rank order violations, deadlocks, etc. at high loglevel.

derekbruening commented 3 years ago

A list of the issues I hit and fixed:

DONE logfiles are huge at 4+ level => from vmm_dump_map() 4K blocks; disabling it

CLOSED: [2021-03-24 Wed 16:44]

DONE deadlock at 6 => limited size of memquery log which seems like a good idea anyway

CLOSED: [2021-03-24 Wed 16:44]

(gdb) bt
#0  report_dynamorio_problem (dcontext=0x0, dumpcore_flag=8, exception_addr=0x0, report_ebp=0x0, 
    fmt=0x7ffff7ec57f0 "DynamoRIO debug check failure: %s:%d %s\n(Error occurred @%d frags)") at /home/bruening/dr/git/src/core/utils.c:2117
#1  0x00007ffff7c603b5 in d_r_internal_error (file=0x7ffff7ec5690 "/home/bruening/dr/git/src/core/utils.c", line=636, 
    expr=0x7ffff7ec6358 "lock->owner != d_r_get_thread_id() && \"deadlock on recursive mutex_lock\"") at /home/bruening/dr/git/src/core/utils.c:179
#2  0x00007ffff7c626e7 in deadlock_avoidance_lock (lock=0x7ffff7fb2340 <memory_info_buf_lock>, acquired=false, ownable=true)
    at /home/bruening/dr/git/src/core/utils.c:636
#3  0x00007ffff7c62ea6 in d_r_mutex_trylock (lock=0x7ffff7fb2340 <memory_info_buf_lock>) at /home/bruening/dr/git/src/core/utils.c:915
#4  0x00007ffff7c62d85 in d_r_mutex_lock_app (lock=0x7ffff7fb2340 <memory_info_buf_lock>, mc=0x0) at /home/bruening/dr/git/src/core/utils.c:850
#5  0x00007ffff7c62e59 in d_r_mutex_lock (lock=0x7ffff7fb2340 <memory_info_buf_lock>) at /home/bruening/dr/git/src/core/utils.c:896
#6  0x00007ffff7e7cb3f in memquery_iterator_start (iter=0x7fffffffa8a0, start=0x7fffffffb000 "0000\006", may_alloc=false)
    at /home/bruening/dr/git/src/core/unix/memquery_linux.c:155
#7  0x00007ffff7e7d426 in memquery_from_os (pc=0x7fffffffb000 "0000\006", info=0x7fffffffa9c0, have_type=0x7fffffffa98e)
    at /home/bruening/dr/git/src/core/unix/memquery_linux.c:339
#8  0x00007ffff7e582c9 in query_memory_ex_from_os (pc=0x7fffffffb000 "0000\006", info=0x7fffffffa9c0) at /home/bruening/dr/git/src/core/unix/os.c:9583
#9  0x00007ffff7e5837c in get_memory_info_from_os (pc=0x7fffffffb000 "0000\006", base_pc=0x0, size=0x0, prot=0x7fffffffaa10)
    at /home/bruening/dr/git/src/core/unix/os.c:9616
#10 0x00007ffff7e49748 in is_readable_without_exception_internal (pc=0x7fffffffb360 "д\377\377\377\177", size=8, query_os=true)
    at /home/bruening/dr/git/src/core/unix/os.c:4601
#11 0x00007ffff7e49847 in is_readable_without_exception_query_os (pc=0x7fffffffb360 "д\377\377\377\177", size=8)
    at /home/bruening/dr/git/src/core/unix/os.c:4628
#12 0x00007ffff7ddf6b0 in internal_dump_callstack_to_buffer (buf=0x7fffffffab30 "Thread 698128 call stack:\n", bufsz=2048, sofar=0x7fffffffab28, 
    cur_pc=0x0, ebp=0x7fffffffb360 "д\377\377\377\177", flags=18) at /home/bruening/dr/git/src/core/ir/disassemble_shared.c:1626
#13 0x00007ffff7ddf76d in internal_dump_callstack (cur_pc=0x0, ebp=0x7fffffffb360 "д\377\377\377\177", outfile=32672, dump_xml=false, header=false)
    at /home/bruening/dr/git/src/core/ir/disassemble_shared.c:1667
#14 0x00007ffff7ddf9b2 in dump_dr_callstack (outfile=32672) at /home/bruening/dr/git/src/core/ir/disassemble_shared.c:1706
#15 0x00007ffff7c66098 in report_dynamorio_problem (dcontext=0xffffffffffffffff, dumpcore_flag=128, exception_addr=0x0, 
    report_ebp=0x7fffffffb4d0 " \275\377\377\377\177", fmt=0x7ffff7ec57c8 "CURIOSITY : %s in file %s line %d")
    at /home/bruening/dr/git/src/core/utils.c:2250
#16 0x00007ffff7c644ed in do_file_write (f=32672, fmt=0x7ffff7f27fd0 "\nget_memory_info_from_os: newline=[%s]\n", ap=0x7fffffffbd58)
    at /home/bruening/dr/git/src/core/utils.c:1653
#17 0x00007ffff7c64e6d in d_r_print_log (logfile=32672, mask=8192, level=6, fmt=0x7ffff7f27fd0 "\nget_memory_info_from_os: newline=[%s]\n")
    at /home/bruening/dr/git/src/core/utils.c:1841
#18 0x00007ffff7e7d0c8 in memquery_iterator_next (iter=0x7fffffffbf20) at /home/bruening/dr/git/src/core/unix/memquery_linux.c:243
#19 0x00007ffff7e7d555 in memquery_from_os (pc=0x4b718000 "\340\177qK", info=0x7fffffffc040, have_type=0x7fffffffc00e)
    at /home/bruening/dr/git/src/core/unix/memquery_linux.c:340
#20 0x00007ffff7e582c9 in query_memory_ex_from_os (pc=0x4b718000 "\340\177qK", info=0x7fffffffc040) at /home/bruening/dr/git/src/core/unix/os.c:9583
#21 0x00007ffff7e58226 in get_memory_info (pc=0x4b718000 "\340\177qK", base_pc=0x0, size=0x0, prot=0x7fffffffc08c)
    at /home/bruening/dr/git/src/core/unix/os.c:9560
#22 0x00007ffff7e4a20a in make_unwritable (pc=0x4b718000 "\340\177qK", size=8192) at /home/bruening/dr/git/src/core/unix/os.c:4780
#23 0x00007ffff7e49def in change_protection (pc=0x4b718000 "\340\177qK", length=8192, writable=false) at /home/bruening/dr/git/src/core/unix/os.c:4706
#24 0x00007ffff7d89509 in protect_generated_code (code_in=0x4b717000, writable=false) at /home/bruening/dr/git/src/core/arch/arch.c:1514
#25 0x00007ffff7d886c1 in shared_gencode_init (gencode_mode=GENCODE_X64) at /home/bruening/dr/git/src/core/arch/arch.c:593
#26 0x00007ffff7d888b7 in d_r_arch_init () at /home/bruening/dr/git/src/core/arch/arch.c:765

DONE assert at 5 "instr_decode requires a Level 1 or higher instruction" => avoid asking for opcode for level 0

CLOSED: [2021-03-24 Wed 16:44]

<Application /home/bruening/dr/git/build_x64_dbg_tests/suite/tests/bin/common.loglevel (899417) DynamoRIO usage error : instr_decode requires a Level 1 or higher instruction>

Breakpoint 1, report_dynamorio_problem (dcontext=0x0, dumpcore_flag=16, exception_addr=0x0, report_ebp=0x0, 
    fmt=0x7ffff7ec5877 "Usage error: %s (%s, line %d)") at /home/bruening/dr/git/src/core/utils.c:2117
2117        synchronize_dynamic_options();
(gdb) bt
#0  report_dynamorio_problem (dcontext=0x0, dumpcore_flag=16, exception_addr=0x0, report_ebp=0x0, fmt=0x7ffff7ec5877 "Usage error: %s (%s, line %d)")
    at /home/bruening/dr/git/src/core/utils.c:2117
#1  0x00007ffff7c604d7 in external_error (file=0x7ffff7efded0 "/home/bruening/dr/git/src/core/ir/instr_shared.c", line=1549, 
    msg=0x7ffff7efe790 "instr_decode requires a Level 1 or higher instruction") at /home/bruening/dr/git/src/core/utils.c:200
#2  0x00007ffff7db32e5 in instr_decode (dcontext=0x7ffdf7c01080, instr=0x7ffdf7c2b880) at /home/bruening/dr/git/src/core/ir/instr_shared.c:1549
#3  0x00007ffff7db330b in instr_decode_with_current_dcontext (instr=0x7ffdf7c2b880) at /home/bruening/dr/git/src/core/ir/instr_shared.c:1561
#4  0x00007ffff7db0ba1 in instr_get_opcode (instr=0x7ffdf7c2b880) at /home/bruening/dr/git/src/core/ir/instr_shared.c:424
#5  0x00007ffff7ddffe5 in instr_opcode_name (instr=0x7ffdf7c2b880) at /home/bruening/dr/git/src/core/ir/x86/disassemble.c:256
#6  0x00007ffff7de05eb in print_opcode_name (instr=0x7ffdf7c2b880, name=0x7ffff7f05813 "<RAW>", buf=0x7ffdf7c278a0 "", bufsz=196, sofar=0x7ffdf7c27898)
    at /home/bruening/dr/git/src/core/ir/x86/disassemble.c:355
#7  0x00007ffff7ddcacf in internal_instr_disassemble (buf=0x7ffdf7c278a0 "", bufsz=196, sofar=0x7ffdf7c27898, dcontext=0x7ffdf7c01080, 
    instr=0x7ffdf7c2b880) at /home/bruening/dr/git/src/core/ir/disassemble_shared.c:1108
#8  0x00007ffff7ddd141 in instr_disassemble (dcontext=0x7ffdf7c01080, instr=0x7ffdf7c2b880, outfile=32673)
    at /home/bruening/dr/git/src/core/ir/disassemble_shared.c:1190
#9  0x00007ffff7db3cd3 in d_r_loginst (dcontext=0x7ffdf7c01080, level=4, instr=0x7ffdf7c2b880, string=0x7ffff7efe584 "instr_expand")
    at /home/bruening/dr/git/src/core/ir/instr_shared.c:1659
#10 0x00007ffff7db2860 in instr_expand (dcontext=0x7ffdf7c01080, ilist=0x7ffdf7c2b138, instr=0x7ffdf7c2a920)
    at /home/bruening/dr/git/src/core/ir/instr_shared.c:1287
#11 0x00007ffff7db2e36 in instr_get_prev_expanded (dcontext=0x7ffdf7c01080, ilist=0x7ffdf7c2b138, instr=0x7ffdf7c2bca0)
    at /home/bruening/dr/git/src/core/ir/instr_shared.c:1420
#12 0x00007ffff7e0b770 in find_syscall_num (dcontext=0x7ffdf7c01080, ilist=0x7ffdf7c2b138, instr=0x7ffdf7c2bca0)
    at /home/bruening/dr/git/src/core/arch/mangle_shared.c:1877
#13 0x00007ffff7de8b14 in bb_process_syscall (dcontext=0x7ffdf7c01080, bb=0x7ffdf7c27d70) at /home/bruening/dr/git/src/core/arch/interp.c:1921
#14 0x00007ffff7deffce in build_bb_ilist (dcontext=0x7ffdf7c01080, bb=0x7ffdf7c27d70) at /home/bruening/dr/git/src/core/arch/interp.c:3859
#15 0x00007ffff7df642e in build_basic_block_fragment (dcontext=0x7ffdf7c01080, start=0x401000 "H\203\344\360H\307\303\020", initial_flags=0, link=true, 
    visible=true, for_trace=false, unmangled_ilist=0x0) at /home/bruening/dr/git/src/core/arch/interp.c:5088
#16 0x00007ffff7c488a3 in d_r_dispatch (dcontext=0x7ffdf7c01080) at /home/bruening/dr/git/src/core/dispatch.c:210

DONE rank order at 5 => avoid diagnostic if holding fcache_unit_areas lock

CLOSED: [2021-03-24 Wed 18:06]

<rank order violation module_data_lock(readwrite)@/home/bruening/dr/git/src/core/module_list.c:59 acquired after fcache_unit_areas(readwrite)@/home/bruening/dr/git/src/core/fcache.c:880 in tid:dc491>

#1  0x00007ffff7c603b5 in d_r_internal_error (file=0x7ffff7ec5690 "/home/bruening/dr/git/src/core/utils.c", line=614, 
    expr=0x7ffff7ec62e0 "(dcontext->thread_owned_locks->last_lock->rank < lock->rank || first_client || both_client) && \"rank order violation\"")
    at /home/bruening/dr/git/src/core/utils.c:179
#2  0x00007ffff7c625af in deadlock_avoidance_lock (lock=0x7ffff7fb6040 <module_data_lock>, acquired=true, ownable=false)
    at /home/bruening/dr/git/src/core/utils.c:614
#3  0x00007ffff7c63726 in d_r_read_lock (rw=0x7ffff7fb6040 <module_data_lock>) at /home/bruening/dr/git/src/core/utils.c:1214
#4  0x00007ffff7d3eef2 in os_get_module_info_lock () at /home/bruening/dr/git/src/core/module_list.c:67
#5  0x00007ffff7e750b8 in get_module_base (pc=0x41618000 '\253' <repeats 200 times>...) at /home/bruening/dr/git/src/core/unix/module.c:329
#6  0x00007ffff7d11b3b in print_vm_area (v=0x7ffdf7bd70a8, area=0x7ffdf7bd60a8, outf=32672, prefix=0x7ffff7edbf57 "  ")
    at /home/bruening/dr/git/src/core/vmareas.c:746
#7  0x00007ffff7d11dc4 in print_vm_areas (v=0x7ffdf7bd70a8, outf=32672) at /home/bruening/dr/git/src/core/vmareas.c:792
#8  0x00007ffff7d14a23 in add_vm_area (v=0x7ffdf7bd70a8, start=0x41646000 '\253' <repeats 200 times>..., end=0x41654000 "", vm_flags=0, frag_flags=0, 
    data=0x7ffdf7bed0a0, comment=0x7ffff7edbe31 "") at /home/bruening/dr/git/src/core/vmareas.c:1267
#9  0x00007ffff7d17ee2 in vmvector_add (v=0x7ffdf7bd70a8, start=0x41646000 '\253' <repeats 200 times>..., end=0x41654000 "", data=0x7ffdf7bed0a0)
    at /home/bruening/dr/git/src/core/vmareas.c:1921
#10 0x00007ffff7c10263 in fcache_create_unit (dcontext=0x7ffdf7c01080, cache=0x7ffdf7c33df0, pc=0x0, size=57344)
    at /home/bruening/dr/git/src/core/fcache.c:1415
#11 0x00007ffff7c12622 in fcache_cache_init (dcontext=0x7ffdf7c01080, flags=0, initial_unit=true) at /home/bruening/dr/git/src/core/fcache.c:1601
#12 0x00007ffff7c2e33d in get_cache_for_new_fragment (dcontext=0x7ffdf7c01080, f=0x7ffdf7c33d50) at /home/bruening/dr/git/src/core/fcache.c:3632
#13 0x00007ffff7c2e457 in fcache_add_fragment (dcontext=0x7ffdf7c01080, f=0x7ffdf7c33d50) at /home/bruening/dr/git/src/core/fcache.c:3649
#14 0x00007ffff7bef420 in fragment_create (dcontext=0x7ffdf7c01080, tag=0x401000 "H\203\344\360H\307\303\020", body_size=55, direct_exits=2, 
    indirect_exits=0, exits_size=46, flags=5632) at /home/bruening/dr/git/src/core/fragment.c:2411
#15 0x00007ffff7c5c119 in emit_fragment_common (dcontext=0x7ffdf7c01080, tag=0x401000 "H\203\344\360H\307\303\020", ilist=0x7ffdf7c2b138, flags=5632, 
    vmlist=0x7ffdf7bed058, link_fragment=true, add_to_htable=true, replace_fragment=0x0) at /home/bruening/dr/git/src/core/emit.c:572
#16 0x00007ffff7c5fef7 in emit_fragment_ex (dcontext=0x7ffdf7c01080, tag=0x401000 "H\203\344\360H\307\303\020", ilist=0x7ffdf7c2b138, flags=5632, 
    vmlist=0x7ffdf7bed058, link=true, visible=true) at /home/bruening/dr/git/src/core/emit.c:855
#17 0x00007ffff7df6901 in build_basic_block_fragment (dcontext=0x7ffdf7c01080, start=0x401000 "H\203\344\360H\307\303\020", initial_flags=0, link=true, 
    visible=true, for_trace=false, unmangled_ilist=0x0) at /home/bruening/dr/git/src/core/arch/interp.c:5123
#18 0x00007ffff7c488a3 in d_r_dispatch (dcontext=0x7ffdf7c01080) at /home/bruening/dr/git/src/core/dispatch.c:210

Xref:

            /* i#1649: avoid rank order for dynamo_areas */
            (v == dynamo_areas ? NULL : get_module_base(area->start));

DONE IR leak at 5

CLOSED: [2021-03-24 Wed 18:12]

<memory leak: IR 1248 bytes not freed>

Aha: instr_free should be instr_destroy.

DONE infinite recursion at 7 => avoid print_vm_area module lookup (again) for loaded_module_areas

CLOSED: [2021-03-24 Wed 18:22]

#18 0x00007ffff7d11b7e in print_vm_area (v=0x7ffdf7bb64f0, area=0x7ffdf7c068d0, outf=32672, prefix=0x7ffff7edbf57 "  ")
    at /home/bruening/dr/git/src/core/vmareas.c:747
#19 0x00007ffff7d11e07 in print_vm_areas (v=0x7ffdf7bb64f0, outf=32672) at /home/bruening/dr/git/src/core/vmareas.c:795
#20 0x00007ffff7d16084 in binary_search (v=0x7ffdf7bb64f0, start=0x400000 "\177ELF\002\001\001", end=0x400001 "ELF\002\001\001", area=0x7fffff7fff90, 
    index=0x0, first=false) at /home/bruening/dr/git/src/core/vmareas.c:1517
#21 0x00007ffff7d163e0 in lookup_addr (v=0x7ffdf7bb64f0, addr=0x400000 "\177ELF\002\001\001", area=0x7fffff7fff90)
    at /home/bruening/dr/git/src/core/vmareas.c:1570
#22 0x00007ffff7d18976 in vmvector_lookup_data (v=0x7ffdf7bb64f0, pc=0x400000 "\177ELF\002\001\001", start=0x0, end=0x0, data=0x7fffff7fffc8)
    at /home/bruening/dr/git/src/core/vmareas.c:2029
#23 0x00007ffff7d18867 in vmvector_lookup (v=0x7ffdf7bb64f0, pc=0x400000 "\177ELF\002\001\001") at /home/bruening/dr/git/src/core/vmareas.c:2011
#24 0x00007ffff7d3fdfc in module_pc_lookup (pc=0x400000 "\177ELF\002\001\001") at /home/bruening/dr/git/src/core/module_list.c:414
#25 0x00007ffff7e75107 in get_module_base (pc=0x400000 "\177ELF\002\001\001") at /home/bruening/dr/git/src/core/unix/module.c:330
#26 0x00007ffff7d11b7e in print_vm_area (v=0x7ffdf7bb64f0, area=0x7ffdf7c068d0, outf=32672, prefix=0x7ffff7edbf57 "  ")
    at /home/bruening/dr/git/src/core/vmareas.c:747

DONE a64 crash reading NULL thread_kstats

CLOSED: [2021-03-24 Wed 21:32]

DONE windows crash on lock: ok it's the earlier fcache_unit_areas de-ref

CLOSED: [2021-03-24 Wed 21:41]

0:000> kn
 # Child-SP          RetAddr           Call Site
00 00000001`000fecf0 00000000`151e17a6 dynamorio!mutex_testlock+0xe [d:\derek\dr\git\src\core\utils.h @ 806] 
01 00000001`000fed10 00000000`151e1b3a dynamorio!print_vm_area+0x1a6 [d:\derek\dr\git\src\core\vmareas.c @ 746] 
02 00000001`000feda0 00000000`151e5324 dynamorio!print_vm_areas+0x15a [d:\derek\dr\git\src\core\vmareas.c @ 798] 
03 00000001`000fede0 00000000`151c370d dynamorio!add_vm_area+0x2f94 [d:\derek\dr\git\src\core\vmareas.c @ 1272] 
04 00000001`000ff070 00000000`15199650 dynamorio!vmvector_add+0x12d [d:\derek\dr\git\src\core\vmareas.c @ 1927] 
05 00000001`000ff0e0 00000000`153aa3f6 dynamorio!alloc_landing_pad+0x890 [d:\derek\dr\git\src\core\heap.c @ 5854] 
06 00000001`000ff210 00000000`1539deae dynamorio!intercept_call+0x706 [d:\derek\dr\git\src\core\win32\callback.c @ 1728] 
07 00000001`000ff350 00000000`150115c0 dynamorio!callback_interception_init_start+0x2ce [d:\derek\dr\git\src\core\win32\callback.c @ 7608] 
08 00000001`000ff400 00000000`15010fce dynamorio!dynamorio_app_init_part_two_finalize+0x2f0 [d:\derek\dr\git\src\core\dynamo.c @ 588] 
09 00000001`000ffd80 00000000`15026351 dynamorio!dynamorio_app_init+0xe [d:\derek\dr\git\src\core\dynamo.c @ 391] 
0a 00000001`000ffdb0 00000000`153482e3 dynamorio!dynamorio_earliest_init_takeover_C+0x41 [d:\derek\dr\git\src\core\dynamo.c @ 3058] 
0b 00000001`000ffe00 00000000`155b1000 dynamorio!dynamorio_earliest_init_takeover+0x2d [D:\derek\dr\git\build_x64_dbg_tests\core\CMakeFiles\dynamorio.dir\arch\x86\x86.asm.obj.s @ 4650]