CRASH (symcache_free_entry) during shutdown of media_unittests since updating DR in r1230 from r1938 to r1977

[derekbruening]

From rnk@google.com on March 12, 2013 11:19:21

See the list of build here: http://build.chromium.org/p/client.drmemory/builders/win7-cr First failing build: http://build.chromium.org/p/client.drmemory/builders/win7-cr/builds/1507 Stack trace: <Application E:\b\build\slave\win7-cr-builder\build\src\build\Debug\media_unittests.exe (3032). Client exception at PC 0x73850cc4. Program aborted. 0xc0000005 0x00000000 0x73850cc4 0x73850cc4 0x00000000 0x0000064c Base: 0x6aaa0000 Registers: eax=0x00000003 ebx=0x22e1af8c ecx=0x208d2a44 edx=0x00000080 esi=0x00000644 edi=0x22e20961 esp=0x206eed1c ebp=0x206eed2c eflags=0x00010202 version 4.0.1977, custom build -logdir 'C:\Users\chrome-bot\AppData\LocalLow\drmemory.logs\dynamorio' -client_lib 'E:\b\build\slave\win7-cr\build\unpacked\bin\release\drmemorylib.dll;0;-suppress E:\b\build\slave\win7-cr-builder\build\src\tools\valgrind\drmemory\suppressions.txt -symcache_dir C:\Users\chrome-bot\AppData\LocalLow\drmemory.symcache -no_summary -callstack_max_frames 40 `-callstack_srcfil 0x206eed2c 0x73850dbe 0x206eed38 0x738420d4 0x206eed48 0x73850d02 0x206eed64 0x73850dbe 0x206eed70 0x73843193 0x206eedac 0x6aacf430 0x206eedbc 0x6ab5b283 0x206eedcc 0x2069e100 0x6ab3cf13 0x5b01b05e E:\b\build\slave\win7-cr\build\unpacked\bin\release\drmemorylib.dll=0x73800000 E:\b\build\slave\win7-cr\build\unpacked\bin\release/dbghelp.dll=0x6a950000 C:\Windows/system32/msvcrt.dll=0x01190000 C:\Windows/system32/KERNEL32.dll=0x01080000 C:\Windows/system32/KERNELBASE.dll=0x002f0000>

If I'm reading that right, it looks like a crash inside a dbghelp callback to something in drmemorylib (drsyms is linked in statically).

I'm updating my Windows binaries to try and repro with a real stack trace, but if anyone else can try the same in parallel that would help.

Here's a quick list of possibly relevant revs: $ git log --pretty='%aN %s' $(git svn find-rev r1938 )..$(git svn find-rev r1977 ) derek.bruening Fix bug in appending extension library paths to .drpath files. derek.bruening issue #915: allow kernelbase to run on x64 derek.bruening issue #1093 addendum: top 16 bits must be zero for x64 rnk@google.com Insert a space between string literals and macro identifiers rnk@google.com Ignore stderr from the linker when checking from gold rnk@google.com issue #1105: Revert "Use a stack allocated buffer for private_instr_encode" zhaoqin@google.com fixed issue #262 - add DR_MEMPROT_EXEC in client.alloc test if READ_IMPLIES_EXEC is set in personality rnk@google.com Use a stack allocated buffer for private_instr_encode rnk@google.com issue #1100: Fix off-by-one in redirect_RegQueryValueExA and accept REG_SZ TEMP derek.bruening Fix configure error in 2nd DR client/standalone in the same listdir when CMAKE_C_FLAGS is empty (such as 64-bit Dr. Memory). derek.bruening Fix bug in use_DynamoRIO_extension() on standalone client zhaoqin@google.com fixed issue #1095 - add instrlist_insert_mov_immed_ptrsz and instrlist_insert_push_immed_ptrsz - add test in abort rnk@google.com issue #1101: Reorder lock ranks for coarse info table after incoming rnk@google.com issue #1090: Don't swap retaddrs when the TOS is a native PC derek.bruening fixes issue #1099 derek.bruening issue #65: test samples derek.bruening fixes issue #1098 derek.bruening Redirect kernel32 imports from kernelbase where possible, while still supporting a handful of redirection routines calling back into priv kernel32. derek.bruening issue #912: add 4 more Win8 API set mappings. derek.bruening fixes issue #1093 rnk@google.com issue #1097: Alias -v to -verbose and add -version for drrun rnk@google.com issue #1096: Fix protect-dstack test on Windows rnk@google.com Add CMake options for easier profiling on Linux rnk@google.com issue #1077: Avoid interpreting back_from_native rnk@google.com issue #1097: Always override DYNAMORIO_OPTIONS on execve rnk@google.com issue #1094: Don't search NULL rpaths and fix Linux impl of GetFullPathName() derek.bruening fixes issue #1091 rnk@google.com issue #786: Support linking with GNU gold rnk@google.com Fix native_exec hotp assertion rnk@google.com Fix MSVC generator errors about generate_nativeexec rnk@google.com issue #1092: Remove the drdeploy symlink before creating it zhaoqin@google.com fixed issue #1084 - adjust dr_unmap_file map range to the whole file on Windows rnk@google.com issue #978: Use a stack of native retaddrs to handle nested native calls rnk@google.com Use KSTART_DC in dispatch() derek.bruening fixes issue #1159 rnk@google.com Un-revert r1933 now that issue #1088 (drrun -logdir) is fixed rnk@google.com issue #1088: Add a -logdir option to the drdeploy frontends rnk@google.com issue #1086: Use a non-ignorable syscall in linux.infloop

