CRASH (unit_tests on win7-cr bot)

[derekbruening]

From bruen...@google.com on January 30, 2014 11:08:12

http://build.chromium.org/p/client.drmemory/builders/win7-cr/builds/4921/steps/Chromium%20%27unit%27%20tests/logs/stdio [ RUN ] DownloadProtectionServiceTest.CheckClientDownloadZip
<Application E:\b\build\slave\win7-cr-builder\build\src\out\Debug\unit_tests.exe (4272). Client exception at PC 0x1efc64d8. Program aborted.
0xc0000005 0x00000000 0x1efc64d8 0x1efc64d8 0x00000000 0x00000003
Base: 0x6d600000
Registers: eax=0x00000000 ebx=0x1f164f80 ecx=0x00000000 edx=0x00000000
esi=0x1ff6eba8 edi=0x25502805 esp=0x1f1fe6bc ebp=0x1f1fe6c8
eflags=0x00010202
version 4.2.2499, custom build
-no_dynamic_options -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
0x1f1fe6c8 0x1f014927
0x1f1fe714 0x6d691ce5
0x1f1fe760 0x6d682a12
0x1f1fe7ac 0x6d6837f0
0x1f1fe810 0x6d6842de
0x1f1fe88c 0x6d665b50
0x1f1fe8cc 0x6d667896
0x1f1feb9c 0x6d667dc9
0x1f1febc0 0x6d6a8c71
0x1f1feea4 0x6d727bec
0x0018d2b0 0x75707abc
0x0018d2d0 0x75707a8a
0x0018d2e4 0x75707a56
0x0018d30c 0x7578df69
0x0018d31c 0x7578dfc0
E:\b\build\slave\win7-cr\build\unpacked\bin\release\drmemorylib.dll=0x1efc0000
E:\b\build\slave\win7-cr\build\unpacked\bin\release/dbghelp.dll=0x6d4b0000
C:\Windows/system32/msvcrt.dll=0x2f170000
C:\Windows/system32/KERNEL32.dll=0x1ee30000
C:\Windows/system32/KERNELBASE.dll=0x1ef60000>

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

[derekbruening]

From bruen...@google.com on January 30, 2014 09:08:49

Passed on the FYI bot: http://build.chromium.org/p/chromium.fyi/builders/Windows%20Unit%20%28DrMemory%20full%29%20%284%29/builds/150/steps/memory%20test%3A%20unit_4/logs/stdio [ RUN ] DownloadProtectionServiceTest.CheckClientDownloadZip
[ OK ] DownloadProtectionServiceTest.CheckClientDownloadZip (1123 ms)

But win7-cr is using r1689 while FYI has r1686 .

Locally I've been running r1689 though and I can't repro this.

