New test infrastructure for producing verbose logs in failing tests.

chrome/test/base/test_log_collector_win.cc

+// Copyright (c) 2012 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "chrome/test/base/test_log_collector_win.h"
+
+#include <windows.h>
+
+#include <algorithm>
+#include <ios>  // For std::hex
+
+#include "base/command_line.h"
+#include "base/compiler_specific.h"
+#include "base/file_path.h"
+#include "base/file_util.h"
+#include "base/lazy_instance.h"
+#include "base/logging.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/scoped_temp_dir.h"
+#include "base/stringprintf.h"
+#include "chrome/test/base/file_logger_win.h"
+#include "chrome/test/base/test_switches.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace {
+
+const char kTraceLogExtension[] = ".etl";
+
+class TestLogCollector {
+ public:
+  TestLogCollector();
+  ~TestLogCollector();
+
+  void Initialize(testing::UnitTest* unit_test);
+
+  void SetUp();
+  void StartSessionForTest(const testing::TestInfo& test_info);
+  bool LogTestPartResult(const testing::TestPartResult& test_part_result);
+  void ProcessSessionForTest(const testing::TestInfo& test_info);
+  void TearDown();
+
+ private:
+  // An EventListener that generally delegates to a given default result
+  // printer with a few exceptions; see individual method comments for details.
+  class EventListener : public testing::TestEventListener {
+   public:
+    // Ownership of |default_result_printer| is taken by the new instance.
+    EventListener(TestLogCollector* test_log_collector,
+                  testing::TestEventListener* default_result_printer);
+    virtual ~EventListener();
+
+    // Sets up the log collector.
+    virtual void OnTestProgramStart(
+        const testing::UnitTest& unit_test) OVERRIDE {
+      test_log_collector_->SetUp();
+      default_result_printer_->OnTestProgramStart(unit_test);
+    }
+
+    virtual void OnTestIterationStart(const testing::UnitTest& unit_test,
+                                      int iteration) OVERRIDE {
+      default_result_printer_->OnTestIterationStart(unit_test, iteration);
+    }
+
+    virtual void OnEnvironmentsSetUpStart(
+        const testing::UnitTest& unit_test) OVERRIDE {
+      default_result_printer_->OnEnvironmentsSetUpStart(unit_test);
+    }
+
+    virtual void OnEnvironmentsSetUpEnd(
+        const testing::UnitTest& unit_test) OVERRIDE {
+      default_result_printer_->OnEnvironmentsSetUpEnd(unit_test);
+    }
+
+    virtual void OnTestCaseStart(const testing::TestCase& test_case) OVERRIDE {
+      default_result_printer_->OnTestCaseStart(test_case);
+    }
+
+    // Calls back to the collector to start collecting logs for this test.
+    virtual void OnTestStart(const testing::TestInfo& test_info) OVERRIDE {
+      default_result_printer_->OnTestStart(test_info);
+      test_log_collector_->StartSessionForTest(test_info);
+    }
+
+    // Calls back to the collector with the partial result.  If the collector
+    // does not handle it, it is given to the default result printer.
+    virtual void OnTestPartResult(
+        const testing::TestPartResult& test_part_result) OVERRIDE {
+      if (!test_log_collector_->LogTestPartResult(test_part_result))
+        default_result_printer_->OnTestPartResult(test_part_result);
+    }
+
+    // Calls back to the collector to handle the collected log for the test that
+    // has just ended.
+    virtual void OnTestEnd(const testing::TestInfo& test_info) OVERRIDE {
+      test_log_collector_->ProcessSessionForTest(test_info);
+      default_result_printer_->OnTestEnd(test_info);
+    }
+
+    virtual void OnTestCaseEnd(const testing::TestCase& test_case) OVERRIDE {
+      default_result_printer_->OnTestCaseEnd(test_case);
+    }
+
+    virtual void OnEnvironmentsTearDownStart(
+        const testing::UnitTest& unit_test) OVERRIDE {
+      default_result_printer_->OnEnvironmentsTearDownStart(unit_test);
+    }
+
+    virtual void OnEnvironmentsTearDownEnd(
+        const testing::UnitTest& unit_test) OVERRIDE {
+      default_result_printer_->OnEnvironmentsTearDownEnd(unit_test);
+    }
+
+    virtual void OnTestIterationEnd(const testing::UnitTest& unit_test,
+                                    int iteration) OVERRIDE {
+      default_result_printer_->OnTestIterationEnd(unit_test, iteration);
+    }
+
+    // Tears down the log collector.
+    virtual void OnTestProgramEnd(const testing::UnitTest& unit_test) OVERRIDE {
+      default_result_printer_->OnTestProgramEnd(unit_test);
+      test_log_collector_->TearDown();
+    }
+
+   private:
+    TestLogCollector* test_log_collector_;
+    scoped_ptr<testing::TestEventListener> default_result_printer_;
+
+    DISALLOW_COPY_AND_ASSIGN(EventListener);
+  };
+
+  // The Google Test unit test into which the collector has been installed.
+  testing::UnitTest* unit_test_;
+
+  // A temporary directory into which a log file is placed for the duration of
+  // each test.  Created/destroyed at collector SetUp and TearDown.
+  ScopedTempDir log_temp_dir_;
+
+  // The test logger.  Initialized/Unintitialized at collector SetUp and
+  // TearDown.
+  FileLogger file_logger_;
+
+  // The current log file.  Valid only during a test.
+  FilePath log_file_;
+
+  // True if --also-emit-success-logs was specified on the command line.
+  bool also_emit_success_logs_;
+
+  DISALLOW_COPY_AND_ASSIGN(TestLogCollector);
+};
+
+base::LazyInstance<TestLogCollector> g_test_log_collector =
+    LAZY_INSTANCE_INITIALIZER;
+
+// TestLogCollector::EventListener implementation
+
+TestLogCollector::EventListener::EventListener(
+    TestLogCollector* test_log_collector,
+    testing::TestEventListener* default_result_printer)
+    : test_log_collector_(test_log_collector),
+      default_result_printer_(default_result_printer) {
+}
+
+TestLogCollector::EventListener::~EventListener() {
+}
+
+// TestLogCollector implementation
+
+TestLogCollector::TestLogCollector()
+    : unit_test_(NULL), also_emit_success_logs_(false) {
+}
+
+TestLogCollector::~TestLogCollector() {
+}
+
+void TestLogCollector::Initialize(testing::UnitTest* unit_test) {
+  if (unit_test_ != NULL) {
+    CHECK_EQ(unit_test, unit_test_)
+        << "Cannot install the test log collector in multiple unit tests.";
+    return;  // Already initialized.
+  }
+
+  // Remove the default result printer and install the collector's listener
+  // which delegates to the printer.  If the default result printer has already
+  // been released, log an error and move on.
+  testing::TestEventListeners& listeners = unit_test->listeners();
+  testing::TestEventListener* default_result_printer =
+      listeners.default_result_printer();
+  if (default_result_printer == NULL) {
+    LOG(ERROR) << "Failed to initialize the test log collector on account of "
+                  "another component having released the default result "
+                  "printer.";
+  } else {
+    // Ownership of |default_release_printer| is passed to the new listener, and
+    // ownership of the new listener is passed to the unit test.
+    listeners.Append(
+        new EventListener(this, listeners.Release(default_result_printer)));
+
+    also_emit_success_logs_ = CommandLine::ForCurrentProcess()->HasSwitch(
+        switches::kAlsoEmitSuccessLogs);
+
+    unit_test_ = unit_test;
+  }
+}
+
+// Invoked by the listener at test program start to create the temporary log
+// directory and initialize the logger.
+void TestLogCollector::SetUp() {
+  if (!log_temp_dir_.CreateUniqueTempDir()) {
+    LOG(ERROR) << "Failed to create temporary directory to hold log files.";
+  } else {
+    file_logger_.Initialize();
+  }
+}
+
+// Invoked by the listener at test start to begin collecting logs in a file.
+void TestLogCollector::StartSessionForTest(const testing::TestInfo& test_info) {
+  if (log_temp_dir_.IsValid()) {
+    std::string log_file_name(test_info.name());
+    std::replace(log_file_name.begin(), log_file_name.end(), '/', '_');

[robertshield, 2012/03/02 22:37:41]

can test names contain other invalid characters (\ / : * ? " < > | according to
http://support.microsoft.com/kb/177506)

[grt (UTC plus 2), 2012/03/03 02:12:43]

Nope, they're identifiers in the C/C++ sense.

+    log_file_name.append(kTraceLogExtension);
+    log_file_ = log_temp_dir_.path().AppendASCII(log_file_name);
+
+    file_logger_.StartLogging(log_file_);
+  }
+}
+
+// Invoked by the listener when a test result is produced to log an event for
+// the result.
+bool TestLogCollector::LogTestPartResult(
+    const testing::TestPartResult& test_part_result) {
+  // Can't handle the event if no trace session.
+  if (!file_logger_.is_logging())
+    return false;
+
+  if (test_part_result.type() != testing::TestPartResult::kSuccess) {
+    // Approximate Google Test's message formatting.
+    LOG(ERROR)
+        << base::StringPrintf("%s(%d): error: %s", test_part_result.file_name(),
+                              test_part_result.line_number(),
+                              test_part_result.message());
+  }
+  return true;
+}
+
+// Invoked by the listener at test end to dump the collected log in case of
+// error.
+void TestLogCollector::ProcessSessionForTest(
+    const testing::TestInfo& test_info) {
+  if (file_logger_.is_logging()) {
+    file_logger_.StopLogging();
+
+    if (also_emit_success_logs_ || test_info.result()->Failed()) {
+      std::cerr << "----- log messages for "
+                << test_info.test_case_name() << "." << test_info.name()
+                << " above this line are repeated below -----" << std::endl;
+      // Dump the log to stderr.
+      file_logger_.DumpLogFile(log_file_, std::cerr);
+    }
+
+    if (!file_util::Delete(log_file_, false))
+      LOG(ERROR) << "Failed to delete log file " << log_file_.value();
+  }
+
+  log_file_.clear();
+}
+
+// Invoked by the listener at test program end to shut down the logger and
+// delete the temporary log directory.
+void TestLogCollector::TearDown() {
+  file_logger_.Uninitialize();
+
+  (void) log_temp_dir_.Delete();

[robertshield, 2012/03/02 22:37:41]

(void)? I guess you did this because Delete() is marked with 
WARN_UNUSED_RESULT, in which case you want ignore_result().

[grt (UTC plus 2), 2012/03/03 02:12:43]

Awesome, thanks!

+}
+
+}  // namespace
+
+void InstallTestLogCollector(testing::UnitTest* unit_test) {
+  // Must be called before running any tests.
+  DCHECK(unit_test);
+  DCHECK(!unit_test->current_test_case());
+
+  g_test_log_collector.Get().Initialize(unit_test);
+}