I have a bunch of commits but I'm not sure if they're related. The win32 redirection stuff seems like it might cause this.

Original issue: http://code.google.com/p/drmemory/issues/detail?id=1168

[derekbruening]

From bruen...@google.com on March 12, 2013 09:56:26

with my chrome build from ~March 1, I can't repro. full mode runs fine. -light, to match the run here, ends up w/ WASAPIAudioOutputStreamTest.* failing. When I exclude those, it runs to completion just fine.

[derekbruening]

From bruen...@google.com on March 12, 2013 16:01:44

someone should grab dbghelp.dll from the build bot and build drmemorylib to match this one and recreate the callstack

[derekbruening]

From bruen...@google.com on March 13, 2013 11:59:33

tsan tests have something similar: http://build.chromium.org/p/client.drmemory/builders/win-7_x64-drm/builds/2996/steps/rel%20light%20TSan%20tests/logs/stdio

[derekbruening]

From bruen...@google.com on March 13, 2013 13:41:18

I spent a while trying to reproduce the tsan crash with no luck.

[derekbruening]

From bruen...@google.com on March 13, 2013 13:57:37

time to look at the callstack printed in the logs

no, dbghelp is not involved: this is DR calling drmem. it's a symcache issue. not clear what DR change is involved, or whether it's just nondet.

tsan for which I went on the bot and got the dlls: % bin/symquery -f -e bin/release/drmemorylib.dll -a 0x50dbe 0x420d4 0x50d02 0x50dbe 0x43193 hashtable_delete+0x1e e:\b\build\slave\win-7_x64-drm\drmemory\dynamorio\ext\drcontainers\hashtable.c:491+0x0 symcache_free_entry+0x14 e:\b\build\slave\win-7_x64-drm\drmemory\common\symcache.c:130+0x0 hashtable_clear_internal+0x72 e:\b\build\slave\win-7_x64-drm\drmemory\dynamorio\ext\drcontainers\hashtable.c:465+0x6 hashtable_delete+0x1e e:\b\build\slave\win-7_x64-drm\drmemory\dynamorio\ext\drcontainers\hashtable.c:491+0x0 symcache_exit+0x63 e:\b\build\slave\win-7_x64-drm\drmemory\common\symcache.c:502+0x0

Summary: CRASH (symcache_free_entry) during shutdown of media_unittests since updating DR in r1230 from r1938 to r1977 (was: Crash in drmemory during shutdown of media_unittests since updating DR in r1230 from r1938 to r1977)
Owner: bruen...@google.com

[derekbruening]

From bruen...@google.com on March 13, 2013 14:38:06

can you, with graphical login capabilities that I don't have, try to repro on the bot and get more information?

Owner: rnk@google.com
Labels: Bug-ToolCrash

[derekbruening]

From rnk@google.com on March 13, 2013 14:42:35

Yeah, I'll take go take a look.

[derekbruening]

