Integrate the TestLogCollector with the Chrome Frame net tests.

ETW logs are captured from npchrome_frame, the test suite, and the single-process Chrome running within the test executable. They are output upon a test failure as well as a failure to launch or shut down IE.

BUG=114369
TEST=Add a FAIL() to the end of a test, or comment out OnInitialTab/OnProviderDestroyed. Verify that ETW logs are output.


Review URL: http://codereview.chromium.org/9864052

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@129501 0039d316-1c4b-4281-b951-d872f2087c98

2 files changed, 109 insertions, 12 deletions

diff --git a/chrome_frame/test/net/fake_external_tab.cc b/chrome_frame/test/net/fake_external_tab.cc
index cd8103c..322231c 100644
--- a/chrome_frame/test/net/fake_external_tab.cc
+++ b/chrome_frame/test/net/fake_external_tab.cc
@@ -44,6 +44,9 @@
 #include "chrome/common/chrome_switches.h"
 #include "chrome/common/pref_names.h"
 #include "chrome/renderer/chrome_content_renderer_client.h"
+#include "chrome/test/logging/win/file_logger.h"
+#include "chrome/test/logging/win/log_file_printer.h"
+#include "chrome/test/logging/win/test_log_collector.h"
 #include "chrome_frame/crash_server_init.h"
 #include "chrome_frame/test/chrome_frame_test_utils.h"
 #include "chrome_frame/test/net/test_automation_resource_message_filter.h"
@@ -140,6 +143,8 @@ class FakeMainDelegate : public content::ContentMainDelegate {
   virtual ~FakeMainDelegate() {}
 
   virtual bool BasicStartupComplete(int* exit_code) OVERRIDE {
+    logging_win::InstallTestLogCollector(
+        testing::UnitTest::GetInstance());
     return false;
   }
 
@@ -313,12 +318,6 @@ void FilterDisabledTests() {
   ::testing::FLAGS_gtest_filter = filter;
 }
 
-void OnIEShutdownFailure() {
-  DLOG(ERROR) << "Failed to shutdown IE and npchrome_frame cleanly after test "
-                 "execution.";
-  ::ExitProcess(1);
-}
-
 }  // namespace
 
 // Same as BrowserProcessImpl, but uses custom profile manager.
@@ -539,6 +538,13 @@ void CFUrlRequestUnittestRunner::ShutDownHostBrowser() {
   }
 }
 
