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..7dea87f83f0dcfe568a5fbd5da2f71b77cea6277
--- /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 {
+
+bool g_is_initialized = false;
+
+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";
+unsigned int kBroadcastTimeoutMilliseconds = 2 * 1000;
+
+}  // namespace
+
+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.

[erikwright (departed), 2012/03/09 18:25:50]

I wouldn't mind seeing the functionality of modifying the system environment
turned into a separate scoped object (ScopedSystemEnvironmentVariable?).

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

Good idea.  Done.  I also followed a previous suggestion of yours and got rid of
Uninitialize.

+  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(!g_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;
+
+  g_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();
+
+  g_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 {

[erikwright (departed), 2012/03/09 18:25:50]

You're ignoring the result of EnableProviders. Mightn't the caller want to know
about a failure there? Should you StopLogging if that happens?

if (!SUCCEEDED(hr)) {
  ...
  return false;
}

if (!EnableProviders()) {
  StopLogging();
  return false;
}

return true;

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

This was intentional.  If the session can't be established at all, then it makes
sense to return false from here ('cause there'd be no logging in that case).  On
the other hand, it becomes ambiguous as to what the "right thing" is when one of
four providers can't be enabled.  I've chosen to log the fact that the provider
couldn't be enabled, but not consider that sufficiently severe to make
StartLogging fail.  I've just changed it so that StartLogging returns false if
none of the providers could be enabled.  WDYT?

+    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;
+}