diff --git a/documentation/wiki/ChangeWaves.md b/documentation/wiki/ChangeWaves.md index f59da4c4ac3..a6fd5b23f0f 100644 --- a/documentation/wiki/ChangeWaves.md +++ b/documentation/wiki/ChangeWaves.md @@ -41,6 +41,7 @@ Change wave checks around features will be removed in the release that accompani - [AbsolutePath.GetCanonicalForm optimization - avoid expensive Path.GetFullPath calls when paths don't need canonicalization](https://github.com/dotnet/msbuild/pull/13369) - [TaskHostTask forwards request-level global properties (e.g. MSBuildRestoreSessionId) to out-of-proc TaskHost in -mt mode](https://github.com/dotnet/msbuild/pull/13443) - [Fix ShouldTreatWarningAsError in OOP TaskHost checking wrong collection (WarningsAsMessages instead of WarningsAsErrors)](https://github.com/dotnet/msbuild/issues/11952) +- [Fix ToolTask hang when tool spawns grandchild processes that inherit stdout/stderr pipe handles](https://github.com/dotnet/msbuild/issues/2981) ### 18.5 - [FindUnderPath and AssignTargetPath tasks no longer throw on invalid path characters when using TaskEnvironment.GetAbsolutePath](https://github.com/dotnet/msbuild/pull/13069) diff --git a/eng/Versions.props b/eng/Versions.props index 8ce917f4743..bd45dd455e2 100644 --- a/eng/Versions.props +++ b/eng/Versions.props @@ -1,9 +1,9 @@ - + - 18.8.2release + 18.8.3release servicing 18.7.0-preview-26230-02 15.1.0.0 diff --git a/src/Utilities.UnitTests/ToolTask_Tests.cs b/src/Utilities.UnitTests/ToolTask_Tests.cs index 7720698a252..222cb6bcbec 100644 --- a/src/Utilities.UnitTests/ToolTask_Tests.cs +++ b/src/Utilities.UnitTests/ToolTask_Tests.cs @@ -1112,6 +1112,72 @@ public void ToolTaskThatTimeoutAndRetry(int repeats, bool timeoutOnFirstExecutio } } + /// + /// Verifies that ToolTask does not hang when the tool process spawns a grandchild + /// process that inherits stdout/stderr pipe handles and outlives the tool. + /// This is a regression test for https://github.com/dotnet/msbuild/issues/2981. + /// + [Fact] + public void ToolTaskDoesNotHangWhenGrandchildInheritsPipeHandles() + { + using (MyTool t = new MyTool()) + { + MockEngine3 engine = new MockEngine3(); + t.BuildEngine = engine; + + // cmd echoes "hello", then starts a background ping that inherits + // pipe handles. cmd exits immediately; ping outlives the 30s EOF timeout. + t.MockCommandLineCommands = NativeMethodsShared.IsWindows + ? "/c echo hello & start /b ping -n 40 127.0.0.1 > nul" + : "-c \"echo hello; sleep 40 &\""; + + // Outer task timeout is generous; the EOF timeout (30s) is what bounds us. + t.Timeout = 60000; + + var sw = Stopwatch.StartNew(); + bool result = t.Execute(); + sw.Stop(); + + _output.WriteLine(engine.Log); + + engine.Log.ShouldContain("hello"); + // The task must return within ~30s (EOF timeout) even though the grandchild lives longer. + sw.Elapsed.TotalSeconds.ShouldBeLessThan(35, "ToolTask should be bounded by the 30s EOF timeout, not the grandchild's lifetime"); + // The diagnostic message must appear so CI reports show why the wait ended. + engine.Log.ShouldContain("Pipe EOF not received"); + } + } + + /// + /// Verifies that ToolTask still captures all output from the tool process + /// even with the grandchild pipe fix enabled. This is a regression test for + /// https://github.com/dotnet/msbuild/issues/10378 where switching to + /// WaitForExit(int) caused output to be lost. + /// + [Fact] + public void ToolTaskCapturesAllOutputWithFix() + { + using (MyTool t = new MyTool()) + { + MockEngine3 engine = new MockEngine3(); + t.BuildEngine = engine; + + // Echo multiple lines to verify all output is captured + t.MockCommandLineCommands = NativeMethodsShared.IsWindows ? + "/c echo line1 & echo line2 & echo line3" + : "-c \"echo line1; echo line2; echo line3\""; + + bool result = t.Execute(); + + _output.WriteLine(engine.Log); + + result.ShouldBeTrue(); + engine.Log.ShouldContain("line1"); + engine.Log.ShouldContain("line2"); + engine.Log.ShouldContain("line3"); + } + } + /// /// A simple implementation of to sleep for a while. /// diff --git a/src/Utilities/Resources/Strings.resx b/src/Utilities/Resources/Strings.resx index ad673518ba6..2167e4257b9 100644 --- a/src/Utilities/Resources/Strings.resx +++ b/src/Utilities/Resources/Strings.resx @@ -168,6 +168,9 @@ Environment Variables passed to tool: + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + MSB6011: Invalid parameters passed to the {0} task. {StrBegin="MSB6011: "} diff --git a/src/Utilities/Resources/xlf/Strings.cs.xlf b/src/Utilities/Resources/xlf/Strings.cs.xlf index 01efc804e00..d8db478a91b 100644 --- a/src/Utilities/Resources/xlf/Strings.cs.xlf +++ b/src/Utilities/Resources/xlf/Strings.cs.xlf @@ -72,6 +72,11 @@ Úlohu nelze přeskočit, protože není aktuální. + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: Příkaz {0} byl ukončen s kódem {1}. diff --git a/src/Utilities/Resources/xlf/Strings.de.xlf b/src/Utilities/Resources/xlf/Strings.de.xlf index f31ae54aa3e..7953fb83c84 100644 --- a/src/Utilities/Resources/xlf/Strings.de.xlf +++ b/src/Utilities/Resources/xlf/Strings.de.xlf @@ -72,6 +72,11 @@ Die Aufgabe kann nicht übersprungen werden, da sie nicht auf dem neuesten Stand ist. + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: "{0}" wurde mit dem Code {1} beendet. diff --git a/src/Utilities/Resources/xlf/Strings.es.xlf b/src/Utilities/Resources/xlf/Strings.es.xlf index 25a603833f9..404be9711e3 100644 --- a/src/Utilities/Resources/xlf/Strings.es.xlf +++ b/src/Utilities/Resources/xlf/Strings.es.xlf @@ -72,6 +72,11 @@ No se puede omitir la tarea porque no está actualizada. + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: "{0}" salió con el código {1}. diff --git a/src/Utilities/Resources/xlf/Strings.fr.xlf b/src/Utilities/Resources/xlf/Strings.fr.xlf index 9f7081d4b93..62aee2304ac 100644 --- a/src/Utilities/Resources/xlf/Strings.fr.xlf +++ b/src/Utilities/Resources/xlf/Strings.fr.xlf @@ -72,6 +72,11 @@ Nous n’avons pas pu ignorer la tâche, car elle n’est pas à jour. + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: Arrêt de "{0}" avec le code {1}. diff --git a/src/Utilities/Resources/xlf/Strings.it.xlf b/src/Utilities/Resources/xlf/Strings.it.xlf index b8571d61ca5..c36effec9b5 100644 --- a/src/Utilities/Resources/xlf/Strings.it.xlf +++ b/src/Utilities/Resources/xlf/Strings.it.xlf @@ -72,6 +72,11 @@ Non è possibile ignorare l'attività perché non è aggiornata. + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: "{0}" terminato con il codice {1}. diff --git a/src/Utilities/Resources/xlf/Strings.ja.xlf b/src/Utilities/Resources/xlf/Strings.ja.xlf index 32d07e722b9..390d2252e2e 100644 --- a/src/Utilities/Resources/xlf/Strings.ja.xlf +++ b/src/Utilities/Resources/xlf/Strings.ja.xlf @@ -72,6 +72,11 @@ タスクは最新ではないため、スキップできません。 + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: "{0}" はコード {1} を伴って終了しました。 diff --git a/src/Utilities/Resources/xlf/Strings.ko.xlf b/src/Utilities/Resources/xlf/Strings.ko.xlf index 92717cf6b5f..35d20b92f56 100644 --- a/src/Utilities/Resources/xlf/Strings.ko.xlf +++ b/src/Utilities/Resources/xlf/Strings.ko.xlf @@ -72,6 +72,11 @@ 작업이 최신 상태가 아니므로 건너뛸 수 없습니다. + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: "{0}"이(가) 종료되었습니다(코드: {1}). diff --git a/src/Utilities/Resources/xlf/Strings.pl.xlf b/src/Utilities/Resources/xlf/Strings.pl.xlf index a9cd195e78e..e3a30fe7208 100644 --- a/src/Utilities/Resources/xlf/Strings.pl.xlf +++ b/src/Utilities/Resources/xlf/Strings.pl.xlf @@ -72,6 +72,11 @@ Nie można pominąć zadania, ponieważ nie jest ono aktualne. + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: Polecenie „{0}” zakończone przez kod {1}. diff --git a/src/Utilities/Resources/xlf/Strings.pt-BR.xlf b/src/Utilities/Resources/xlf/Strings.pt-BR.xlf index 1ad5f8e64c4..58b46449de2 100644 --- a/src/Utilities/Resources/xlf/Strings.pt-BR.xlf +++ b/src/Utilities/Resources/xlf/Strings.pt-BR.xlf @@ -72,6 +72,11 @@ Não foi possível ignorar a tarefa porque ela não está atualizada. + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: "{0}" foi encerrado com o código {1}. diff --git a/src/Utilities/Resources/xlf/Strings.ru.xlf b/src/Utilities/Resources/xlf/Strings.ru.xlf index 76e99c6ee79..a8f48b89954 100644 --- a/src/Utilities/Resources/xlf/Strings.ru.xlf +++ b/src/Utilities/Resources/xlf/Strings.ru.xlf @@ -72,6 +72,11 @@ Невозможно пропустить задачу, поскольку она не обновлена. + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: "{0}" завершилась с кодом {1}. diff --git a/src/Utilities/Resources/xlf/Strings.tr.xlf b/src/Utilities/Resources/xlf/Strings.tr.xlf index ad4d04c0dc3..2dbf03ad7df 100644 --- a/src/Utilities/Resources/xlf/Strings.tr.xlf +++ b/src/Utilities/Resources/xlf/Strings.tr.xlf @@ -72,6 +72,11 @@ Güncel olmadığı için görev atlanamıyor. + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: "{0}" öğesinden {1} koduyla çıkıldı. diff --git a/src/Utilities/Resources/xlf/Strings.zh-Hans.xlf b/src/Utilities/Resources/xlf/Strings.zh-Hans.xlf index 1513cad0038..fb427250d27 100644 --- a/src/Utilities/Resources/xlf/Strings.zh-Hans.xlf +++ b/src/Utilities/Resources/xlf/Strings.zh-Hans.xlf @@ -72,6 +72,11 @@ 无法跳过任务，因为它不是最新的。 + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: “{0}”已退出，代码为 {1}。 diff --git a/src/Utilities/Resources/xlf/Strings.zh-Hant.xlf b/src/Utilities/Resources/xlf/Strings.zh-Hant.xlf index 9b40829dcf6..d2cae6d6368 100644 --- a/src/Utilities/Resources/xlf/Strings.zh-Hant.xlf +++ b/src/Utilities/Resources/xlf/Strings.zh-Hant.xlf @@ -72,6 +72,11 @@ 無法略過工作，因為它不是最新的。 + + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + Pipe EOF not received within {0} seconds. A grandchild process may still be holding the pipe open. Output already delivered has been logged. + + MSB6006: "{0}" exited with code {1}. MSB6006: "{0}" 以返回碼 {1} 結束。 diff --git a/src/Utilities/ToolTask.cs b/src/Utilities/ToolTask.cs index e9e2d58447a..389e75e70ea 100644 --- a/src/Utilities/ToolTask.cs +++ b/src/Utilities/ToolTask.cs @@ -766,6 +766,12 @@ protected virtual int ExecuteTool( _standardErrorDataAvailable = new ManualResetEvent(false); _standardOutputDataAvailable = new ManualResetEvent(false); + if (ChangeWaves.AreFeaturesEnabled(ChangeWaves.Wave18_6)) + { + // One count each for the stdout and stderr EOF notifications. + _eofCountdown = new CountdownEvent(2); + } + _toolExited = new ManualResetEvent(false); _terminatedTool = false; _toolTimeoutExpired = new ManualResetEvent(false); @@ -859,6 +865,9 @@ protected virtual int ExecuteTool( _standardErrorDataAvailable.Dispose(); _standardOutputDataAvailable.Dispose(); + _eofCountdown?.Dispose(); + _eofCountdown = null; + _toolExited.Dispose(); _toolTimeoutExpired.Dispose(); @@ -1097,13 +1106,51 @@ private void TerminateToolProcess(Process proc, bool isBeingCancelled) /// process is still finishing up, this method waits until it is done. /// /// - /// This method is a hack, but it needs to be called after both - /// Process.WaitForExit() and Process.Kill(). + /// On both .NET Framework and modern .NET, the parameterless Process.WaitForExit() waits not + /// only for the process to exit, but also for stdout/stderr pipe EOF via + /// AsyncStreamReader.WaitUtilEOF() (Framework) or awaiting the EOF task (Core). + /// If the tool spawned child processes that inherited the pipe handles, the EOF wait blocks + /// forever even though the tool itself has exited — causing the entire build node to hang. /// /// - private static void WaitForProcessExit(Process proc) + private void WaitForProcessExit(Process proc) { - proc.WaitForExit(); + if (ChangeWaves.AreFeaturesEnabled(ChangeWaves.Wave18_6)) + { + // Step 1: Wait for the process handle to be signaled. + // Use int.MaxValue to avoid blocking on pipe EOF, + // as Process.WaitForExit does not wait for EOF when any timeout is provided. + proc.WaitForExit(int.MaxValue); + + // Step 2: Wait for the AsyncStreamReader to deliver all remaining data. + // When the pipe reaches EOF, AsyncStreamReader flushes its StringBuilder + // (delivering any final partial line) and sends Data=null via the callback. + // Our ReceiveStandardErrorOrOutputData handler signals the EOF events. + // + // Use a bounded timeout as a safety net for the grandchild case where + // EOF never arrives because grand child inherited the pipe and keeps it open. + const int eofTimeoutSec = 30; + + // CountdownEvent.Wait is STA-safe (it falls back to a single-handle wait), + // unlike WaitHandle.WaitAll over multiple handles which throws + // NotSupportedException on STA threads (for example when a task such as + // AspNetCompiler runs on an STA thread). + bool allEOFReceived = _eofCountdown.Wait(TimeSpan.FromSeconds(eofTimeoutSec)); + if (!allEOFReceived) + { + // Timeout: a grandchild process likely still holds the pipe open. + // Drain whatever data has already arrived before returning. + LogMessagesFromStandardError(); + LogMessagesFromStandardOutput(); + LogPrivate.LogMessageFromResources(MessageImportance.Low, "ToolTask.PipeEOFTimeout", eofTimeoutSec); + } + } + else + { + // Legacy behavior: parameterless WaitForExit waits for pipe EOF. + // This can hang if grandchild processes hold pipe handles. + proc.WaitForExit(); + } // Process.WaitForExit() may return prematurely. We need to check to be sure. while (!proc.HasExited) @@ -1269,36 +1316,48 @@ protected void ReceiveExitNotification(object sender, EventArgs e) /// private void ReceiveStandardErrorOrOutputData(DataReceivedEventArgs e, Queue dataQueue, ManualResetEvent dataAvailableSignal) { - // NOTE: don't ignore empty string, because we need to log that - if (e.Data != null) + if (e.Data == null) { - ErrorUtilities.VerifyThrow(dataQueue != null, - "The data queue must be available."); - - // synchronize access to the queue -- this is a producer-consumer problem - // NOTE: we lock the entire queue instead of using synchronized queue - // wrappers, because ManualResetEvents don't have ref counts, and it's - // difficult to discretely signal the availability of each instance of - // data in the queue -- so instead we let the consumer lock and empty - // the queue and reset the ManualResetEvent, before we add more data - // into the queue, and signal the ManualResetEvent again - lock (dataQueue.SyncRoot) + // The AsyncStreamReader sends Data=null exactly once per stream when the + // pipe reaches EOF. Count it down so WaitForProcessExit knows when all + // data from both streams has been delivered. + lock (_eventCloseLock) { - dataQueue.Enqueue(e.Data); + if (!_eventsDisposed && _eofCountdown is { IsSet: false }) + { + _eofCountdown.Signal(); + } + } - ErrorUtilities.VerifyThrow(dataAvailableSignal != null, - "The signalling event must be available."); + return; + } + + // NOTE: don't ignore empty string, because we need to log that + ErrorUtilities.VerifyThrow(dataQueue != null, "The data queue must be available."); - // signal the availability of data - // NOTE: intentionally, do the signalling inside the lock, because - // ManualResetEvents don't have ref counts, and we want to make sure - // we don't signal the notification just before the consumer resets it - lock (_eventCloseLock) + // synchronize access to the queue -- this is a producer-consumer problem + // NOTE: we lock the entire queue instead of using synchronized queue + // wrappers, because ManualResetEvents don't have ref counts, and it's + // difficult to discretely signal the availability of each instance of + // data in the queue -- so instead we let the consumer lock and empty + // the queue and reset the ManualResetEvent, before we add more data + // into the queue, and signal the ManualResetEvent again + lock (dataQueue.SyncRoot) + { + dataQueue.Enqueue(e.Data); + + ErrorUtilities.VerifyThrow(dataAvailableSignal != null, + "The signalling event must be available."); + + // signal the availability of data + // NOTE: intentionally, do the signalling inside the lock, because + // ManualResetEvents don't have ref counts, and we want to make sure + // we don't signal the notification just before the consumer resets it + lock (_eventCloseLock) + { + if (!_eventsDisposed) { - if (!_eventsDisposed) - { - dataAvailableSignal.Set(); - } + dataAvailableSignal.Set(); } } } @@ -1808,6 +1867,13 @@ private bool LogEnvironmentVariable(bool alreadyLoggedEnvironmentHeader, string /// private bool _eventsDisposed; + /// + /// Counts down once for each of stdout/stderr when its AsyncStreamReader reaches + /// EOF (sends Data=null). Used by WaitForProcessExit to know when all data from + /// both streams has been delivered. + /// + private CountdownEvent _eofCountdown; + /// /// List of name, value pairs to be passed to the spawned tool's environment. /// May be null.