Merge topic 'add_progress_summary_console_logging_mode'

b3d5b8b3fb ctest: Add option for live progress summary in terminal
62fbe5002a cmCTestRunTest: Thread number of completed tests through start APIs
02c5091c90 cmCTestRunTest: Simplify number width computation
6a285bb737 cmCTestRunTest: Buffer test result output before printing

Acked-by: Kitware Robot <kwrobot@kitware.com>
Merge-request: !2240

Help/release/dev/ctest-progress-output.rst

@@ -0,0 +1,5 @@
+ctest-progress-output
+---------------------
+
+* :manual:`ctest(1)` gained a ``--progress`` option to enable a live
+  test progress summary when output goes to a terminal.

Source/CTest/cmCTestMultiProcessHandler.cxx

@@ -178,7 +178,7 @@ bool cmCTestMultiProcessHandler::StartTestProcess(int test)
                           this->Properties[test]->Directory + " : " +
                           std::strerror(workdir.GetLastResult()));
   } else {
-    if (testRun->StartTest(this->Total)) {
+    if (testRun->StartTest(this->Completed, this->Total)) {
       return true;
     }
   }
@@ -440,7 +440,7 @@ void cmCTestMultiProcessHandler::FinishTestProcess(cmCTestRunTest* runner,
     this->SetStopTimePassed();
   }
   if (started) {
-    if (!this->StopTimePassed && runner->StartAgain()) {
+    if (!this->StopTimePassed && runner->StartAgain(this->Completed)) {
       this->Completed--; // remove the completed test because run again
       return;
     }

Source/CTest/cmCTestRunTest.cxx

@@ -181,6 +181,7 @@ bool cmCTestRunTest::EndTest(size_t completed, size_t total, bool started)
       }
     }
   }
+  std::ostringstream outputStream;
   if (res == cmProcess::State::Exited) {
     bool success = !forceFail &&
       (retVal == 0 ||
@@ -196,36 +197,36 @@ bool cmCTestRunTest::EndTest(size_t completed, size_t total, bool started)
     } else if ((success && !this->TestProperties->WillFail) ||
                (!success && this->TestProperties->WillFail)) {
       this->TestResult.Status = cmCTestTestHandler::COMPLETED;
-      cmCTestLog(this->CTest, HANDLER_OUTPUT, "   Passed  ");
+      outputStream << "   Passed  ";
     } else {
       this->TestResult.Status = cmCTestTestHandler::FAILED;
-      cmCTestLog(this->CTest, HANDLER_OUTPUT, "***Failed  " << reason);
+      outputStream << "***Failed  " << reason;
       outputTestErrorsToConsole = this->CTest->OutputTestOutputOnTestFailure;
     }
   } else if (res == cmProcess::State::Expired) {
-    cmCTestLog(this->CTest, HANDLER_OUTPUT, "***Timeout ");
+    outputStream << "***Timeout ";
     this->TestResult.Status = cmCTestTestHandler::TIMEOUT;
     outputTestErrorsToConsole = this->CTest->OutputTestOutputOnTestFailure;
   } else if (res == cmProcess::State::Exception) {
     outputTestErrorsToConsole = this->CTest->OutputTestOutputOnTestFailure;
-    cmCTestLog(this->CTest, HANDLER_OUTPUT, "***Exception: ");
+    outputStream << "***Exception: ";
     this->TestResult.ExceptionStatus =
       this->TestProcess->GetExitExceptionString();
     switch (this->TestProcess->GetExitException()) {
       case cmProcess::Exception::Fault:
-        cmCTestLog(this->CTest, HANDLER_OUTPUT, "SegFault");
+        outputStream << "SegFault";
         this->TestResult.Status = cmCTestTestHandler::SEGFAULT;
         break;
       case cmProcess::Exception::Illegal:
-        cmCTestLog(this->CTest, HANDLER_OUTPUT, "Illegal");
+        outputStream << "Illegal";
         this->TestResult.Status = cmCTestTestHandler::ILLEGAL;
         break;
       case cmProcess::Exception::Interrupt:
-        cmCTestLog(this->CTest, HANDLER_OUTPUT, "Interrupt");
+        outputStream << "Interrupt";
         this->TestResult.Status = cmCTestTestHandler::INTERRUPT;
         break;
       case cmProcess::Exception::Numerical:
-        cmCTestLog(this->CTest, HANDLER_OUTPUT, "Numerical");
+        outputStream << "Numerical";
         this->TestResult.Status = cmCTestTestHandler::NUMERICAL;
         break;
       default:
@@ -234,16 +235,41 @@ bool cmCTestRunTest::EndTest(size_t completed, size_t total, bool started)
         this->TestResult.Status = cmCTestTestHandler::OTHER_FAULT;
     }
   } else if ("Disabled" == this->TestResult.CompletionStatus) {
-    cmCTestLog(this->CTest, HANDLER_OUTPUT, "***Not Run (Disabled) ");
+    outputStream << "***Not Run (Disabled) ";
   } else // cmProcess::State::Error
   {
-    cmCTestLog(this->CTest, HANDLER_OUTPUT, "***Not Run ");
+    outputStream << "***Not Run ";
   }
 
   passed = this->TestResult.Status == cmCTestTestHandler::COMPLETED;
   char buf[1024];
   sprintf(buf, "%6.2f sec", this->TestProcess->GetTotalTime().count());
