Home | History | Annotate | Download | only in launcher 
      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
   1100