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 cdf899c..6097aa5 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 2c24f2d..ea72a26 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 30ed178..db59dbf 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 284e4b1..2938d8e 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