11:59 AM ~/drmemory/bugs/i1430/unpacked
% bin/symquery.exe -e bin/release/drmemorylib.dll -f -a 0x64d8 0x54927
instru_event_bb_analysis+0x78
e:\b\build\slave\win-builder\drmemory\drmemory\readwrite.c:4630+0x0
drmgr_bb_event+0x147
e:\b\build\slave\win-builder\drmemory\dynamorio\ext\drmgr\drmgr.c:439+0x16

    if (translating) {
        bb_saved_info_t *save;
        hashtable_lock(&bb_table);
        save = (bb_saved_info_t *) hashtable_lookup(&bb_table, tag);
        ASSERT(save != NULL, "missing bb info");
        if (save->check_ignore_unaddr)

Owner: bruen...@google.com

[derekbruening]

From bruen...@google.com on January 30, 2014 09:11:36

% bin/symquery.exe -e dynamorio/lib32/release/dynamorio.dll -f -a 0x91ce5 0x82a12 0x837f0 0x842de 0x65b50 0x67896 0x67dc9 0xa8c71 0x127bec
instrument_basic_block+0xf5
e:\b\build\slave\win-builder\drmemory\dynamorio\core\x86\instrument.c:1428+0x7c
client_process_bb+0x92
e:\b\build\slave\win-builder\drmemory\dynamorio\core\x86\interp.c:2557+0x23
build_bb_ilist+0xaa0
e:\b\build\slave\win-builder\drmemory\dynamorio\core\x86\interp.c:3643+0x7
recreate_bb_ilist+0xbe
e:\b\build\slave\win-builder\drmemory\dynamorio\core\x86\interp.c:4743+0x0
recreate_selfmod_ilist+0x30
e:\b\build\slave\win-builder\drmemory\dynamorio\core\x86\arch.c:3271+0x0
recreate_app_state_internal+0x2d6
e:\b\build\slave\win-builder\drmemory\dynamorio\core\x86\arch.c:3437+0x0
recreate_app_state+0x49
e:\b\build\slave\win-builder\drmemory\dynamorio\core\x86\arch.c:3688+0x13
intercept_exception+0x461
e:\b\build\slave\win-builder\drmemory\dynamorio\core\win32\callback.c:5439+0x0
interception_code_array+0xbec
??:0

[derekbruening]

From bruen...@google.com on January 31, 2014 15:48:14

Now, other tests are crashing in the same way:
[ RUN ] EmfTest.FileBackedEmf
<Application E:\b\build\slave\win7-cr-builder\build\src\out\Debug\printing_unittests.exe (3000). Client exception at PC 0x738064d8. Program aborted.
0xc0000005 0x00000000 0x738064d8 0x738064d8 0x00000000 0x00000003
Base: 0x6d480000
Registers: eax=0x00000000 ebx=0x1d451040 ecx=0x00000000 edx=0x00000000
esi=0x1e30cf20 edi=0x1e3311b0 esp=0x1e2ce6bc ebp=0x1e2ce6c8
eflags=0x00010202

On the bot, it runs fine unless I point at the symcache:

$ unpacked/bin/drmemory.exe -light ../../win7-cr-builder/build/src/out/Debug/printing_unittests.exe --gtest_filter=EmfTest.* --single-process-tests
Dr.M Dr. Memory version 1.6.1691
Dr.M Running "../../win7-cr-builder/build/src/out/Debug/printing_unittests.exe --gtest_filter=EmfTest.* --single-process-tests"
Valgrind detected, switching to single process mode.
Pass --test-launcher-debug-launcher to valgrind the launcher itself.
Note: Google Test filter = EmfTest.*
[==========] Running 3 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 3 tests from EmfTest
[ RUN ] EmfTest.DC
[ OK ] EmfTest.DC (78 ms)
[ RUN ] EmfTest.FileBackedEmf
[ OK ] EmfTest.FileBackedEmf (1560 ms)
[ RUN ] EmfTest.RasterizeMetafile
[ OK ] EmfTest.RasterizeMetafile (188 ms)
[----------] 3 tests from EmfTest (1841 ms total)

[----------] Global test environment tear-down
[==========] 3 tests from 1 test case ran. (1888 ms total)
[ PASSED ] 3 tests.

$ unpacked/bin/drmemory.exe -symcache_dir C:/Users//AppData/LocalLow/drmemory.symcache -light ../../win7-cr-builder/build/src/out/Debug/printing_unittests.exe --gtest_filter=EmfTest.* --single-process-tests
Dr.M Dr. Memory version 1.6.1691
Dr.M Running "../../win7-cr-builder/build/src/out/Debug/printing_unittests.exe --gtest_filter=EmfTest.* --single-process-tests"
Valgrind detected, switching to single process mode.
Pass --test-launcher-debug-launcher to valgrind the launcher itself.
Note: Google Test filter = EmfTest.*
[==========] Running 3 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 3 tests from EmfTest
[ RUN ] EmfTest.DC
[ OK ] EmfTest.DC (32 ms)
[ RUN ] EmfTest.FileBackedEmf
<Application E:\b\build\slave\win7-cr-builder\build\src\out\Debug\printing_unittests.exe (316). Client exception at PC 0x738064c8. Program aborted.

So like issue #1427 and issue #1428 this is yet another corrupted symcache on
this same machine!!!

[derekbruening]

From bruen...@google.com on February 01, 2014 08:48:02

binary search => it's RPCRT4.dll.txt

cd /work/drmemory/bugs/i1428

diff fresh.symcache/RPCRT4.dll.txt drmemory.i1430.copy/RPCRT4.dll.txt

2c2
< 1153,663040,2139566520035311617,2139566520035311617,719520,1290254937,983040

  1492,663040,2139566520035311617,2139566520035311617,719520,1290254937,983040

7,8d6
< memmove,0x0
< malloc,0x0
9a8,9

memmove,0x10608
malloc,0x0
21a22,25
_CrtDbgReportWV,0x0
_CrtDbgReportV,0x0
_CrtDbgReportW,0x0
_CrtDbgReport,0x0
22a27
_CrtSetDbgFlag,0x0
29d33
< malloc_set_state,0x0
30a35
malloc_set_state,0x0
32c37
< wmemcpy,0x0

---

wmemcpy,0x3ea0
37a43
_CrtIsValidHeapPointer,0x0
39c45
< strlen,0x0

---

strlen,0x105fc
44c50
< memcpy,0x0

---

memcpy,0x10602
47d52
< strnlen,0x0
48a54
strnlen,0x0
50c56,57
< operator new,0x0

---

_free_dbg_impl,0x0
operator new,0x10614
51a59,63
_crtheap,0x0
_malloc_dbg_impl,0x0
_calloc_dbg_impl,0x0
_nh_malloc_dbg,0x0
_msize_dbg,0x0
54a67,68
_malloc_dbg,0x11096
_calloc_dbg,0x0
56d69
< _malloc_dbg,0x0
57a71,72
_free_dbg,0x0
_realloc_dbg_impl,0x0
59d73
< operator new nothrow,0x0
60a75,77
operator new nothrow,0x0
_CrtDbgBreak,0x0
_realloc_dbg,0x0
65d81
< sbrk,0x0
68c84
< operator new[] nothrow,0x0

---

sbrk,0x0
69a86
operator new[] nothrow,0x0

grep 0x10614 drmemory.i1430.copy/*
drmemory.i1430.copy/CRYPT32.dll.txt:operator new,0x10614
drmemory.i1430.copy/DEVOBJ.dll.txt:operator new,0x10614
drmemory.i1430.copy/KERNEL32.dll.txt:operator new,0x10614
drmemory.i1430.copy/oak.dll.txt:operator new,0x10614
drmemory.i1430.copy/RPCRT4.dll.txt:operator new,0x10614
drmemory.i1430.copy/SHLWAPI.dll.txt:operator new,0x10614

wc drmemory.i1430.copy/CRYPT32.dll.txt drmemory.i1430.copy/DEVOBJ.dll.txt drmemory.i1430.copy/KERNEL32.dll.txt drmemory.i1430.copy/oak.dll.txt drmemory.i1430.copy/RPCRT4.dll.txt drmemory.i1430.copy/SHLWAPI.dll.txt
13 30 397 drmemory.i1430.copy/CRYPT32.dll.txt
13 30 391 drmemory.i1430.copy/DEVOBJ.dll.txt
98 115 1609 drmemory.i1430.copy/KERNEL32.dll.txt
13 30 353 drmemory.i1430.copy/oak.dll.txt
88 105 1492 drmemory.i1430.copy/RPCRT4.dll.txt
13 30 394 drmemory.i1430.copy/SHLWAPI.dll.txt
238 340 4636 total

diff drmemory.i1430.copy/CRYPT32.dll.txt drmemory.i1430.copy/DEVOBJ.dll.txt
2c2
< 397,1159680,2139567988914126849,2139567988914126849,1203019,1338611300,1171456

---

   391,64512,2139566979596812289,2139566979596812289,98607,1306232957,73728

cat drmemory.i1430.copy/CRYPT32.dll.txt
Dr. Memory symbol cache version 11
397,1159680,2139567988914126849,2139567988914126849,1203019,1338611300,1171456
0
operator delete,0x105f6
std::_DebugHeapDelete<>,0x0
Concurrency::details::Security::EncodePointer,0x0
operator delete[] nothrow,0x0
operator delete[],0x0
operator delete nothrow,0x0
operator new nothrow,0x0
operator new,0x10614
operator new[] nothrow,0x0
operator new[],0x0

for i in CRYPT32.dll.txt DEVOBJ.dll.txt KERNEL32.dll.txt oak.dll.txt RPCRT4.dll.txt SHLWAPI.dll.txt; do grep 'operator delete,' drmemory.i1430.copy/$i; done
operator delete,0x105f6
operator delete,0x105f6
operator delete,0x105f6
operator delete,0x105f6
operator delete,0x0
operator delete,0x105f6

$ unpacked/bin/symquery.exe -v -e c:/windows/syswow64/crypt32.dll -s 'operator new'
<debug info: type=no symbols, NO symbols, NO line numbers>
drsym error 5 looking up "operator new" in "c:\windows\syswow64\crypt32.dll"

diff drmemory.i1430.copy/CRYPT32.dll.txt drmemory.i1430.copy/oak.dll.txt
2,3c2,3
< 397,1159680,2139567988914126849,2139567988914126849,1203019,1338611300,1171456
< 0

---

   353,154112,0,0,0,1390753728,167936

1

so oak.dll has syms

$ unpacked/bin/symquery.exe -v -e ../../win7-cr-builder/build/src/out/Debug/oak.dll -s 'operator new'
<debug info: type=PDB, has symbols, has line numbers>
+0xca80
$ unpacked/bin/symquery.exe -v -e ../../win7-cr-builder/build/src/out/Debug/oak.dll -s 'operator delete'
<debug info: type=PDB, has symbols, has line numbers>
+0xca90

$ unpacked/bin/symquery.exe -v -e ../../win7-cr-builder/build/src/out/Debug/oak.dll --searchall -s 'operator delete'
<debug info: type=PDB, has symbols, has line numbers>
operator delete +0xca90-0xca95
operator delete +0x105f6-0x105f6
operator delete +0xca90-0xca90

$ unpacked/bin/symquery.exe -v -e ../../win7-cr-builder/build/src/out/Debug/oak.dll --searchall -s 'operator new' <debug info: type=PDB, has symbols, has line numbers>
operator new +0xca80-0xca88
operator new +0xca80-0xca80
operator new +0x10614-0x10614

$ unpacked/bin/symquery.exe -v -e ../../win7-cr-builder/build/src/out/Debug/oak.dll --search -s 'operator new'
<debug info: type=PDB, has symbols, has line numbers>
operator new +0xca80-0xca88
operator new +0x10614-0x1061a

$ unpacked/bin/symquery.exe -v -e ../../win7-cr-builder/build/src/out/Debug/oak.dll --search -s 'operator delete'
<debug info: type=PDB, has symbols, has line numbers>
operator delete +0xca90-0xca95
operator delete +0x105f6-0x105fc

cd drmemory.i1430.copy; ls -lrt CRYPT32.dll.txt DEVOBJ.dll.txt KERNEL32.dll.txt oak.dll.txt RPCRT4.dll.txt SHLWAPI.dll.txt
-rwx------. 1 walnut users 353 Jan 30 00:48 oak.dll.txt
-rwx------. 1 walnut users 391 Jan 30 10:50 DEVOBJ.dll.txt
-rwx------. 1 walnut users 394 Jan 30 12:48 SHLWAPI.dll.txt
-rwx------. 1 walnut users 1492 Jan 31 17:52 RPCRT4.dll.txt
-rwx------. 1 walnut users 1609 Jan 31 17:52 KERNEL32.dll.txt
-rwx------. 1 walnut users 397 Jan 31 20:15 CRYPT32.dll.txt

for i in CRYPT32.dll.txt DEVOBJ.dll.txt KERNEL32.dll.txt oak.dll.txt RPCRT4.dll.txt SHLWAPI.dll.txt; do wc drmemory.i1430.copy/$i; wc fresh.symcache/$i; done
13 30 397 drmemory.i1430.copy/CRYPT32.dll.txt
13 30 389 fresh.symcache/CRYPT32.dll.txt
13 30 391 drmemory.i1430.copy/DEVOBJ.dll.txt
13 30 383 fresh.symcache/DEVOBJ.dll.txt
98 115 1609 drmemory.i1430.copy/KERNEL32.dll.txt
73 90 1194 fresh.symcache/KERNEL32.dll.txt
13 30 353 drmemory.i1430.copy/oak.dll.txt
wc: fresh.symcache/oak.dll.txt: No such file or directory
88 105 1492 drmemory.i1430.copy/RPCRT4.dll.txt
71 88 1153 fresh.symcache/RPCRT4.dll.txt
13 30 394 drmemory.i1430.copy/SHLWAPI.dll.txt
13 30 386 fresh.symcache/SHLWAPI.dll.txt

So it doesn't look like an entire file is incorrect (module meta info is
all correct too) -- just this one value, which is a 2nd value. Right?
Fresh oak.dll.txt has 2 values?

Which test loads it?
oak.dll has just one export:

git grep ShowOakWindowWithContext
ash/accelerators/accelerator_controller.cc: oak::ShowOakWindowWithContext(Shell::GetPrimaryRoo
ui/oak/oak.h:OAK_EXPORT void ShowOakWindowWithContext(gfx::NativeView context);
ui/oak/oak_window.cc:void ShowOakWindowWithContext(gfx::NativeView context) {

Hmm, on my laptop ~/drmemory/git/build_x86_dbg/logs/symcache/oak.dll.txt
has just one entry for each. Loading up the oak.dll there:

0:000> x oak!operator new*
1000ca70 oak!operator new (unsigned int, void *)
10010624 oak!operator new ()

So the other one is placement new which we don't intercept. So it's not a
2nd value.

Versus issue #1427, issue #1313 shell32 badness but no other module's symcache has
that value?

Could mod->full_path somehow change or have a race?
modcache = (mod_cache_t *) hashtable_lookup(&symcache_table, (void *)mod->full_path);

It's a dr_strdup inside DR, and then dr_strdup to client.

What if it were drsyms (or dbghelp) messing up? But then wouldn't we see
failures w/o symcache?

What if DR gets the path wrong, and there's already a symcache (or it
queries dbghelp w/ that wrong path)? Maybe ends up using some other lib's
path? Doing section tracking and it got off?
But we're using get_mapped_file_name().
Could oak.dll be mapped as non-image => we'd use section hashtable?