New test infrastructure for producing verbose logs in failing tests.

chrome/test/base/file_logger_win.cc

Index: chrome/test/base/file_logger_win.cc
diff --git a/chrome/test/base/file_logger_win.cc b/chrome/test/base/file_logger_win.cc
new file mode 100644
index 0000000000000000000000000000000000000000..8ac03adf9c0282cbff7536412c904abdc8660f3b
--- /dev/null
+++ b/chrome/test/base/file_logger_win.cc
@@ -0,0 +1,245 @@
+// 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/file_logger_win.h"
+
+#include <windows.h>
+#include <guiddef.h>
+#include <objbase.h>
+
+#include <ios>
+
+#include "base/debug/trace_event_win.h"
+#include "base/logging.h"
+#include "base/file_path.h"
+#include "base/logging_win.h"
+#include "base/string16.h"
+#include "base/utf_string_conversions.h"
+#include "base/win/event_trace_consumer.h"
+#include "base/win/registry.h"
+#include "chrome/common/env_vars.h"
+
+namespace {
+
+const wchar_t kChromeTestSession[] = L"chrome_tests";
+
+// From chrome_tab.cc: {0562BFC3-2550-45b4-BD8E-A310583D3A6F}
+const GUID kChromeFrameProvider =
+    { 0x562bfc3, 0x2550, 0x45b4,
+        { 0xbd, 0x8e, 0xa3, 0x10, 0x58, 0x3d, 0x3a, 0x6f } };
+
+// From chrome/common/logging_chrome.cc: {7FE69228-633E-4f06-80C1-527FEA23E3A7}
+const GUID kChromeTraceProviderName =
+    { 0x7fe69228, 0x633e, 0x4f06,
+        { 0x80, 0xc1, 0x52, 0x7f, 0xea, 0x23, 0xe3, 0xa7 } };
+
+// {81729947-CD2A-49e6-8885-785429F339F5}
+const GUID kChromeTestsProvider =
+    { 0x81729947, 0xcd2a, 0x49e6,
+        { 0x88, 0x85, 0x78, 0x54, 0x29, 0xf3, 0x39, 0xf5 } };
+
+// The configurations for the supported providers.  This must be in sync with
+// FileLogger::EventProviderBits.
+const struct {
+  const GUID* provider_name;
+  uint8 level;
+  uint32 flags;
+} kProviders[] = {
+  { &kChromeTraceProviderName, 255, 0 },
+  { &kChromeFrameProvider, 255, 0 },
+  { &kChromeTestsProvider, 255, 0 },
+  { &base::debug::kChromeTraceProviderName, 255, 0 }
+};
+
+COMPILE_ASSERT((1 << arraysize(kProviders)) - 1 ==
+                   FileLogger::kAllEventProviders,
+               size_of_kProviders_is_inconsistent_with_kAllEventProviders);
+
+const HKEY kEnvironmentRoot = HKEY_LOCAL_MACHINE;
+const wchar_t kEnvironmentKey[] =
+    L"SYSTEM\\CurrentControlSet\\Control\\Session Manager\\Environment";
+const wchar_t kEnvironment[] = L"Environment";
+const unsigned int kBroadcastTimeoutMilliseconds = 2 * 1000;

[Paweł Hajdan Jr., 2012/03/09 18:12:12]

Why not base/test/test_timeouts?

[grt (UTC plus 2), 2012/03/09 20:38:58]

The closest timeout that's already defined there (action_timeout) is 10 seconds,
which would be a really long time for this.  It's common for this timeout to be
reached on a regular basis, since all it takes is for a window to not respond to
the WM_SETTINGCHANGE message.  Adding a new member to TestTimeouts for this
seems overkill.

+
+}  // namespace
+
+bool FileLogger::is_initialized_ = false;
+
+FileLogger::FileLogger()
+    : event_provider_mask_(),
+      added_chrome_etw_variable_() {
+}
+
+FileLogger::~FileLogger() {
+  if (event_provider_mask_) {
+    LOG(WARNING)
+        << __FUNCTION__ << " don't forget to call FileLogger::Uninitialize()";
+    Uninitialize();
+  }
+}
+
+void FileLogger::ConfigureChromeEtwLogging() {
+  const string16 chrome_etw_logging(ASCIIToWide(env_vars::kEtwLogging));
+
+  // Set the value in this process and its children.
+  ::SetEnvironmentVariable(chrome_etw_logging.c_str(), L"1");
+
+  // Set the value for the whole system and ask everyone to refresh.
+  base::win::RegKey environment;
+  LONG result = environment.Open(kEnvironmentRoot, kEnvironmentKey,
+                                 KEY_QUERY_VALUE | KEY_SET_VALUE);
+  if (result == ERROR_SUCCESS) {
+    string16 value;
+    // The actual value of the variable is insignificant in the eyes of Chrome.
+    if (environment.ReadValue(chrome_etw_logging.c_str(),
+                              &value) != ERROR_SUCCESS &&
+        environment.WriteValue(chrome_etw_logging.c_str(),
+                               L"1") == ERROR_SUCCESS) {
+      environment.Close();
+      added_chrome_etw_variable_ = true;
+      // Announce to the system that a change has been made so that the shell
+      // and other Windowsy bits pick it up; see
+      // http://msdn.microsoft.com/en-us/library/windows/desktop/ms682653.aspx.
+      SendMessageTimeout(HWND_BROADCAST, WM_SETTINGCHANGE, 0,
+                         reinterpret_cast<LPARAM>(kEnvironment),
+                         SMTO_ABORTIFHUNG,
+                         kBroadcastTimeoutMilliseconds, NULL);
+    }
+  } else {
+    SetLastError(result);
+    PLOG(ERROR) << "Failed to open HKLM to check/modify the system environment";
+  }
+}
+
+void FileLogger::RevertChromeEtwLogging() {
+  if (added_chrome_etw_variable_) {
+    base::win::RegKey environment;
+    if (environment.Open(kEnvironmentRoot, kEnvironmentKey,
+                         KEY_SET_VALUE) == ERROR_SUCCESS) {
+      environment.DeleteValue(ASCIIToWide(env_vars::kEtwLogging).c_str());
+      environment.Close();
+      SendMessageTimeout(HWND_BROADCAST, WM_SETTINGCHANGE, 0,
+                         reinterpret_cast<LPARAM>(kEnvironment),
+                         SMTO_ABORTIFHUNG,
+                         kBroadcastTimeoutMilliseconds, NULL);
+    }
+    added_chrome_etw_variable_ = false;
+  }
+}
+
+bool FileLogger::EnableProviders() {
+  bool result = true;
+
+  // Generate ETW log events for this test binary.  Log messages at and above
+  // logging::GetMinLogLevel() will continue to go to stderr as well.  This
+  // leads to double logging in case of test failures: each LOG statement at
+  // or above the min level will go to stderr during test execution, and then
+  // all events logged to the file session will be dumped again.  If this
+  // turns out to be an issue, one could call logging::SetMinLogLevel(INT_MAX)
+  // here (stashing away the previous min log level to be restored in
+  // Uninitialize) to suppress stderr logging during test execution.  Then those
+  // events in the file that were logged at/above the old min level from the
+  // test binary could be dumped to stderr if there were no failures.
+  if (event_provider_mask_ & CHROME_TESTS_LOG_PROVIDER)
+    logging::LogEventProvider::Initialize(kChromeTestsProvider);
+
+  HRESULT hr = S_OK;
+  for (size_t i = 0; i < arraysize(kProviders); ++i) {
+    if (event_provider_mask_ & (1 << i)) {
+      hr = controller_.EnableProvider(*kProviders[i].provider_name,
+                                      kProviders[i].level,
+                                      kProviders[i].flags);
+      if (FAILED(hr)) {
+        result = false;
+        LOG(ERROR) << "Failed to enable event provider " << i
+                   << "; hr=" << std::hex << hr;
+      }
+    }
+  }
+
+  return result;
+}
+
+void FileLogger::DisableProviders() {
+  HRESULT hr = S_OK;
+  for (size_t i = 0; i < arraysize(kProviders); ++i) {
+    if (event_provider_mask_ & (1 << i)) {
+      hr = controller_.DisableProvider(*kProviders[i].provider_name);
+      LOG_IF(ERROR, FAILED(hr)) << "Failed to disable event provider "
+                                << i << "; hr=" << std::hex << hr;
+    }
+  }
+
+  if (event_provider_mask_ & CHROME_TESTS_LOG_PROVIDER)
+    logging::LogEventProvider::Uninitialize();
+}
+
+void FileLogger::Initialize() {
+  Initialize(kAllEventProviders);
+}
+
+void FileLogger::Initialize(uint32 event_provider_mask) {
+  DCHECK(event_provider_mask_ == 0 && !added_chrome_etw_variable_);
+  CHECK(!is_initialized_);
+
+  ConfigureChromeEtwLogging();
+
+  // Stop a previous session that wasn't shut down properly.
+  base::win::EtwTraceProperties ignore;
+  HRESULT hr = base::win::EtwTraceController::Stop(kChromeTestSession,
+                                                   &ignore);
+  LOG_IF(ERROR, FAILED(hr) &&
+             hr != HRESULT_FROM_WIN32(ERROR_WMI_INSTANCE_NOT_FOUND))
+      << "Failed to stop a previous trace session; hr=" << std::hex << hr;
+
+  event_provider_mask_ = event_provider_mask;
+
+  is_initialized_ = true;
+}
+
+void FileLogger::Uninitialize() {
+  if (is_logging()) {
+    LOG(ERROR)
+        << __FUNCTION__ << " don't forget to call FileLogger::StopLogging()";
+    StopLogging();
+  }
+
+  event_provider_mask_ = 0;
+
+  RevertChromeEtwLogging();
+
+  is_initialized_ = false;
+}
+
+bool FileLogger::StartLogging(const FilePath& log_file) {
+  HRESULT hr =
+      controller_.StartFileSession(kChromeTestSession,
+                                   log_file.value().c_str(), false);
+  if (SUCCEEDED(hr)) {
+    EnableProviders();
+  } else {
+    if (hr == HRESULT_FROM_WIN32(ERROR_ACCESS_DENIED)) {
+      LOG(WARNING) << "Access denied while trying to start trace session. "
+                      "This is expected when not running as an administrator.";
+    } else {
+      LOG(ERROR) << "Failed to start trace session to file " << log_file.value()
+                 << "; hr=" << std::hex << hr;
+    }
+    return false;
+  }
+  return true;
+}
+
+void FileLogger::StopLogging() {
+  HRESULT hr = S_OK;
+
+  DisableProviders();
+
+  hr = controller_.Flush(NULL);
+  LOG_IF(ERROR, FAILED(hr))
+      << "Failed to flush events; hr=" << std::hex << hr;
+  hr = controller_.Stop(NULL);
+  LOG_IF(ERROR, FAILED(hr))
+      << "Failed to stop ETW session; hr=" << std::hex << hr;
+}