DynamoRIO / DynamoRIO/dynamorio

HANG on Appveyor hitting 1-hour timeout with logs ending much sooner

Open
#4,067 3 comments 0 reactions 0 assignees View on GitHub
Component-DrMemtrace Component-Tests Hotlist-ContinuousIntegration OpSys-Windows
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

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.