+void CFUrlRequestUnittestRunner::OnIEShutdownFailure() {
+  LOG(ERROR) << "Failed to shutdown IE and npchrome_frame cleanly after test "
+                "execution.";
+  StopFileLogger(true);
+  ::ExitProcess(1);
+}
+
 // Override virtual void Initialize to not call icu initialize.
 void CFUrlRequestUnittestRunner::Initialize() {
   DCHECK(::GetCurrentThreadId() == test_thread_id_);
@@ -580,11 +586,17 @@ void CFUrlRequestUnittestRunner::OnConnectAutomationProviderToChannel(
 
 void CFUrlRequestUnittestRunner::OnInitialTabLoaded() {
   test_http_server_.reset();
+  BrowserThread::PostTask(
+      BrowserThread::UI,
+      FROM_HERE,
+      base::Bind(&CFUrlRequestUnittestRunner::CancelInitializationTimeout,
+                 base::Unretained(this)));
   StartTests();
 }
 
 void CFUrlRequestUnittestRunner::OnProviderDestroyed() {
   if (tests_ran_) {
+    StopFileLogger(false);
     if (crash_service_)
       base::KillProcess(crash_service_, 0, false);
     ::ExitProcess(test_result());
@@ -599,6 +611,7 @@ void CFUrlRequestUnittestRunner::StartTests() {
     MessageBoxA(NULL, "click ok to run", "", MB_OK);
 
   DCHECK_EQ(test_thread_.IsValid(), false);
+  StopFileLogger(false);
   test_thread_.Set(::CreateThread(NULL, 0, RunAllUnittests, this, 0,
                                   &test_thread_id_));
   DCHECK(test_thread_.IsValid());
@@ -623,6 +636,11 @@ void CFUrlRequestUnittestRunner::TakeDownBrowser() {
   if (prompt_after_setup_)
     MessageBoxA(NULL, "click ok to exit", "", MB_OK);
 
+  // Start capturing logs from npchrome_frame and the in-process Chrome to help
+  // diagnose failures in IE shutdown. This will be Stopped in either
+  // OnIEShutdownFailure or OnProviderDestroyed.
+  StartFileLogger();
+
   // AddRef to ensure that IE going away does not trigger the Chrome shutdown
   // process.
   // IE shutting down will, however, trigger the automation channel to shut
@@ -632,10 +650,12 @@ void CFUrlRequestUnittestRunner::TakeDownBrowser() {
 
   // In case IE is somehow hung, make sure we don't sit around until a try-bot
   // kills us. OnIEShutdownFailure will log and exit with an error.
-  BrowserThread::PostDelayedTask(BrowserThread::UI,
-                                 FROM_HERE,
-                                 base::Bind(&OnIEShutdownFailure),
-                                 TestTimeouts::action_max_timeout_ms());
+  BrowserThread::PostDelayedTask(
+      BrowserThread::UI,
+      FROM_HERE,
+      base::Bind(&CFUrlRequestUnittestRunner::OnIEShutdownFailure,
+                 base::Unretained(this)),
+      TestTimeouts::action_max_timeout_ms());
 }
 
 void CFUrlRequestUnittestRunner::InitializeLogging() {
@@ -653,6 +673,35 @@ void CFUrlRequestUnittestRunner::InitializeLogging() {
   logging::SetLogItems(true, true, true, true);
 }
 
+void CFUrlRequestUnittestRunner::CancelInitializationTimeout() {
+  timeout_closure_.Cancel();
+}
+
+void CFUrlRequestUnittestRunner::StartInitializationTimeout() {
+  timeout_closure_.Reset(
+      base::Bind(&CFUrlRequestUnittestRunner::OnInitializationTimeout,
+                 base::Unretained(this)));
+  MessageLoop::current()->PostDelayedTask(
+      FROM_HERE,
+      timeout_closure_.callback(),
+      TestTimeouts::action_max_timeout_ms());
+}
+
+void CFUrlRequestUnittestRunner::OnInitializationTimeout() {
+  LOG(ERROR) << "Failed to start Chrome Frame in the host browser.";
+  StopFileLogger(true);
+
+  if (launch_browser_) {
+    base::win::ScopedCOMInitializer com;
+    chrome_frame_test::CloseAllIEWindows();
+  }
+
+  if (crash_service_)
+    base::KillProcess(crash_service_, 0, false);
+
+  ::ExitProcess(1);
+}
+
 void CFUrlRequestUnittestRunner::OverrideHttpHost() {
   net::NetworkInterfaceList nic_list;
   if (!net::GetNetworkList(&nic_list)) {
@@ -685,6 +734,7 @@ void CFUrlRequestUnittestRunner::OverrideHttpHost() {
 void CFUrlRequestUnittestRunner::PreEarlyInitialization() {
   testing::InitGoogleTest(&g_argc, g_argv);
   FilterDisabledTests();
+  StartFileLogger();
 }
 
 MessageLoop* CFUrlRequestUnittestRunner::GetMainMessageLoop() {
@@ -713,6 +763,7 @@ bool CFUrlRequestUnittestRunner::MainMessageLoopRun(int* result_code) {
   // We need to allow IO on the main thread for these tests.
   base::ThreadRestrictions::SetIOAllowed(true);
 
+  StartInitializationTimeout();
   return false;
 }
 
@@ -743,6 +794,37 @@ void CFUrlRequestUnittestRunner::PostDestroyThreads() {
 #endif
 }
 
+void CFUrlRequestUnittestRunner::StartFileLogger() {
+  if (file_util::CreateTemporaryFile(&log_file_)) {
+    file_logger_.reset(new logging_win::FileLogger());
+    file_logger_->Initialize();
+    file_logger_->StartLogging(log_file_);
+  } else {
+    LOG(ERROR) << "Failed to create an ETW log file";
+  }
+}
+
+void CFUrlRequestUnittestRunner::StopFileLogger(bool print) {
+  if (file_logger_.get() != NULL && file_logger_->is_logging()) {
+    file_logger_->StopLogging();
+
+    if (print) {
+      // Flushing stdout should prevent unrelated output from being interleaved
+      // with the log file output.
+      std::cout.flush();
+      // Dump the log to stderr.
+      logging_win::PrintLogFile(log_file_, &std::cerr);
+      std::cerr.flush();
+    }
+  }
+
+  if (!log_file_.empty() && !file_util::Delete(log_file_, false))
+    LOG(ERROR) << "Failed to delete log file " << log_file_.value();
+
+  log_file_.clear();
+  file_logger_.reset();
+}
+
 const char* IEVersionToString(IEVersion version) {
   switch (version) {
     case IE_6:
diff --git a/chrome_frame/test/net/fake_external_tab.h b/chrome_frame/test/net/fake_external_tab.h
index 46479b5..964cb13 100644
--- a/chrome_frame/test/net/fake_external_tab.h
+++ b/chrome_frame/test/net/fake_external_tab.h
@@ -8,6 +8,7 @@
 
 #include <string>
 
+#include "base/cancelable_callback.h"
 #include "base/file_path.h"
 #include "base/message_loop.h"
 #include "base/process.h"
@@ -27,7 +28,11 @@ class ProcessSingleton;
 
 namespace content {
 class NotificationService;
-}
+}  // namespace content
+
+namespace logging_win {
+class FileLogger;
+}  // namespace logging_win
 
 class FakeExternalTab {
  public:
@@ -89,7 +94,7 @@ class CFUrlRequestUnittestRunner
   void StartTests();
 
   // Borrowed from TestSuite::Initialize().
-  static void InitializeLogging();
+  void InitializeLogging();
 
   int test_result() const {
     return test_result_;
@@ -140,10 +145,20 @@ class CFUrlRequestUnittestRunner
   // Causes HTTP tests to run over an external address rather than 127.0.0.1.
   // See http://crbug.com/114369 .
   void OverrideHttpHost();
+  void StartFileLogger();
+  void StopFileLogger(bool print);
+  void OnIEShutdownFailure();
+
+  void CancelInitializationTimeout();
+  void StartInitializationTimeout();
+  void OnInitializationTimeout();
 
   bool launch_browser_;
   bool prompt_after_setup_;
   bool tests_ran_;
+  base::CancelableClosure timeout_closure_;
+  scoped_ptr<logging_win::FileLogger> file_logger_;
+  FilePath log_file_;
 
   DISALLOW_COPY_AND_ASSIGN(CFUrlRequestUnittestRunner);
 };