DynamoRIO / dynamorio

Dynamic Instrumentation Tool Platform
Other
2.61k stars 554 forks source link

Multiple tests failing on Appveyor VS2017 Win10 1607 #4058

Open derekbruening opened 4 years ago

derekbruening commented 4 years ago

2924 put a lot of work into getting DR switched over to VS2017. Despite all the work there to get the build and tests working, there are still some tests which are failing and which I separated out here in order to finish off the base switch. This issue covers fixing these issues one by one.

derekbruening commented 4 years ago

More failures not on the original ignore list: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/30390790

14464debug-internal-32: 258 tests passed, **** 4 tests failed: ****
14465   code_api|win32.tls 
14466   code_api|security-win32.except-execution 
14467   code_api|client.pcache-use 
14468   code_api|tool.drcacheoff.view 
derekbruening commented 4 years ago

Another: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/30417232

26916debug-internal-32: 258 tests passed, **** 4 tests failed, but ignoring 3 for i#2145: ****
26917   code_api|win32.callback 
26918   (ignore: i#2145)    code_api|client.pcache-use 
26919   (ignore: i#2145)    code_api|tool.drcacheoff.burst_replaceall 
26920   (ignore: i#2145)    code_api|tool.drcacheoff.view 
johnfxgalea commented 4 years ago

Another (_drcacheoff.burstreplace): https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/30490048#L27116

====> FAILURE in debug-internal-32 <====
27117debug-internal-32: 257 tests passed, **** 5 tests failed, of which 1 were flaky, but ignoring 3 for i#2145: ****
27118   (ignore: i#2145)    code_api|win32.reload-newaddr 
27119   code_api|security-win32.codemod-threads_FLAKY 
27120   (ignore: i#2145)    code_api|client.pcache-use 
27121   code_api|tool.drcacheoff.burst_replace 
27122   (ignore: i#2145)    code_api|tool.drcacheoff.view 
27123debug-internal-64: 227 tests passed, **** 7 tests failed, but ignoring 7 for i#2145: ****
27124   (ignore: i#2145)    code_api|common.decode 
27125
derekbruening commented 4 years ago

Another 32-bit failure: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/30511381

debug-internal-32: 258 tests passed, **** 4 tests failed, but ignoring 3 for i#2145: ****
26890   (ignore: i#2145)    code_api|client.winxfer 
26891   (ignore: i#2145)    code_api|client.pcache-use 
26892   code_api|tool.basic_counts 
26893   (ignore: i#2145)    code_api|tool.drcacheoff.view 
derekbruening commented 4 years ago

Another:

debug-internal-32: 257 tests passed, **** 5 tests failed, but ignoring 4 for i#2145: ****
26823   code_api|common.fib 
26824   (ignore: i#2145)    code_api|client.nudge_test 
26825   (ignore: i#2145)    code_api|client.pcache-use 
26826   (ignore: i#2145)    code_api|client.nudge_ex 
26827   (ignore: i#2145)    code_api|tool.drcacheoff.view 

This one is disturbing: fib doesn't do much. This seems to just hang part-way in:

[00:07:13] 10: Test command: C:\projects\dynamorio\build\build_debug-internal-32\bin32\drrun.exe "-s" "90" "-quiet" "-debug" "-use_dll" "C:/projects/dynamorio/bui
ld/build_debug-internal-32/lib32/debug/dynamorio.dll" "-exit0" "-stderr_mask" "0xC" "-msgbox_mask" "0" "-dumpcore_mask" "0x7d" "-staged" "-no_early_inject" "-code
_api" "--" "C:/projects/dynamorio/build/build_debug-internal-32/suite/tests/bin/common.fib.exe"
[00:07:13] 10: Test timeout computed to be: 600
[00:07:13] 10: fib(5)=8
[00:07:13] 10: fib(15)=987
[00:08:33]  75/262 Test  #10: code_api|common.fib ..........................................***Failed  Required regular expression not found. Regex=[^fib\(5\)=8
[00:08:33] ?
[00:08:33] fib\(15\)=987
[00:08:33] ?
[00:08:33] fib\(25\)=121393
[00:08:33] ?
[00:08:33] fib\(0\)=1
[00:08:33] ?
[00:08:33] fib\(1\)=1
[00:08:33] ?
[00:08:33] fib\(2\)=2
[00:08:33] ?
[00:08:33] fib\(3\)=3
[00:08:33] ?
[00:08:33] fib\(4\)=5
[00:08:33] ?
[00:08:33] fib\(5\)=8
[00:08:33] ?
[00:08:33] fib\(6\)=13
[00:08:33] ?
[00:08:33] fib\(7\)=21
[00:08:33] ?
[00:08:33] fib\(8\)=34
[00:08:33] ?
[00:08:33] fib\(9\)=55
[00:08:33] ?
[00:08:33] fib\(10\)=89
[00:08:33] ?
[00:08:33] fib\(11\)=144
[00:08:33] ?
[00:08:33] fib\(12\)=233
[00:08:33] ?
[00:08:33] fib\(13\)=377
[00:08:33] ?
[00:08:33] fib\(14\)=610
[00:08:33] ?
[00:08:33] fib\(15\)=987
[00:08:33] ?
[00:08:33] fib\(16\)=1597
[00:08:33] ?
[00:08:33] fib\(17\)=2584
[00:08:33] ?
[00:08:33] fib\(18\)=4181
[00:08:33] ?
[00:08:33] fib\(19\)=6765
[00:08:33] ?
[00:08:33] fib\(20\)=10946
[00:08:33] ?
[00:08:33] fib\(21\)=17711
[00:08:33] ?
[00:08:33] fib\(22\)=28657
[00:08:33] ?
[00:08:33] fib\(23\)=46368
[00:08:33] ?
[00:08:33] fib\(24\)=75025
[00:08:33] ?
[00:08:33] fib\(25\)=121393
[00:08:33] ?
[00:08:33] fib\(26\)=196418
[00:08:33] ?
[00:08:33] fib\(27\)=317811
[00:08:33] ?
[00:08:33] fib\(28\)=514229
[00:08:33] ?
[00:08:33] fib\(29\)=832040
[00:08:33] ?
[00:08:33] fib\(30\)=1346269
[00:08:33] ?
[00:08:33] fib\(31\)=2178309
[00:08:33] ?
[00:08:33] fib\(32\)=3524578
[00:08:33] ?
[00:08:33] fib\(12\)=233
[00:08:33] ?
[00:08:33] $
[00:08:33] ] 90.02 sec
[00:08:33] fib(5)=8
[00:08:33] fib(15)=987
derekbruening commented 4 years ago

Another 32-bit drcachesim failure: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/30519514

26688debug-internal-32: 257 tests passed, **** 5 tests failed, but ignoring 4 for i#2145: ****
26689   (ignore: i#2145)    code_api|client.nudge_test 
26690   (ignore: i#2145)    code_api|client.pcache-use 
26691   (ignore: i#2145)    code_api|tool.drcacheoff.burst_replaceall 
26692   code_api|tool.histogram.offline 
26693   (ignore: i#2145)    code_api|tool.drcacheoff.view 
derekbruening commented 4 years ago

Details:

[00:13:53] 230/262 Test #231: code_api|tool.histogram.offline ..............................***Failed    1.34 sec
[00:13:53] Running cmd |C:/projects/dynamorio/build/build_debug-internal-32/bin32/drrun.exe;-s;180;-quiet;-debug;-use_dll;C:/projects/dynamorio/build/build_debug-internal-32/lib32/debug/dynamorio.dll;-exit0;-stderr_mask;0xC;-msgbox_mask;0;-dumpcore_mask;0x7d;-staged;-code_api;-t;drcachesim;-offline;-subdir_prefix;tool.histogram.offline;-trace_after_instrs;5K;-exit_after_tracing;50K;--;C:/projects/dynamorio/build/build_debug-internal-32/suite/tests/bin/client.winxfer.exe|
[00:13:53] Running postcmd |C:/projects/dynamorio/build/build_debug-internal-32/clients/bin32/drcachesim.exe;-indir;C:/projects/dynamorio/build/build_debug-internal-32/suite/tests/tool.histogram.offline.client.winxfer.exe.05676.5907.dir|
[00:13:53] CMake Error at C:/projects/dynamorio/suite/tests/runmulti.cmake:106 (message):
[00:13:53]   *** postcmd failed (Access violation): ***
[00:13:53] 
[00:13:53] Call Stack (most recent call first):
[00:13:53]   C:/projects/dynamorio/suite/tests/runmulti.cmake:118 (process_cmdline)
derekbruening commented 4 years ago

Another: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/30522584

debug-internal-64: 204 tests passed, **** 12 tests failed, but ignoring 11 for i#2145: ****
21002   (ignore: i#2145)    code_api|common.decode 
21003   (ignore: i#2145)    code_api|common.decode-stress 
21004   (ignore: i#2145)    code_api|common.nativeexec 
21005   (ignore: i#2145)    code_api|win32.mixedmode_late 
21006   code_api|common.fib 
21007   (ignore: i#2145)    code_api|client.cleancall 
21008   (ignore: i#2145)    code_api|client.loader 
21009   (ignore: i#2145)    code_api|client.nudge_test 
21010   (ignore: i#2145)    code_api|client.pcache-use 
21011   (ignore: i#2145)    code_api|api.startstop 
21012   (ignore: i#2145)    code_api|api.detach 
21013   (ignore: i#2145)    code_api|tool.drcacheoff.view 
derekbruening commented 4 years ago

Another: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/30526018

debug-internal-32: 221 tests passed, **** 2 tests failed, but ignoring 1 for i#2145: ****
22868   code_api|common.broadfun 
22869   (ignore: i#2145)    code_api|client.pcache-use 
derekbruening commented 4 years ago

Seems to have died up front before any output:

[00:06:39]         Start   8: code_api|common.broadfun
[00:06:39] 
[00:06:39] 8: Test command: C:\projects\dynamorio\build\build_debug-internal-32\bin32\drrun.exe "-s" "90" "-quiet" "-debug" "-use_dll" "C:/projects/dynamorio/build/build_debug-internal-32/lib32/debug/dynamorio.dll" "-exit0" "-stderr_mask" "0xC" "-msgbox_mask" "0" "-dumpcore_mask" "0x7d" "-staged" "-code_api" "--" "C:/projects/dynamorio/build/build_debug-internal-32/suite/tests/bin/common.broadfun spaces.exe"
[00:06:39] 8: Test timeout computed to be: 600
[00:06:39]   8/223 Test   #8: code_api|common.broadfun .....................................***Failed  Required regular expression not found. Regex=[^sort\(\) = >
[00:06:39] ?
[00:06:39] done
[00:06:39] ?
[00:06:39] $
[00:06:39] ]  0.24 sec
derekbruening commented 4 years ago

4077 is blocking un-ignoring client.nudge_test

derekbruening commented 4 years ago

tool.drcachesim.coherence just failed: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/30795606

debug-internal-64: 226 tests passed, **** 10 tests failed, but ignoring 9 for i#2145: ****
22984   (ignore: i#2145)    code_api|common.decode 
22985   (ignore: i#2145)    code_api|common.decode-stress 
22986   (ignore: i#2145)    code_api|common.nativeexec 
22987   (ignore: i#2145)    code_api|win32.mixedmode_late 
22988   (ignore: i#2145)    code_api|client.cleancall 
22989   (ignore: i#2145)    code_api|client.loader 
22990   (ignore: i#2145)    code_api|client.pcache-use 
22991   code_api|tool.drcachesim.coherence 
22992   (ignore: i#2145)    code_api|tool.drcacheoff.view 
22993   (ignore: i#2145)    code_api|tool.histogram.offline 
derekbruening commented 4 years ago

Strike that: the coherence failure is the type_is_instr assert #3320.

derekbruening commented 4 years ago

client.alloc just failed with: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/30815212

[00:08:40] 92: error: memory iteration failed
johnfxgalea commented 4 years ago

Triggered on master: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/31407113

derekbruening commented 4 years ago

Coherence test failed again: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/31469702

derekbruening commented 4 years ago

client.alloc again: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/31540294

derekbruening commented 4 years ago

This new test is apparently flaky on the new Appveyor setup. Lumping here. It failed once in its first 8 or so runs on Appveyor:

https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/31753305

debug-internal-32: 225 tests passed, **** 3 tests failed: ****
    code_api|client.drwrap-test-detach 
derekbruening commented 4 years ago

Happened again on 32-bit. Looks like a timeout: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/31894097

[00:10:16]         Start 208: code_api|client.drwrap-test-detach
[00:10:16] 208: Test command: C:\projects\dynamorio\build\build_debug-internal-32\bin32\drrun.exe "-s" "90" "-quiet" "-debug" "-use_dll" "C:/projects/dynamorio/build/build_debug-internal-32/lib32/debug/dynamorio.dll" "-exit0" "-noinject" "-stderr_mask" "0xC" "-msgbox_mask" "0" "-dumpcore_mask" "0x7d" "-staged" "-code_api" "--" "C:/projects/dynamorio/build/build_debug-internal-32/suite/tests/bin/client.drwrap-test-detach.exe"
[00:10:16] 208: Test timeout computed to be: 600
[00:10:16] 208: in dr_client_main
[00:12:06] 228/228 Test #208: code_api|client.drwrap-test-detach ...........................***Failed  Required regular expression not found. Regex=[^in dr_client_main
[00:12:06] ?
[00:12:06] client done
[00:12:06] ?
[00:12:06] app done
[00:12:06] ?
[00:12:06] $
[00:12:06] ] 90.02 sec
johnfxgalea commented 4 years ago

Hit the pcache-use failure on master.

https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/32132267

johnfxgalea commented 4 years ago

Again, hit the pcache-use failure on master.

https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/32258154

johnfxgalea commented 4 years ago

Hit failure concerning code_api|client.drwrap-test-detach

https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/33279665

derekbruening commented 4 years ago

Hit drwrap-test-detach again -- and this time it's 64-bit: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/33296561

johnfxgalea commented 4 years ago

client.pcache-use failed on master: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/33359183

abhinav92003 commented 4 years ago

debug-internal-32 tests code_api|tool.drcacheoff.burst_traceopts and code_api|tool.histogram.offline failed on master: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/33444189.

Both succeeded on a manually triggered re-run: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/33450693

derekbruening commented 4 years ago

Again, burst_ tests failing flakily, succeeding on re-run:

debug-internal-64: 240 tests passed, **** 10 tests failed, but ignoring 7 for i#2145: ****
    code_api|tool.drcacheoff.burst_static 
    code_api|tool.drcacheoff.burst_replace 
    code_api|tool.drcacheoff.burst_traceopts
derekbruening commented 4 years ago

client.winxfer failed at https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/33760586. It looks like it's just an output ordering issue or sthg? Or at least, there's no crash or anything:

[00:21:01]         Start 108: code_api|client.winxfer
[00:21:01] 108: Test command: C:\projects\dynamorio\build\build_debug-internal-64\bin64\drrun.exe "-s" "90" "-quiet" "-debug" "-use_dll" "C:/projects/dynamorio/build/build_debug-internal-64/lib64/debug/dynamorio.dll" "-exit0" "-stderr_mask" "0xC" "-msgbox_mask" "0" "-dumpcore_mask" "0x7d" "-staged" "-code_api" "-c" "C:/projects/dynamorio/build/build_debug-internal-64/suite/tests/bin/client.winxfer.dll.dll" "--" "C:/projects/dynamorio/build/build_debug-internal-64/suite/tests/bin/client.winxfer.exe"
[00:21:01] 108: Test timeout computed to be: 600
[00:21:01] 108: kernel_xfer_event: type 2
[00:21:01] 108: kernel_xfer_event: type 7
[00:21:01] 108: About to create thread
[00:21:01] 108: kernel_xfer_event: type 2
[00:21:01] 108: kernel_xfer_event: type 7
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: in wnd_callback 0x0000000000000024 0
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: in wnd_callback 0x0000000000000081 0
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: in wnd_callback 0x0000000000000083 0
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: in wnd_callback 0x0000000000000001 0
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: in wnd_callback 0x0000000000008001 3 0
[00:21:01] 108: About to crash
[00:21:01] 108: exception c0000005 addr 0x0000000000000040
[00:21:01] 108: kernel_xfer_event: type 3
[00:21:01] 108: Inside handler
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: kernel_xfer_event: type 5
[00:21:01] 108: in wnd_callback 0x0000000000008001 0 2
[00:21:01] 108: kernel_xfer_event: type 6
[00:21:01] 108: Got message 0x0000000000008001 1 3
[00:21:01] 108: Before _beginthreadex
[00:21:01] 108: kernel_xfer_event: type 2
[00:21:01] 108: kernel_xfer_event: type 7
[00:21:01] 108: QueueUserAPC returned 1
[00:21:01] 108: kernel_xfer_event: type 2
[00:21:01] 108: kernel_xfer_event: type 7
[00:21:01] 108: SleepEx returned 192
[00:21:01] 108: Apc arg = 37
[00:21:01] 108: Result = 100
[00:21:01] 108: After _beginthreadex
[00:21:01] 108: All done
[00:21:01] 110/251 Test #108: code_api|client.winxfer ......................................***Failed  Required regular expression not found. Regex=[^About to create thread
derekbruening commented 4 years ago

For the winxfer in the prior comment: it looks like About to create thread is on the 3rd line instead of the 1st. So it is just output ordering.

johnfxgalea commented 4 years ago

Failed on master: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/34455213

derekbruening commented 4 years ago

winxfer again: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/34721664

derekbruening commented 3 years ago

Grrr, client.winxfer failed again with output mismatches even after PR #4411: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/35794972

derekbruening commented 3 years ago

client.winxfer again: https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/36393951

derekbruening commented 3 years ago

Split some of the failures off: #2246, #4616, #4617, #4618, #4621, #4622.

4131 is another umbrella case: trying to move to separate issues instead of it and here covering all Windows test failures. Will leave this open for now as there are still more that should get their own issues but I think I covered the highest priority.