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