From bruen...@google.com on March 13, 2013 14:45:51

I grabbed the symcache files and a quick look shows nothing weird. I even tried running with them on my machine (kind of risky) and no errors.

[derekbruening]

From rnk@google.com on March 13, 2013 15:25:54

I used ldmp + windbg to try to get a stack: 0:000> k ChildEBP RetAddr
WARNING: Stack unwind information not available. Following frames may be wrong. 16d4e358 5fbbb8c7 dynamorio!dr_create_client_thread+0xb0a 16d4e364 5fb66c91 dynamorio!dr_create_client_thread+0x11f7 16d4e384 5fbc1aa0 dynamorio!dr_close_file+0x1501 16d4e3f8 5fbc2d65 dynamorio!dr_syscall_invoke_another+0x2290 16d4e6d4 16ce1bec dynamorio!dr_syscall_invoke_another+0x3555 16d4ecf8 02ff6bf6 <Unloaded???dwmapi.dll>+0x16c81beb 16d4ed04 02fb363c drmemorylib!hashtable_delete+0x26 [e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drcontainers\hashtable.c @ 489] 16d4ed14 02ff6b8e drmemorylib!symcache_free_entry+0x1c [e:\b\build\slave\win-builder\drmemory\common\symcache.c @ 129] 16d4ed2c 02ff6bf6 drmemorylib!hashtable_clear_internal+0x8e [e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drcontainers\hashtable.c @ 465] 16d4ed38 02fb39b2 drmemorylib!hashtable_delete+0x26 [e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drcontainers\hashtable.c @ 489] 16d4ed78 02dbab42 drmemorylib!symcache_exit+0x332 [e:\b\build\slave\win-builder\drmemory\common\symcache.c @ 501] 16d4ed80 5fbad5c6 drmemorylib!event_exit+0xc2 [e:\b\build\slave\win-builder\drmemory\drmemory\drmemory.c @ 432] 16d4edac 5fb4f430 dynamorio!decode_next_pc+0x4c6 16d4edbc 5fbdadc3 dynamorio!instr_set_prev+0x1250 16d4edcc 16cf2c80 dynamorio!dynamorio_app_take_over+0x8a

Looks like windbg can't find dynamorio.pdb.

[derekbruening]

From rnk@google.com on March 14, 2013 08:12:06

After adjusting .sympath, I got a better trace:

0:000> kn

ChildEBP RetAddr

00 16d4e358 5fbbb8c7 dynamorio!os_dump_core_live_dump+0x26a [e:\b\build\slave\win-builder\drmemory\dynamorio\core\win32\os.c @ 6067] 01 16d4e364 5fb66c91 dynamorio!os_dump_core+0x37 [e:\b\build\slave\win-builder\drmemory\dynamorio\core\win32\os.c @ 6288] 02 16d4e384 5fbc1aa0 dynamorio!report_dynamorio_problem+0x171 [e:\b\build\slave\win-builder\drmemory\dynamorio\core\utils.c @ 2177] 03 16d4e3f8 5fbc2d65 dynamorio!report_internal_exception+0xb0 [e:\b\build\slave\win-builder\drmemory\dynamorio\core\win32\callback.c @ 4529] 04 16d4e6d4 16ce1bec dynamorio!intercept_exception+0x295 [e:\b\build\slave\win-builder\drmemory\dynamorio\core\win32\callback.c @ 5100] WARNING: Frame IP not in any known module. Following frames may be wrong. 05 16d4ecf8 02ff6bf6 0x16ce1bec 06 16d4ed04 02fb363c drmemorylib!hashtable_delete+0x26 [e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drcontainers\hashtable.c @ 489] 07 16d4ed14 02ff6b8e drmemorylib!symcache_free_entry+0x1c [e:\b\build\slave\win-builder\drmemory\common\symcache.c @ 129] 08 16d4ed2c 02ff6bf6 drmemorylib!hashtable_clear_internal+0x8e [e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drcontainers\hashtable.c @ 465] 09 16d4ed38 02fb39b2 drmemorylib!hashtable_delete+0x26 [e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drcontainers\hashtable.c @ 489] 0a 16d4ed78 02dbab42 drmemorylib!symcache_exit+0x332 [e:\b\build\slave\win-builder\drmemory\common\symcache.c @ 501] 0b 16d4ed80 5fbad5c6 drmemorylib!event_exit+0xc2 [e:\b\build\slave\win-builder\drmemory\drmemory\drmemory.c @ 432] 0c 16d4edac 5fb4f430 dynamorio!instrument_exit+0x86 [e:\b\build\slave\win-builder\drmemory\dynamorio\core\x86\instrument.c @ 674] 0d 16d4edbc 5fbdadc3 dynamorio!dynamo_process_exit+0x260 [e:\b\build\slave\win-builder\drmemory\dynamorio\core\dynamo.c @ 1396] 0e 16d4edcc 16cf2c80 dynamorio!cleanup_and_terminate+0x4b [E:\b\build\slave\win-builder\build\build_drheapstat-release-32\dynamorio\core\x86.asm_core.s @ 1276] 0f 5fbbcf03 5b01b05e 0x16cf2c80 10 5f20c483 00000000 0x5b01b05e

