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