CTest: Fix reported duration on timeout when grindchild keeps pipes open

Since commit d1976cd1f2 (CTest: Fix timeout when grandchild keeps pipes
open, 2020-01-13, v3.17.0-rc1~169^2) we no longer hang, but the test
duration we report after the timeout is the amount of time the immediate
child ran before exiting.  Fix the logic to instead report the actual
amount of time we spent monitoring the test before the timeout.

Fixes: #20509

4 files changed, 16 insertions, 10 deletions

diff --git a/Source/CTest/cmProcess.cxx b/Source/CTest/cmProcess.cxx
index cdf899c497..6097aa5bdd 100644
--- a/Source/CTest/cmProcess.cxx
+++ b/Source/CTest/cmProcess.cxx
@@ -249,7 +249,7 @@ void cmProcess::OnRead(ssize_t nread, const uv_buf_t* buf)
   this->PipeReader.reset();
   if (this->ProcessHandleClosed) {
     uv_timer_stop(this->Timer);
-    this->Runner.FinalizeTest();
+    this->Finish();
   }
 }
 
@@ -291,7 +291,7 @@ void cmProcess::OnTimeout()
     // Our on-exit handler already ran but did not finish the test
     // because we were still reading output.  We've just dropped
     // our read handler, so we need to finish the test now.
-    this->Runner.FinalizeTest();
+    this->Finish();
   }
 }
 
@@ -321,6 +321,16 @@ void cmProcess::OnExit(int64_t exit_status, int term_signal)
   // Record exit information.
   this->ExitValue = exit_status;
   this->Signal = term_signal;
+
+  this->ProcessHandleClosed = true;
+  if (this->ReadHandleClosed) {
+    uv_timer_stop(this->Timer);
+    this->Finish();
+  }
+}
+
+void cmProcess::Finish()
+{
   this->TotalTime = std::chrono::steady_clock::now() - this->StartTime;
   // Because of a processor clock scew the runtime may become slightly
   // negative. If someone changed the system clock while the process was
@@ -329,12 +339,7 @@ void cmProcess::OnExit(int64_t exit_status, int term_signal)
   if (this->TotalTime <= cmDuration::zero()) {
     this->TotalTime = cmDuration::zero();
   }
-
-  this->ProcessHandleClosed = true;
-  if (this->ReadHandleClosed) {
-    uv_timer_stop(this->Timer);
-    this->Runner.FinalizeTest();
-  }
+  this->Runner.FinalizeTest();
 }
 
 cmProcess::State cmProcess::GetProcessStatus()
diff --git a/Source/CTest/cmProcess.h b/Source/CTest/cmProcess.h
index 2c24f2df02..ea72a26506 100644
--- a/Source/CTest/cmProcess.h
+++ b/Source/CTest/cmProcess.h
@@ -101,6 +101,7 @@ private:
   void OnAllocate(size_t suggested_size, uv_buf_t* buf);
 
   void StartTimer();
+  void Finish();
 
   class Buffer : public std::vector<char>
   {
diff --git a/Tests/RunCMake/CTestTimeout/Basic-stdout.txt b/Tests/RunCMake/CTestTimeout/Basic-stdout.txt
index 30ed1782f6..db59dbf0a2 100644
--- a/Tests/RunCMake/CTestTimeout/Basic-stdout.txt
+++ b/Tests/RunCMake/CTestTimeout/Basic-stdout.txt
@@ -1,6 +1,6 @@
 Test project [^
 ]*/Tests/RunCMake/CTestTimeout/Basic-build
     Start 1: TestTimeout
-1/1 Test #1: TestTimeout ......................\*\*\*Timeout +[0-9.]+ sec
+1/1 Test #1: TestTimeout ......................\*\*\*Timeout +[1-9][0-9.]* sec
 +
 0% tests passed, 1 tests failed out of 1
diff --git a/Tests/RunCMake/CTestTimeout/Fork-stdout.txt b/Tests/RunCMake/CTestTimeout/Fork-stdout.txt
index 284e4b1083..2938d8ee3b 100644
--- a/Tests/RunCMake/CTestTimeout/Fork-stdout.txt
+++ b/Tests/RunCMake/CTestTimeout/Fork-stdout.txt
@@ -1,6 +1,6 @@
 Test project [^
 ]*/Tests/RunCMake/CTestTimeout/Fork-build
     Start 1: TestTimeout
-1/1 Test #1: TestTimeout ......................\*\*\*Timeout +[0-9.]+ sec
+1/1 Test #1: TestTimeout ......................\*\*\*Timeout +[1-9][0-9.]* sec
 +
 0% tests passed, 1 tests failed out of 1