So it's a crash on hashtable.c:489. This was with debug drmemory and release DR.

Looking into hashtable_delete() next...

[derekbruening]

From bruen...@google.com on March 14, 2013 08:31:00

no, hashtable.c:489 is the parent. you want to do .cxr on the exception context to get the full context at the time of the crash.

[derekbruening]

From rnk@google.com on March 14, 2013 09:46:15

This time with the last frame: 0:000> kp ** Stack trace for last set context - .thread/.cxr resets it ChildEBP RetAddr
16d4ecf8 02ff6bf6 drmemorylib!hashtable_clear_internal(struct _hashtable_t * table = 0x16df80b0)+0x45 [e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drcontainers\hashtable.c @ 461] 16d4ed04 02fb363c drmemorylib!hashtable_delete(struct _hashtable_t * table = 0x16df80b0)+0x26 [e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drcontainers\hashtable.c @ 489] 16d4ed14 02ff6b8e drmemorylib!symcache_free_entry(void * v = 0x16df80a8)+0x1c [e:\b\build\slave\win-builder\drmemory\common\symcache.c @ 129] 16d4ed2c 02ff6bf6 drmemorylib!hashtable_clear_internal(struct _hashtable_t * table = 0x03267620)+0x8e [e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drcontainers\hashtable.c @ 465] 16d4ed38 02fb39b2 drmemorylib!hashtable_delete(struct _hashtable_t \ table = 0x03267620)+0x26 [e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drcontainers\hashtable.c @ 489] 16d4ed78 02dbab42 drmemorylib!symcache_exit(void)+0x332 [e:\b\build\slave\win-builder\drmemory\common\symcache.c @ 501] 16d4ed80 5fbad5c6 drmemorylib!event_exit(void)+0xc2 [e:\b\build\slave\win-builder\drmemory\drmemory\drmemory.c @ 432] 16d4edac 5fb4f430 dynamorio!instrument_exit(void)+0x86 [e:\b\build\slave\win-builder\drmemory\dynamorio\core\x86\instrument.c @ 674] 16d4edbc 5fbdadc3 dynamorio!dynamo_process_exit(void)+0x260 [e:\b\build\slave\win-builder\drmemory\dynamorio\core\dynamo.c @ 1396] 16d4edcc 16cf2c80 dynamorio!cleanup_and_terminate(void)+0x4b [E:\b\build\slave\win-builder\build\build_drheapstat-release-32\dynamorio\core\x86.asm_core.s @ 1276] WARNING: Frame IP not in any known module. Following frames may be wrong.

