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

[robertshield, 2012/03/09 16:58:04]

std::hex does not appear in this file.

[grt (UTC plus 2), 2012/03/09 17:55:25]

I never said it did.  :-)  The C++ spec says that you include <ios> to get
std::hex.  Whether the implementation of the spec puts it in some other file
included by that or not is up to them.

In any case, I've removed the comment since it seems to have added rather than
removed confusion.

+
+#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/log_file_printer_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(), '/', '_');
+    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.
+      logging_win::PrintLogFile(log_file_, &std::cerr);
+      std::cerr.flush();
+    }
+
+    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();
+
+  ignore_result(log_temp_dir_.Delete());
+}
+
+}  // 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);
+}