Skip to content

Commit f02d6a2

Browse files
tyrielvtyrielv
committed
functional tests: add process timeout + diagnostic logging for hang diagnosis
Add per-process timeout to ProcessHelper and GitProcess to prevent functional tests from hanging indefinitely when a git process stalls. Previously, ProcessHelper.StartProcess() called ReadToEnd() and WaitForExit() with no timeout, causing the entire CI job to hit the 60-minute GitHub Actions timeout with no diagnostics. Changes: - ProcessHelper: add configurable timeout with async stdout read. Uses ReadToEndAsync() + Task.Wait(timeout) to bound the entire process lifecycle. On timeout, kills the process tree and throws TimeoutException with process details. Logs slow processes (>30s). Configurable via GVFS_FT_PROCESS_TIMEOUT_SECONDS env var. - GitProcess: default 5-minute timeout per git operation, overridable via GVFS_FT_GIT_TIMEOUT_SECONDS env var. - GitRepoTests: add timestamped [TEST-SETUP-START/END] and [TEST-TEARDOWN-START/END] logging with full test name to identify which specific test hangs. - functional-tests.yaml: temporarily restrict matrix to slice 3 (Release, x86_64) to iterate on the flaky GitCommandsTests(Full) hang. Set GVFS_FT_GIT_TIMEOUT_SECONDS=300 in CI. AB#62098959 Assisted-by: Claude Opus 4.6 Signed-off-by: Tyrie Vella <tyrielv@gmail.com>
1 parent c9da2ee commit f02d6a2

4 files changed

Lines changed: 142 additions & 16 deletions

File tree

‎.github/workflows/functional-tests.yaml‎

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -61,10 +61,15 @@ jobs:
6161

6262
strategy:
6363
matrix:
64-
configuration: [ Debug, Release ]
65-
architecture: [ x86_64, arm64 ]
66-
nr: [0, 1, 2, 3, 4, 5, 6, 7, 8, 9] # 10 parallel jobs to speed up the tests
67-
fail-fast: false # most failures are flaky tests, no need to stop the other jobs from succeeding
64+
# TEMPORARY: Restricted to slice 3 (Release, x86_64) to diagnose
65+
# GitCommandsTests(Full) hang. Restore full matrix after fix:
66+
# configuration: [ Debug, Release ]
67+
# architecture: [ x86_64, arm64 ]
68+
# nr: [0, 1, 2, 3, 4, 5, 6, 7, 8, 9]
69+
configuration: [ Release ]
70+
architecture: [ x86_64 ]
71+
nr: [3]
72+
fail-fast: false
6873

6974
steps:
7075
- name: Skip this job if there is a previous successful run
@@ -157,6 +162,7 @@ jobs:
157162
run: |
158163
SET PATH=C:\Program Files\VFS for Git;%PATH%
159164
SET GIT_TRACE2_PERF=C:\temp\git-trace2.log
165+
SET GVFS_FT_GIT_TIMEOUT_SECONDS=300
160166
ft\GVFS.FunctionalTests.exe /result:TestResult.xml --ci --slice=${{ matrix.nr }},10 --workers=1
161167
162168
- name: Upload functional test results

‎GVFS/GVFS.FunctionalTests/Tests/GitCommands/GitRepoTests.cs‎

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -129,6 +129,10 @@ public virtual void TearDownForFixture()
129129
[SetUp]
130130
public virtual void SetupForTest()
131131
{
132+
string testName = TestContext.CurrentContext.Test.FullName;
133+
Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fff}] [TEST-SETUP-START] {testName}");
134+
Console.Out.Flush();
135+
132136
if (this.enlistmentPerTest)
133137
{
134138
this.CreateEnlistment();
@@ -151,12 +155,22 @@ public virtual void SetupForTest()
151155
}
152156

153157
this.ValidateGitCommand("status");
158+
159+
Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fff}] [TEST-SETUP-END] {testName}");
160+
Console.Out.Flush();
154161
}
155162

156163
[TearDown]
157164
public virtual void TearDownForTest()
158165
{
166+
string testName = TestContext.CurrentContext.Test.FullName;
167+
Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fff}] [TEST-TEARDOWN-START] {testName}");
168+
Console.Out.Flush();
169+
159170
this.TestValidationAndCleanup();
171+
172+
Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fff}] [TEST-TEARDOWN-END] {testName}");
173+
Console.Out.Flush();
160174
}
161175

162176
protected void TestValidationAndCleanup(bool ignoreCase = false)

