DynamoRIO / DynamoRIO/dynamorio
HANG on Appveyor hitting 1-hour timeout with logs ending much sooner
- Dominant language
- C
- Stars
- 3.2k
- Forks
- 629
- Avg merge
- 2d 15h
- Merged PRs (30d)
- 31
Description
While moving Appveyor to VS2017/Win10 (#2924) I hit several cases where Appveyor failed because the build hit their 1-hour time limit. Yet the full log ended at much less than 1 hour: 40 minutes, 20 minutes, and in the latest case 17 minutes. It ended during the 64-bit build a few times, and during the 32-bit build a few times. I ran locally to see if I could repro any popups or something and I did find a few, which I fixed in PR #3999. I thought it was all behind us but now I just saw another timeout:
https://ci.appveyor.com/project/DynamoRIO/dynamorio/builds/30450667
I've attached the full log. It ends with:
```
[00:17:28] test 261
[00:17:28] Start 261: code_api,disable_traces|client.events
[00:17:28]
[00:17:28] 261: 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" "-disable_traces" "-c" "C:/projects/dynamorio/build/build_debug-internal-32/suite/tests/bin/client.events.dll.dll" "--" "C:/projects/dynamorio/build/build_debug-internal-32/suite/tests/bin/client.events.exe" "C:/projects/dynamorio/build/build_debug-internal-32/suite/tests/bin/client.events.appdll.dll"
[00:17:28] 261: Test timeout computed to be: 600
[00:17:28] 261: appdll initialized
[00:17:28] 261: exception event redirect
[00:17:28] 261: Redirect success!
[00:17:28] 261: exit event 2
[00:17:28] 261: exit event 1
[00:17:28] 261: module load event 1 is called 1 time
[00:17:28] 261: module load event 2 is called 1 time
[00:17:28] 261: thread init event 1 is called 1 time
[00:17:28] 261: thread init event 2 is called 1 time
[00:17:28] 261: bb event 1 is called 1 time
[00:17:28] 261: bb event 2 is called 1 time
[00:17:28] 261: delete event 1 is called 1 time
[00:17:28] 261: delete event 2 is called 1 time
[00:17:28] 261: filter syscall event 1 is called 1 time
[00:17:28] 261: filter syscall event 2 is called 1 time
[00:17:28] 261: pre syscall event 1 is called 1 time
[00:17:28] 261: pre syscall event 2 is called 1 time
[00:17:28] 261: post syscall event 1 is called 1 time
[00:17:28] 261: post syscall event 2 is called 1 time
```
The time prefix is the total time since the build started: so if the log itself is not truncated, it sat there for 43 minutes from that point.
Two tests have not finished:
```
$ egrep 'Test #|Start [0-9]' ~/Downloads/log\ \(24\).txt | cut -c 31-90 | awk '{print $1}' | sed 's/\r$//' | sort | uniq -u
code_api,disable_traces|client.events
code_api|tool.drcachesim.invariants
```
The invariants test:
```
[00:14:25] Start 221: code_api|tool.drcachesim.invariants
[00:14:25] 221: 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" "-t" "drcachesim" "-ipc_name" "drtestpipe_invariants" "-test_mode" "--" "C:/projects/dynamorio/build/build_debug-internal-32/suite/tests/bin/client.winxfer.exe"
[00:14:25] 221: Test timeout computed to be: 600
[00:14:25] 221: About to create thread
[00:17:15] 221:
Contributor guide
Assessment
This issue has not been assessed yet.