cmCTestRunTest.cxx 39 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894895896897898899900901902903904905906907908909910911912913914915916917918919920921922923924925926927928929930931932933934935936937938939940941942943944945946947948949950951952953954955956957958959960961962963964965966967968969970971972973974975976977978979980981982983984985986987988989990991992993994995996997998999100010011002100310041005100610071008100910101011101210131014101510161017101810191020102110221023102410251026102710281029103010311032103310341035103610371038103910401041104210431044104510461047104810491050105110521053105410551056105710581059106010611062106310641065106610671068106910701071107210731074
  1. /* Distributed under the OSI-approved BSD 3-Clause License. See accompanying
  2. file Copyright.txt or https://cmake.org/licensing for details. */
  3. #include "cmCTestRunTest.h"
  4. #include <algorithm>
  5. #include <chrono>
  6. #include <cstddef> // IWYU pragma: keep
  7. #include <cstdint>
  8. #include <cstdio>
  9. #include <cstring>
  10. #include <functional>
  11. #include <iomanip>
  12. #include <ratio>
  13. #include <sstream>
  14. #include <utility>
  15. #include <cm/memory>
  16. #include <cm/optional>
  17. #include <cm/string_view>
  18. #include <cmext/string_view>
  19. #include "cmsys/RegularExpression.hxx"
  20. #include "cmCTest.h"
  21. #include "cmCTestMemCheckHandler.h"
  22. #include "cmCTestMultiProcessHandler.h"
  23. #include "cmProcess.h"
  24. #include "cmStringAlgorithms.h"
  25. #include "cmSystemTools.h"
  26. #include "cmWorkingDirectory.h"
  27. cmCTestRunTest::cmCTestRunTest(cmCTestMultiProcessHandler& multiHandler)
  28. : MultiTestHandler(multiHandler)
  29. {
  30. this->CTest = multiHandler.CTest;
  31. this->TestHandler = multiHandler.TestHandler;
  32. this->TestResult.ExecutionTime = cmDuration::zero();
  33. this->TestResult.ReturnValue = 0;
  34. this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
  35. this->TestResult.TestCount = 0;
  36. this->TestResult.Properties = nullptr;
  37. }
  38. void cmCTestRunTest::CheckOutput(std::string const& line)
  39. {
  40. cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
  41. this->GetIndex() << ": " << line << std::endl);
  42. // Check for special CTest XML tags in this line of output.
  43. // If any are found, this line is excluded from ProcessOutput.
  44. if (!line.empty() && line.find("<CTest") != std::string::npos) {
  45. bool ctest_tag_found = false;
  46. if (this->TestHandler->CustomCompletionStatusRegex.find(line)) {
  47. ctest_tag_found = true;
  48. this->TestResult.CustomCompletionStatus =
  49. this->TestHandler->CustomCompletionStatusRegex.match(1);
  50. cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
  51. this->GetIndex() << ": "
  52. << "Test Details changed to '"
  53. << this->TestResult.CustomCompletionStatus
  54. << "'" << std::endl);
  55. } else if (this->TestHandler->CustomLabelRegex.find(line)) {
  56. ctest_tag_found = true;
  57. auto label = this->TestHandler->CustomLabelRegex.match(1);
  58. auto& labels = this->TestProperties->Labels;
  59. if (std::find(labels.begin(), labels.end(), label) == labels.end()) {
  60. labels.push_back(label);
  61. std::sort(labels.begin(), labels.end());
  62. cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
  63. this->GetIndex()
  64. << ": "
  65. << "Test Label added: '" << label << "'" << std::endl);
  66. }
  67. }
  68. if (ctest_tag_found) {
  69. return;
  70. }
  71. }
  72. this->ProcessOutput += line;
  73. this->ProcessOutput += "\n";
  74. // Check for TIMEOUT_AFTER_MATCH property.
  75. if (!this->TestProperties->TimeoutRegularExpressions.empty()) {
  76. for (auto& reg : this->TestProperties->TimeoutRegularExpressions) {
  77. if (reg.first.find(this->ProcessOutput)) {
  78. cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
  79. this->GetIndex()
  80. << ": "
  81. << "Test timeout changed to "
  82. << std::chrono::duration_cast<std::chrono::seconds>(
  83. this->TestProperties->AlternateTimeout)
  84. .count()
  85. << std::endl);
  86. this->TestProcess->ResetStartTime();
  87. this->TestProcess->ChangeTimeout(
  88. this->TestProperties->AlternateTimeout);
  89. this->TestProperties->TimeoutRegularExpressions.clear();
  90. break;
  91. }
  92. }
  93. }
  94. }
  95. bool cmCTestRunTest::EndTest(size_t completed, size_t total, bool started)
  96. {
  97. this->WriteLogOutputTop(completed, total);
  98. std::string reason;
  99. bool passed = true;
  100. cmProcess::State res =
  101. started ? this->TestProcess->GetProcessStatus() : cmProcess::State::Error;
  102. if (res != cmProcess::State::Expired) {
  103. this->TimeoutIsForStopTime = false;
  104. }
  105. std::int64_t retVal = this->TestProcess->GetExitValue();
  106. bool forceFail = false;
  107. bool forceSkip = false;
  108. bool skipped = false;
  109. bool outputTestErrorsToConsole = false;
  110. if (!this->TestProperties->RequiredRegularExpressions.empty() &&
  111. this->FailedDependencies.empty()) {
  112. bool found = false;
  113. for (auto& pass : this->TestProperties->RequiredRegularExpressions) {
  114. if (pass.first.find(this->ProcessOutput)) {
  115. found = true;
  116. reason = cmStrCat("Required regular expression found. Regex=[",
  117. pass.second, ']');
  118. break;
  119. }
  120. }
  121. if (!found) {
  122. reason = "Required regular expression not found. Regex=[";
  123. for (auto& pass : this->TestProperties->RequiredRegularExpressions) {
  124. reason += pass.second;
  125. reason += "\n";
  126. }
  127. reason += "]";
  128. forceFail = true;
  129. }
  130. }
  131. if (!this->TestProperties->ErrorRegularExpressions.empty() &&
  132. this->FailedDependencies.empty()) {
  133. for (auto& fail : this->TestProperties->ErrorRegularExpressions) {
  134. if (fail.first.find(this->ProcessOutput)) {
  135. reason = cmStrCat("Error regular expression found in output. Regex=[",
  136. fail.second, ']');
  137. forceFail = true;
  138. break;
  139. }
  140. }
  141. }
  142. if (!this->TestProperties->SkipRegularExpressions.empty() &&
  143. this->FailedDependencies.empty()) {
  144. for (auto& skip : this->TestProperties->SkipRegularExpressions) {
  145. if (skip.first.find(this->ProcessOutput)) {
  146. reason = cmStrCat("Skip regular expression found in output. Regex=[",
  147. skip.second, ']');
  148. forceSkip = true;
  149. break;
  150. }
  151. }
  152. }
  153. std::ostringstream outputStream;
  154. if (res == cmProcess::State::Exited) {
  155. bool success = !forceFail &&
  156. (retVal == 0 ||
  157. !this->TestProperties->RequiredRegularExpressions.empty());
  158. if ((this->TestProperties->SkipReturnCode >= 0 &&
  159. this->TestProperties->SkipReturnCode == retVal) ||
  160. forceSkip) {
  161. this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
  162. std::ostringstream s;
  163. if (forceSkip) {
  164. s << "SKIP_REGULAR_EXPRESSION_MATCHED";
  165. } else {
  166. s << "SKIP_RETURN_CODE=" << this->TestProperties->SkipReturnCode;
  167. }
  168. this->TestResult.CompletionStatus = s.str();
  169. outputStream << "***Skipped ";
  170. skipped = true;
  171. } else if (success != this->TestProperties->WillFail) {
  172. this->TestResult.Status = cmCTestTestHandler::COMPLETED;
  173. outputStream << " Passed ";
  174. } else {
  175. this->TestResult.Status = cmCTestTestHandler::FAILED;
  176. outputStream << "***Failed " << reason;
  177. outputTestErrorsToConsole =
  178. this->CTest->GetOutputTestOutputOnTestFailure();
  179. }
  180. } else if (res == cmProcess::State::Expired) {
  181. outputStream << "***Timeout ";
  182. this->TestResult.Status = cmCTestTestHandler::TIMEOUT;
  183. outputTestErrorsToConsole =
  184. this->CTest->GetOutputTestOutputOnTestFailure();
  185. } else if (res == cmProcess::State::Exception) {
  186. outputTestErrorsToConsole =
  187. this->CTest->GetOutputTestOutputOnTestFailure();
  188. outputStream << "***Exception: ";
  189. this->TestResult.ExceptionStatus =
  190. this->TestProcess->GetExitExceptionString();
  191. switch (this->TestProcess->GetExitException()) {
  192. case cmProcess::Exception::Fault:
  193. outputStream << "SegFault";
  194. this->TestResult.Status = cmCTestTestHandler::SEGFAULT;
  195. break;
  196. case cmProcess::Exception::Illegal:
  197. outputStream << "Illegal";
  198. this->TestResult.Status = cmCTestTestHandler::ILLEGAL;
  199. break;
  200. case cmProcess::Exception::Interrupt:
  201. outputStream << "Interrupt";
  202. this->TestResult.Status = cmCTestTestHandler::INTERRUPT;
  203. break;
  204. case cmProcess::Exception::Numerical:
  205. outputStream << "Numerical";
  206. this->TestResult.Status = cmCTestTestHandler::NUMERICAL;
  207. break;
  208. default:
  209. cmCTestLog(this->CTest, HANDLER_OUTPUT,
  210. this->TestResult.ExceptionStatus);
  211. this->TestResult.Status = cmCTestTestHandler::OTHER_FAULT;
  212. }
  213. } else if ("Disabled" == this->TestResult.CompletionStatus) {
  214. outputStream << "***Not Run (Disabled) ";
  215. } else // cmProcess::State::Error
  216. {
  217. outputStream << "***Not Run ";
  218. }
  219. passed = this->TestResult.Status == cmCTestTestHandler::COMPLETED;
  220. char buf[1024];
  221. snprintf(buf, sizeof(buf), "%6.2f sec",
  222. this->TestProcess->GetTotalTime().count());
  223. outputStream << buf << "\n";
  224. bool passedOrSkipped = passed || skipped;
  225. if (this->CTest->GetTestProgressOutput()) {
  226. if (!passedOrSkipped) {
  227. // If the test did not pass, reprint test name and error
  228. std::string output = this->GetTestPrefix(completed, total);
  229. std::string testName = this->TestProperties->Name;
  230. const int maxTestNameWidth = this->CTest->GetMaxTestNameWidth();
  231. testName.resize(maxTestNameWidth + 4, '.');
  232. output += testName;
  233. output += outputStream.str();
  234. outputStream.str("");
  235. outputStream.clear();
  236. outputStream << output;
  237. cmCTestLog(this->CTest, HANDLER_TEST_PROGRESS_OUTPUT, "\n"); // flush
  238. }
  239. if (completed == total) {
  240. std::string testName = this->GetTestPrefix(completed, total) +
  241. this->TestProperties->Name + "\n";
  242. cmCTestLog(this->CTest, HANDLER_TEST_PROGRESS_OUTPUT, testName);
  243. }
  244. }
  245. if (!this->CTest->GetTestProgressOutput() || !passedOrSkipped) {
  246. cmCTestLog(this->CTest, HANDLER_OUTPUT, outputStream.str());
  247. }
  248. if (outputTestErrorsToConsole) {
  249. cmCTestLog(this->CTest, HANDLER_OUTPUT, this->ProcessOutput << std::endl);
  250. }
  251. if (this->TestHandler->LogFile) {
  252. *this->TestHandler->LogFile << "Test time = " << buf << std::endl;
  253. }
  254. this->ParseOutputForMeasurements();
  255. // if this is doing MemCheck then all the output needs to be put into
  256. // Output since that is what is parsed by cmCTestMemCheckHandler
  257. if (!this->TestHandler->MemCheck && started) {
  258. this->TestHandler->CleanTestOutput(
  259. this->ProcessOutput,
  260. static_cast<size_t>(
  261. this->TestResult.Status == cmCTestTestHandler::COMPLETED
  262. ? this->TestHandler->CustomMaximumPassedTestOutputSize
  263. : this->TestHandler->CustomMaximumFailedTestOutputSize),
  264. this->TestHandler->TestOutputTruncation);
  265. }
  266. this->TestResult.Reason = reason;
  267. if (this->TestHandler->LogFile) {
  268. bool pass = true;
  269. const char* reasonType = "Test Pass Reason";
  270. if (this->TestResult.Status != cmCTestTestHandler::COMPLETED &&
  271. this->TestResult.Status != cmCTestTestHandler::NOT_RUN) {
  272. reasonType = "Test Fail Reason";
  273. pass = false;
  274. }
  275. auto ttime = this->TestProcess->GetTotalTime();
  276. auto hours = std::chrono::duration_cast<std::chrono::hours>(ttime);
  277. ttime -= hours;
  278. auto minutes = std::chrono::duration_cast<std::chrono::minutes>(ttime);
  279. ttime -= minutes;
  280. auto seconds = std::chrono::duration_cast<std::chrono::seconds>(ttime);
  281. char buffer[100];
  282. snprintf(buffer, sizeof(buffer), "%02d:%02d:%02d",
  283. static_cast<unsigned>(hours.count()),
  284. static_cast<unsigned>(minutes.count()),
  285. static_cast<unsigned>(seconds.count()));
  286. *this->TestHandler->LogFile
  287. << "----------------------------------------------------------"
  288. << std::endl;
  289. if (!this->TestResult.Reason.empty()) {
  290. *this->TestHandler->LogFile << reasonType << ":\n"
  291. << this->TestResult.Reason << "\n";
  292. } else {
  293. if (pass) {
  294. *this->TestHandler->LogFile << "Test Passed.\n";
  295. } else {
  296. *this->TestHandler->LogFile << "Test Failed.\n";
  297. }
  298. }
  299. *this->TestHandler->LogFile
  300. << "\"" << this->TestProperties->Name
  301. << "\" end time: " << this->CTest->CurrentTime() << std::endl
  302. << "\"" << this->TestProperties->Name << "\" time elapsed: " << buffer
  303. << std::endl
  304. << "----------------------------------------------------------"
  305. << std::endl
  306. << std::endl;
  307. }
  308. // if the test actually started and ran
  309. // record the results in TestResult
  310. if (started) {
  311. std::string compressedOutput;
  312. if (!this->TestHandler->MemCheck &&
  313. this->CTest->ShouldCompressTestOutput()) {
  314. std::string str = this->ProcessOutput;
  315. if (this->CTest->CompressString(str)) {
  316. compressedOutput = std::move(str);
  317. }
  318. }
  319. bool compress = !compressedOutput.empty() &&
  320. compressedOutput.length() < this->ProcessOutput.length();
  321. this->TestResult.Output =
  322. compress ? compressedOutput : this->ProcessOutput;
  323. this->TestResult.CompressOutput = compress;
  324. this->TestResult.ReturnValue = this->TestProcess->GetExitValue();
  325. if (!skipped) {
  326. this->TestResult.CompletionStatus = "Completed";
  327. }
  328. this->TestResult.ExecutionTime = this->TestProcess->GetTotalTime();
  329. this->MemCheckPostProcess();
  330. this->ComputeWeightedCost();
  331. }
  332. // If the test does not need to rerun push the current TestResult onto the
  333. // TestHandler vector
  334. if (!this->NeedsToRepeat()) {
  335. this->TestHandler->TestResults.push_back(this->TestResult);
  336. }
  337. this->TestProcess.reset();
  338. return passed || skipped;
  339. }
  340. bool cmCTestRunTest::StartAgain(std::unique_ptr<cmCTestRunTest> runner,
  341. size_t completed)
  342. {
  343. auto* testRun = runner.get();
  344. if (!testRun->RunAgain) {
  345. return false;
  346. }
  347. testRun->RunAgain = false; // reset
  348. testRun->TestProcess = cm::make_unique<cmProcess>(std::move(runner));
  349. // change to tests directory
  350. cmWorkingDirectory workdir(testRun->TestProperties->Directory);
  351. if (workdir.Failed()) {
  352. testRun->StartFailure("Failed to change working directory to " +
  353. testRun->TestProperties->Directory + " : " +
  354. std::strerror(workdir.GetLastResult()),
  355. "Failed to change working directory");
  356. return true;
  357. }
  358. testRun->StartTest(completed, testRun->TotalNumberOfTests);
  359. return true;
  360. }
  361. bool cmCTestRunTest::NeedsToRepeat()
  362. {
  363. this->NumberOfRunsLeft--;
  364. if (this->NumberOfRunsLeft == 0) {
  365. return false;
  366. }
  367. // If a test is marked as NOT_RUN it will not be repeated
  368. // no matter the repeat settings, so just record it as-is.
  369. if (this->TestResult.Status == cmCTestTestHandler::NOT_RUN) {
  370. return false;
  371. }
  372. // if number of runs left is not 0, and we are running until
  373. // we find a failed (or passed) test, then return true so the test can be
  374. // restarted
  375. if ((this->RepeatMode == cmCTest::Repeat::UntilFail &&
  376. this->TestResult.Status == cmCTestTestHandler::COMPLETED) ||
  377. (this->RepeatMode == cmCTest::Repeat::UntilPass &&
  378. this->TestResult.Status != cmCTestTestHandler::COMPLETED) ||
  379. (this->RepeatMode == cmCTest::Repeat::AfterTimeout &&
  380. this->TestResult.Status == cmCTestTestHandler::TIMEOUT)) {
  381. this->RunAgain = true;
  382. return true;
  383. }
  384. return false;
  385. }
  386. void cmCTestRunTest::ComputeWeightedCost()
  387. {
  388. double prev = static_cast<double>(this->TestProperties->PreviousRuns);
  389. double avgcost = static_cast<double>(this->TestProperties->Cost);
  390. double current = this->TestResult.ExecutionTime.count();
  391. if (this->TestResult.Status == cmCTestTestHandler::COMPLETED) {
  392. this->TestProperties->Cost =
  393. static_cast<float>(((prev * avgcost) + current) / (prev + 1.0));
  394. this->TestProperties->PreviousRuns++;
  395. }
  396. }
  397. void cmCTestRunTest::MemCheckPostProcess()
  398. {
  399. if (!this->TestHandler->MemCheck) {
  400. return;
  401. }
  402. cmCTestOptionalLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
  403. this->Index << ": process test output now: "
  404. << this->TestProperties->Name << " "
  405. << this->TestResult.Name << std::endl,
  406. this->TestHandler->GetQuiet());
  407. cmCTestMemCheckHandler* handler =
  408. static_cast<cmCTestMemCheckHandler*>(this->TestHandler);
  409. handler->PostProcessTest(this->TestResult, this->Index);
  410. }
  411. void cmCTestRunTest::StartFailure(std::unique_ptr<cmCTestRunTest> runner,
  412. std::string const& output,
  413. std::string const& detail)
  414. {
  415. auto* testRun = runner.get();
  416. testRun->TestProcess = cm::make_unique<cmProcess>(std::move(runner));
  417. testRun->StartFailure(output, detail);
  418. testRun->FinalizeTest(false);
  419. }
  420. void cmCTestRunTest::StartFailure(std::string const& output,
  421. std::string const& detail)
  422. {
  423. // Still need to log the Start message so the test summary records our
  424. // attempt to start this test
  425. if (!this->CTest->GetTestProgressOutput()) {
  426. cmCTestLog(this->CTest, HANDLER_OUTPUT,
  427. std::setw(2 * getNumWidth(this->TotalNumberOfTests) + 8)
  428. << "Start "
  429. << std::setw(getNumWidth(this->TestHandler->GetMaxIndex()))
  430. << this->TestProperties->Index << ": "
  431. << this->TestProperties->Name << std::endl);
  432. }
  433. this->ProcessOutput.clear();
  434. if (!output.empty()) {
  435. *this->TestHandler->LogFile << output << std::endl;
  436. cmCTestLog(this->CTest, ERROR_MESSAGE, output << std::endl);
  437. }
  438. this->TestResult.Properties = this->TestProperties;
  439. this->TestResult.ExecutionTime = cmDuration::zero();
  440. this->TestResult.CompressOutput = false;
  441. this->TestResult.ReturnValue = -1;
  442. this->TestResult.CompletionStatus = detail;
  443. this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
  444. this->TestResult.TestCount = this->TestProperties->Index;
  445. this->TestResult.Name = this->TestProperties->Name;
  446. this->TestResult.Path = this->TestProperties->Directory;
  447. this->TestResult.Output = output;
  448. this->TestResult.FullCommandLine.clear();
  449. this->TestResult.Environment.clear();
  450. }
  451. std::string cmCTestRunTest::GetTestPrefix(size_t completed, size_t total) const
  452. {
  453. std::ostringstream outputStream;
  454. outputStream << std::setw(getNumWidth(total)) << completed << "/";
  455. outputStream << std::setw(getNumWidth(total)) << total << " ";
  456. if (this->TestHandler->MemCheck) {
  457. outputStream << "MemCheck";
  458. } else {
  459. outputStream << "Test";
  460. }
  461. std::ostringstream indexStr;
  462. indexStr << " #" << this->Index << ":";
  463. outputStream << std::setw(3 + getNumWidth(this->TestHandler->GetMaxIndex()))
  464. << indexStr.str();
  465. outputStream << " ";
  466. return outputStream.str();
  467. }
  468. bool cmCTestRunTest::StartTest(std::unique_ptr<cmCTestRunTest> runner,
  469. size_t completed, size_t total)
  470. {
  471. auto* testRun = runner.get();
  472. testRun->TestProcess = cm::make_unique<cmProcess>(std::move(runner));
  473. if (!testRun->StartTest(completed, total)) {
  474. testRun->FinalizeTest(false);
  475. return false;
  476. }
  477. return true;
  478. }
  479. // Starts the execution of a test. Returns once it has started
  480. bool cmCTestRunTest::StartTest(size_t completed, size_t total)
  481. {
  482. this->TotalNumberOfTests = total; // save for rerun case
  483. if (!this->CTest->GetTestProgressOutput()) {
  484. cmCTestLog(this->CTest, HANDLER_OUTPUT,
  485. std::setw(2 * getNumWidth(total) + 8)
  486. << "Start "
  487. << std::setw(getNumWidth(this->TestHandler->GetMaxIndex()))
  488. << this->TestProperties->Index << ": "
  489. << this->TestProperties->Name << std::endl);
  490. } else {
  491. std::string testName = this->GetTestPrefix(completed, total) +
  492. this->TestProperties->Name + "\n";
  493. cmCTestLog(this->CTest, HANDLER_TEST_PROGRESS_OUTPUT, testName);
  494. }
  495. this->ProcessOutput.clear();
  496. this->TestResult.Properties = this->TestProperties;
  497. this->TestResult.ExecutionTime = cmDuration::zero();
  498. this->TestResult.CompressOutput = false;
  499. this->TestResult.ReturnValue = -1;
  500. this->TestResult.TestCount = this->TestProperties->Index;
  501. this->TestResult.Name = this->TestProperties->Name;
  502. this->TestResult.Path = this->TestProperties->Directory;
  503. // Return immediately if test is disabled
  504. if (this->TestProperties->Disabled) {
  505. this->TestResult.CompletionStatus = "Disabled";
  506. this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
  507. this->TestResult.Output = "Disabled";
  508. this->TestResult.FullCommandLine.clear();
  509. this->TestResult.Environment.clear();
  510. return false;
  511. }
  512. this->TestResult.CompletionStatus = "Failed to start";
  513. this->TestResult.Status = cmCTestTestHandler::BAD_COMMAND;
  514. // Check for failed fixture dependencies before we even look at the command
  515. // arguments because if we are not going to run the test, the command and
  516. // its arguments are irrelevant. This matters for the case where a fixture
  517. // dependency might be creating the executable we want to run.
  518. if (!this->FailedDependencies.empty()) {
  519. std::string msg = "Failed test dependencies:";
  520. for (std::string const& failedDep : this->FailedDependencies) {
  521. msg += " " + failedDep;
  522. }
  523. *this->TestHandler->LogFile << msg << std::endl;
  524. cmCTestLog(this->CTest, HANDLER_OUTPUT, msg << std::endl);
  525. this->TestResult.Output = msg;
  526. this->TestResult.FullCommandLine.clear();
  527. this->TestResult.Environment.clear();
  528. this->TestResult.CompletionStatus = "Fixture dependency failed";
  529. this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
  530. return false;
  531. }
  532. this->ComputeArguments();
  533. std::vector<std::string>& args = this->TestProperties->Args;
  534. if (args.size() >= 2 && args[1] == "NOT_AVAILABLE") {
  535. std::string msg;
  536. if (this->CTest->GetConfigType().empty()) {
  537. msg = "Test not available without configuration. (Missing \"-C "
  538. "<config>\"?)";
  539. } else {
  540. msg = cmStrCat("Test not available in configuration \"",
  541. this->CTest->GetConfigType(), "\".");
  542. }
  543. *this->TestHandler->LogFile << msg << std::endl;
  544. cmCTestLog(this->CTest, ERROR_MESSAGE, msg << std::endl);
  545. this->TestResult.Output = msg;
  546. this->TestResult.FullCommandLine.clear();
  547. this->TestResult.Environment.clear();
  548. this->TestResult.CompletionStatus = "Missing Configuration";
  549. this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
  550. return false;
  551. }
  552. // Check if all required files exist
  553. for (std::string const& file : this->TestProperties->RequiredFiles) {
  554. if (!cmSystemTools::FileExists(file)) {
  555. // Required file was not found
  556. *this->TestHandler->LogFile << "Unable to find required file: " << file
  557. << std::endl;
  558. cmCTestLog(this->CTest, ERROR_MESSAGE,
  559. "Unable to find required file: " << file << std::endl);
  560. this->TestResult.Output = "Unable to find required file: " + file;
  561. this->TestResult.FullCommandLine.clear();
  562. this->TestResult.Environment.clear();
  563. this->TestResult.CompletionStatus = "Required Files Missing";
  564. this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
  565. return false;
  566. }
  567. }
  568. // log and return if we did not find the executable
  569. if (this->ActualCommand.empty()) {
  570. // if the command was not found create a TestResult object
  571. // that has that information
  572. *this->TestHandler->LogFile << "Unable to find executable: " << args[1]
  573. << std::endl;
  574. cmCTestLog(this->CTest, ERROR_MESSAGE,
  575. "Unable to find executable: " << args[1] << std::endl);
  576. this->TestResult.Output = "Unable to find executable: " + args[1];
  577. this->TestResult.FullCommandLine.clear();
  578. this->TestResult.Environment.clear();
  579. this->TestResult.CompletionStatus = "Unable to find executable";
  580. this->TestResult.Status = cmCTestTestHandler::NOT_RUN;
  581. return false;
  582. }
  583. this->StartTime = this->CTest->CurrentTime();
  584. auto timeout = this->TestProperties->Timeout;
  585. this->TimeoutIsForStopTime = false;
  586. std::chrono::system_clock::time_point stop_time = this->CTest->GetStopTime();
  587. if (stop_time != std::chrono::system_clock::time_point()) {
  588. std::chrono::duration<double> stop_timeout =
  589. (stop_time - std::chrono::system_clock::now()) % std::chrono::hours(24);
  590. if (stop_timeout <= std::chrono::duration<double>::zero()) {
  591. stop_timeout = std::chrono::duration<double>::zero();
  592. }
  593. if (timeout == std::chrono::duration<double>::zero() ||
  594. stop_timeout < timeout) {
  595. this->TimeoutIsForStopTime = true;
  596. timeout = stop_timeout;
  597. }
  598. }
  599. return this->ForkProcess(timeout, this->TestProperties->ExplicitTimeout,
  600. &this->TestProperties->Environment,
  601. &this->TestProperties->EnvironmentModification,
  602. &this->TestProperties->Affinity);
  603. }
  604. void cmCTestRunTest::ComputeArguments()
  605. {
  606. this->Arguments.clear(); // reset because this might be a rerun
  607. auto j = this->TestProperties->Args.begin();
  608. ++j; // skip test name
  609. // find the test executable
  610. if (this->TestHandler->MemCheck) {
  611. cmCTestMemCheckHandler* handler =
  612. static_cast<cmCTestMemCheckHandler*>(this->TestHandler);
  613. this->ActualCommand = handler->MemoryTester;
  614. this->TestProperties->Args[1] =
  615. this->TestHandler->FindTheExecutable(this->TestProperties->Args[1]);
  616. } else {
  617. this->ActualCommand =
  618. this->TestHandler->FindTheExecutable(this->TestProperties->Args[1]);
  619. ++j; // skip the executable (it will be actualCommand)
  620. }
  621. std::string testCommand =
  622. cmSystemTools::ConvertToOutputPath(this->ActualCommand);
  623. // Prepends memcheck args to our command string
  624. this->TestHandler->GenerateTestCommand(this->Arguments, this->Index);
  625. for (std::string const& arg : this->Arguments) {
  626. testCommand += " \"";
  627. testCommand += arg;
  628. testCommand += "\"";
  629. }
  630. for (; j != this->TestProperties->Args.end(); ++j) {
  631. testCommand += " \"";
  632. testCommand += *j;
  633. testCommand += "\"";
  634. this->Arguments.push_back(*j);
  635. }
  636. this->TestResult.FullCommandLine = testCommand;
  637. // Print the test command in verbose mode
  638. cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
  639. std::endl
  640. << this->Index << ": "
  641. << (this->TestHandler->MemCheck ? "MemCheck" : "Test")
  642. << " command: " << testCommand << std::endl);
  643. // Print any test-specific env vars in verbose mode
  644. if (!this->TestProperties->Environment.empty()) {
  645. cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
  646. this->Index << ": "
  647. << "Environment variables: " << std::endl);
  648. }
  649. for (std::string const& env : this->TestProperties->Environment) {
  650. cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
  651. this->Index << ": " << env << std::endl);
  652. }
  653. if (!this->TestProperties->EnvironmentModification.empty()) {
  654. cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
  655. this->Index << ": "
  656. << "Environment variable modifications: "
  657. << std::endl);
  658. }
  659. for (std::string const& envmod :
  660. this->TestProperties->EnvironmentModification) {
  661. cmCTestLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
  662. this->Index << ": " << envmod << std::endl);
  663. }
  664. }
  665. void cmCTestRunTest::ParseOutputForMeasurements()
  666. {
  667. if (!this->ProcessOutput.empty() &&
  668. (this->ProcessOutput.find("<DartMeasurement") != std::string::npos ||
  669. this->ProcessOutput.find("<CTestMeasurement") != std::string::npos)) {
  670. if (this->TestHandler->AllTestMeasurementsRegex.find(
  671. this->ProcessOutput)) {
  672. this->TestResult.TestMeasurementsOutput =
  673. this->TestHandler->AllTestMeasurementsRegex.match(1);
  674. // keep searching and replacing until none are left
  675. while (this->TestHandler->SingleTestMeasurementRegex.find(
  676. this->ProcessOutput)) {
  677. // replace the exact match for the string
  678. cmSystemTools::ReplaceString(
  679. this->ProcessOutput,
  680. this->TestHandler->SingleTestMeasurementRegex.match(1).c_str(), "");
  681. }
  682. }
  683. }
  684. }
  685. bool cmCTestRunTest::ForkProcess(
  686. cmDuration testTimeOut, bool explicitTimeout,
  687. std::vector<std::string>* environment,
  688. std::vector<std::string>* environment_modification,
  689. std::vector<size_t>* affinity)
  690. {
  691. this->TestProcess->SetId(this->Index);
  692. this->TestProcess->SetWorkingDirectory(this->TestProperties->Directory);
  693. this->TestProcess->SetCommand(this->ActualCommand);
  694. this->TestProcess->SetCommandArguments(this->Arguments);
  695. // determine how much time we have
  696. cmDuration timeout = this->CTest->GetRemainingTimeAllowed();
  697. if (timeout != cmCTest::MaxDuration()) {
  698. timeout -= std::chrono::minutes(2);
  699. }
  700. if (this->CTest->GetTimeOut() > cmDuration::zero() &&
  701. this->CTest->GetTimeOut() < timeout) {
  702. timeout = this->CTest->GetTimeOut();
  703. }
  704. if (testTimeOut > cmDuration::zero() &&
  705. testTimeOut < this->CTest->GetRemainingTimeAllowed()) {
  706. timeout = testTimeOut;
  707. }
  708. // always have at least 1 second if we got to here
  709. if (timeout <= cmDuration::zero()) {
  710. timeout = std::chrono::seconds(1);
  711. }
  712. // handle timeout explicitly set to 0
  713. if (testTimeOut == cmDuration::zero() && explicitTimeout) {
  714. timeout = cmDuration::zero();
  715. }
  716. cmCTestOptionalLog(this->CTest, HANDLER_VERBOSE_OUTPUT,
  717. this->Index << ": "
  718. << "Test timeout computed to be: "
  719. << cmDurationTo<unsigned int>(timeout)
  720. << "\n",
  721. this->TestHandler->GetQuiet());
  722. this->TestProcess->SetTimeout(timeout);
  723. #ifndef CMAKE_BOOTSTRAP
  724. cmSystemTools::SaveRestoreEnvironment sre;
  725. #endif
  726. std::ostringstream envMeasurement;
  727. if (environment && !environment->empty()) {
  728. // Environment modification works on the assumption that the environment is
  729. // actually modified here. If another strategy is used, there will need to
  730. // be updates below in `apply_diff`.
  731. cmSystemTools::AppendEnv(*environment);
  732. for (auto const& var : *environment) {
  733. envMeasurement << var << std::endl;
  734. }
  735. }
  736. if (environment_modification && !environment_modification->empty()) {
  737. std::map<std::string, cm::optional<std::string>> env_application;
  738. #ifdef _WIN32
  739. char path_sep = ';';
  740. #else
  741. char path_sep = ':';
  742. #endif
  743. auto apply_diff =
  744. [&env_application](const std::string& name,
  745. std::function<void(std::string&)> const& apply) {
  746. cm::optional<std::string> old_value = env_application[name];
  747. std::string output;
  748. if (old_value) {
  749. output = *old_value;
  750. } else {
  751. // This only works because the environment is actually modified above
  752. // (`AppendEnv`). If CTest ever just creates an environment block
  753. // directly, that block will need to be queried for the subprocess'
  754. // value instead.
  755. const char* curval = cmSystemTools::GetEnv(name);
  756. if (curval) {
  757. output = curval;
  758. }
  759. }
  760. apply(output);
  761. env_application[name] = output;
  762. };
  763. bool err_occurred = false;
  764. for (auto const& envmod : *environment_modification) {
  765. // Split on `=`
  766. auto const eq_loc = envmod.find_first_of('=');
  767. if (eq_loc == std::string::npos) {
  768. cmCTestLog(this->CTest, ERROR_MESSAGE,
  769. "Error: Missing `=` after the variable name in: "
  770. << envmod << std::endl);
  771. err_occurred = true;
  772. continue;
  773. }
  774. auto const name = envmod.substr(0, eq_loc);
  775. // Split value on `:`
  776. auto const op_value_start = eq_loc + 1;
  777. auto const colon_loc = envmod.find_first_of(':', op_value_start);
  778. if (colon_loc == std::string::npos) {
  779. cmCTestLog(this->CTest, ERROR_MESSAGE,
  780. "Error: Missing `:` after the operation in: " << envmod
  781. << std::endl);
  782. err_occurred = true;
  783. continue;
  784. }
  785. auto const op =
  786. envmod.substr(op_value_start, colon_loc - op_value_start);
  787. auto const value_start = colon_loc + 1;
  788. auto const value = envmod.substr(value_start);
  789. // Determine what to do with the operation.
  790. if (op == "reset"_s) {
  791. auto entry = env_application.find(name);
  792. if (entry != env_application.end()) {
  793. env_application.erase(entry);
  794. }
  795. } else if (op == "set"_s) {
  796. env_application[name] = value;
  797. } else if (op == "unset"_s) {
  798. env_application[name] = {};
  799. } else if (op == "string_append"_s) {
  800. apply_diff(name, [&value](std::string& output) { output += value; });
  801. } else if (op == "string_prepend"_s) {
  802. apply_diff(name,
  803. [&value](std::string& output) { output.insert(0, value); });
  804. } else if (op == "path_list_append"_s) {
  805. apply_diff(name, [&value, path_sep](std::string& output) {
  806. if (!output.empty()) {
  807. output += path_sep;
  808. }
  809. output += value;
  810. });
  811. } else if (op == "path_list_prepend"_s) {
  812. apply_diff(name, [&value, path_sep](std::string& output) {
  813. if (!output.empty()) {
  814. output.insert(output.begin(), path_sep);
  815. }
  816. output.insert(0, value);
  817. });
  818. } else if (op == "cmake_list_append"_s) {
  819. apply_diff(name, [&value](std::string& output) {
  820. if (!output.empty()) {
  821. output += ';';
  822. }
  823. output += value;
  824. });
  825. } else if (op == "cmake_list_prepend"_s) {
  826. apply_diff(name, [&value](std::string& output) {
  827. if (!output.empty()) {
  828. output.insert(output.begin(), ';');
  829. }
  830. output.insert(0, value);
  831. });
  832. } else {
  833. cmCTestLog(this->CTest, ERROR_MESSAGE,
  834. "Error: Unrecognized environment manipulation argument: "
  835. << op << std::endl);
  836. err_occurred = true;
  837. continue;
  838. }
  839. }
  840. if (err_occurred) {
  841. return false;
  842. }
  843. for (auto const& env_apply : env_application) {
  844. if (env_apply.second) {
  845. auto const env_update =
  846. cmStrCat(env_apply.first, '=', *env_apply.second);
  847. cmSystemTools::PutEnv(env_update);
  848. envMeasurement << env_update << std::endl;
  849. } else {
  850. cmSystemTools::UnsetEnv(env_apply.first.c_str());
  851. // Signify that this variable is being actively unset
  852. envMeasurement << "#" << env_apply.first << "=" << std::endl;
  853. }
  854. }
  855. }
  856. if (this->UseAllocatedResources) {
  857. std::vector<std::string> envLog;
  858. this->SetupResourcesEnvironment(&envLog);
  859. for (auto const& var : envLog) {
  860. envMeasurement << var << std::endl;
  861. }
  862. } else {
  863. cmSystemTools::UnsetEnv("CTEST_RESOURCE_GROUP_COUNT");
  864. // Signify that this variable is being actively unset
  865. envMeasurement << "#CTEST_RESOURCE_GROUP_COUNT=" << std::endl;
  866. }
  867. this->TestResult.Environment = envMeasurement.str();
  868. // Remove last newline
  869. this->TestResult.Environment.erase(this->TestResult.Environment.length() -
  870. 1);
  871. return this->TestProcess->StartProcess(this->MultiTestHandler.Loop,
  872. affinity);
  873. }
  874. void cmCTestRunTest::SetupResourcesEnvironment(std::vector<std::string>* log)
  875. {
  876. std::string processCount = "CTEST_RESOURCE_GROUP_COUNT=";
  877. processCount += std::to_string(this->AllocatedResources.size());
  878. cmSystemTools::PutEnv(processCount);
  879. if (log) {
  880. log->push_back(processCount);
  881. }
  882. std::size_t i = 0;
  883. for (auto const& process : this->AllocatedResources) {
  884. std::string prefix = "CTEST_RESOURCE_GROUP_";
  885. prefix += std::to_string(i);
  886. std::string resourceList = prefix + '=';
  887. prefix += '_';
  888. bool firstType = true;
  889. for (auto const& it : process) {
  890. if (!firstType) {
  891. resourceList += ',';
  892. }
  893. firstType = false;
  894. auto resourceType = it.first;
  895. resourceList += resourceType;
  896. std::string var = prefix + cmSystemTools::UpperCase(resourceType) + '=';
  897. bool firstName = true;
  898. for (auto const& it2 : it.second) {
  899. if (!firstName) {
  900. var += ';';
  901. }
  902. firstName = false;
  903. var += "id:" + it2.Id + ",slots:" + std::to_string(it2.Slots);
  904. }
  905. cmSystemTools::PutEnv(var);
  906. if (log) {
  907. log->push_back(var);
  908. }
  909. }
  910. cmSystemTools::PutEnv(resourceList);
  911. if (log) {
  912. log->push_back(resourceList);
  913. }
  914. ++i;
  915. }
  916. }
  917. void cmCTestRunTest::WriteLogOutputTop(size_t completed, size_t total)
  918. {
  919. std::ostringstream outputStream;
  920. // If this is the last or only run of this test, or progress output is
  921. // requested, then print out completed / total.
  922. // Only issue is if a test fails and we are running until fail
  923. // then it will never print out the completed / total, same would
  924. // got for run until pass. Trick is when this is called we don't
  925. // yet know if we are passing or failing.
  926. bool const progressOnLast =
  927. (this->RepeatMode != cmCTest::Repeat::UntilPass &&
  928. this->RepeatMode != cmCTest::Repeat::AfterTimeout);
  929. if ((progressOnLast && this->NumberOfRunsLeft == 1) ||
  930. (!progressOnLast && this->NumberOfRunsLeft == this->NumberOfRunsTotal) ||
  931. this->CTest->GetTestProgressOutput()) {
  932. outputStream << std::setw(getNumWidth(total)) << completed << "/";
  933. outputStream << std::setw(getNumWidth(total)) << total << " ";
  934. }
  935. // if this is one of several runs of a test just print blank space
  936. // to keep things neat
  937. else {
  938. outputStream << std::setw(getNumWidth(total)) << " ";
  939. outputStream << std::setw(getNumWidth(total)) << " ";
  940. }
  941. if (this->TestHandler->MemCheck) {
  942. outputStream << "MemCheck";
  943. } else {
  944. outputStream << "Test";
  945. }
  946. std::ostringstream indexStr;
  947. indexStr << " #" << this->Index << ":";
  948. outputStream << std::setw(3 + getNumWidth(this->TestHandler->GetMaxIndex()))
  949. << indexStr.str();
  950. outputStream << " ";
  951. const int maxTestNameWidth = this->CTest->GetMaxTestNameWidth();
  952. std::string outname = this->TestProperties->Name + " ";
  953. outname.resize(maxTestNameWidth + 4, '.');
  954. outputStream << outname;
  955. *this->TestHandler->LogFile << this->TestProperties->Index << "/"
  956. << this->TestHandler->TotalNumberOfTests
  957. << " Testing: " << this->TestProperties->Name
  958. << std::endl;
  959. *this->TestHandler->LogFile << this->TestProperties->Index << "/"
  960. << this->TestHandler->TotalNumberOfTests
  961. << " Test: " << this->TestProperties->Name
  962. << std::endl;
  963. *this->TestHandler->LogFile << "Command: \"" << this->ActualCommand << "\"";
  964. for (std::string const& arg : this->Arguments) {
  965. *this->TestHandler->LogFile << " \"" << arg << "\"";
  966. }
  967. *this->TestHandler->LogFile
  968. << std::endl
  969. << "Directory: " << this->TestProperties->Directory << std::endl
  970. << "\"" << this->TestProperties->Name
  971. << "\" start time: " << this->StartTime << std::endl;
  972. *this->TestHandler->LogFile
  973. << "Output:" << std::endl
  974. << "----------------------------------------------------------"
  975. << std::endl;
  976. *this->TestHandler->LogFile << this->ProcessOutput << "<end of output>"
  977. << std::endl;
  978. if (!this->CTest->GetTestProgressOutput()) {
  979. cmCTestLog(this->CTest, HANDLER_OUTPUT, outputStream.str());
  980. }
  981. cmCTestLog(this->CTest, DEBUG,
  982. "Testing " << this->TestProperties->Name << " ... ");
  983. }
  984. void cmCTestRunTest::FinalizeTest(bool started)
  985. {
  986. this->MultiTestHandler.FinishTestProcess(this->TestProcess->GetRunner(),
  987. started);
  988. }