‎GVFS/GVFS.FunctionalTests/Tools/GitProcess.cs‎

Lines changed: 25 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,17 +1,26 @@
1-
using System.Collections.Generic;
1+
using System;
2+
using System.Collections.Generic;
23
using System.Diagnostics;
34
using System.IO;
45

56
namespace GVFS.FunctionalTests.Tools
67
{
78
public static class GitProcess
89
{
10+
// Default: 5 minutes per git operation. Override with GVFS_FT_GIT_TIMEOUT_SECONDS.
11+
public static int DefaultGitTimeoutMs { get; set; } = ReadGitTimeoutFromEnvironment();
12+
913
public static string Invoke(string executionWorkingDirectory, string command)
1014
{
1115
return InvokeProcess(executionWorkingDirectory, command).Output;
1216
}
1317

14-
public static ProcessResult InvokeProcess(string executionWorkingDirectory, string command, Dictionary<string, string> environmentVariables = null, Stream inputStream = null)
18+
public static ProcessResult InvokeProcess(
19+
string executionWorkingDirectory,
20+
string command,
21+
Dictionary<string, string> environmentVariables = null,
22+
Stream inputStream = null,
23+
int timeoutMs = -1)
1524
{
1625
ProcessStartInfo processInfo = new ProcessStartInfo(Properties.Settings.Default.PathToGit);
1726
processInfo.WorkingDirectory = executionWorkingDirectory;
@@ -35,7 +44,20 @@ public static ProcessResult InvokeProcess(string executionWorkingDirectory, stri
3544
}
3645
}
3746

38-
return ProcessHelper.Run(processInfo, inputStream: inputStream);
47+
int effectiveTimeout = timeoutMs > 0 ? timeoutMs : DefaultGitTimeoutMs;
48+
return ProcessHelper.Run(processInfo, inputStream: inputStream, timeoutMs: effectiveTimeout);
49+
}
50+
51+
private static int ReadGitTimeoutFromEnvironment()
52+
{
53+
string envValue = Environment.GetEnvironmentVariable("GVFS_FT_GIT_TIMEOUT_SECONDS");
54+
if (!string.IsNullOrEmpty(envValue) && int.TryParse(envValue, out int seconds) && seconds > 0)
55+
{
56+
return seconds * 1000;
57+
}
58+
59+
// Default: 5 minutes per git operation
60+
return 300_000;
3961
}
4062
}
4163
}

‎GVFS/GVFS.FunctionalTests/Tools/ProcessHelper.cs‎

Lines changed: 93 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,16 +1,25 @@
1-
using System.Diagnostics;
1+
using System;
2+
using System.Diagnostics;
23
using System.IO;
4+
using System.Threading.Tasks;
35

