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}

[erikwright (departed), 2012/03/02 20:47:59]

I would argue against declaring these here, and against this class having
default providers.

Make the definitions suitably accessible, and then simply expect the client to
supply the list they're interested in.

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

My argument is that these are the only three providers.  I think that the common
(perhaps only) case is that users would want to listen to all three.  Even if
they only care about the test and Chrome (and not CF), I'd go in favor of the
simple interface.  I put the extra Initialize method in just in case there was a
fringe user, or if someone wanted to write a unit test for this test code.

[erikwright (departed), 2012/03/03 02:04:56]

I'll explain my reasoning, but leave it at that. I don't care too much either
way.

The main source of smell for me is the duplication of these values here. So I
wondered whether they could be included from elsewhere, but I realized that this
code here could not really have a dependency on chrome_frame. The only way to
neither duplicate nor add an inappropriate dependency would be to take them out.

Two other options present themselves:

1) Move this code higher up, to chrome_frame/test, for example. Of course, then
it would not be reusable by other teams.
2) Make a base class that does not include the Chrome Frame provider, and then
put a subclass in chrome_frame/test

The 3rd option of leaving it as is is OK too.

[grt (UTC plus 2), 2012/03/03 02:31:59]

Understood.  Duplicating them here made me a bit uneasy as well, but beer and
the fact that it's test infrastructure helped me feel better.  Not that test
code should necessarily be held to a lower standard...  Okay, maybe I'm taking
the easy way out.
Yeah, yuk.
Hmm.  I'll think on that.  I'd like to keep it as drop-dead simple for consumers
as possible.
Another would be to put all of the constants in a central place in chrome/common
somewhere.  That'd be accessible to this, Chrome, and CF.  I'll think on it.

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

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

Is MofData guaranteed to be null terminated or should you use MofLength here?

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

The terminator is always added by loggin_win.cc.  It's better not to blow up if
it's missing for some reason, so I've made it safe.  Thanks for pointing this
out.

+}
+
+// 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");

[erikwright (departed), 2012/03/02 20:47:59]

Should this also be reverted? If not, why not?

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

It's more work.  The change won't persist beyond the lifetime of this process. 
I can understand the purity and symmetry of doing so, but I don't think there's
any harm in leaving it there.  The extra steps are taken to conditionally undo
the registry change since that's a persistent system-wide modification.

+
+  // 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 &&

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

do you need to check value here?

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

Nope, Chrome doesn't care.  I've added a comment.

+        environment.WriteValue(chrome_etw_logging.c_str(),
+                               L"1") == ERROR_SUCCESS) {
+      environment.Close();
+      added_chrome_etw_variable_ = true;
+      SendMessageTimeout(HWND_BROADCAST, WM_SETTINGCHANGE, 0,

[erikwright (departed), 2012/03/02 20:47:59]

I would appreciate further comments as to how this actually works. Is this a
standard Windows thing? What part of Chrome is reacting to it?

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

Comment added.  It's a standard Windows thing
(http://msdn.microsoft.com/en-us/library/windows/desktop/ms682653(v=vs.85).aspx);
no part of Chrome would react to it, to my knowledge.  The idea is that we want
the environment for IE and Chrome to have the env var.  The hope is that after
the broadcast, the Windows shell and any other relevant parts of the system have
picked up the new env var.

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

Did you test this against IE8/9 in protected mode? I vaguely recall that env
vars weren't always propagated when IE spawned child processes (which might be
why you added this), so this I suppose will have to be handled by IE as well for
CF logging to be caught.

[erikwright (departed), 2012/03/03 02:04:56]

So I gather that this class can only catch log messages from processes that are
not yet started, correct? If so, I would suggest including that in comments.

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

I've tested against IE8, but I didn't do anything special for protected mode. 
How do I do that?
IE shouldn't be running when this happens (or if it is, it'll be killed shortly
thereafter).  The question is whether or not IE is handed the system env vars by
whatever fires it up, and whether or not it passes them on to child processes it
spawns.  I'll try it out with IE8.

[grt (UTC plus 2), 2012/03/03 02:31:59]

Not necessarily.  If you already had that var in your environment (because
you've installed Sawbuck, for example), then it would work for running procs as
well.  I'll add a comment nonetheless.

[robertshield, 2012/03/05 19:20:53]

I just meant with IE8/9 in multi-process mode (the default), verify that either
the env var is handed off to *new* low-integrity processes, or that those low
integrity processes respond as desired to the WM_SETTINGCHANGE (they probably
do).

+                         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) {

[erikwright (departed), 2012/03/02 20:47:59]

Is it actually considered costly to just inline the call to
provider_names_.end()?

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

For a release build, no.  For a debug build it'll create/destroy an iterator
each time through the loop.  Old habits die hard...

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

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

If these are initialized on different threads, you could still have two of them
initialized without hitting this CHECK.

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

The documentation for the class says only one instance may be initialized at a
time.  This is a feeble attempt at enforcing that so that unexpected things
don't happen.  I'll add a note that the class isn't threadsafe in any way,
shape, or form.

+
+  provider_names_.resize(provider_count);
+  for (size_t i = 0; i < provider_count; ++i) {
+    provider_names_[i] = *provider_names[i];
+  }
+
+  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;
+
+  // 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 {
+    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);
+}