New test infrastructure for producing verbose logs in failing tests.

chrome/test/base/file_logger_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/file_logger_win.h"
+
+#include <windows.h>
+
+#include <ios>  // For std::hex
+
+#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 } };
+
+const GUID* const kDefaultProviders[] = {
+  &kChromeTraceProviderName,
+  &kChromeFrameProvider,
+  &kChromeTestsProvider,
+};
+
+const HKEY kEnvironmentRoot = HKEY_LOCAL_MACHINE;

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

I take it that this can only be used for tests running as admin, not the
user-level tests?

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

Yeah, firing up an ETW session requires admin, as does the environment
twiddling.

+const wchar_t kEnvironmentKey[] =
+    L"SYSTEM\\CurrentControlSet\\Control\\Session Manager\\Environment";
+const wchar_t kEnvironment[] = L"Environment";
+unsigned int kBroadcastTimeoutMilliseconds = 2 * 1000;
+
+// A helper class that dumps a log file to an output stream.  Only one may be
+// in use at a time.
+class LogDumper {
+ public:
+  // Dump |log_file| to |out|.
+  static void DumpLog(const FilePath& log_file, std::ostream& out);
+
+ private:
+  // An implementation of a trace consumer that sends the message text of
+  // events to a given output stream.
+  class TraceConsumer : public base::win::EtwTraceConsumerBase<TraceConsumer> {
+   public:
+    explicit TraceConsumer(std::ostream& out);
+    ~TraceConsumer();
+
+    static void ProcessEvent(EVENT_TRACE* event);
+
+   private:
+    static std::ostream* out_;
+    DISALLOW_COPY_AND_ASSIGN(TraceConsumer);
+  };
+
+  DISALLOW_IMPLICIT_CONSTRUCTORS(LogDumper);
+};
+
+// static
+std::ostream* LogDumper::TraceConsumer::out_ = NULL;
+
+LogDumper::TraceConsumer::TraceConsumer(std::ostream& out) {
+  DCHECK(out_ == NULL);
+  out_ = &out;
+}
+
+LogDumper::TraceConsumer::~TraceConsumer() {
+  out_ = NULL;
+}
+
+// static
+void LogDumper::TraceConsumer::ProcessEvent(EVENT_TRACE* event) {
+  // The payload for events generated with the ENABLE_LOG_MESSAGE_ONLY and
+  // ENABLE_DETAILED_LOG_MESSAGE flags is simply the message text.
+  *out_ << reinterpret_cast<const char*>(event->MofData);
+}
+
+// static
+void LogDumper::DumpLog(const FilePath& log_file, std::ostream& out) {
+  TraceConsumer consumer(out);
+  HRESULT hr = S_OK;
+
+  hr = consumer.OpenFileSession(log_file.value().c_str());
+  if (FAILED(hr)) {
+    LOG(ERROR) << "Failed to open session for log file " << log_file.value()
+               << "; hr=" << std::hex << hr;
+  } else {
+    consumer.Consume();
+    consumer.Close();
+    out.flush();
+  }
+}
+
+}  // namespace
+
+FileLogger::FileLogger()
+    : added_chrome_etw_variable_(false) {
+}
+
+FileLogger::~FileLogger() {
+  if (!provider_names_.empty()) {
+    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;
+  if (environment.Open(kEnvironmentRoot, kEnvironmentKey,
+                       KEY_QUERY_VALUE | KEY_SET_VALUE) == ERROR_SUCCESS) {
+    string16 value;
+    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);
+    }
+  }
+}
+
+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;
+  HRESULT hr = S_OK;
+  const std::vector<GUID>::const_iterator end(provider_names_.end());
+  for (std::vector<GUID>::const_iterator scan(provider_names_.begin());
+       scan != end; ++scan) {
+    hr = controller_.EnableProvider(*scan, 255,
+                                    (logging::ENABLE_LOG_MESSAGE_ONLY |
+                                     logging::ENABLE_DETAILED_LOG_MESSAGE));
+    if (FAILED(hr)) {
+      result = false;
+      LOG(ERROR) << "Failed to enable event provider "
+                 << scan - provider_names_.begin()
+                 << "; hr=" << std::hex << hr;
+    }
+  }
+  return result;
+}
+
+void FileLogger::DisableProviders() {
+  HRESULT hr = S_OK;
+  const std::vector<GUID>::const_iterator end(provider_names_.end());
+  for (std::vector<GUID>::const_iterator scan(provider_names_.begin());
+       scan != end; ++scan) {
+    hr = controller_.DisableProvider(*scan);
+    LOG_IF(ERROR, FAILED(hr)) << "Failed to disable event provider "
+                              << scan - provider_names_.begin()
+                              << "; hr=" << std::hex << hr;
+  }
+}
+
+void FileLogger::Initialize() {
+  Initialize(&kDefaultProviders[0], arraysize(kDefaultProviders));
+}
+
+
+void FileLogger::Initialize(const GUID* const* provider_names,
+                            size_t provider_count) {
+  DCHECK(provider_names || provider_count == 0);
+  DCHECK(provider_names_.empty() && !added_chrome_etw_variable_);
+  CHECK(!g_is_initialized);
+
+  provider_names_.resize(provider_count);
+  for (size_t i = 0; i < provider_count; ++i) {
+    provider_names_[i] = *provider_names[i];
+  }
+
+  ConfigureChromeEtwLogging();

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

Make this return a value and log if it fails?

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

I've added some logging to the implementation.  WDYT?

+
+  // 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;
+
+  // 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.
+  logging::LogEventProvider::Initialize(kChromeTestsProvider);
+
+  g_is_initialized = true;
+}
+
+void FileLogger::Uninitialize() {
+  if (is_logging()) {
+    LOG(ERROR)
+        << __FUNCTION__ << " don't forget to call FileLogger::StopLogging()";
+    StopLogging();
+  }
+
+  logging::LogEventProvider::Uninitialize();
+
+  provider_names_.clear();
+
+  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 {
+    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;
+}
+
+// static
+void FileLogger::DumpLogFile(const FilePath& log_file, std::ostream& out) {
+  LogDumper::DumpLog(log_file, out);
+}