46
namespace GVFS.FunctionalTests.Tools
57
{
68
public static class ProcessHelper
79
{
10+
/// <summary>
11+
/// Default timeout in milliseconds for child processes. -1 means infinite.
12+
/// Set via GVFS_FT_PROCESS_TIMEOUT_SECONDS environment variable (applies to all
13+
/// ProcessHelper.Run calls) or override per-call via the timeoutMs parameter.
14+
/// </summary>
15+
public static int DefaultTimeoutMs { get; set; } = ReadTimeoutFromEnvironment();
16+
817
public static ProcessResult Run(string fileName, string arguments)
918
{
10-
return Run(fileName, arguments, null);
19+
return Run(fileName, arguments, workingDirectory: null);
1120
}
1221

13-
public static ProcessResult Run(string fileName, string arguments, string workingDirectory)
22+
public static ProcessResult Run(string fileName, string arguments, string workingDirectory, int timeoutMs = -1)
1423
{
1524
ProcessStartInfo startInfo = new ProcessStartInfo();
1625
startInfo.UseShellExecute = false;
@@ -24,11 +33,18 @@ public static ProcessResult Run(string fileName, string arguments, string workin
2433
startInfo.WorkingDirectory = workingDirectory;
2534
}
2635

27-
return Run(startInfo);
36+
return Run(startInfo, timeoutMs: timeoutMs);
2837
}
2938

30-
public static ProcessResult Run(ProcessStartInfo processInfo, string errorMsgDelimeter = "\r\n", object executionLock = null, Stream inputStream = null)
39+
public static ProcessResult Run(
40+
ProcessStartInfo processInfo,
41+
string errorMsgDelimeter = "\r\n",
42+
object executionLock = null,
43+
Stream inputStream = null,
44+
int timeoutMs = -1)
3145
{
46+
int effectiveTimeout = timeoutMs > 0 ? timeoutMs : DefaultTimeoutMs;
47+
3248
using (Process executingProcess = new Process())
3349
{
3450
string output = string.Empty;
@@ -50,25 +66,27 @@ public static ProcessResult Run(ProcessStartInfo processInfo, string errorMsgDel
5066
{
5167
lock (executionLock)
5268
{
53-
output = StartProcess(executingProcess, inputStream);
69+
output = StartProcess(executingProcess, inputStream, effectiveTimeout);
5470
}
5571
}
5672
else
5773
{
58-
output = StartProcess(executingProcess, inputStream);
74+
output = StartProcess(executingProcess, inputStream, effectiveTimeout);
5975
}
6076

6177
return new ProcessResult(output.ToString(), errors.ToString(), executingProcess.ExitCode);
6278
}
6379
}
6480

65-
private static string StartProcess(Process executingProcess, Stream inputStream = null)
81+
private static string StartProcess(Process executingProcess, Stream inputStream, int timeoutMs)
6682
{
83+
Stopwatch stopwatch = Stopwatch.StartNew();
6784
executingProcess.Start();
6885

6986
if (inputStream != null)
7087
{
7188
inputStream.CopyTo(executingProcess.StandardInput.BaseStream);
89+
executingProcess.StandardInput.Close();
7290
}
7391

7492
if (executingProcess.StartInfo.RedirectStandardError)
@@ -79,12 +97,78 @@ private static string StartProcess(Process executingProcess, Stream inputStream
7997
string output = string.Empty;
8098
if (executingProcess.StartInfo.RedirectStandardOutput)
8199
{
82-
output = executingProcess.StandardOutput.ReadToEnd();
100+
if (timeoutMs > 0)
101+
{
102+
// Read stdout asynchronously so we can enforce a timeout on the
103+
// entire process lifecycle. Without this, ReadToEnd() blocks
104+
// indefinitely if the child process hangs.
105+
Task<string> readTask = executingProcess.StandardOutput.ReadToEndAsync();
106+
if (!readTask.Wait(timeoutMs))
107+
{
108+
KillProcessTree(executingProcess);
109+
string processDesc = FormatProcessDescription(executingProcess);
110+
throw new TimeoutException(
111+
$"Process timed out after {timeoutMs / 1000}s: {processDesc}");
112+
}
113+
114+
output = readTask.Result;
115+
}
116+
else
117+
{
118+
output = executingProcess.StandardOutput.ReadToEnd();
119+
}
83120
}
84121

85122
executingProcess.WaitForExit();
86123

124+
if (timeoutMs > 0)
125+
{
126+
stopwatch.Stop();
127+
long elapsedMs = stopwatch.ElapsedMilliseconds;
128+
if (elapsedMs > 30_000)
129+
{
130+
// Log slow processes to help diagnose intermittent hangs
131+
string processDesc = FormatProcessDescription(executingProcess);
132+
Console.WriteLine(
133+
$"[{DateTime.Now:HH:mm:ss.fff}] [SLOW-PROCESS] {processDesc} " +
134+
$"completed in {elapsedMs / 1000.0:F1}s (timeout: {timeoutMs / 1000}s)");
135+
Console.Out.Flush();
136+
}
137+
}
138+
87139
return output;
88140
}
141+
142+
private static void KillProcessTree(Process process)
143+
{
144+
try
145+
{
146+
process.Kill(entireProcessTree: true);
147+
}
148+
catch (Exception ex)
149+
{
150+
Console.WriteLine($"[{DateTime.Now:HH:mm:ss.fff}] [WARN] Failed to kill process tree: {ex.Message}");
151+
Console.Out.Flush();
152+
}
153+
}
154+
155+
private static string FormatProcessDescription(Process process)
156+
{
157+
string fileName = process.StartInfo.FileName;
158+
string args = process.StartInfo.Arguments;
159+
string workDir = process.StartInfo.WorkingDirectory;
160+
return $"'{fileName} {args}' (cwd: {workDir})";
161+
}
162+
163+
private static int ReadTimeoutFromEnvironment()
164+
{
165+
string envValue = Environment.GetEnvironmentVariable("GVFS_FT_PROCESS_TIMEOUT_SECONDS");
166+
if (!string.IsNullOrEmpty(envValue) && int.TryParse(envValue, out int seconds) && seconds > 0)
167+
{
168+
return seconds * 1000;
169+
}
170+
171+
return -1;
172+
}
89173
}
90174
}

0 commit comments

Comments
 (0)