-  cmCTestLog(this->CTest, HANDLER_OUTPUT, buf << "\n");
+  outputStream << buf << "\n";
+
+  if (this->CTest->GetTestProgressOutput()) {
+    if (!passed) {
+      // If the test did not pass, reprint test name and error
+      std::string output = GetTestPrefix(completed, total);
+      std::string testName = this->TestProperties->Name;
+      const int maxTestNameWidth = this->CTest->GetMaxTestNameWidth();
+      testName.resize(maxTestNameWidth + 4, '.');
+
+      output += testName;
+      output += outputStream.str();
+      outputStream.str("");
+      outputStream.clear();
+      outputStream << output;
+      cmCTestLog(this->CTest, HANDLER_TEST_PROGRESS_OUTPUT, "\n"); // flush
+    }
+    if (completed == total) {
+      std::string testName =
+        GetTestPrefix(completed, total) + this->TestProperties->Name + "\n";
+      cmCTestLog(this->CTest, HANDLER_TEST_PROGRESS_OUTPUT, testName);
+    }
+  }
+  if (!this->CTest->GetTestProgressOutput() || !passed) {
+    cmCTestLog(this->CTest, HANDLER_OUTPUT, outputStream.str());
+  }
 
   if (outputTestErrorsToConsole) {
     cmCTestLog(this->CTest, HANDLER_OUTPUT, this->ProcessOutput << std::endl);
@@ -331,7 +357,7 @@ bool cmCTestRunTest::EndTest(size_t completed, size_t total, bool started)
   return passed || skipped;
 }
 
-bool cmCTestRunTest::StartAgain()
+bool cmCTestRunTest::StartAgain(size_t completed)
 {
   if (!this->RunAgain) {
     return false;
@@ -346,7 +372,7 @@ bool cmCTestRunTest::StartAgain()
     return true;
   }
 
-  this->StartTest(this->TotalNumberOfTests);
+  this->StartTest(completed, this->TotalNumberOfTests);
   return true;
 }
 
