src/base/test/launcher/test_launcher.cc

   1 // Copyright 2013 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "base/test/launcher/test_launcher.h"
   6
   7 #if defined(OS_POSIX)
   8 #include <fcntl.h>
   9 #endif
  10
  11 #include "base/at_exit.h"
  12 #include "base/bind.h"
  13 #include "base/command_line.h"
  14 #include "base/environment.h"
  15 #include "base/files/file_path.h"
  16 #include "base/files/file_util.h"
  17 #include "base/files/scoped_file.h"
  18 #include "base/format_macros.h"
  19 #include "base/hash.h"
  20 #include "base/lazy_instance.h"
  21 #include "base/logging.h"
  22 #include "base/memory/scoped_ptr.h"
  23 #include "base/message_loop/message_loop.h"
  24 #include "base/process/kill.h"
  25 #include "base/process/launch.h"
  26 #include "base/strings/string_number_conversions.h"
  27 #include "base/strings/string_split.h"
  28 #include "base/strings/string_util.h"
  29 #include "base/strings/stringize_macros.h"
  30 #include "base/strings/stringprintf.h"
  31 #include "base/strings/utf_string_conversions.h"
  32 #include "base/test/launcher/test_results_tracker.h"
  33 #include "base/test/sequenced_worker_pool_owner.h"
  34 #include "base/test/test_switches.h"
  35 #include "base/test/test_timeouts.h"
  36 #include "base/threading/thread_checker.h"
  37 #include "base/time/time.h"
  38 #include "testing/gtest/include/gtest/gtest.h"
  39
  40 #if defined(OS_MACOSX)
  41 #include "base/mac/scoped_nsautorelease_pool.h"
  42 #endif
  43
  44 #if defined(OS_WIN)
  45 #include "base/win/windows_version.h"
  46 #endif
  47
  48 namespace base {
  49
  50 // Launches a child process using |command_line|. If the child process is still
  51 // running after |timeout|, it is terminated and |*was_timeout| is set to true.
  52 // Returns exit code of the process.
  53 int LaunchChildTestProcessWithOptions(const CommandLine& command_line,
  54                                       const LaunchOptions& options,
  55                                       int flags,
  56                                       base::TimeDelta timeout,
  57                                       bool* was_timeout);
  58
  59 // See https://groups.google.com/a/chromium.org/d/msg/chromium-dev/nkdTP7sstSc/uT3FaE_sgkAJ .
  60 using ::operator<<;
  61
  62 // The environment variable name for the total number of test shards.
  63 const char kTestTotalShards[] = "GTEST_TOTAL_SHARDS";
  64 // The environment variable name for the test shard index.
  65 const char kTestShardIndex[] = "GTEST_SHARD_INDEX";
  66
  67 namespace {
  68
  69 // Global tag for test runs where the results are incomplete or unreliable
  70 // for any reason, e.g. early exit because of too many broken tests.
  71 const char kUnreliableResultsTag[] = "UNRELIABLE_RESULTS";
  72
  73 // Maximum time of no output after which we print list of processes still
  74 // running. This deliberately doesn't use TestTimeouts (which is otherwise
  75 // a recommended solution), because they can be increased. This would defeat
  76 // the purpose of this timeout, which is 1) to avoid buildbot "no output for
  77 // X seconds" timeout killing the process 2) help communicate status of
  78 // the test launcher to people looking at the output (no output for a long
  79 // time is mysterious and gives no info about what is happening) 3) help
  80 // debugging in case the process hangs anyway.
  81 const int kOutputTimeoutSeconds = 15;
  82
  83 // Limit of output snippet lines when printing to stdout.
  84 // Avoids flooding the logs with amount of output that gums up
  85 // the infrastructure.
  86 const size_t kOutputSnippetLinesLimit = 5000;
  87
  88 // Set of live launch test processes with corresponding lock (it is allowed
  89 // for callers to launch processes on different threads).
  90 LazyInstance<std::map<ProcessHandle, CommandLine> > g_live_processes
  91     = LAZY_INSTANCE_INITIALIZER;
  92 LazyInstance<Lock> g_live_processes_lock = LAZY_INSTANCE_INITIALIZER;
  93
  94 #if defined(OS_POSIX)
  95 // Self-pipe that makes it possible to do complex shutdown handling
  96 // outside of the signal handler.
  97 int g_shutdown_pipe[2] = { -1, -1 };
  98
  99 void ShutdownPipeSignalHandler(int signal) {
 100   HANDLE_EINTR(write(g_shutdown_pipe[1], "q", 1));
 101 }
 102
 103 void KillSpawnedTestProcesses() {
 104   // Keep the lock until exiting the process to prevent further processes
 105   // from being spawned.
 106   AutoLock lock(g_live_processes_lock.Get());
 107
 108   fprintf(stdout,
 109           "Sending SIGTERM to %" PRIuS " child processes... ",
 110           g_live_processes.Get().size());
 111   fflush(stdout);
 112
 113   for (std::map<ProcessHandle, CommandLine>::iterator i =
 114            g_live_processes.Get().begin();
 115        i != g_live_processes.Get().end();
 116        ++i) {
 117     // Send the signal to entire process group.
 118     kill((-1) * (i->first), SIGTERM);
 119   }
 120
 121   fprintf(stdout,
 122           "done.\nGiving processes a chance to terminate cleanly... ");
 123   fflush(stdout);
 124
 125   PlatformThread::Sleep(TimeDelta::FromMilliseconds(500));
 126
 127   fprintf(stdout, "done.\n");
 128   fflush(stdout);
 129
 130   fprintf(stdout,
 131           "Sending SIGKILL to %" PRIuS " child processes... ",
 132           g_live_processes.Get().size());
 133   fflush(stdout);
 134
 135   for (std::map<ProcessHandle, CommandLine>::iterator i =
 136            g_live_processes.Get().begin();
 137        i != g_live_processes.Get().end();
 138        ++i) {
 139     // Send the signal to entire process group.
 140     kill((-1) * (i->first), SIGKILL);
 141   }
 142
 143   fprintf(stdout, "done.\n");
 144   fflush(stdout);
 145 }
 146
 147 // I/O watcher for the reading end of the self-pipe above.
 148 // Terminates any launched child processes and exits the process.
 149 class SignalFDWatcher : public MessageLoopForIO::Watcher {
 150  public:
 151   SignalFDWatcher() {
 152   }
 153
 154   virtual void OnFileCanReadWithoutBlocking(int fd) OVERRIDE {
 155     fprintf(stdout, "\nCaught signal. Killing spawned test processes...\n");
 156     fflush(stdout);
 157
 158     KillSpawnedTestProcesses();
 159
 160     // The signal would normally kill the process, so exit now.
 161     exit(1);
 162   }
 163
 164   virtual void OnFileCanWriteWithoutBlocking(int fd) OVERRIDE {
 165     NOTREACHED();
 166   }
 167
 168  private:
 169   DISALLOW_COPY_AND_ASSIGN(SignalFDWatcher);
 170 };
 171 #endif  // defined(OS_POSIX)
 172
 173 // Parses the environment variable var as an Int32.  If it is unset, returns
 174 // true.  If it is set, unsets it then converts it to Int32 before
 175 // returning it in |result|.  Returns true on success.
 176 bool TakeInt32FromEnvironment(const char* const var, int32* result) {
 177   scoped_ptr<Environment> env(Environment::Create());
 178   std::string str_val;
 179
 180   if (!env->GetVar(var, &str_val))
 181     return true;
 182
 183   if (!env->UnSetVar(var)) {
 184     LOG(ERROR) << "Invalid environment: we could not unset " << var << ".\n";
 185     return false;
 186   }
 187
 188   if (!StringToInt(str_val, result)) {
 189     LOG(ERROR) << "Invalid environment: " << var << " is not an integer.\n";
 190     return false;
 191   }
 192
 193   return true;
 194 }
 195
 196 // Unsets the environment variable |name| and returns true on success.
 197 // Also returns true if the variable just doesn't exist.
 198 bool UnsetEnvironmentVariableIfExists(const std::string& name) {
 199   scoped_ptr<Environment> env(Environment::Create());
 200   std::string str_val;
 201
 202   if (!env->GetVar(name.c_str(), &str_val))
 203     return true;
 204
 205   return env->UnSetVar(name.c_str());
 206 }
 207
 208 // Returns true if bot mode has been requested, i.e. defaults optimized
 209 // for continuous integration bots. This way developers don't have to remember
 210 // special command-line flags.
 211 bool BotModeEnabled() {
 212   scoped_ptr<Environment> env(Environment::Create());
 213   return CommandLine::ForCurrentProcess()->HasSwitch(
 214       switches::kTestLauncherBotMode) ||
 215       env->HasVar("CHROMIUM_TEST_LAUNCHER_BOT_MODE");
 216 }
 217
 218 void RunCallback(
 219     const TestLauncher::LaunchChildGTestProcessCallback& callback,
 220     int exit_code,
 221     const TimeDelta& elapsed_time,
 222     bool was_timeout,
 223     const std::string& output) {
 224   callback.Run(exit_code, elapsed_time, was_timeout, output);
 225 }
 226
 227 void DoLaunchChildTestProcess(
 228     const CommandLine& command_line,
 229     base::TimeDelta timeout,
 230     int flags,
 231     bool redirect_stdio,
 232     scoped_refptr<MessageLoopProxy> message_loop_proxy,
 233     const TestLauncher::LaunchChildGTestProcessCallback& callback) {
 234   TimeTicks start_time = TimeTicks::Now();
 235
 236   // Redirect child process output to a file.
 237   base::FilePath output_file;
 238   CHECK(base::CreateTemporaryFile(&output_file));
 239
 240   LaunchOptions options;
 241 #if defined(OS_WIN)
 242   win::ScopedHandle handle;
 243
 244   if (redirect_stdio) {
 245     // Make the file handle inheritable by the child.
 246     SECURITY_ATTRIBUTES sa_attr;
 247     sa_attr.nLength = sizeof(SECURITY_ATTRIBUTES);
 248     sa_attr.lpSecurityDescriptor = NULL;
 249     sa_attr.bInheritHandle = TRUE;
 250
 251     handle.Set(CreateFile(output_file.value().c_str(),
 252                           GENERIC_WRITE,
 253                           FILE_SHARE_READ | FILE_SHARE_DELETE,
 254                           &sa_attr,
 255                           OPEN_EXISTING,
 256                           FILE_ATTRIBUTE_TEMPORARY,
 257                           NULL));
 258     CHECK(handle.IsValid());
 259     options.inherit_handles = true;
 260     options.stdin_handle = INVALID_HANDLE_VALUE;
 261     options.stdout_handle = handle.Get();
 262     options.stderr_handle = handle.Get();
 263   }
 264 #elif defined(OS_POSIX)
 265   options.new_process_group = true;
 266
 267   base::FileHandleMappingVector fds_mapping;
 268   base::ScopedFD output_file_fd;
 269
 270   if (redirect_stdio) {
 271     output_file_fd.reset(open(output_file.value().c_str(), O_RDWR));
 272     CHECK(output_file_fd.is_valid());
 273
 274     fds_mapping.push_back(std::make_pair(output_file_fd.get(), STDOUT_FILENO));
 275     fds_mapping.push_back(std::make_pair(output_file_fd.get(), STDERR_FILENO));
 276     options.fds_to_remap = &fds_mapping;
 277   }
 278 #endif
 279
 280   bool was_timeout = false;
 281   int exit_code = LaunchChildTestProcessWithOptions(
 282       command_line, options, flags, timeout, &was_timeout);
 283
 284   if (redirect_stdio) {
 285 #if defined(OS_WIN)
 286     FlushFileBuffers(handle.Get());
 287     handle.Close();
 288 #elif defined(OS_POSIX)
 289     output_file_fd.reset();
 290 #endif
 291   }
 292
 293   std::string output_file_contents;
 294   CHECK(base::ReadFileToString(output_file, &output_file_contents));
 295
 296   if (!base::DeleteFile(output_file, false)) {
 297     // This needs to be non-fatal at least for Windows.
 298     LOG(WARNING) << "Failed to delete " << output_file.AsUTF8Unsafe();
 299   }
 300
 301   // Run target callback on the thread it was originating from, not on
 302   // a worker pool thread.
 303   message_loop_proxy->PostTask(
 304       FROM_HERE,
 305       Bind(&RunCallback,
 306            callback,
 307            exit_code,
 308            TimeTicks::Now() - start_time,
 309            was_timeout,
 310            output_file_contents));
 311 }
 312
 313 }  // namespace
 314
 315 const char kGTestFilterFlag[] = "gtest_filter";
 316 const char kGTestHelpFlag[]   = "gtest_help";
 317 const char kGTestListTestsFlag[] = "gtest_list_tests";
 318 const char kGTestRepeatFlag[] = "gtest_repeat";
 319 const char kGTestRunDisabledTestsFlag[] = "gtest_also_run_disabled_tests";
 320 const char kGTestOutputFlag[] = "gtest_output";
 321
 322 TestLauncherDelegate::~TestLauncherDelegate() {
 323 }
 324
 325 TestLauncher::TestLauncher(TestLauncherDelegate* launcher_delegate,
 326                            size_t parallel_jobs)
 327     : launcher_delegate_(launcher_delegate),
 328       total_shards_(1),
 329       shard_index_(0),
 330       cycles_(1),
 331       test_started_count_(0),
 332       test_finished_count_(0),
 333       test_success_count_(0),
 334       test_broken_count_(0),
 335       retry_count_(0),
 336       retry_limit_(0),
 337       run_result_(true),
 338       watchdog_timer_(FROM_HERE,
 339                       TimeDelta::FromSeconds(kOutputTimeoutSeconds),
 340                       this,
 341                       &TestLauncher::OnOutputTimeout),
 342       parallel_jobs_(parallel_jobs) {
 343 }
 344
 345 TestLauncher::~TestLauncher() {
 346   if (worker_pool_owner_)
 347     worker_pool_owner_->pool()->Shutdown();
 348 }
 349
 350 bool TestLauncher::Run() {
 351   if (!Init())
 352     return false;
 353
 354   // Value of |cycles_| changes after each iteration. Keep track of the
 355   // original value.
 356   int requested_cycles = cycles_;
 357
 358 #if defined(OS_POSIX)
 359   CHECK_EQ(0, pipe(g_shutdown_pipe));
 360
 361   struct sigaction action;
 362   memset(&action, 0, sizeof(action));
 363   sigemptyset(&action.sa_mask);
 364   action.sa_handler = &ShutdownPipeSignalHandler;
 365
 366   CHECK_EQ(0, sigaction(SIGINT, &action, NULL));
 367   CHECK_EQ(0, sigaction(SIGQUIT, &action, NULL));
 368   CHECK_EQ(0, sigaction(SIGTERM, &action, NULL));
 369
 370   MessageLoopForIO::FileDescriptorWatcher controller;
 371   SignalFDWatcher watcher;
 372
 373   CHECK(MessageLoopForIO::current()->WatchFileDescriptor(
 374             g_shutdown_pipe[0],
 375             true,
 376             MessageLoopForIO::WATCH_READ,
 377             &controller,
 378             &watcher));
 379 #endif  // defined(OS_POSIX)
 380
 381   // Start the watchdog timer.
 382   watchdog_timer_.Reset();
 383
 384   MessageLoop::current()->PostTask(
 385       FROM_HERE,
 386       Bind(&TestLauncher::RunTestIteration, Unretained(this)));
 387
 388   MessageLoop::current()->Run();
 389
 390   if (requested_cycles != 1)
 391     results_tracker_.PrintSummaryOfAllIterations();
 392
 393   MaybeSaveSummaryAsJSON();
 394
 395   return run_result_;
 396 }
 397
 398 void TestLauncher::LaunchChildGTestProcess(
 399     const CommandLine& command_line,
 400     const std::string& wrapper,
 401     base::TimeDelta timeout,
 402     int flags,
 403     const LaunchChildGTestProcessCallback& callback) {
 404   DCHECK(thread_checker_.CalledOnValidThread());
 405
 406   // Record the exact command line used to launch the child.
 407   CommandLine new_command_line(
 408       PrepareCommandLineForGTest(command_line, wrapper));
 409
 410   // When running in parallel mode we need to redirect stdio to avoid mixed-up
 411   // output. We also always redirect on the bots to get the test output into
 412   // JSON summary.
 413   bool redirect_stdio = (parallel_jobs_ > 1) || BotModeEnabled();
 414
 415   worker_pool_owner_->pool()->PostWorkerTask(
 416       FROM_HERE,
 417       Bind(&DoLaunchChildTestProcess,
 418            new_command_line,
 419            timeout,
 420            flags,
 421            redirect_stdio,
 422            MessageLoopProxy::current(),
 423            Bind(&TestLauncher::OnLaunchTestProcessFinished,
 424                 Unretained(this),
 425                 callback)));
 426 }
 427
 428 void TestLauncher::OnTestFinished(const TestResult& result) {
 429   ++test_finished_count_;
 430
 431   bool print_snippet = false;
 432   std::string print_test_stdio("auto");
 433   if (CommandLine::ForCurrentProcess()->HasSwitch(
 434           switches::kTestLauncherPrintTestStdio)) {
 435     print_test_stdio = CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
 436         switches::kTestLauncherPrintTestStdio);
 437   }
 438   if (print_test_stdio == "auto") {
 439     print_snippet = (result.status != TestResult::TEST_SUCCESS);
 440   } else if (print_test_stdio == "always") {
 441     print_snippet = true;
 442   } else if (print_test_stdio == "never") {
 443     print_snippet = false;
 444   } else {
 445     LOG(WARNING) << "Invalid value of " << switches::kTestLauncherPrintTestStdio
 446                  << ": " << print_test_stdio;
 447   }
 448   if (print_snippet) {
 449     std::vector<std::string> snippet_lines;
 450     SplitString(result.output_snippet, '\n', &snippet_lines);
 451     if (snippet_lines.size() > kOutputSnippetLinesLimit) {
 452       size_t truncated_size = snippet_lines.size() - kOutputSnippetLinesLimit;
 453       snippet_lines.erase(
 454           snippet_lines.begin(),
 455           snippet_lines.begin() + truncated_size);
 456       snippet_lines.insert(snippet_lines.begin(), "<truncated>");
 457     }
 458     fprintf(stdout, "%s", JoinString(snippet_lines, "\n").c_str());
 459     fflush(stdout);
 460   }
 461
 462   if (result.status == TestResult::TEST_SUCCESS) {
 463     ++test_success_count_;
 464   } else {
 465     tests_to_retry_.insert(result.full_name);
 466   }
 467
 468   results_tracker_.AddTestResult(result);
 469
 470   // TODO(phajdan.jr): Align counter (padding).
 471   std::string status_line(
 472       StringPrintf("[%" PRIuS "/%" PRIuS "] %s ",
 473                    test_finished_count_,
 474                    test_started_count_,
 475                    result.full_name.c_str()));
 476   if (result.completed()) {
 477     status_line.append(StringPrintf("(%" PRId64 " ms)",
 478                                     result.elapsed_time.InMilliseconds()));
 479   } else if (result.status == TestResult::TEST_TIMEOUT) {
 480     status_line.append("(TIMED OUT)");
 481   } else if (result.status == TestResult::TEST_CRASH) {
 482     status_line.append("(CRASHED)");
 483   } else if (result.status == TestResult::TEST_SKIPPED) {
 484     status_line.append("(SKIPPED)");
 485   } else if (result.status == TestResult::TEST_UNKNOWN) {
 486     status_line.append("(UNKNOWN)");
 487   } else {
 488     // Fail very loudly so it's not ignored.
 489     CHECK(false) << "Unhandled test result status: " << result.status;
 490   }
 491   fprintf(stdout, "%s\n", status_line.c_str());
 492   fflush(stdout);
 493
 494   // We just printed a status line, reset the watchdog timer.
 495   watchdog_timer_.Reset();
 496
 497   // Do not waste time on timeouts. We include tests with unknown results here
 498   // because sometimes (e.g. hang in between unit tests) that's how a timeout
 499   // gets reported.
 500   if (result.status == TestResult::TEST_TIMEOUT ||
 501       result.status == TestResult::TEST_UNKNOWN) {
 502     test_broken_count_++;
 503   }
 504   size_t broken_threshold =
 505       std::max(static_cast<size_t>(20), test_started_count_ / 10);
 506   if (test_broken_count_ >= broken_threshold) {
 507     fprintf(stdout, "Too many badly broken tests (%" PRIuS "), exiting now.\n",
 508             test_broken_count_);
 509     fflush(stdout);
 510
 511 #if defined(OS_POSIX)
 512     KillSpawnedTestProcesses();
 513 #endif  // defined(OS_POSIX)
 514
 515     results_tracker_.AddGlobalTag("BROKEN_TEST_EARLY_EXIT");
 516     results_tracker_.AddGlobalTag(kUnreliableResultsTag);
 517     MaybeSaveSummaryAsJSON();
 518
 519     exit(1);
 520   }
 521
 522   if (test_finished_count_ != test_started_count_)
 523     return;
 524
 525   if (tests_to_retry_.empty() || retry_count_ >= retry_limit_) {
 526     OnTestIterationFinished();
 527     return;
 528   }
 529
 530   if (tests_to_retry_.size() >= broken_threshold) {
 531     fprintf(stdout,
 532             "Too many failing tests (%" PRIuS "), skipping retries.\n",
 533             tests_to_retry_.size());
 534     fflush(stdout);
 535
 536     results_tracker_.AddGlobalTag("BROKEN_TEST_SKIPPED_RETRIES");
 537     results_tracker_.AddGlobalTag(kUnreliableResultsTag);
 538
 539     OnTestIterationFinished();
 540     return;
 541   }
 542
 543   retry_count_++;
 544
 545   std::vector<std::string> test_names(tests_to_retry_.begin(),
 546                                       tests_to_retry_.end());
 547
 548   tests_to_retry_.clear();
 549
 550   size_t retry_started_count = launcher_delegate_->RetryTests(this, test_names);
 551   if (retry_started_count == 0) {
 552     // Signal failure, but continue to run all requested test iterations.
 553     // With the summary of all iterations at the end this is a good default.
 554     run_result_ = false;
 555
 556     OnTestIterationFinished();
 557     return;
 558   }
 559
 560   fprintf(stdout, "Retrying %" PRIuS " test%s (retry #%" PRIuS ")\n",
 561           retry_started_count,
 562           retry_started_count > 1 ? "s" : "",
 563           retry_count_);
 564   fflush(stdout);
 565
 566   test_started_count_ += retry_started_count;
 567 }
 568
 569 // static
 570 std::string TestLauncher::FormatFullTestName(const std::string& test_case_name,
 571                                              const std::string& test_name) {
 572   return test_case_name + "." + test_name;
 573 }
 574
 575 bool TestLauncher::Init() {
 576   const CommandLine* command_line = CommandLine::ForCurrentProcess();
 577
 578   // Initialize sharding. Command line takes precedence over legacy environment
 579   // variables.
 580   if (command_line->HasSwitch(switches::kTestLauncherTotalShards) &&
 581       command_line->HasSwitch(switches::kTestLauncherShardIndex)) {
 582     if (!StringToInt(
 583             command_line->GetSwitchValueASCII(
 584                 switches::kTestLauncherTotalShards),
 585             &total_shards_)) {
 586       LOG(ERROR) << "Invalid value for " << switches::kTestLauncherTotalShards;
 587       return false;
 588     }
 589     if (!StringToInt(
 590             command_line->GetSwitchValueASCII(
 591                 switches::kTestLauncherShardIndex),
 592             &shard_index_)) {
 593       LOG(ERROR) << "Invalid value for " << switches::kTestLauncherShardIndex;
 594       return false;
 595     }
 596     fprintf(stdout,
 597             "Using sharding settings from command line. This is shard %d/%d\n",
 598             shard_index_, total_shards_);
 599     fflush(stdout);
 600   } else {
 601     if (!TakeInt32FromEnvironment(kTestTotalShards, &total_shards_))
 602       return false;
 603     if (!TakeInt32FromEnvironment(kTestShardIndex, &shard_index_))
 604       return false;
 605     fprintf(stdout,
 606             "Using sharding settings from environment. This is shard %d/%d\n",
 607             shard_index_, total_shards_);
 608     fflush(stdout);
 609   }
 610   if (shard_index_ < 0 ||
 611       total_shards_ < 0 ||
 612       shard_index_ >= total_shards_) {
 613     LOG(ERROR) << "Invalid sharding settings: we require 0 <= "
 614                << kTestShardIndex << " < " << kTestTotalShards
 615                << ", but you have " << kTestShardIndex << "=" << shard_index_
 616                << ", " << kTestTotalShards << "=" << total_shards_ << ".\n";
 617     return false;
 618   }
 619
 620   // Make sure we don't pass any sharding-related environment to the child
 621   // processes. This test launcher implements the sharding completely.
 622   CHECK(UnsetEnvironmentVariableIfExists("GTEST_TOTAL_SHARDS"));
 623   CHECK(UnsetEnvironmentVariableIfExists("GTEST_SHARD_INDEX"));
 624
 625   if (command_line->HasSwitch(kGTestRepeatFlag) &&
 626       !StringToInt(command_line->GetSwitchValueASCII(kGTestRepeatFlag),
 627                    &cycles_)) {
 628     LOG(ERROR) << "Invalid value for " << kGTestRepeatFlag;
 629     return false;
 630   }
 631
 632   if (CommandLine::ForCurrentProcess()->HasSwitch(
 633           switches::kTestLauncherRetryLimit)) {
 634     int retry_limit = -1;
 635     if (!StringToInt(CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
 636                          switches::kTestLauncherRetryLimit), &retry_limit) ||
 637         retry_limit < 0) {
 638       LOG(ERROR) << "Invalid value for " << switches::kTestLauncherRetryLimit;
 639       return false;
 640     }
 641
 642     retry_limit_ = retry_limit;
 643   } else if (!CommandLine::ForCurrentProcess()->HasSwitch(kGTestFilterFlag)) {
 644     // Retry failures 3 times by default if we are running all of the tests.
 645     retry_limit_ = 3;
 646   }
 647
 648   if (CommandLine::ForCurrentProcess()->HasSwitch(
 649           switches::kTestLauncherJobs)) {
 650     int jobs = -1;
 651     if (!StringToInt(CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
 652                          switches::kTestLauncherJobs), &jobs) ||
 653         jobs < 0) {
 654       LOG(ERROR) << "Invalid value for " << switches::kTestLauncherJobs;
 655       return false;
 656     }
 657
 658     parallel_jobs_ = jobs;
 659   } else if (CommandLine::ForCurrentProcess()->HasSwitch(kGTestFilterFlag)) {
 660     // Do not run jobs in parallel by default if we are running a subset of
 661     // the tests.
 662     parallel_jobs_ = 1;
 663   }
 664
 665   fprintf(stdout, "Using %" PRIuS " parallel jobs.\n", parallel_jobs_);
 666   fflush(stdout);
 667   worker_pool_owner_.reset(
 668       new SequencedWorkerPoolOwner(parallel_jobs_, "test_launcher"));
 669
 670   if (command_line->HasSwitch(switches::kTestLauncherFilterFile) &&
 671       command_line->HasSwitch(kGTestFilterFlag)) {
 672     LOG(ERROR) << "Only one of --test-launcher-filter-file and --gtest_filter "
 673                << "at a time is allowed.";
 674     return false;
 675   }
 676
 677   if (command_line->HasSwitch(switches::kTestLauncherFilterFile)) {
 678     std::string filter;
 679     if (!ReadFileToString(
 680             command_line->GetSwitchValuePath(switches::kTestLauncherFilterFile),
 681             &filter)) {
 682       LOG(ERROR) << "Failed to read the filter file.";
 683       return false;
 684     }
 685
 686     std::vector<std::string> filter_lines;
 687     SplitString(filter, '\n', &filter_lines);
 688     for (size_t i = 0; i < filter_lines.size(); i++) {
 689       if (filter_lines[i].empty())
 690         continue;
 691
 692       if (filter_lines[i][0] == '-')
 693         negative_test_filter_.push_back(filter_lines[i].substr(1));
 694       else
 695         positive_test_filter_.push_back(filter_lines[i]);
 696     }
 697   } else {
 698     // Split --gtest_filter at '-', if there is one, to separate into
 699     // positive filter and negative filter portions.
 700     std::string filter = command_line->GetSwitchValueASCII(kGTestFilterFlag);
 701     size_t dash_pos = filter.find('-');
 702     if (dash_pos == std::string::npos) {
 703       SplitString(filter, ':', &positive_test_filter_);
 704     } else {
 705       // Everything up to the dash.
 706       SplitString(filter.substr(0, dash_pos), ':', &positive_test_filter_);
 707
 708       // Everything after the dash.
 709       SplitString(filter.substr(dash_pos + 1), ':', &negative_test_filter_);
 710     }
 711   }
 712
 713   if (!results_tracker_.Init(*command_line)) {
 714     LOG(ERROR) << "Failed to initialize test results tracker.";
 715     return 1;
 716   }
 717
 718 #if defined(NDEBUG)
 719   results_tracker_.AddGlobalTag("MODE_RELEASE");
 720 #else
 721   results_tracker_.AddGlobalTag("MODE_DEBUG");
 722 #endif
 723
 724   // Operating systems (sorted alphabetically).
 725   // Note that they can deliberately overlap, e.g. OS_LINUX is a subset
 726   // of OS_POSIX.
 727 #if defined(OS_ANDROID)
 728   results_tracker_.AddGlobalTag("OS_ANDROID");
 729 #endif
 730
 731 #if defined(OS_BSD)
 732   results_tracker_.AddGlobalTag("OS_BSD");
 733 #endif
 734
 735 #if defined(OS_FREEBSD)
 736   results_tracker_.AddGlobalTag("OS_FREEBSD");
 737 #endif
 738
 739 #if defined(OS_IOS)
 740   results_tracker_.AddGlobalTag("OS_IOS");
 741 #endif
 742
 743 #if defined(OS_LINUX)
 744   results_tracker_.AddGlobalTag("OS_LINUX");
 745 #endif
 746
 747 #if defined(OS_MACOSX)
 748   results_tracker_.AddGlobalTag("OS_MACOSX");
 749 #endif
 750
 751 #if defined(OS_NACL)
 752   results_tracker_.AddGlobalTag("OS_NACL");
 753 #endif
 754
 755 #if defined(OS_OPENBSD)
 756   results_tracker_.AddGlobalTag("OS_OPENBSD");
 757 #endif
 758
 759 #if defined(OS_POSIX)
 760   results_tracker_.AddGlobalTag("OS_POSIX");
 761 #endif
 762
 763 #if defined(OS_SOLARIS)
 764   results_tracker_.AddGlobalTag("OS_SOLARIS");
 765 #endif
 766
 767 #if defined(OS_WIN)
 768   results_tracker_.AddGlobalTag("OS_WIN");
 769 #endif
 770
 771   // CPU-related tags.
 772 #if defined(ARCH_CPU_32_BITS)
 773   results_tracker_.AddGlobalTag("CPU_32_BITS");
 774 #endif
 775
 776 #if defined(ARCH_CPU_64_BITS)
 777   results_tracker_.AddGlobalTag("CPU_64_BITS");
 778 #endif
 779
 780   return true;
 781 }
 782
 783 void TestLauncher::RunTests() {
 784   testing::UnitTest* const unit_test = testing::UnitTest::GetInstance();
 785
 786   std::vector<std::string> test_names;
 787
 788   for (int i = 0; i < unit_test->total_test_case_count(); ++i) {
 789     const testing::TestCase* test_case = unit_test->GetTestCase(i);
 790     for (int j = 0; j < test_case->total_test_count(); ++j) {
 791       const testing::TestInfo* test_info = test_case->GetTestInfo(j);
 792       std::string test_name = FormatFullTestName(
 793           test_info->test_case_name(), test_info->name());
 794
 795       results_tracker_.AddTest(test_name);
 796
 797       const CommandLine* command_line = CommandLine::ForCurrentProcess();
 798       if (test_name.find("DISABLED") != std::string::npos) {
 799         results_tracker_.AddDisabledTest(test_name);
 800
 801         // Skip disabled tests unless explicitly requested.
 802         if (!command_line->HasSwitch(kGTestRunDisabledTestsFlag))
 803           continue;
 804       }
 805
 806       if (!launcher_delegate_->ShouldRunTest(test_case, test_info))
 807         continue;
 808
 809       // Skip the test that doesn't match the filter (if given).
 810       if (!positive_test_filter_.empty()) {
 811         bool found = false;
 812         for (size_t k = 0; k < positive_test_filter_.size(); ++k) {
 813           if (MatchPattern(test_name, positive_test_filter_[k])) {
 814             found = true;
 815             break;
 816           }
 817         }
 818
 819         if (!found)
 820           continue;
 821       }
 822       bool excluded = false;
 823       for (size_t k = 0; k < negative_test_filter_.size(); ++k) {
 824         if (MatchPattern(test_name, negative_test_filter_[k])) {
 825           excluded = true;
 826           break;
 827         }
 828       }
 829       if (excluded)
 830         continue;
 831
 832       if (base::Hash(test_name) % total_shards_ !=
 833           static_cast<uint32>(shard_index_)) {
 834         continue;
 835       }
 836
 837       test_names.push_back(test_name);
 838     }
 839   }
 840
 841   test_started_count_ = launcher_delegate_->RunTests(this, test_names);
 842
 843   if (test_started_count_ == 0) {
 844     fprintf(stdout, "0 tests run\n");
 845     fflush(stdout);
 846
 847     // No tests have actually been started, so kick off the next iteration.
 848     MessageLoop::current()->PostTask(
 849         FROM_HERE,
 850         Bind(&TestLauncher::RunTestIteration, Unretained(this)));
 851   }
 852 }
 853
 854 void TestLauncher::RunTestIteration() {
 855   if (cycles_ == 0) {
 856     MessageLoop::current()->Quit();
 857     return;
 858   }
 859
 860   // Special value "-1" means "repeat indefinitely".
 861   cycles_ = (cycles_ == -1) ? cycles_ : cycles_ - 1;
 862
 863   test_started_count_ = 0;
 864   test_finished_count_ = 0;
 865   test_success_count_ = 0;
 866   test_broken_count_ = 0;
 867   retry_count_ = 0;
 868   tests_to_retry_.clear();
 869   results_tracker_.OnTestIterationStarting();
 870
 871   MessageLoop::current()->PostTask(
 872       FROM_HERE, Bind(&TestLauncher::RunTests, Unretained(this)));
 873 }
 874
 875 void TestLauncher::MaybeSaveSummaryAsJSON() {
 876   const CommandLine* command_line = CommandLine::ForCurrentProcess();
 877   if (command_line->HasSwitch(switches::kTestLauncherSummaryOutput)) {
 878     FilePath summary_path(command_line->GetSwitchValuePath(
 879                               switches::kTestLauncherSummaryOutput));
 880     if (!results_tracker_.SaveSummaryAsJSON(summary_path)) {
 881       LOG(ERROR) << "Failed to save test launcher output summary.";
 882     }
 883   }
 884 }
 885
 886 void TestLauncher::OnLaunchTestProcessFinished(
 887     const LaunchChildGTestProcessCallback& callback,
 888     int exit_code,
 889     const TimeDelta& elapsed_time,
 890     bool was_timeout,
 891     const std::string& output) {
 892   DCHECK(thread_checker_.CalledOnValidThread());
 893
 894   callback.Run(exit_code, elapsed_time, was_timeout, output);
 895 }
 896
 897 void TestLauncher::OnTestIterationFinished() {
 898   TestResultsTracker::TestStatusMap tests_by_status(
 899       results_tracker_.GetTestStatusMapForCurrentIteration());
 900   if (!tests_by_status[TestResult::TEST_UNKNOWN].empty())
 901     results_tracker_.AddGlobalTag(kUnreliableResultsTag);
 902
 903   // When we retry tests, success is determined by having nothing more
 904   // to retry (everything eventually passed), as opposed to having
 905   // no failures at all.
 906   if (tests_to_retry_.empty()) {
 907     fprintf(stdout, "SUCCESS: all tests passed.\n");
 908     fflush(stdout);
 909   } else {
 910     // Signal failure, but continue to run all requested test iterations.
 911     // With the summary of all iterations at the end this is a good default.
 912     run_result_ = false;
 913   }
 914
 915   results_tracker_.PrintSummaryOfCurrentIteration();
 916
 917   // Kick off the next iteration.
 918   MessageLoop::current()->PostTask(
 919       FROM_HERE,
 920       Bind(&TestLauncher::RunTestIteration, Unretained(this)));
 921 }
 922
 923 void TestLauncher::OnOutputTimeout() {
 924   DCHECK(thread_checker_.CalledOnValidThread());
 925
 926   AutoLock lock(g_live_processes_lock.Get());
 927
 928   fprintf(stdout, "Still waiting for the following processes to finish:\n");
 929
 930   for (std::map<ProcessHandle, CommandLine>::iterator i =
 931            g_live_processes.Get().begin();
 932        i != g_live_processes.Get().end();
 933        ++i) {
 934 #if defined(OS_WIN)
 935     fwprintf(stdout, L"\t%s\n", i->second.GetCommandLineString().c_str());
 936 #else
 937     fprintf(stdout, "\t%s\n", i->second.GetCommandLineString().c_str());
 938 #endif
 939   }
 940
 941   fflush(stdout);
 942
 943   // Arm the timer again - otherwise it would fire only once.
 944   watchdog_timer_.Reset();
 945 }
 946
 947 std::string GetTestOutputSnippet(const TestResult& result,
 948                                  const std::string& full_output) {
 949   size_t run_pos = full_output.find(std::string("[ RUN      ] ") +
 950                                     result.full_name);
 951   if (run_pos == std::string::npos)
 952     return std::string();
 953
 954   size_t end_pos = full_output.find(std::string("[  FAILED  ] ") +
 955                                     result.full_name,
 956                                     run_pos);
 957   // Only clip the snippet to the "OK" message if the test really
 958   // succeeded. It still might have e.g. crashed after printing it.
 959   if (end_pos == std::string::npos &&
 960       result.status == TestResult::TEST_SUCCESS) {
 961     end_pos = full_output.find(std::string("[       OK ] ") +
 962                                result.full_name,
 963                                run_pos);
 964   }
 965   if (end_pos != std::string::npos) {
 966     size_t newline_pos = full_output.find("\n", end_pos);
 967     if (newline_pos != std::string::npos)
 968       end_pos = newline_pos + 1;
 969   }
 970
 971   std::string snippet(full_output.substr(run_pos));
 972   if (end_pos != std::string::npos)
 973     snippet = full_output.substr(run_pos, end_pos - run_pos);
 974
 975   return snippet;
 976 }
 977
 978 CommandLine PrepareCommandLineForGTest(const CommandLine& command_line,
 979                                        const std::string& wrapper) {
 980   CommandLine new_command_line(command_line.GetProgram());
 981   CommandLine::SwitchMap switches = command_line.GetSwitches();
 982
 983   // Strip out gtest_repeat flag - this is handled by the launcher process.
 984   switches.erase(kGTestRepeatFlag);
 985
 986   // Don't try to write the final XML report in child processes.
 987   switches.erase(kGTestOutputFlag);
 988
 989   for (CommandLine::SwitchMap::const_iterator iter = switches.begin();
 990        iter != switches.end(); ++iter) {
 991     new_command_line.AppendSwitchNative((*iter).first, (*iter).second);
 992   }
 993
 994   // Prepend wrapper after last CommandLine quasi-copy operation. CommandLine
 995   // does not really support removing switches well, and trying to do that
 996   // on a CommandLine with a wrapper is known to break.
 997   // TODO(phajdan.jr): Give it a try to support CommandLine removing switches.
 998 #if defined(OS_WIN)
 999   new_command_line.PrependWrapper(ASCIIToWide(wrapper));
1000 #elif defined(OS_POSIX)
1001   new_command_line.PrependWrapper(wrapper);
1002 #endif
1003
1004   return new_command_line;
1005 }
1006
1007 // TODO(phajdan.jr): Move to anonymous namespace.
1008 int LaunchChildTestProcessWithOptions(const CommandLine& command_line,
1009                                       const LaunchOptions& options,
1010                                       int flags,
1011                                       base::TimeDelta timeout,
1012                                       bool* was_timeout) {
1013 #if defined(OS_POSIX)
1014   // Make sure an option we rely on is present - see LaunchChildGTestProcess.
1015   DCHECK(options.new_process_group);
1016 #endif
1017
1018   LaunchOptions new_options(options);
1019
1020 #if defined(OS_WIN)
1021   DCHECK(!new_options.job_handle);
1022
1023   win::ScopedHandle job_handle;
1024   if (flags & TestLauncher::USE_JOB_OBJECTS) {
1025     job_handle.Set(CreateJobObject(NULL, NULL));
1026     if (!job_handle.IsValid()) {
1027       LOG(ERROR) << "Could not create JobObject.";
1028       return -1;
1029     }
1030
1031     DWORD job_flags = JOB_OBJECT_LIMIT_KILL_ON_JOB_CLOSE;
1032
1033     // Allow break-away from job since sandbox and few other places rely on it
1034     // on Windows versions prior to Windows 8 (which supports nested jobs).
1035     if (win::GetVersion() < win::VERSION_WIN8 &&
1036         flags & TestLauncher::ALLOW_BREAKAWAY_FROM_JOB) {
1037       job_flags |= JOB_OBJECT_LIMIT_BREAKAWAY_OK;
1038     }
1039
1040     if (!SetJobObjectLimitFlags(job_handle.Get(), job_flags)) {
1041       LOG(ERROR) << "Could not SetJobObjectLimitFlags.";
1042       return -1;
1043     }
1044
1045     new_options.job_handle = job_handle.Get();
1046   }
1047 #endif  // defined(OS_WIN)
1048
1049 #if defined(OS_LINUX)
1050   // To prevent accidental privilege sharing to an untrusted child, processes
1051   // are started with PR_SET_NO_NEW_PRIVS. Do not set that here, since this
1052   // new child will be privileged and trusted.
1053   new_options.allow_new_privs = true;
1054 #endif
1055
1056   base::ProcessHandle process_handle;
1057
1058   {
1059     // Note how we grab the lock before the process possibly gets created.
1060     // This ensures that when the lock is held, ALL the processes are registered
1061     // in the set.
1062     AutoLock lock(g_live_processes_lock.Get());
1063
1064     if (!base::LaunchProcess(command_line, new_options, &process_handle))
1065       return -1;
1066
1067     g_live_processes.Get().insert(std::make_pair(process_handle, command_line));
1068   }
1069
1070   int exit_code = 0;
1071   if (!base::WaitForExitCodeWithTimeout(process_handle,
1072                                         &exit_code,
1073                                         timeout)) {
1074     *was_timeout = true;
1075     exit_code = -1;  // Set a non-zero exit code to signal a failure.
1076
1077     // Ensure that the process terminates.
1078     base::KillProcess(process_handle, -1, true);
1079   }
1080
1081   {
1082     // Note how we grab the log before issuing a possibly broad process kill.
1083     // Other code parts that grab the log kill processes, so avoid trying
1084     // to do that twice and trigger all kinds of log messages.
1085     AutoLock lock(g_live_processes_lock.Get());
1086
1087 #if defined(OS_POSIX)
1088     if (exit_code != 0) {
1089       // On POSIX, in case the test does not exit cleanly, either due to a crash
1090       // or due to it timing out, we need to clean up any child processes that
1091       // it might have created. On Windows, child processes are automatically
1092       // cleaned up using JobObjects.
1093       base::KillProcessGroup(process_handle);
1094     }
1095 #endif
1096
1097     g_live_processes.Get().erase(process_handle);
1098   }
1099
1100   base::CloseProcessHandle(process_handle);
1101
1102   return exit_code;
1103 }
1104
1105 }  // namespace base