Crash is here: while (e != NULL) { hash_entry_t _nexte = e->next; // here if (table->str_dup) hash_free(e->key, strlen((const char *)e->key) + 1); if (table->free_payload_func != NULL) (table->free_payload_func)(e->payload); hash_free(e, sizeof(_e)); e = nexte; }

Let's see what e is.

[derekbruening]

From rnk@google.com on March 14, 2013 09:48:08

Someone wrote something bad into the table:

0:000> .frame 00 16d4ecf8 02ff6bf6 drmemorylib!hashtable_clear_internal+0x45 [e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drcontainers\hashtable.c @ 461] 0:000> dv nexte = 0x00000000 e = 0x0000cc0c table = 0x16df80b0 i = 3 0:000> ?? table struct _hashtable_t * 0x16df80b0 0:000> ?? table->table[i] struct _hash_entry_t * 0x0000cc0c

[derekbruening]

From rnk@google.com on March 14, 2013 10:49:44

This looks like a heap stomper. I can repro something else locally, which looks like:

2507e734 66a6463d dynamorio!external_error(char * file = 0x66c4c9e4 "....\core\heap.c", int line = 2936, char * msg = 0x66c514e4 "memory corruption detected")+0xf2 [d:\src\dynamorio\core\utils.c @ 204] 2507e7a0 66a58eae dynamorio!threadunits_exit(struct _thread_units_t * tu = 0x66ce9790, struct _dcontext_t * dcontext = 0xffffffff)+0xfd [d:\src\dynamorio\core\heap.c @ 2936] 2507e7e4 6694144d dynamorio!heap_exit(void)+0x1fe [d:\src\dynamorio\core\heap.c @ 1561] 2507e80c 669418e6 dynamorio!dynamo_shared_exit(struct _thread_record_t * toexit = 0x00000000, char detach_stacked_callbacks = 0 '')+0x43d [d:\src\dynamorio\core\dynamo.c @ 1038] 2507e834 6694173b dynamorio!dynamo_process_exit_cleanup(void)+0x196 [d:\src\dynamorio\core\dynamo.c @ 1225] 2507e844 66b597f2 dynamorio!dynamo_process_exit(void)+0x12b [d:\src\dynamorio\core\dynamo.c @ 1284] 2507e854 25016100 dynamorio!cleanup_and_terminate(void)+0x4b [D:\src\dynamorio\build\build_debug-i32-static-ext\core\CMakeFiles\dynamorio.dir\x86\x86.asm.obj.s @ 1281] 66b997bd 8b5e5f01 0x25016100

Dumping the memory looks like:

0:000> ?? p unsigned char * 0x2510fae4 "???" 0:000> ddp 0x2510fae4 2510fae4 cdcdcdcd 2510fae8 cdcdcdcd 2510faec 0000cdcd 2510faf0 cdcdcdcd 2510faf4 cdcdcdcd 2510faf8 cdcdcdcd 2510fafc cdcdcdcd 2510fb00 cdcdcdcd 2510fb04 cdcdcdcd

Not very informative. I seem to be able to repro 1 out of 4 runs on media_unittests, though, so I could possibly do a bisect on DR revs.

[derekbruening]

From rnk@google.com on March 14, 2013 13:06:27

I also see this double-free stack sometimes:

0:000> kp ChildEBP RetAddr
WARNING: Stack unwind information not available. Following frames may be wrong. 1dcddcd4 665eb50d ntdll!NtRaiseHardError+0x12 1dcddcfc 66456354 dynamorio!debugbox(char * msg = 0x1dcddd10 "CURIOSITY : (_(uint )p != 0xcdcdcdcd || (size >= 2_sizeof(uint) && (((uint )p)+1) != 0xcdcdcdcd)) && (uint )(p+size-sizeof(int)) != 0xcdcdcdcd && "attempting to free memory containing HEAP_UNALLOCATED pattern, " "possible double free!" in file ....\core\heap.c line.version 4.0.1990, custom build.-logdir 'D:\src\drmemory\exports32\drmemory\logs\dynamorio' -client_lib 'D:\src\drmemory\exports32\bin\debug\drmemorylib.dll;0;-light -logdir D:\src\drmemory\exports32\drmemory\logs -resfile 4724 ' -code_api -probe_api -msgbox_mask 15 -dumpcore_mask 0x40039 -stderr_mask 15 -stack_size 56K -disable_traces -no_enable_traces -max_elide_jmp 0 -max_elide_call 0 -max_bb_instrs 256 .0x1dcde5a8 0x664c98c0.0x1dcde6c4 0x664caad5.0x1dcde6e8 0x665d625b.0x1dcde70c 0x0493f404.0x1dcde720 0x049b2903.0x1dcde78c 0x049b2c1f.0x1dcde7a0 0x04999203.0x1dcde7c0 0x04998cc5.0x1dcde7d0 0x665d32bd.0x1dcde800 0x663a3660.0x1dcde80c 0x663a1817.0x1dcde834 0x663a16fb.0x1dcde844 0x665b9c32.0x1dcde854 0x1dc98040.0x665f9c3d 0x8b5e5f01.D:\src\drmemory\exports32\bin\debug\drmemorylib.dll=0x04750000.D:\src\drmemory\exports32\bin\debug/dbghelp.dll=0x66c80000.C:\Windows/system32/msvcrt.dll=0x04c90000.C:\Windows/system32/kernel32.dll=0x04eb0000.C:\Windows/system32/KERNELBASE.dll=0x04d40000")+0x4d [d:\src\dynamorio\core\win32\os.c @ 3798] 1dcde518 664568b2 dynamorio!notify(syslog_event_type_t priority = SYSLOG_WARNING (2), char internal = 1 '', char synch = 0 '', unsigned int message_id = 0x80ff03ef, unsigned int substitution_num = 0, char * prefix = 0x6666bb8c "SYSLOG_WARNING", char * fmt = 0x66668820 "%s", char * ap = 0x00000000 "")+0x1e4 [d:\src\dynamorio\core\utils.c @ 1950] 1dcde5a8 664c98c0 dynamorio!report_dynamorio_problem(struct _dcontext_t * dcontext = 0x1dc98040, unsigned int dumpcore_flag = 0x80, unsigned char * exception_addr = 0x00000000 "", unsigned char * report_ebp = 0x1dcde5a8 "???", char * fmt = 0x66674ab8 "CURIOSITY : %s in file %s line %d", char * curbuf = 0x667676d5 "")+0x502 [d:\src\dynamorio\core\utils.c @ 2211] 1dcde6c4 664caad5 dynamorio!common_heap_free(struct _thread_units_t * tu = 0x1dc98314, void * p_void = 0x1e44d964, unsigned int size = 0x800, which_heap_t which = ACCT_CLIENT (19))+0x130 [d:\src\dynamorio\core\heap.c @ 3503] 1dcde6e8 665d625b dynamorio!heap_free(struct _dcontext_t * dcontext = 0x1dc98040, void * p = 0x1e44d964, unsigned int size = 0x800, which_heap_t which = ACCT_CLIENT (19))+0x45 [d:\src\dynamorio\core\heap.c @ 3626] 1dcde70c 0493f404 dynamorio!dr_thread_free(void * drcontext = 0x1dc98040, void * mem = 0x1e44d964, unsigned int size = 0x800)+0x8b [d:\src\dynamorio\core\x86\instrument.c @ 2403] 1dcde720 049b2903 drmemorylib!thread_free(void * drcontext = 0x1dc98040, void * p = 0x1e44d964, unsigned int size = 0x800, heapstat_t type = HEAPSTAT_MISC (7))+0x24 [d:\src\drmemory\common\utils.c @ 1119] 1dcde78c 049b2c1f drmemorylib!syscall_reset_per_thread(void * drcontext = 0x1dc98040, struct _cls_syscall_t * cpt = 0x1def8e0c)+0x313 [d:\src\drmemory\drsyscall\drsyscall.c @ 1826] 1dcde7a0 04999203 drmemorylib!syscall_context_exit(void * drcontext = 0x1dc98040, char thread_exit = 1 '')+0x2f [d:\src\drmemory\drsyscall\drsyscall.c @ 1862] 1dcde7c0 04998cc5 drmemorylib!drmgr_cls_stack_exit(void * drcontext = 0x1dc98040)+0xa3 [d:\src\dynamorio\ext\drmgr\drmgr.c @ 1533] 1dcde7d0 665d32bd drmemorylib!drmgr_thread_exit_event(void * drcontext = 0x1dc98040)+0x55 [d:\src\dynamorio\ext\drmgr\drmgr.c @ 1311] 1dcde800 663a3660 dynamorio!instrument_thread_exit_event(struct _dcontext_t * dcontext = 0x1dc98040)+0xdd [d:\src\dynamorio\core\x86\instrument.c @ 1201] 1dcde80c 663a1817 dynamorio!dynamo_thread_exit_pre_client(struct _dcontext_t \ dcontext = 0x1dc98040, unsigned int id = 0x1ff0)+0x30 [d:\src\dynamorio\core\dynamo.c @ 2219] 1dcde834 663a16fb dynamorio!dynamo_process_exit_cleanup(void)+0x107 [d:\src\dynamorio\core\dynamo.c @ 1205] 1dcde844 665b9c32 dynamorio!dynamo_process_exit(void)+0x12b [d:\src\dynamorio\core\dynamo.c @ 1283] 1dcde854 1dc98040 dynamorio!cleanup_and_terminate(void)+0x4b [D:\src\dynamorio\build\build_debug-i32-static-ext\core\CMakeFiles\dynamorio.dir\x86\x86.asm.obj.s @ 1281]

Looking into that now.

[derekbruening]

From rnk@google.com on March 14, 2013 13:21:57

That might be a red herring, because sysarg_val[i] is copied from the app, so it's plausible that the app might poison the pre-value with a bunch of 0xcd bytes. I see this in the debugger:

0:000> ?? cpt->sysarg_val[i] unsigned char * 0x1e44d964 "x???" 0:000> ?? cpt->sysarg_val_bytes[i] unsigned int 0x800 0:000> ddp 0x1e44d964 1e44d964 0764a778 1e44d968 edededed 1e44d96c cdcdcdcd 1e44d970 cdcdcdcd 1e44d974 cdcdcdcd

It also doesn't seem plausible that these are double-freed, since we unconditionally overwrite the sysarg slots after freeing them.

[derekbruening]

From rnk@google.com on March 14, 2013 13:59:05

I reproduced something much closer to the original heap overwrite while running the pre-commit suite for the recv changes:

1b0f3c48 cd cd cd cd cd cd cd cd-30 2f 0f 1b cd cd cd cd ........0/...... 0:000> kn

ChildEBP RetAddr

00 1b08e3f0 6670e6c7 dynamorio!os_dump_core_live_dump+0x26a [d:\src\dynamorio\core\win32\os.c @ 6067] 01 1b08e408 665767ad dynamorio!os_dump_core+0x57 [d:\src\dynamorio\core\win32\os.c @ 6277] 02 1b08e47c 66571554 dynamorio!report_dynamorio_problem+0x3fd [d:\src\dynamorio\core\utils.c @ 2177] 03 1b08e5b4 665ea24a dynamorio!internal_error+0x124 [d:\src\dynamorio\core\utils.c @ 188] 04 1b08e6bc 665e2e3c dynamorio!common_heap_free+0xaba [d:\src\dynamorio\core\heap.c @ 3585] 05 1b08e6e0 665e2d6f dynamorio!common_global_heap_free+0x6c [d:\src\dynamorio\core\heap.c @ 2537] 06 1b08e6f8 666f62a2 dynamorio!global_heap_free+0x1f [d:\src\dynamorio\core\heap.c @ 2565] 07 1b08e70c 739eede0 dynamorio!dr_global_free+0x12 [d:\src\dynamorio\core\x86\instrument.c @ 2422] 08 1b08e71c 739efc92 drmemorylib!global_free+0x20 [d:\src\drmemory\common\utils.c @ 1101] 09 1b08e730 73a4656a drmemorylib!hashwrap_free+0x12 [d:\src\drmemory\common\utils.c @ 1191] 0a 1b08e740 73a46b33 drmemorylib!hash_free+0x1a [d:\src\dynamorio\ext\drcontainers\hashtable.c @ 145] 0b 1b08e75c 73a46bb6 drmemorylib!hashtable_clear_internal+0x73 [d:\src\dynamorio\ext\drcontainers\hashtable.c @ 463] 0c 1b08e768 73a039a2 drmemorylib!hashtable_delete+0x26 [d:\src\dynamorio\ext\drcontainers\hashtable.c @ 489] 0d 1b08e7a8 7380ab42 drmemorylib!symcache_exit+0x332 [d:\src\drmemory\common\symcache.c @ 501] 0e 1b08e7b0 666f1ec3 drmemorylib!event_exit+0xc2 [d:\src\drmemory\drmemory\drmemory.c @ 432] 0f 1b08e7e4 664c11f1 dynamorio!instrument_exit+0xa3 [d:\src\dynamorio\core\x86\instrument.c @ 674] 10 1b08e80c 664c18a6 dynamorio!dynamo_shared_exit+0x221 [d:\src\dynamorio\core\dynamo.c @ 960] 11 1b08e834 664c16fb dynamorio!dynamo_process_exit_cleanup+0x196 [d:\src\dynamorio\core\dynamo.c @ 1224] 12 1b08e844 666d9c32 dynamorio!dynamo_process_exit+0x12b [d:\src\dynamorio\core\dynamo.c @ 1283] 13 1b08e854 1b0483c0 dynamorio!cleanup_and_terminate+0x4b [D:\src\dynamorio\build\build_debug-i32-static-ext\core\CMakeFiles\dynamorio.dir\x86\x86.asm.obj.s @ 1281]

0:000> db 0x1b0f3bd8 1b0f3bd8 44 3a 5c 73 72 63 5c 64-79 6e 61 6d 6f 72 00 00 D:\src\dynamor.. 1b0f3be8 5c 65 78 70 6f 72 74 73-5c 6c 69 62 33 32 5c 64 \exports\lib32\d 1b0f3bf8 65 62 75 67 5c 64 79 6e-61 6d 6f 72 69 6f 2e 64 ebug\dynamorio.d 1b0f3c08 6c 6c 00 bc bc bc bc bc-bc bc bc bc 18 d4 21 1b ll............!. 1b0f3c18 cd cd cd cd cd cd cd cd-cd cd cd cd cd cd cd cd ................ 1b0f3c28 cd cd cd cd cd cd cd cd-cd cd cd cd cd cd cd cd ................ 1b0f3c38 cd cd cd cd cd cd cd cd-cd cd cd cd cd cd cd cd ................ 1b0f3c48 cd cd cd cd cd cd cd cd-30 2f 0f 1b cd cd cd cd ........0/......

It's the same overwrite as in comment 14: 2 zero bytes at offset 14.

We're freeing a string here, so the zero byte shortens the result of strlen() and we get the wrong size and hence an assertion about padding being overwritten.

[derekbruening]

From bruen...@google.com on March 14, 2013 14:44:47

re: 0xcd: xref issue #1148

[derekbruening]

From rnk@google.com on March 15, 2013 10:30:23

Drilling in on the path overwrite bug, I found the allocation site of the string that has the semi-deterministic overwrite and point a watchpoint on it.

Here's the allocation site: 00cceca4 73a46f29 dynamorio!dr_messagebox+0xee [d:\src\dynamorio\core\x86\instrument.c @ 3693] 00ccecbc 73a079d0 drmemorylib!hashtable_add+0x199 [d:\src\dynamorio\ext\drcontainers\hashtable.c @ 339] 00cced20 7380cc46 drmemorylib!symcache_module_load+0x5d0 [d:\src\drmemory\common\symcache.c @ 637] 00cced84 73a493f1 drmemorylib!event_module_load+0x1f6 [d:\src\drmemory\drmemory\drmemory.c @ 1435] 00cced9c 6d8a4bb8 drmemorylib!drmgr_modload_event+0x41 [d:\src\dynamorio\ext\drmgr\drmgr.c @ 1057] 00ccedd8 6d8a1cd1 dynamorio!instrument_module_load+0xb8 [d:\src\dynamorio\core\x86\instrument.c @ 1754] ...

The overwrite always happens at 14 bytes in (the "io" in dynamorio), so I did "baw 2 0x22fd3bd8 + e"

The watchpoint hits at: dynamorio!convert_to_NT_file_path_wide+0x162 [d:\src\dynamorio\core\win32\os.c @ 4908]

It looks like there's some confusion on bytes vs. elements as the unit of buf_len.

[derekbruening]

From rnk@google.com on March 15, 2013 10:34:18

Pasting some more info before I quit the session: 0:000> du 22fd39d8 22fd39d8 "\??\C:\Windows\WinSxS\x86_micros" 22fd3a18 "oft.windows.common-controls_6595" 22fd3a58 "b64144ccf1df_5.82.7601.17514_non" 22fd3a98 "e_ec83dffa859149af\comctl32v582." 22fd3ad8 "pdb" 0:000> dv fixedbuf = 0x00ccc600 fname = 0x00000108 "" fixedbuf_len = 0x104 allocbuf_sz = 0x00ccc810 size_needed = 0x108 is_UNC = 0 ''