@@ -398,12 +424,14 @@ void cmCTestRunTest::StartFailure(std::string const& output)
 {
   // Still need to log the Start message so the test summary records our
   // attempt to start this test
-  cmCTestLog(this->CTest, HANDLER_OUTPUT,
-             std::setw(2 * getNumWidth(this->TotalNumberOfTests) + 8)
-               << "Start "
-               << std::setw(getNumWidth(this->TestHandler->GetMaxIndex()))
-               << this->TestProperties->Index << ": "
-               << this->TestProperties->Name << std::endl);
+  if (!this->CTest->GetTestProgressOutput()) {
+    cmCTestLog(this->CTest, HANDLER_OUTPUT,
+               std::setw(2 * getNumWidth(this->TotalNumberOfTests) + 8)
+                 << "Start "
+                 << std::setw(getNumWidth(this->TestHandler->GetMaxIndex()))
+                 << this->TestProperties->Index << ": "
+                 << this->TestProperties->Name << std::endl);
+  }
 
   this->ProcessOutput.clear();
   if (!output.empty()) {
@@ -425,16 +453,44 @@ void cmCTestRunTest::StartFailure(std::string const& output)
   this->TestProcess = cm::make_unique<cmProcess>(*this);
 }
 
+std::string cmCTestRunTest::GetTestPrefix(size_t completed, size_t total) const
+{
+  std::ostringstream outputStream;
+  outputStream << std::setw(getNumWidth(total)) << completed << "/";
+  outputStream << std::setw(getNumWidth(total)) << total << " ";
+
+  if (this->TestHandler->MemCheck) {
+    outputStream << "MemCheck";
+  } else {
+    outputStream << "Test";
+  }
+
+  std::ostringstream indexStr;
+  indexStr << " #" << this->Index << ":";
+  outputStream << std::setw(3 + getNumWidth(this->TestHandler->GetMaxIndex()))
+               << indexStr.str();
+  outputStream << " ";
+
+  return outputStream.str();
+}
+
 // Starts the execution of a test.  Returns once it has started
-bool cmCTestRunTest::StartTest(size_t total)
+bool cmCTestRunTest::StartTest(size_t completed, size_t total)
 {
   this->TotalNumberOfTests = total; // save for rerun case
-  cmCTestLog(this->CTest, HANDLER_OUTPUT,
-             std::setw(2 * getNumWidth(total) + 8)
-               << "Start "
-               << std::setw(getNumWidth(this->TestHandler->GetMaxIndex()))
-               << this->TestProperties->Index << ": "
-               << this->TestProperties->Name << std::endl);
+  if (!this->CTest->GetTestProgressOutput()) {
+    cmCTestLog(this->CTest, HANDLER_OUTPUT,
+               std::setw(2 * getNumWidth(total) + 8)
+                 << "Start "
+                 << std::setw(getNumWidth(this->TestHandler->GetMaxIndex()))
+                 << this->TestProperties->Index << ": "
+                 << this->TestProperties->Name << std::endl);
+  } else {
+    std::string testName =
+      GetTestPrefix(completed, total) + this->TestProperties->Name + "\n";
+    cmCTestLog(this->CTest, HANDLER_TEST_PROGRESS_OUTPUT, testName);
+  }
+
   this->ProcessOutput.clear();
 
   // Return immediately if test is disabled
@@ -689,44 +745,41 @@ bool cmCTestRunTest::ForkProcess(cmDuration testTimeOut, bool explicitTimeout,
 
 void cmCTestRunTest::WriteLogOutputTop(size_t completed, size_t total)
 {
-  // if this is the last or only run of this test
-  // then print out completed / total
+  std::ostringstream outputStream;
+
+  // If this is the last or only run of this test, or progress output is
+  // requested, then print out completed / total.
   // Only issue is if a test fails and we are running until fail
   // then it will never print out the completed / total, same would
   // got for run until pass.  Trick is when this is called we don't
   // yet know if we are passing or failing.
-  if (this->NumberOfRunsLeft == 1) {
-    cmCTestLog(this->CTest, HANDLER_OUTPUT,
-               std::setw(getNumWidth(total)) << completed << "/");
-    cmCTestLog(this->CTest, HANDLER_OUTPUT,
-               std::setw(getNumWidth(total)) << total << " ");
+  if (this->NumberOfRunsLeft == 1 || this->CTest->GetTestProgressOutput()) {
+    outputStream << std::setw(getNumWidth(total)) << completed << "/";
+    outputStream << std::setw(getNumWidth(total)) << total << " ";
   }
   // if this is one of several runs of a test just print blank space
   // to keep things neat
   else {
-    cmCTestLog(this->CTest, HANDLER_OUTPUT,
-               std::setw(getNumWidth(total)) << " "
-                                             << " ");
-    cmCTestLog(this->CTest, HANDLER_OUTPUT,
-               std::setw(getNumWidth(total)) << " "
-                                             << " ");
+    outputStream << std::setw(getNumWidth(total)) << "  ";
+    outputStream << std::setw(getNumWidth(total)) << "  ";
   }
 
   if (this->TestHandler->MemCheck) {
-    cmCTestLog(this->CTest, HANDLER_OUTPUT, "MemCheck");
+    outputStream << "MemCheck";
   } else {
-    cmCTestLog(this->CTest, HANDLER_OUTPUT, "Test");
+    outputStream << "Test";
   }
 
   std::ostringstream indexStr;
   indexStr << " #" << this->Index << ":";
-  cmCTestLog(this->CTest, HANDLER_OUTPUT,
-             std::setw(3 + getNumWidth(this->TestHandler->GetMaxIndex()))
-               << indexStr.str());
-  cmCTestLog(this->CTest, HANDLER_OUTPUT, " ");
+  outputStream << std::setw(3 + getNumWidth(this->TestHandler->GetMaxIndex()))
+               << indexStr.str();
+  outputStream << " ";
+
   const int maxTestNameWidth = this->CTest->GetMaxTestNameWidth();
   std::string outname = this->TestProperties->Name + " ";
   outname.resize(maxTestNameWidth + 4, '.');
+  outputStream << outname;
 
   *this->TestHandler->LogFile << this->TestProperties->Index << "/"
                               << this->TestHandler->TotalNumberOfTests
@@ -754,7 +807,10 @@ void cmCTestRunTest::WriteLogOutputTop(size_t completed, size_t total)
   *this->TestHandler->LogFile << this->ProcessOutput << "<end of output>"
                               << std::endl;
 
-  cmCTestLog(this->CTest, HANDLER_OUTPUT, outname.c_str());
+  if (!this->CTest->GetTestProgressOutput()) {
+    cmCTestLog(this->CTest, HANDLER_OUTPUT, outputStream.str());
+  }
+
   cmCTestLog(this->CTest, DEBUG,
              "Testing " << this->TestProperties->Name << " ... ");
 }

Source/CTest/cmCTestRunTest.h

@@ -5,6 +5,7 @@
 
 #include "cmConfigure.h" // IWYU pragma: keep
 
+#include <cmath>
 #include <set>
 #include <stddef.h>
 #include <string>
@@ -64,7 +65,7 @@ public:
   void CompressOutput();
 
   // launch the test process, return whether it started correctly
-  bool StartTest(size_t total);
+  bool StartTest(size_t completed, size_t total);
   // capture and report the test results
   bool EndTest(size_t completed, size_t total, bool started);
   // Called by ctest -N to log the command string
@@ -72,7 +73,7 @@ public:
 
   void ComputeWeightedCost();
 
-  bool StartAgain();
+  bool StartAgain(size_t completed);
 
   void StartFailure(std::string const& output);
 
@@ -93,6 +94,9 @@ private:
   // Run post processing of the process output for MemCheck
   void MemCheckPostProcess();
 
+  // Returns "completed/total Test #Index: "
+  std::string GetTestPrefix(size_t completed, size_t total) const;
+
   cmCTestTestHandler::cmCTestTestProperties* TestProperties;
   bool TimeoutIsForStopTime = false;
   // Pointer back to the "parent"; the handler that invoked this test run
@@ -118,14 +122,7 @@ private:
 
 inline int getNumWidth(size_t n)
 {
-  int numWidth = 1;
-  if (n >= 10) {
-    numWidth = 2;
-  }
-  if (n >= 100) {
-    numWidth = 3;
-  }
-  return numWidth;
+  return static_cast<int>(std::log10(n)) + 1;
 }
 
 #endif

Source/cmCTest.cxx

@@ -24,6 +24,11 @@
 #include <time.h>
 #include <utility>
 #include <vector>
+#if defined(_WIN32)
+#  include <windows.h> // IWYU pragma: keep
+#else
+#  include <unistd.h> // IWYU pragma: keep
+#endif
 
 #include "cmAlgorithms.h"
 #include "cmCTestBuildAndTestHandler.h"
@@ -263,6 +268,8 @@ cmCTest::cmCTest()
   this->Failover = false;
   this->ForceNewCTestProcess = false;
   this->TomorrowTag = false;
+  this->TestProgressOutput = false;
+  this->FlushTestProgressLine = false;
   this->Verbose = false;
 
   this->Debug = false;
@@ -290,10 +297,16 @@ cmCTest::cmCTest()
   this->OutputTestOutputOnTestFailure = false;
   this->RepeatTests = 1; // default to run each test once
   this->RepeatUntilFail = false;
-  std::string outOnFail;
-  if (cmSystemTools::GetEnv("CTEST_OUTPUT_ON_FAILURE", outOnFail)) {
-    this->OutputTestOutputOnTestFailure = !cmSystemTools::IsOff(outOnFail);
+
+  std::string envValue;
+  if (cmSystemTools::GetEnv("CTEST_OUTPUT_ON_FAILURE", envValue)) {
+    this->OutputTestOutputOnTestFailure = !cmSystemTools::IsOff(envValue);
   }
+  envValue.clear();
+  if (cmSystemTools::GetEnv("CTEST_PROGRESS_OUTPUT", envValue)) {
+    this->TestProgressOutput = !cmSystemTools::IsOff(envValue);
+  }
+
   this->InitStreams();
 
   this->Parts[PartStart].SetName("Start");
@@ -1875,6 +1888,9 @@ bool cmCTest::HandleCommandLineArguments(size_t& i,
   if (this->CheckArgument(arg, "-Q", "--quiet")) {
     this->Quiet = true;
   }
+  if (this->CheckArgument(arg, "--progress")) {
+    this->TestProgressOutput = true;
+  }
   if (this->CheckArgument(arg, "-V", "--verbose")) {
     this->Verbose = true;
   }
@@ -2038,6 +2054,23 @@ bool cmCTest::HandleCommandLineArguments(size_t& i,
   return true;
 }
 
+bool cmCTest::ProgressOutputSupportedByConsole() const
+{
+#if defined(_WIN32)
+  // On Windows we need a console buffer.
+  void* console = GetStdHandle(STD_OUTPUT_HANDLE);
+  CONSOLE_SCREEN_BUFFER_INFO csbi;
+  return GetConsoleScreenBufferInfo(console, &csbi);
+#else
+  // On UNIX we need a non-dumb tty.
+  std::string term_env_variable;
+  if (cmSystemTools::GetEnv("TERM", term_env_variable)) {
+    return isatty(1) && term_env_variable != "dumb";
+  }
+#endif
+  return false;
+}
+
 // handle the -S -SR and -SP arguments
 void cmCTest::HandleScriptArguments(size_t& i, std::vector<std::string>& args,
                                     bool& SRArgumentSpecified)
@@ -2192,6 +2225,18 @@ int cmCTest::Run(std::vector<std::string>& args, std::string* output)
     }
   }
 
+  // TestProgressOutput only supported if console supports it and not logging
+  // to a file
+  this->TestProgressOutput = this->TestProgressOutput &&
+    !this->OutputLogFile && this->ProgressOutputSupportedByConsole();
+#ifdef _WIN32
+  if (this->TestProgressOutput) {
+    // Disable output line buffering so we can print content without
+    // a newline.
+    std::setvbuf(stdout, nullptr, _IONBF, 0);
+  }
+#endif
+
   // now what should cmake do? if --build-and-test was specified then
   // we run the build and test handler and return
   if (cmakeAndTest) {
@@ -2761,6 +2806,7 @@ static const char* cmCTestStringLogType[] = { "DEBUG",
                                               "OUTPUT",
                                               "HANDLER_OUTPUT",
                                               "HANDLER_PROGRESS_OUTPUT",
+                                              "HANDLER_TEST_PROGRESS_OUTPUT",
                                               "HANDLER_VERBOSE_OUTPUT",
                                               "WARNING",
                                               "ERROR_MESSAGE",
@@ -2821,6 +2867,34 @@ void cmCTest::Log(int logType, const char* file, int line, const char* msg,
   if (!this->Quiet) {
     std::ostream& out = *this->StreamOut;
     std::ostream& err = *this->StreamErr;
+
+    if (logType == HANDLER_TEST_PROGRESS_OUTPUT) {
+      if (this->TestProgressOutput) {
+        cmCTestLogOutputFileLine(out);
+        if (this->FlushTestProgressLine) {
+          printf("\r");
+          this->FlushTestProgressLine = false;
+          out.flush();
+        }
+
+        std::string msg_str{ msg };
+        auto const lineBreakIt = msg_str.find('\n');
+        if (lineBreakIt != std::string::npos) {
+          this->FlushTestProgressLine = true;
+          msg_str.erase(std::remove(msg_str.begin(), msg_str.end(), '\n'),
+                        msg_str.end());
+        }
+
+        out << msg_str;
+#ifndef _WIN32
+        printf("\x1B[K"); // move caret to end
+#endif
+        out.flush();
+        return;
+      }
+      logType = HANDLER_OUTPUT;
+    }
+
     switch (logType) {
       case DEBUG:
         if (this->Debug) {

Source/cmCTest.h

@@ -390,6 +390,7 @@ public:
     OUTPUT,
     HANDLER_OUTPUT,
     HANDLER_PROGRESS_OUTPUT,
+    HANDLER_TEST_PROGRESS_OUTPUT,
     HANDLER_VERBOSE_OUTPUT,
     WARNING,
     ERROR_MESSAGE,
@@ -429,6 +430,8 @@ public:
   void SetFailover(bool failover) { this->Failover = failover; }
   bool GetFailover() { return this->Failover; }
 
+  bool GetTestProgressOutput() const { return this->TestProgressOutput; }
+
   bool GetVerbose() { return this->Verbose; }
   bool GetExtraVerbose() { return this->ExtraVerbose; }
 
@@ -467,6 +470,7 @@ private:
   std::string ConfigType;
   std::string ScheduleType;
   std::chrono::system_clock::time_point StopTime;
+  bool TestProgressOutput;
   bool Verbose;
   bool ExtraVerbose;
   bool ProduceXML;
@@ -476,6 +480,8 @@ private:
   bool PrintLabels;
   bool Failover;
 
+  bool FlushTestProgressLine;
+
   bool ForceNewCTestProcess;
 
   bool RunConfigurationScript;
@@ -561,6 +567,9 @@ private:
   bool HandleCommandLineArguments(size_t& i, std::vector<std::string>& args,
                                   std::string& errormsg);
 
+  /** returns true iff the console supports progress output */
+  bool ProgressOutputSupportedByConsole() const;
+
   /** handle the -S -SP and -SR arguments */
   void HandleScriptArguments(size_t& i, std::vector<std::string>& args,
                              bool& SRArgumentSpecified);

Source/ctest.cxx

@@ -27,6 +27,7 @@ static const char* cmDocumentationUsage[][2] = { { nullptr,
 
 static const char* cmDocumentationOptions[][2] = {
   { "-C <cfg>, --build-config <cfg>", "Choose configuration to test." },
+  { "--progress", "Enable short progress output from tests." },
   { "-V,--verbose", "Enable verbose output from tests." },
   { "-VV,--extra-verbose", "Enable more verbose output from tests." },
   { "--debug", "Displaying more verbose internals of CTest." },